Query hangs intermittently

[Travis Pogmore]

I run a query processing uploaded data in order to determine whether or not it will pass primary and foreign key constraints in order to provide better feedback to the uploader besides a database query failure message. On some occasions this query will run in just a few minutes but on other occasions it will hang on this query for hours before completing, and in still other cases it has hung indefinitely and not completed after days of waiting. It doesn't generate any entries in the error log.

Even when fed identical data via our DAIS01S05__data_import database we are unable to predict whether or not the query will hang.

It's unclear if this is a bug or a tuning issue, can someone help me?

----

Here's the (partial) results from the processlist and the table structure.

mysql> show full processlist;
+------+----------+---------------------+---------------------+---------+------+--------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+------+----------+---------------------+---------------------+---------+------+--------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------------+
| 1470 | cyeoman | 192.168.122.1:49370 | DAIS01S05__daisi | Query | 8976 | Sending data | INSERT INTO program_data_upload_constraint_violations
     (
      fiscal_year
      , program_id
      , file_structure_type_id
      , constraint_index
      , constraint_violation_line_number
      , constraint_violation_display
     )
     SELECT data_import_table.fiscal_year fiscal_year
      , data_import_table.program_id program_id
      , 17 file_structure_type_id
      , 3 constraint_index
      , data_import_table.uploaded_file_line_number constraint_violation_line_number
      , CONCAT_WS('|',

         data_import_table.student_id

       ) constraint_violation_display
     FROM DAIS01S05__data_import._import_data_class_student data_import_table
     WHERE data_import_table.fiscal_year = 2015
      AND data_import_table.program_id = 508
      AND NOT EXISTS (
       SELECT *
       FROM DAIS01S05__data_import._import_data_student_current reference_data_import_table
       WHERE reference_data_import_table.fiscal_year = data_import_table.fiscal_year
        AND reference_data_import_table.program_id = data_import_table.program_id

         AND reference_data_import_table.student_id = data_import_table.student_id

      ) | 0 | 3889265525 |
+------+----------+---------------------+---------------------+---------+------+--------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------------+

mysql> desc program_data_upload_constraint_violations;
+----------------------------------+--------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+----------------------------------+--------------+------+-----+---------+-------+
| fiscal_year | int(6) | NO | PRI | NULL | |
| program_id | int(11) | NO | PRI | NULL | |
| file_structure_type_id | int(11) | NO | PRI | NULL | |
| constraint_index | int(11) | NO | PRI | NULL | |
| constraint_violation_line_number | int(11) | NO | PRI | NULL | |
| constraint_violation_display | varchar(128) | NO | | NULL | |
+----------------------------------+--------------+------+-----+---------+-------+
6 rows in set (5.25 sec)

mysql> desc DAIS01S05__data_import._import_data_class_student;
+---------------------------+-------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+---------------------------+-------------+------+-----+---------+-------+
| fiscal_year | int(6) | NO | PRI | NULL | |
| program_id | int(11) | NO | PRI | NULL | |
| college_id | int(11) | NO | | NULL | |
| student_id | int(11) | NO | | NULL | |
| course_id | int(11) | NO | | NULL | |
| class_id | int(11) | NO | | NULL | |
| midterm_score | varchar(20) | YES | | NULL | |
| final_score | varchar(20) | YES | | NULL | |
| funding_source_id | int(11) | NO | | NULL | |
| instructional_type_id | int(11) | NO | | NULL | |
| class_exit_id | int(11) | YES | | NULL | |
| uploaded_file_line_number | int(11) | NO | PRI | NULL | |
| original_row_text | blob | NO | | NULL | |
| parsed_data_object | blob | NO | | NULL | |
+---------------------------+-------------+------+-----+---------+-------+
14 rows in set (0.08 sec)

mysql> desc DAIS01S05__data_import._import_data_student_current;
+----------------------------------------+---------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+----------------------------------------+---------------+------+-----+---------+-------+
| fiscal_year | int(6) | NO | PRI | NULL | |
| program_id | int(11) | NO | PRI | NULL | |
| student_id | int(11) | NO | | NULL | |
| address1 | varchar(255) | NO | | NULL | |
| address2 | varchar(255) | YES | | NULL | |
| birth_date | datetime | YES | | NULL | |
| cell_phone | varchar(50) | YES | | NULL | |
| city | varchar(50) | NO | | NULL | |
| state_id | int(11) | YES | | NULL | |
| country_of_origin | varchar(50) | YES | | NULL | |
| county_of_residence_id | int(11) | YES | | NULL | |
| date_first_name_changed | datetime | YES | | NULL | |
| date_last_name_changed | datetime | YES | | NULL | |
| date_received | datetime | YES | | NULL | |
| dependent_number_minor_children | int(11) | YES | | NULL | |
| dependent_number_other | int(11) | YES | | NULL | |
| diploma_date | datetime | YES | | NULL | |
| disability_id | int(11) | YES | | NULL | |
| distance_learning | tinyint(4) | YES | | NULL | |
| email_address | varchar(100) | YES | | NULL | |
| emergency_first_name | varchar(50) | YES | | NULL | |
| emergency_last_name | varchar(50) | YES | | NULL | |
| emergency_phone | varchar(50) | YES | | NULL | |
| encrypted_ssn | varchar(64) | NO | | NULL | |
| encrypted_ssn_l4 | varchar(64) | YES | | NULL | |
| english_not_first_language | tinyint(4) | YES | | NULL | |
| ethnicity_id | int(11) | YES | | NULL | |
| external_student_id | varchar(50) | YES | | NULL | |
| first_name | varchar(50) | NO | | NULL | |
| gender_id | int(11) | YES | | NULL | |
| has_diploma | tinyint(4) | YES | | NULL | |
| has_ged | tinyint(4) | YES | | NULL | |
| history_notes | text | YES | | NULL | |
| home_phone | varchar(50) | YES | | NULL | |
| hours_worked_per_week | decimal(10,2) | YES | | NULL | |
| is_eg_american_indian_alaska_native | tinyint(4) | YES | | NULL | |
| is_eg_asian | tinyint(4) | YES | | NULL | |
| is_eg_black | tinyint(4) | YES | | NULL | |
| is_eg_native_hawaiian_pacific_islander | tinyint(4) | YES | | NULL | |
| is_eg_white | tinyint(4) | YES | | NULL | |
| is_spanish_origin | tinyint(4) | YES | | NULL | |
| last_access_date | datetime | YES | | NULL | |
| last_name | varchar(50) | NO | | NULL | |
| last_school_attended | varchar(255) | YES | | NULL | |
| marital_id | int(11) | YES | | NULL | |
| middle_name | varchar(50) | YES | | NULL | |
| native_language | varchar(50) | YES | | NULL | |
| occupation_id | int(11) | YES | | NULL | |
| primary_ethnic_group_id | int(11) | YES | | NULL | |
| primary_goal_date_achieved | datetime | YES | | NULL | |
| primary_goal_date_entered | datetime | YES | | NULL | |
| primary_goal_date_modified | datetime | YES | | NULL | |
| primary_goal_date_set | datetime | YES | | NULL | |
| primary_goal_id | int(11) | YES | | NULL | |
| public_aid_id | varchar(20) | YES | | NULL | |
| emergency_relationship | varchar(30) | YES | | NULL | |
| returning_student_in_fy07 | tinyint(4) | YES | | NULL | |
| school_type_id | int(11) | YES | | NULL | |
| school_year_completed | varchar(10) | YES | | NULL | |
| secondary_goal_date_achieved | datetime | YES | | NULL | |
| secondary_goal_date_entered | datetime | YES | | NULL | |
| secondary_goal_date_modified | datetime | YES | | NULL | |
| secondary_goal_date_set | datetime | YES | | NULL | |
| secondary_goal_id | int(11) | YES | | NULL | |
| separation_date | datetime | YES | | NULL | |
| separation_reason_id | int(11) | YES | | NULL | |
| status_id | int(11) | NO | | NULL | |
| student_employment_status_id | int(11) | YES | | NULL | |
| student_recruitment_means_id | int(11) | YES | | NULL | |
| student_residence_area_Id | int(11) | YES | | NULL | |
| name_suffix | varchar(20) | YES | | NULL | |
| work_phone | varchar(50) | YES | | NULL | |
| yearly_household_income | decimal(10,2) | YES | | NULL | |
| zip | varchar(10) | NO | | NULL | |
| country_of_origin_id | int(11) | YES | | NULL | |
| month_year_last_enrolled | date | YES | | NULL | |
| school_year_details_type_id | int(11) | YES | | NULL | |
| uploaded_file_line_number | int(11) | NO | PRI | NULL | |
| original_row_text | blob | NO | | NULL | |
| parsed_data_object | blob | NO | | NULL | |
+----------------------------------------+---------------+------+-----+---------+-------+
80 rows in set (0.11 sec)

And here's my.cnf:

# Percona Server template configuration

[mysqld]
#
# Remove leading # and set to the amount of RAM for the most important data
# cache in MySQL. Start at 70% of total RAM for dedicated server, else 10%.
# innodb_buffer_pool_size = 128M
#
# Remove leading # to turn on a very important data integrity option: logging
# changes to the binary log between backups.
# log_bin
#
# Remove leading # to set options mainly useful for reporting servers.
# The server defaults are faster for transactions and fast SELECTs.
# Adjust sizes as needed, experiment to find the optimal values.
# join_buffer_size = 128M
# sort_buffer_size = 2M
# read_rnd_buffer_size = 2M
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock

# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0

# Recommended in standard MySQL setup
sql_mode=NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

[Valerii Kravchuk (valerii-kravchuk)]

What's you've reported above sounds like a support request that somebody has to spend a lot of time one to say anything definite about the root cause of the problem you have. I am not sure it's a result (or indication) of any bug in Percona Server.

To begin with, please, check the output of:

explain SELECT data_import_table.fiscal_year fiscal_year
                        , data_import_table.program_id program_id
                        , 17 file_structure_type_id
                        , 3 constraint_index
                        , data_import_table.uploaded_file_line_number constraint_violation_line_number
                        , CONCAT_WS('|',

                                                data_import_table.student_id

                                ) constraint_violation_display
                FROM DAIS01S05__data_import._import_data_class_student data_import_table
                WHERE data_import_table.fiscal_year = 2015
                        AND data_import_table.program_id = 508
                        AND NOT EXISTS (
                                SELECT *
                                FROM DAIS01S05__data_import._import_data_student_current reference_data_import_table
                                WHERE reference_data_import_table.fiscal_year = data_import_table.fiscal_year
                                        AND reference_data_import_table.program_id = data_import_table.program_id

                                                AND reference_data_import_table.student_id = data_import_table.student_id

                        );

(that is, SELECT part of your INSERT ... SELECT) when the query hangs and when it was executed fast enough. Maybe we can come up with some useful conclusion based on this comparison.

[Travis Pogmore (tpogmore)]

An explain from a situation where it hung but finished after a few hours:

+----+--------------------+-----------------------------+------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------+---------+--------------------------------------------------------------------------------------------------------------------------------------------------------------+--------+--------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+--------------------+-----------------------------+------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------+---------+--------------------------------------------------------------------------------------------------------------------------------------------------------------+--------+--------------------------+
| 1 | PRIMARY | data_import_table | ref | PRIMARY,tt_17_c1_class_id_c2_student_id,tt_17_c1_student_id,tt_17_c1_class_id,tt_17_c1_college_id_c2_funding_source_id_c3_instruct56590600,tt_17_c1_class_id_c2_course_id,tt_17_c1_course_id_c2_instructional_type_id | tt_17_c1_student_id | 8 | const,const | 120058 | Using where; Using index |
| 2 | DEPENDENT SUBQUERY | reference_data_import_table | ref | PRIMARY,tt_16_c1_student_id | tt_16_c1_student_id | 12 | DAIS01S05__data_import.data_import_table.fiscal_year,DAIS01S05__data_import.data_import_table.program_id,DAIS01S05__data_import.data_import_table.student_id | 1 | Using index |
+----+--------------------+-----------------------------+------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------+---------+--------------------------------------------------------------------------------------------------------------------------------------------------------------+--------+--------------------------+

An explain from a situation where it didn't hang and finished in a few minu...

[Valerii Kravchuk (valerii-kravchuk)]

So, plans look the same. Can you, please, try to get the output of:

show engine innodb status\G

when query is already running for a long time?

[Travis Pogmore (tpogmore)]

The lead developer for the project tweaked the code and I have so far been unable to recreate the slowdown since his changes were pushed. If it does hang again I'll be sure to get the engine status from it.

In the meantime in case it helps identifying a bug (or anyone else experiencing a similar problem), the code change was just adding "SQL_NO_CACHE" to the select portion of the query, making that line read "SELECT SQL_NO_CACHE data_import_table.fiscal_year fiscal_year".

[Sveta Smirnova (svetasmirnova)]

Thank you for the feedback.

Plan is same in both cases, so there is a chance this to be a locking issue: check if table is not used by any other connection. You will find it if check SHOW PROCESSLIST output and/or transaction list of SHOW ENGINE INNODB STATUS (if table uses InnoDB storage engine)

[Travis Pogmore (tpogmore)]

All of the information I provided above is from running this on an isolated server, so there were no other connections.

[Launchpad Janitor (janitor)]

[Expired for Percona Server because there has been no activity for 60 days.]

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3281