MySQL 5.6.34 RDS Warning: a long semaphore wait causes crash -- log included

Question

I had my RDS MySQL 5.6.34 server crash under normal load with nothing out of the ordinary today (That I could find). Amazon support pointed me the the error log.

MySQL config: https://gist.github.com/blasto333/9e82b6261681303f7369c3a2652e03f2

You can see full error log at:

https://www.dropbox.com/s/8y10mfok4l6zc1m/mysql-error-running.log.21.txt?dl=0

Most of the error log has:

InnoDB: Warning: a long semaphore wait: --Thread 47504778909440 has waited at dict0dict.cc line 1122 for 241.00 seconds the semaphore: Mutex at 0x2b33b16f34a8 created file dict0dict.cc line 1057, lock var 1 waiters flag 1 InnoDB: Warning: a long semaphore wait:

There is deadlock too

LATEST DETECTED DEADLOCK
------------------------
2018-07-05 23:11:31 2b34c9f8d700
*** (1) TRANSACTION:
TRANSACTION 1056966456, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 22 lock struct(s), heap size 2936, 10 row lock(s), undo log entries 8
MySQL thread id 149979681, OS thread handle 0x2b348aea9700, query id 1268732633 172.31.43.29 phppoint updating
UPDATE `phppos_items` SET `last_modified` = '2018-07-05 18:11:31'
WHERE `item_id` = 9794
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 1273297 n bits 152 index `PRIMARY` of table `phppoint_fatpanda`.`phppos_items` trx id 1056966456 lock_mode X locks rec but not gap waiting
Record lock, heap no 30 PHYSICAL RECORD: n_fields 61; compact format; info bits 0
 0: len 4; hex 80002642; asc   &B;;
 1: len 6; hex 00003f00027d; asc   ?  };;
 2: len 7; hex 1b00013aea2ab2; asc    : * ;;
 3: len 24; hex 4650205468757273646179204368756262792050726f6d6f; asc FP Thursday Chubby Promo;;
 4: len 4; hex 80000041; asc    A;;

Any idea of where I can start looking?

mysql> show global status;
+-----------------------------------------------+--------------+
| Variable_name                                 | Value        |
+-----------------------------------------------+--------------+
| Aborted_clients                               | 75           |
| Aborted_connects                              | 767          |
| Binlog_cache_disk_use                         | 23592        |
| Binlog_cache_use                              | 1910314      |
| Binlog_stmt_cache_disk_use                    | 0            |
| Binlog_stmt_cache_use                         | 9909         |
| Bytes_received                                | 19020005934  |
| Bytes_sent                                    | 450148820308 |
| Com_admin_commands                            | 9            |
| Com_assign_to_keycache                        | 0            |
| Com_alter_db                                  | 0            |
| Com_alter_db_upgrade                          | 0            |
| Com_alter_event                               | 0            |
| Com_alter_function                            | 0            |
| Com_alter_procedure                           | 0            |
| Com_alter_server                              | 0            |
| Com_alter_table                               | 6097         |
| Com_alter_tablespace                          | 0            |
| Com_alter_user                                | 0            |
| Com_analyze                                   | 0            |
| Com_begin                                     | 50002        |
| Com_binlog                                    | 0            |
| Com_call_procedure                            | 66           |
| Com_change_db                                 | 332896       |
| Com_change_master                             | 0            |
| Com_check                                     | 0            |
| Com_checksum                                  | 0            |
| Com_commit                                    | 50169        |
| Com_create_db                                 | 25           |
| Com_create_event                              | 0            |
| Com_create_function                           | 0            |
| Com_create_index                              | 0            |
| Com_create_procedure                          | 0            |
| Com_create_server                             | 0            |
| Com_create_table                              | 2822         |
| Com_create_trigger                            | 0            |
| Com_create_udf                                | 0            |
| Com_create_user                               | 0            |
| Com_create_view                               | 0            |
| Com_dealloc_sql                               | 0            |
| Com_delete                                    | 70492        |
| Com_delete_multi                              | 148          |
| Com_do                                        | 0            |
| Com_drop_db                                   | 1            |
| Com_drop_event                                | 0            |
| Com_drop_function                             | 0            |
| Com_drop_index                                | 0            |
| Com_drop_procedure                            | 0            |
| Com_drop_server                               | 0            |
| Com_drop_table                                | 615          |
| Com_drop_trigger                              | 0            |
| Com_drop_user                                 | 0            |
| Com_drop_view                                 | 0            |
| Com_empty_query                               | 0            |
| Com_execute_sql                               | 0            |
| Com_flush                                     | 2023         |
| Com_get_diagnostics                           | 0            |
| Com_grant                                     | 2            |
| Com_ha_close                                  | 0            |
| Com_ha_open                                   | 0            |
| Com_ha_read                                   | 0            |
| Com_help                                      | 0            |
| Com_insert                                    | 494163       |
| Com_insert_select                             | 0            |
| Com_install_plugin                            | 0            |
| Com_kill                                      | 66           |
| Com_load                                      | 0            |
| Com_lock_tables                               | 2819         |
| Com_optimize                                  | 97           |
| Com_preload_keys                              | 0            |
| Com_prepare_sql                               | 0            |
| Com_purge                                     | 662          |
| Com_purge_before_date                         | 0            |
| Com_release_savepoint                         | 0            |
| Com_rename_table                              | 0            |
| Com_rename_user                               | 0            |
| Com_repair                                    | 0            |
| Com_replace                                   | 47982        |
| Com_replace_select                            | 9            |
| Com_reset                                     | 0            |
| Com_resignal                                  | 0            |
| Com_revoke                                    | 0            |
| Com_revoke_all                                | 0            |
| Com_rollback                                  | 65           |
| Com_rollback_to_savepoint                     | 0            |
| Com_savepoint                                 | 0            |
| Com_select                                    | 14400535     |
| Com_set_option                                | 11497318     |
| Com_signal                                    | 0            |
| Com_show_binlog_events                        | 0            |
| Com_show_binlogs                              | 33           |
| Com_show_charsets                             | 0            |
| Com_show_collations                           | 0            |
| Com_show_create_db                            | 1717         |
| Com_show_create_event                         | 0            |
| Com_show_create_func                          | 0            |
| Com_show_create_proc                          | 208          |
| Com_show_create_table                         | 486369       |
| Com_show_create_trigger                       | 40           |
| Com_show_databases                            | 53           |
| Com_show_engine_logs                          | 0            |
| Com_show_engine_mutex                         | 0            |
| Com_show_engine_status                        | 2            |
| Com_show_events                               | 20           |
| Com_show_errors                               | 0            |
| Com_show_fields                               | 2087822      |
| Com_show_function_code                        | 0            |
| Com_show_function_status                      | 3436         |
| Com_show_grants                               | 10           |
| Com_show_keys                                 | 42           |
| Com_show_master_status                        | 13           |
| Com_show_open_tables                          | 0            |
| Com_show_plugins                              | 0            |
| Com_show_privileges                           | 0            |
| Com_show_procedure_code                       | 0            |
| Com_show_procedure_status                     | 3436         |
| Com_show_processlist                          | 119951       |
| Com_show_profile                              | 0            |
| Com_show_profiles                             | 0            |
| Com_show_relaylog_events                      | 0            |
| Com_show_slave_hosts                          | 0            |
| Com_show_slave_status                         | 10           |
| Com_show_status                               | 1917         |
| Com_show_storage_engines                      | 0            |
| Com_show_table_status                         | 324246       |
| Com_show_tables                               | 1276858      |
| Com_show_triggers                             | 324172       |
| Com_show_variables                            | 2051         |
| Com_show_warnings                             | 4            |
| Com_slave_start                               | 0            |
| Com_slave_stop                                | 0            |
| Com_stmt_close                                | 3            |
| Com_stmt_execute                              | 23           |
| Com_stmt_fetch                                | 10           |
| Com_stmt_prepare                              | 23           |
| Com_stmt_reprepare                            | 0            |
| Com_stmt_reset                                | 0            |
| Com_stmt_send_long_data                       | 0            |
| Com_truncate                                  | 252          |
| Com_uninstall_plugin                          | 0            |
| Com_unlock_tables                             | 4537         |
| Com_update                                    | 1876581      |
| Com_update_multi                              | 0            |
| Com_xa_commit                                 | 0            |
| Com_xa_end                                    | 0            |
| Com_xa_prepare                                | 0            |
| Com_xa_recover                                | 0            |
| Com_xa_rollback                               | 0            |
| Com_xa_start                                  | 0            |
| Compression                                   | OFF          |
| Connection_errors_accept                      | 0            |
| Connection_errors_internal                    | 0            |
| Connection_errors_max_connections             | 0            |
| Connection_errors_peer_address                | 0            |
| Connection_errors_select                      | 0            |
| Connection_errors_tcpwrap                     | 0            |
| Connections                                   | 14109046     |
| Created_tmp_disk_tables                       | 3483968      |
| Created_tmp_files                             | 27074        |
| Created_tmp_tables                            | 5675076      |
| Delayed_errors                                | 0            |
| Delayed_insert_threads                        | 0            |
| Delayed_writes                                | 0            |
| Flush_commands                                | 1            |
| Handler_commit                                | 16730928     |
| Handler_delete                                | 58746        |
| Handler_discover                              | 0            |
| Handler_external_lock                         | 44461222     |
| Handler_mrr_init                              | 0            |
| Handler_prepare                               | 4935298      |
| Handler_read_first                            | 555947737    |
| Handler_read_key                              | 4342441284   |
| Handler_read_last                             | 51021        |
| Handler_read_next                             | 4410037167   |
| Handler_read_prev                             | 1041500      |
| Handler_read_rnd                              | 66317337     |
| Handler_read_rnd_next                         | 4061126421   |
| Handler_rollback                              | 14002        |
| Handler_savepoint                             | 0            |
| Handler_savepoint_rollback                    | 0            |
| Handler_update                                | 6298422      |
| Handler_write                                 | 528228581    |
| Innodb_buffer_pool_dump_status                | not started  |
| Innodb_buffer_pool_load_status                | not started  |
| Innodb_buffer_pool_pages_data                 | 157888       |
| Innodb_buffer_pool_bytes_data                 | 2586836992   |
| Innodb_buffer_pool_pages_dirty                | 1456         |
| Innodb_buffer_pool_bytes_dirty                | 23855104     |
| Innodb_buffer_pool_pages_flushed              | 6097239      |
| Innodb_buffer_pool_pages_free                 | 8192         |
| Innodb_buffer_pool_pages_misc                 | 0            |
| Innodb_buffer_pool_pages_total                | 166080       |
| Innodb_buffer_pool_read_ahead_rnd             | 0            |
| Innodb_buffer_pool_read_ahead                 | 4175098      |
| Innodb_buffer_pool_read_ahead_evicted         | 1998         |
| Innodb_buffer_pool_read_requests              | 20669375353  |
| Innodb_buffer_pool_reads                      | 19725302     |
| Innodb_buffer_pool_wait_free                  | 0            |
| Innodb_buffer_pool_write_requests             | 36813736     |
| Innodb_data_fsyncs                            | 4000141      |
| Innodb_data_pending_fsyncs                    | 0            |
| Innodb_data_pending_reads                     | 0            |
| Innodb_data_pending_writes                    | 0            |
| Innodb_data_read                              | 394739994624 |
| Innodb_data_reads                             | 24092362     |
| Innodb_data_writes                            | 9335083      |
| Innodb_data_written                           | 210941677568 |
| Innodb_dblwr_pages_written                    | 6097239      |
| Innodb_dblwr_writes                           | 577145       |
| Innodb_have_atomic_builtins                   | ON           |
| Innodb_log_waits                              | 0            |
| Innodb_log_write_requests                     | 20665741     |
| Innodb_log_writes                             | 2583719      |
| Innodb_os_log_fsyncs                          | 2659640      |
| Innodb_os_log_pending_fsyncs                  | 0            |
| Innodb_os_log_pending_writes                  | 0            |
| Innodb_os_log_written                         | 11108775936  |
| Innodb_page_size                              | 16384        |
| Innodb_pages_created                          | 323226       |
| Innodb_pages_read                             | 24091712     |
| Innodb_pages_written                          | 6097239      |
| Innodb_row_lock_current_waits                 | 0            |
| Innodb_row_lock_time                          | 658          |
| Innodb_row_lock_time_avg                      | 5            |
| Innodb_row_lock_time_max                      | 19           |
| Innodb_row_lock_waits                         | 123          |
| Innodb_rows_deleted                           | 58747        |
| Innodb_rows_inserted                          | 503434       |
| Innodb_rows_read                              | 9533246024   |
| Innodb_rows_updated                           | 2062321      |
| Innodb_num_open_files                         | 14           |
| Innodb_truncated_status_writes                | 0            |
| Innodb_available_undo_logs                    | 128          |
| Key_blocks_not_flushed                        | 0            |
| Key_blocks_unused                             | 13396        |
| Key_blocks_used                               | 3898         |
| Key_read_requests                             | 968442355    |
| Key_reads                                     | 260          |
| Key_write_requests                            | 314009997    |
| Key_writes                                    | 0            |
| Last_query_cost                               | 0.000000     |
| Last_query_partial_plans                      | 0            |
| Max_used_connections                          | 429          |
| Not_flushed_delayed_rows                      | 0            |
| Open_files                                    | 3            |
| Open_streams                                  | 0            |
| Open_table_definitions                        | 1400         |
| Open_tables                                   | 2000         |
| Opened_files                                  | 15050970     |
| Opened_table_definitions                      | 1057163      |
| Opened_tables                                 | 4565317      |
| Performance_schema_accounts_lost              | 0            |
| Performance_schema_cond_classes_lost          | 0            |
| Performance_schema_cond_instances_lost        | 0            |
| Performance_schema_digest_lost                | 0            |
| Performance_schema_file_classes_lost          | 0            |
| Performance_schema_file_handles_lost          | 0            |
| Performance_schema_file_instances_lost        | 0            |
| Performance_schema_hosts_lost                 | 0            |
| Performance_schema_locker_lost                | 0            |
| Performance_schema_mutex_classes_lost         | 0            |
| Performance_schema_mutex_instances_lost       | 0            |
| Performance_schema_rwlock_classes_lost        | 0            |
| Performance_schema_rwlock_instances_lost      | 0            |
| Performance_schema_session_connect_attrs_lost | 0            |
| Performance_schema_socket_classes_lost        | 0            |
| Performance_schema_socket_instances_lost      | 0            |
| Performance_schema_stage_classes_lost         | 0            |
| Performance_schema_statement_classes_lost     | 0            |
| Performance_schema_table_handles_lost         | 0            |
| Performance_schema_table_instances_lost       | 0            |
| Performance_schema_thread_classes_lost        | 0            |
| Performance_schema_thread_instances_lost      | 0            |
| Performance_schema_users_lost                 | 0            |
| Prepared_stmt_count                           | 0            |
| Qcache_free_blocks                            | 4359         |
| Qcache_free_memory                            | 11838224     |
| Qcache_hits                                   | 53345695     |
| Qcache_inserts                                | 10498816     |
| Qcache_lowmem_prunes                          | 4945792      |
| Qcache_not_cached                             | 3901891      |
| Qcache_queries_in_cache                       | 11254        |
| Qcache_total_blocks                           | 32300        |
| Queries                                       | 100927051    |
| Questions                                     | 100924711    |
| Select_full_join                              | 1119531      |
| Select_full_range_join                        | 1691         |
| Select_range                                  | 976854       |
| Select_range_check                            | 37           |
| Select_scan                                   | 5601093      |
| Slave_heartbeat_period                        | 0.000        |
| Slave_last_heartbeat                          |              |
| Slave_open_temp_tables                        | 0            |
| Slave_received_heartbeats                     | 0            |
| Slave_retried_transactions                    | 0            |
| Slave_running                                 | OFF          |
| Slow_launch_threads                           | 0            |
| Slow_queries                                  | 1045         |
| Sort_merge_passes                             | 7119         |
| Sort_range                                    | 246182       |
| Sort_rows                                     | 66189786     |
| Sort_scan                                     | 1565455      |
| Ssl_accept_renegotiates                       | 0            |
| Ssl_accepts                                   | 0            |
| Ssl_callback_cache_hits                       | 0            |
| Ssl_cipher                                    |              |
| Ssl_cipher_list                               |              |
| Ssl_client_connects                           | 0            |
| Ssl_connect_renegotiates                      | 0            |
| Ssl_ctx_verify_depth                          | 0            |
| Ssl_ctx_verify_mode                           | 0            |
| Ssl_default_timeout                           | 0            |
| Ssl_finished_accepts                          | 0            |
| Ssl_finished_connects                         | 0            |
| Ssl_server_not_after                          |              |
| Ssl_server_not_before                         |              |
| Ssl_session_cache_hits                        | 0            |
| Ssl_session_cache_misses                      | 0            |
| Ssl_session_cache_mode                        | Unknown      |
| Ssl_session_cache_overflows                   | 0            |
| Ssl_session_cache_size                        | 0            |
| Ssl_session_cache_timeouts                    | 0            |
| Ssl_sessions_reused                           | 0            |
| Ssl_used_session_cache_entries                | 0            |
| Ssl_verify_depth                              | 0            |
| Ssl_verify_mode                               | 0            |
| Ssl_version                                   |              |
| Table_locks_immediate                         | 22141644     |
| Table_locks_waited                            | 0            |
| Table_open_cache_hits                         | 20638283     |
| Table_open_cache_misses                       | 4565315      |
| Table_open_cache_overflows                    | 4559458      |
| Tc_log_max_pages_used                         | 0            |
| Tc_log_page_size                              | 0            |
| Tc_log_page_waits                             | 0            |
| Threads_cached                                | 53           |
| Threads_connected                             | 19           |
| Threads_created                               | 31446        |
| Threads_running                               | 2            |
| Uptime                                        | 601636       |
| Uptime_since_flush_status                     | 601636       |
+-----------------------------------------------+--------------+
341 rows in set (0.00 sec)

Appears to be a very old (bug)[https://bugs.mysql.com/bug.php?id=73890] . You can try disabling innodb_adaptive_hash_index and restart the rds instance — Kapil Bhagchandani, Sep 10 '18 at 02:31
This is the conclusion I came to also and made that change. Do you think this will solve it? I have be running this RDS instinct for over 1.5 years without this happening. — Chris Muench, Sep 10 '18 at 21:18
@ChrisMuench Additional information requested. A) RAM on your host server? B) Please post TEXT results of SHOW GLOBAL STATUS; to go with previously posted information. Will try to have Suggestions for you before the bounty expries. — Wilson Hauck, Sep 11 '18 at 17:43
@ChrisMuench MORE Additional information request, please. Post on pastebin.com or here. A) complete (not edited) my.cnf or my.ini
Text results of: D) complete MySQLTuner report AND Optional very helpful information, if available includes - htop OR top OR mytop for most active apps, ulimit -a for a linux/unix list of limits, iostat -x when system is busy for an idea of IOPS by device, df -h for a linux/unix free space list by device, for server tuning analysis. — Wilson Hauck, Sep 11 '18 at 18:01
A. 8gb b. in answer above. I am using rds so I already have a link on github to the file. D. not familiar with mysql tuner — Chris Muench, Sep 11 '18 at 19:19
@ChrisMuench Thanks for the 8GB. What you think is a link to your configuration is actually a link to SHOW VARIABLES; So, still need your my.cnf, htop OR top OR mytop, ulimit -a, and iostat -x posted, please for analysis. Thanks, Wilson — Wilson Hauck, Sep 11 '18 at 21:06
@ChrisMuench I will work with available data. And try to find links to details on how Amazon RDS allows my.cnf equivalent management of your instance. — Wilson Hauck, Sep 12 '18 at 11:03
@ChrisMuench A) Do you know which MODEL AWS you are using? The Model will allow me to determine how many cores are available for your use. T2.? or M5.? or M4.? B) All SSD or rotating storage? — Wilson Hauck, Sep 12 '18 at 12:26
@ChrisMuench The link following will point you toward AMAZON's RDS 'Custom DB Parameter Group' that is used rather than directly using my.cnf to influence the GLOBAL VARIABLE defaults. Please read the article carefully. Still need to know which Model you are using before I can provide reasonable suggestions. — Wilson Hauck, Sep 12 '18 at 14:59
@ChrisMuench Sorry, forgot to paste the link for review. https://dba.stackexchange.com/questions/21914/local-database-vs-amazon-rds/21919#21919 — Wilson Hauck, Sep 12 '18 at 15:09
@chris what all I have suggested is just temporary solution. Actual problem is caused by simultaneously running transactions, where system me fall short of providing enough resources to the transactions. I need following input to give proper solution — Kapil Bhagchandani, Sep 13 '18 at 04:30
It takes 2 to tango. It might help to also see *** (2) TRANSACTION — Rick James, Oct 03 '18 at 00:40

Wilson Hauck · Accepted Answer · 2018-09-13T12:16:54.717

Suggestions for your AMAZON RDS Custom DB Parameter Group to influence my.cnf Rate per Second=RPS

read_rnd_buffer_size=256K  # from 512K to reduce CPU busy
innodb_io_capacity_max=20000  # from 2000 to open the SSD door wider
innodb_io_capacity=10000  # from 200 to take advantage of SSD capability
thread_cache_size=100  # from 68 to reduce threads_created CAP=100
innodb_lru_scan_depth=100  # from 1024 to reduce CPU busy see refman
innodb_flushing_avg_loops=10  # from 30 to reduce loop delay
innodb_purge_threads=4  # from 1 to expedite purge cycles
table_open_cache=10000  # from 2000 to reduce opened_tables RPS
table_definition_cache=10000  # from 1400 to reduce opened_table_definitions RPS
innodb_buffer_pool_size=3G  # from ~2.7G to reduce innodb_data_reads RPS
innodb_log_buffer_size=40M  # from 8M to support ~ 30 minutes in RAM
thread_concurrency=20  # from 10 to expedite processing

The last 2 suggestions are NOT Dynamic, the others are DYNamic updates. SET GLOBAL name=nn; K,M,G not available in CLI, *1024 or *1024*1024 or *1024*1024*1024 for K M G respectively.

Remember the ONE A DAY, monitor BEFORE moving to next Suggestion. When in doubt, put back the old value until you can determine side effects.

14,002 handler_rollback count in 7 days does NOT seem reasonable to me. 23 com_stmt_prepare with only 3 com_stmt_close is abnormal, to release resources, the close is needed.

The very BEST to you and your group.

MySQL 5.6.34 RDS Warning: a long semaphore wait causes crash -- log included

1 Answers1