Bug #96317 Lock wait time out is not occuring for INSERT query
Submitted: 24 Jul 2019 13:52 Modified: 1 Aug 2019 8:50
Reporter: TAMILMARAN C Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: Locking Severity:S3 (Non-critical)
Version:5.7.18 OS:Any
Assigned to: CPU Architecture:Any

[24 Jul 2019 13:52] TAMILMARAN C
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
[24 Jul 2019 13:54] TAMILMARAN C
Engine status, Locks realted data

Attachment: Show Innodb Engine Status (application/octet-stream, text), 26.31 KiB.

[24 Jul 2019 14:09] MySQL Verification Team
Hi Mr. C,

Thank you for your bug report.

Please, always use latest release available. Hence, if you can not repeat it with latest 5.7, then it is not a bug.

Let us know about your findings.
[25 Jul 2019 14:03] TAMILMARAN C
Thank you for the reply. Will upgrade the latest version of 5.7 .
[25 Jul 2019 15:08] MySQL Verification Team
That is fine by us ......

If you see the same problem, let us know .....
[1 Aug 2019 8:50] TAMILMARAN C
Is there any specific bug fix gone for this issue. If it is , please share the bug id.
I can't find any bug fix related to issue. Thanks in advance
[1 Aug 2019 12:52] MySQL Verification Team
Neither can I .......

The problem is that bug description can be about the internal code changes, but not about the effects that you can see in the server behaviour.
[2 Aug 2019 8:54] Sudalai Muthukumar
Dear Sinisa Milivojevic/ MySQL team, 

From our perspective, this should be marked as bug and evaluated. Because It is possible that this might be the side-effects of some other bug, and it might be fixed partially in latest version.  Can please check and confirm it ? 

Thanks for the understanding.
[2 Aug 2019 17:55] MySQL Verification Team
Hi Mr. C,

Thank you for your bug report.

Please, always use latest release available. Hence, if you can not repeat it with latest 5.7, then it is not a bug.

Let us know about your findings.