MySQL: InnoDb: Semaphore wait has lasted > 600 seconds. We intentionally crash the server

3

MySQL 5.7.16 server on Windows Server 2012R2 with 32GB RAM is now restarting itself every 18minutes or so with the following in the error log:

InnoDB: ###### Diagnostic info printed to the standard error stream 2017-11-
16T13:18:39.650036Z 0 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 
600 seconds. We intentionally crash the server because it appears to be 
hung.
2017-11-16 13:18:39 0x1bcc  InnoDB: Assertion failure in thread 7116 in file 
ut0ut.cc line 916
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
13:18:39 UTC - mysqld got exception 0x80000003 ; 
This could be because you hit a bug. It is also possible that this binary 
or one of the libraries it was linked against is corrupt, improperly built, 
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information 
collection process might fail.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=34
max_threads=151
thread_count=6
connection_count=6
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68011K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out 
where mysqld died. If you see no messages after this, something went 
terribly wrong...
7ff7eeb7e262    mysqld.exe!my_sigabrt_handler()[my_thr_init.c:449]
7ff7eef28489    mysqld.exe!raise()[winsig.c:587]
7ff7eef27380    mysqld.exe!abort()[abort.c:82]
7ff7eec8f178    mysqld.exe!ut_dbg_assertion_failed()[ut0dbg.cc:67]
7ff7eec8f391    mysqld.exe!ib::fatal::~fatal()[ut0ut.cc:916]
7ff7eebfd43d    mysqld.exe!srv_error_monitor_thread()[srv0srv.cc:1724]
7ffc55d613d2    KERNEL32.DLL!BaseThreadInitThunk()
7ffc57d854e4    ntdll.dll!RtlUserThreadStart()
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

There appears to be a transaction which is being rolled back when the server restarts. The following can be found in the information_schema.innodb_trx\G

trx_id: 309725166  
trx_state: ROLLING BACK  
trx_started: 2017-11-16 13:30:18
trx_requested_lock_id: NULL 
trx_wait_started: NULL
trx_weight: 17856930 
trx_mysql_thread_id: 0 
trx_query: NULL
trx_operation_state: NULL 
trx_tables_in_use: 0 
trx_tables_locked: 1
trx_lock_structs: 1 
trx_lock_memory_bytes: 1136 
trx_rows_locked: 0
trx_rows_modified: 17856929 
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ 
trx_unique_checks: 1
trx_foreign_key_checks: 1 
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0 
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0 
trx_autocommit_non_locking: 0

Is it possible to stop this transaction being rolled back?

Results from SHOW GLOBAL STATUS:

Aborted_clients                               | 0
Aborted_connects                              | 0
Binlog_cache_disk_use                         | 0
Binlog_cache_use                              | 0
Binlog_stmt_cache_disk_use                    | 0
Binlog_stmt_cache_use                         | 0
Bytes_received                                | 79456733
Bytes_sent                                    | 132918726
Com_admin_commands                            | 53
Com_assign_to_keycache                        | 0
Com_alter_db                                  | 0
Com_alter_db_upgrade                          | 0
Com_alter_event                               | 0
Com_alter_function                            | 0
Com_alter_instance                            | 0
Com_alter_procedure                           | 0
Com_alter_server                              | 0
Com_alter_table                               | 0
Com_alter_tablespace                          | 0
Com_alter_user                                | 0
Com_analyze                                   | 0
Com_begin                                     | 0
Com_binlog                                    | 0
Com_call_procedure                            | 0
Com_change_db                                 | 890
Com_change_master                             | 0
Com_change_repl_filter                        | 0
Com_check                                     | 0
Com_checksum                                  | 0
Com_commit                                    | 0
Com_create_db                                 | 0
Com_create_event                              | 0
Com_create_function                           | 0
Com_create_index                              | 0
Com_create_procedure                          | 0
Com_create_server                             | 0
Com_create_table                              | 0
Com_create_trigger                            | 0
Com_create_udf                                | 0
Com_create_user                               | 0
Com_create_view                               | 0
Com_dealloc_sql                               | 0
Com_delete                                    | 2
Com_delete_multi                              | 0
Com_do                                        | 0
Com_drop_db                                   | 0
Com_drop_event                                | 0
Com_drop_function                             | 0
Com_drop_index                                | 0
Com_drop_procedure                            | 0
Com_drop_server                               | 0
Com_drop_table                                | 0
Com_drop_trigger                              | 0
Com_drop_user                                 | 0
Com_drop_view                                 | 0
Com_empty_query                               | 0
Com_execute_sql                               | 0
Com_explain_other                             | 0
Com_flush                                     | 0
Com_get_diagnostics                           | 0
Com_grant                                     | 0
Com_ha_close                                  | 0
Com_ha_open                                   | 0
Com_ha_read                                   | 0
Com_help                                      | 0
Com_insert                                    | 542
Com_insert_select                             | 1
Com_install_plugin                            | 0
Com_kill                                      | 0
Com_load                                      | 0
Com_lock_tables                               | 0
Com_optimize                                  | 0
Com_preload_keys                              | 0
Com_prepare_sql                               | 0
Com_purge                                     | 0
Com_purge_before_date                         | 0
Com_release_savepoint                         | 0
Com_rename_table                              | 0
Com_rename_user                               | 0
Com_repair                                    | 0
Com_replace                                   | 0
Com_replace_select                            | 0
Com_reset                                     | 0
Com_resignal                                  | 0
Com_revoke                                    | 0
Com_revoke_all                                | 0
Com_rollback                                  | 0
Com_rollback_to_savepoint                     | 0
Com_savepoint                                 | 0
Com_select                                    | 30656
Com_set_option                                | 532
Com_signal                                    | 0
Com_show_binlog_events                        | 0
Com_show_binlogs                              | 0
Com_show_charsets                             | 0
Com_show_collations                           | 16
Com_show_create_db                            | 0
Com_show_create_event                         | 0
Com_show_create_func                          | 0
Com_show_create_proc                          | 0
Com_show_create_table                         | 0
Com_show_create_trigger                       | 0
Com_show_databases                            | 0
Com_show_engine_logs                          | 0
Com_show_engine_mutex                         | 0
Com_show_engine_status                        | 0
Com_show_events                               | 0
Com_show_errors                               | 0
Com_show_fields                               | 0
Com_show_function_code                        | 0
Com_show_function_status                      | 0
Com_show_grants                               | 0
Com_show_keys                                 | 0
Com_show_master_status                        | 0
Com_show_open_tables                          | 0
Com_show_plugins                              | 0
Com_show_privileges                           | 0
Com_show_procedure_code                       | 0
Com_show_procedure_status                     | 0
Com_show_processlist                          | 0
Com_show_profile                              | 0
Com_show_profiles                             | 0
Com_show_relaylog_events                      | 0
Com_show_slave_hosts                          | 0
Com_show_slave_status                         | 0
Com_show_status                               | 1
Com_show_storage_engines                      | 0
Com_show_table_status                         | 0
Com_show_tables                               | 0
Com_show_triggers                             | 0
Com_show_variables                            | 17
Com_show_warnings                             | 375
Com_show_create_user                          | 0
Com_shutdown                                  | 0
Com_slave_start                               | 0
Com_slave_stop                                | 0
Com_group_replication_start                   | 0
Com_group_replication_stop                    | 0
Com_stmt_execute                              | 2264
Com_stmt_close                                | 2264
Com_stmt_fetch                                | 0
Com_stmt_prepare                              | 2264
Com_stmt_reset                                | 0
Com_stmt_send_long_data                       | 0
Com_truncate                                  | 0
Com_uninstall_plugin                          | 0
Com_unlock_tables                             | 0
Com_update                                    | 1204
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
Com_stmt_reprepare                            | 0
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                                   | 342
Created_tmp_disk_tables                       | 0
Created_tmp_files                             | 11
Created_tmp_tables                            | 147767
Delayed_errors                                | 0
Delayed_insert_threads                        | 0
Delayed_writes                                | 0
Flush_commands                                | 1
Handler_commit                                | 32388
Handler_delete                                | 1
Handler_discover                              | 0
Handler_external_lock                         | 564581
Handler_mrr_init                              | 0
Handler_prepare                               | 0
Handler_read_first                            | 1565
Handler_read_key                              | 414968
Handler_read_last                             | 360
Handler_read_next                             | 4100377
Handler_read_prev                             | 207212
Handler_read_rnd                              | 15703
Handler_read_rnd_next                         | 4149804
Handler_rollback                              | 0
Handler_savepoint                             | 0
Handler_savepoint_rollback                    | 0
Handler_update                                | 17817
Handler_write                                 | 3996718
Innodb_buffer_pool_dump_status                | Dumping of buffer pool not     started
Innodb_buffer_pool_load_status                | Buffer pool(s) load     completed at 171117  9:20:31
Innodb_buffer_pool_resize_status              |
Innodb_buffer_pool_pages_data                 | 7204
Innodb_buffer_pool_bytes_data                 | 118030336
Innodb_buffer_pool_pages_dirty                | 105
Innodb_buffer_pool_bytes_dirty                | 1720320
Innodb_buffer_pool_pages_flushed              | 8781
Innodb_buffer_pool_pages_free                 | 988
Innodb_buffer_pool_pages_misc                 | 0
Innodb_buffer_pool_pages_total                | 8192
Innodb_buffer_pool_read_ahead_rnd             | 0
Innodb_buffer_pool_read_ahead                 | 2287
Innodb_buffer_pool_read_ahead_evicted         | 39
Innodb_buffer_pool_read_requests              | 8577383
Innodb_buffer_pool_reads                      | 217476
Innodb_buffer_pool_wait_free                  | 0
Innodb_buffer_pool_write_requests             | 162181
Innodb_data_fsyncs                            | 2971
Innodb_data_pending_fsyncs                    | 0
Innodb_data_pending_reads                     | 0
Innodb_data_pending_writes                    | 0
Innodb_data_read                              | 3691057664
Innodb_data_reads                             | 225979
Innodb_data_writes                            | 11884
Innodb_data_written                           | 316987904
Innodb_dblwr_pages_written                    | 9286
Innodb_dblwr_writes                           | 682
Innodb_log_waits                              | 0
Innodb_log_write_requests                     | 24032
Innodb_log_writes                             | 1816
Innodb_os_log_fsyncs                          | 230
Innodb_os_log_pending_fsyncs                  | 0
Innodb_os_log_pending_writes                  | 0
Innodb_os_log_written                         | 12146688
Innodb_page_size                              | 16384
Innodb_pages_created                          | 327
Innodb_pages_read                             | 224226
Innodb_pages_written                          | 9320
Innodb_row_lock_current_waits                 | 0
Innodb_row_lock_time                          | 12564
Innodb_row_lock_time_avg                      | 546
Innodb_row_lock_time_max                      | 2359
Innodb_row_lock_waits                         | 23
Innodb_rows_deleted                           | 1
Innodb_rows_inserted                          | 11063
Innodb_rows_read                              | 6571175
Innodb_rows_updated                           | 17817
Innodb_num_open_files                         | 398
Innodb_truncated_status_writes                | 0
Innodb_available_undo_logs                    | 128
Key_blocks_not_flushed                        | 0
Key_blocks_unused                             | 6698
Key_blocks_used                               | 3
Key_read_requests                             | 6
Key_reads                                     | 3
Key_write_requests                            | 0
Key_writes                                    | 0
Locked_connects                               | 0
Max_execution_time_exceeded                   | 0
Max_execution_time_set                        | 0
Max_execution_time_set_failed                 | 0
Max_used_connections                          | 40
Max_used_connections_time                     | 2017-11-17 09:30:04
Not_flushed_delayed_rows                      | 0
Ongoing_anonymous_transaction_count           | 0
Open_files                                    | 0
Open_streams                                  | 0
Open_table_definitions                        | 319
Open_tables                                   | 916
Opened_files                                  | 360
Opened_table_definitions                      | 319
Opened_tables                                 | 1066
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_index_stat_lost            | 0
Performance_schema_locker_lost                | 0
Performance_schema_memory_classes_lost        | 0
Performance_schema_metadata_lock_lost         | 0
Performance_schema_mutex_classes_lost         | 0
Performance_schema_mutex_instances_lost       | 0
Performance_schema_nested_statement_lost      | 0
Performance_schema_prepared_statements_lost   | 0
Performance_schema_program_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_table_lock_stat_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                            | 0
Qcache_free_memory                            | 0
Qcache_hits                                   | 0
Qcache_inserts                                | 0
Qcache_lowmem_prunes                          | 0
Qcache_not_cached                             | 0
Qcache_queries_in_cache                       | 0
Qcache_total_blocks                           | 0
Queries                                       | 39149
Questions                                     | 34567
Select_full_join                              | 439
Select_full_range_join                        | 1
Select_range                                  | 1572
Select_range_check                            | 0
Select_scan                                   | 197553
Slave_open_temp_tables                        | 0
Slow_launch_threads                           | 0
Slow_queries                                  | 0
Sort_merge_passes                             | 7
Sort_range                                    | 428
Sort_rows                                     | 14902
Sort_scan                                     | 27
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                        | NONE
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                         | 116
Table_locks_waited                            | 0
Table_open_cache_hits                         | 286526
Table_open_cache_misses                       | 1066
Table_open_cache_overflows                    | 143
Tc_log_max_pages_used                         | 0
Tc_log_page_size                              | 0
Tc_log_page_waits                             | 0
Threads_cached                                | 8
Threads_connected                             | 9
Threads_created                               | 83
Threads_running                               | 5
Uptime                                        | 1022
Uptime_since_flush_status                     | 1022
mysql
database
innodb
rollback
recovery
asked on Stack Overflow Nov 16, 2017 by Kevin F • edited Nov 17, 2017 by Kevin F

2 Answers

1

From your UPTIME of 1022 seconds GLOBAL STATUS report, research and consider these my.cnf/ini add/change/disable with leading # or REMOVE to avoid clutter. Normally only 1 change is made per day and monitor. In your case, with 18 minute crashes, let's make them all in one shutdown/restart.

thread_cache_size=100 # from default because 83 threads created already, V8 CAP is 100 to avoid OOM
innodb_buffer_pool_size=6G # from default of 128M, was full in 17 minutes
table_open_cache=10000 # 1066 already opened in 17 minutes.

Desperately need your SHOW GLOBAL VARIABLES; and SHOW ENGINE INNODB STATUS; and complete my.cnf/ini to avoid GUESSING for additional suggestions. dropbox.com or pastebin.com are reasonable places to share data if you are reaching storage limits here.

Search for '[MySQL] Semaphore wait has lasted' to find earlier solutions in stackoverflow.com dba.stackexchange.com or serverfault.com (our pw are shared by these 3 sites, so you do not need 3 accounts).

The rollback was dealing with 17,856,929 rows. In a single transaction, that is a load that needs analysis for breaking it up into more manageable row counts for a single transaction.

update 2017-11-18 about 09 UTC wh In my.cnf/ini [mysqld] section you NEED

innodb_log_buffer_size=48M # from 256M
innodb_log_file_size=256M # from default of 48M

Today, they are backwards and are a significant part of the cause of your 17 minute restarts. Shutdown/restart required neither value can be dynamically changed.

answered on Stack Overflow Nov 17, 2017 by Wilson Hauck • edited Nov 18, 2017 by Wilson Hauck
0

I found this fix from Stephan Lueckl on https://bugs.mysql.com/bug.php?id=83079 which helped me:

Changing the variable innodb_purge_threads from it’s new default value of 4, to the 5.6 default value of 1 to avoid purge thread contention

innodb_purge_threads=1

Source: https://blog.pythian.com/mysql-crashes-ddl-statement-lesson-purge-threads/

answered on Stack Overflow Jul 6, 2018 by Umme Hunny • edited Jul 6, 2018 by Andrew Myers

User contributions licensed under CC BY-SA 3.0