Description:
In Mysql 5.7.18 INSERT query waiting for S lock on its parent table doesn't get lock wait time out after 50 sec. So i decided to kill that connection which leads to crash mysql.
innodb_lock_wait_timeout - 50 s
innodb_buffer_pool_size - 134217728 bytes
How to repeat:
Table structure:
mysql> show create table Users;
+-------+-------------------------------------------------------------------------------------------------------------------------------------------------+
| Table | Create Table |
+-------+-------------------------------------------------------------------------------------------------------------------------------------------------+
| Users | CREATE TABLE `Users` (
`ID` bigint(5) NOT NULL DEFAULT '0',
`NAME` text NOT NULL,
PRIMARY KEY (`ID`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |
+-------+-------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)
mysql> show create table Purchases;
+-----------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table | Create Table |
+-----------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Purchases | CREATE TABLE `Purchases` (
`PURCHASEID` bigint(19) NOT NULL DEFAULT '0',
`NAME` text NOT NULL,
`PURCHASEDBYID` bigint(19) NOT NULL,
PRIMARY KEY (`PURCHASEID`),
KEY `Purchases_FK4_IDX` (`PURCHASEDBYID`),
CONSTRAINT `Purchases_FK4` FOREIGN KEY (`PURCHASEDBYID`) REFERENCES `Users` (`ID`) ON DELETE CASCADE
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |
+-----------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)
Records in the table:
mysql> select * from Users;
+----+------+
| ID | NAME |
+----+------+
| 1 | Jhon |
+----+------+
1 row in set (0.00 sec)
mysql> select * from Purchases;
+------------+-----------+---------------+
| PURCHASEID | NAME | PURCHASEDBYID |
+------------+-----------+---------------+
| 1 | purchase1 | 1 |
+------------+-----------+---------------+
1 row in set (0.00 sec)
Client 1:
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> update Users set name="Max" where ID=1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1 Changed: 1 Warnings: 0
Transaction is not committed or rollbacked.
Client 2:
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into Purchases values (2,"purchase2",1);
From this we can tell that Client 2 is waiting for S lock on Users table row ID=1.
But Client 1 already got X lock on the same row.
So i expect lock wait time out exception for Client 2 after 50 seconds.
But it doesn't happens.
So i decided to kill that connection.
mysql> show processlist;
+----+------+-----------+--------------------+---------+------+----------+--------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+------+-----------+--------------------+---------+------+----------+--------------------------------------------------+
| 6 | root | localhost | test | Sleep | 375 | | NULL |
| 7 | root | localhost | test | Query | 371 | update | insert into Purchases values (200,"purchase2",1) |
| 8 | root | localhost | information_schema | Query | 0 | starting | show processlist |
+----+------+-----------+--------------------+---------+------+----------+--------------------------------------------------+
3 rows in set (0.01 sec)
mysql> kill 7;
Query OK, 0 rows affected (0.00 sec)
After that i can see that raise in buffer pool size. Around 10 seconds 97 percent of buffer pool is filled by lock heap and leads to mysql crashing.
After the kill command execution:
+---------------------------------------+--------------------------------------------------+
| Variable_name | Value |
+---------------------------------------+--------------------------------------------------+
| Innodb_buffer_pool_dump_status | Dumping of buffer pool not started |
| Innodb_buffer_pool_load_status | Buffer pool(s) load completed at 190723 17:06:45 |
| Innodb_buffer_pool_resize_status | |
| Innodb_buffer_pool_pages_data | 439 |
| Innodb_buffer_pool_bytes_data | 7192576 |
| Innodb_buffer_pool_pages_dirty | 0 |
| Innodb_buffer_pool_bytes_dirty | 0 |
| Innodb_buffer_pool_pages_flushed | 65 |
| Innodb_buffer_pool_pages_free | 715 |
| Innodb_buffer_pool_pages_misc | 7037 |
| Innodb_buffer_pool_pages_total | 8191 |
| Innodb_buffer_pool_read_ahead_rnd | 0 |
| Innodb_buffer_pool_read_ahead | 0 |
| Innodb_buffer_pool_read_ahead_evicted | 0 |
| Innodb_buffer_pool_read_requests | 2591313 |
| Innodb_buffer_pool_reads | 403 |
| Innodb_buffer_pool_wait_free | 0 |
| Innodb_buffer_pool_write_requests | 667 |
+---------------------------------------+--------------------------------------------------+
18 rows in set (0.00 sec)
mysql> show status like "%buffer%";
+---------------------------------------+--------------------------------------------------+
| Variable_name | Value |
+---------------------------------------+--------------------------------------------------+
| Innodb_buffer_pool_dump_status | Dumping of buffer pool not started |
| Innodb_buffer_pool_load_status | Buffer pool(s) load completed at 190723 17:06:45 |
| Innodb_buffer_pool_resize_status | |
| Innodb_buffer_pool_pages_data | 439 |
| Innodb_buffer_pool_bytes_data | 7192576 |
| Innodb_buffer_pool_pages_dirty | 0 |
| Innodb_buffer_pool_bytes_dirty | 0 |
| Innodb_buffer_pool_pages_flushed | 65 |
| Innodb_buffer_pool_pages_free | 348 |
| Innodb_buffer_pool_pages_misc | 7404 |
| Innodb_buffer_pool_pages_total | 8191 |
| Innodb_buffer_pool_read_ahead_rnd | 0 |
| Innodb_buffer_pool_read_ahead | 0 |
| Innodb_buffer_pool_read_ahead_evicted | 0 |
| Innodb_buffer_pool_read_requests | 2726283 |
| Innodb_buffer_pool_reads | 403 |
| Innodb_buffer_pool_wait_free | 0 |
| Innodb_buffer_pool_write_requests | 667 |
+---------------------------------------+--------------------------------------------------+
18 rows in set (0.00 sec)
mysql> show status like "%buffer%";
+---------------------------------------+--------------------------------------------------+
| Variable_name | Value |
+---------------------------------------+--------------------------------------------------+
| Innodb_buffer_pool_dump_status | Dumping of buffer pool not started |
| Innodb_buffer_pool_load_status | Buffer pool(s) load completed at 190723 17:06:45 |
| Innodb_buffer_pool_resize_status | |
| Innodb_buffer_pool_pages_data | 419 |
| Innodb_buffer_pool_bytes_data | 6864896 |
| Innodb_buffer_pool_pages_dirty | 0 |
| Innodb_buffer_pool_bytes_dirty | 0 |
| Innodb_buffer_pool_pages_flushed | 65 |
| Innodb_buffer_pool_pages_free | 0 |
| Innodb_buffer_pool_pages_misc | 7772 |
| Innodb_buffer_pool_pages_total | 8191 |
| Innodb_buffer_pool_read_ahead_rnd | 0 |
| Innodb_buffer_pool_read_ahead | 0 |
| Innodb_buffer_pool_read_ahead_evicted | 0 |
| Innodb_buffer_pool_read_requests | 2861747 |
| Innodb_buffer_pool_reads | 403 |
| Innodb_buffer_pool_wait_free | 0 |
| Innodb_buffer_pool_write_requests | 667 |
+---------------------------------------+--------------------------------------------------+
From this we can see that Innodb_buffer_pool_pages_misc was incresing gradually.
After around ten seconds mysql is crashed.
From mysql err log:
2019-07-24T13:43:03.675397Z 7 [Warning] InnoDB: Over 67 percent of the buffer pool is occupied by lock heaps or the adaptive hash index! Check that your transactions do not set too many row locks. Your buffer pool size is 127 MB. Maybe you should make the buffer pool bigger?. Starting the InnoDB Monitor to print diagnostics, including lock heap and hash index sizes.
2019-07-24T13:43:09.006848Z 7 [ERROR] [FATAL] InnoDB: Over 95 percent of the buffer pool is occupied by lock heaps or the adaptive hash index! Check that your transactions do not set too many row locks. Your buffer pool size is 127 MB. Maybe you should make the buffer pool bigger? We intentionally generate a seg fault to print a stack trace on Linux!
2019-07-24 19:13:09 0x700004f7e000 InnoDB: Assertion failure in thread 123145385664512 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:43:09 UTC - mysqld got signal 6 ;
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=3
max_threads=151
thread_count=3
connection_count=3
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68215 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
Thread pointer: 0x7fe6bc8ba600
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...
stack_bottom = 700004f7de90 thread_stack 0x40000
0 mysqld 0x000000010a61ecbd my_print_stacktrace + 61
1 mysqld 0x000000010a57a770 handle_fatal_signal + 688
2 libsystem_platform.dylib 0x00007fff796acf5a _sigtramp + 26
3 ??? 0x0000700004f782a8 0x0 + 123145385640616
4 libsystem_c.dylib 0x00007fff7944a1ae abort + 127
5 mysqld 0x000000010a87c3b1 _Z23ut_dbg_assertion_failedPKcS0_m + 161
6 mysqld 0x000000010a87f6a2 _ZN2ib5fatalD2Ev + 82
7 mysqld 0x000000010a87f6d9 _ZN2ib5fatalD1Ev + 9
8 mysqld 0x000000010a69c133 _Z22buf_LRU_get_free_blockP10buf_pool_t + 467
9 mysqld 0x000000010a67bcea _Z15buf_block_allocP10buf_pool_t + 58
10 mysqld 0x000000010a7a5b9f _Z26mem_heap_create_block_funcP16mem_block_info_tmm + 191
11 mysqld 0x000000010a7a5d11 _Z18mem_heap_add_blockP16mem_block_info_tm + 113
12 mysqld 0x000000010a7874ef _ZN7RecLock10lock_allocEP5trx_tP12dict_index_tmRK5RecIDm + 143
13 mysqld 0x000000010a787e07 _ZN7RecLock12add_to_waitqEPK9ib_lock_tPK9lock_prdt + 103
14 mysqld 0x000000010a78fd1e _ZL13lock_rec_lockbmPK11buf_block_tmP12dict_index_tP9que_thr_t + 1342
15 mysqld 0x000000010a790535 _Z34lock_clust_rec_read_check_and_lockmPK11buf_block_tPKhP12dict_index_tPKm9lock_modemP9que_thr_t + 357
16 mysqld 0x000000010a7e78c2 _Z32row_ins_check_foreign_constraintmP14dict_foreign_tP12dict_table_tP8dtuple_tP9que_thr_t + 1746
17 mysqld 0x000000010a7ecd21 _ZL33row_ins_check_foreign_constraintsP12dict_table_tP12dict_index_tP8dtuple_tP9que_thr_t + 225
18 mysqld 0x000000010a7ed239 _Z23row_ins_sec_index_entryP12dict_index_tP8dtuple_tP9que_thr_tb + 57
19 mysqld 0x000000010a7edbbd _Z12row_ins_stepP9que_thr_t + 1149
20 mysqld 0x000000010a7fbf80 _Z20row_insert_for_mysqlPKhP14row_prebuilt_t + 4000
21 mysqld 0x000000010a738956 _ZN11ha_innobase9write_rowEPh + 950
22 mysqld 0x0000000109ee33cf _ZN7handler12ha_write_rowEPh + 207
23 mysqld 0x000000010a44c793 _Z12write_recordP3THDP5TABLEP9COPY_INFOS4_ + 1283
24 mysqld 0x000000010a44b3aa _ZN14Sql_cmd_insert12mysql_insertEP3THDP10TABLE_LIST + 2538
25 mysqld 0x000000010a44f268 _ZN14Sql_cmd_insert7executeEP3THD + 216
26 mysqld 0x000000010a480a4e _Z21mysql_execute_commandP3THDb + 2942
27 mysqld 0x000000010a47f52c _Z11mysql_parseP3THDP12Parser_state + 860
28 mysqld 0x000000010a47e381 _Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command + 5169
29 mysqld 0x000000010a47efda _Z10do_commandP3THD + 490
30 mysqld 0x000000010a55df34 handle_connection + 468
31 mysqld 0x000000010a8ddba4 pfs_spawn_thread + 308
32 libsystem_pthread.dylib 0x00007fff796b6661 _pthread_body + 340
33 libsystem_pthread.dylib 0x00007fff796b650d _pthread_body + 0
34 libsystem_pthread.dylib 0x00007fff796b5bf9 thread_start + 13
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7fe6bc1b4230): insert into Purchases values (200,"purchase2",1)
Connection ID (thread ID): 7
Status: KILL_CONNECTION
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.
2019-07-24T13:43:09.936431Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2019-07-24T13:43:09.936895Z 0 [Note] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled
2019-07-24T13:43:09.937210Z 0 [Note] /usr/local/mysql/bin/mysqld (mysqld 5.7.18) starting as process 30274 ...
2019-07-24T13:43:10.039096Z 0 [Warning] Setting lower_case_table_names=2 because file system for /usr/local/mysql/data/ is case insensitive
2019-07-24T13:43:10.048095Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-07-24T13:43:10.048131Z 0 [Note] InnoDB: Uses event mutexes
2019-07-24T13:43:10.048147Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2019-07-24T13:43:10.048158Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2019-07-24T13:43:10.049162Z 0 [Note] InnoDB: Number of pools: 1
2019-07-24T13:43:10.049730Z 0 [Note] InnoDB: Using CPU crc32 instructions
2019-07-24T13:43:10.053682Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2019-07-24T13:43:10.067501Z 0 [Note] InnoDB: Completed initialization of buffer pool
2019-07-24T13:43:10.242974Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2019-07-24T13:43:10.245483Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 2708624
2019-07-24T13:43:10.245517Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 2708633
2019-07-24T13:43:10.245707Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 2708633
2019-07-24T13:43:10.245749Z 0 [Note] InnoDB: Database was not shutdown normally!
2019-07-24T13:43:10.245762Z 0 [Note] InnoDB: Starting crash recovery.
2019-07-24T13:43:10.416402Z 0 [Note] InnoDB: 2 transaction(s) which must be rolled back or cleaned up in total 2 row operations to undo
2019-07-24T13:43:10.417806Z 0 [Note] InnoDB: Trx id counter is 5120
2019-07-24T13:43:10.685694Z 0 [Note] InnoDB: Starting in background the rollback of uncommitted transactions
2019-07-24T13:43:10.685763Z 0 [Note] InnoDB: Rolling back trx with id 4621, 1 rows to undo
2019-07-24T13:43:10.685931Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2019-07-24T13:43:10.686009Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-07-24T13:43:10.686193Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-07-24T13:43:10.687386Z 0 [Note] InnoDB: Rollback of trx with id 4621 completed
2019-07-24T13:43:10.687425Z 0 [Note] InnoDB: Rolling back trx with id 4619, 1 rows to undo
2019-07-24T13:43:10.687694Z 0 [Note] InnoDB: Rollback of trx with id 4619 completed
2019-07-24T13:43:10.687717Z 0 [Note] InnoDB: Rollback of non-prepared transactions completed
2019-07-24T13:43:10.710245Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-07-24T13:43:10.711515Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2019-07-24T13:43:10.711548Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2019-07-24T13:43:10.711746Z 0 [Note] InnoDB: Waiting for purge to start
2019-07-24T13:43:10.767112Z 0 [Note] InnoDB: 5.7.18 started; log sequence number 2708633
2019-07-24T13:43:10.767445Z 0 [Note] InnoDB: Loading buffer pool(s) from /usr/local/mysql-5.7.18-macos10.12-x86_64/data/ib_buffer_pool
2019-07-24T13:43:10.768027Z 0 [Note] Plugin 'FEDERATED' is disabled.
2019-07-24T13:43:10.784949Z 0 [Note] InnoDB: Buffer pool(s) load completed at 190724 19:13:10
2019-07-24T13:43:10.898439Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2019-07-24T13:43:10.908682Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2019-07-24T13:43:10.908804Z 0 [Note] IPv6 is available.
2019-07-24T13:43:10.908843Z 0 [Note] - '::' resolves to '::';
2019-07-24T13:43:10.908936Z 0 [Note] Server socket created on IP: '::'.
2019-07-24T13:43:11.757803Z 0 [Note] Event Scheduler: Loaded 0 events
2019-07-24T13:43:11.758175Z 0 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.7.18' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL)
2019-07-24T13:43:11.758253Z 0 [Note] Executing 'SELECT * FROM INFORMATION_SCHEMA.TABLES;' to get a list of tables using the deprecated partition engine. You may use the startup option '--disable-partition-engine-check' to skip this check.
2019-07-24T13:43:11.758293Z 0 [Note] Beginning of list of non-natively partitioned tables
2019-07-24T13:43:12.236256Z 0 [Note] End of list of non-natively partitioned tables
Suggested fix:
Nor reproducible in Mysql 5.7.24
