[MDEV-21974] InnoDB DML under backup locks make buffer pool usage grow permanently - Jira

Details

Type: Bug
Status: Open (View Workflow)
Priority: Major
Resolution: Unresolved
Affects Version/s: 10.4(EOL), 10.5
Fix Version/s: 10.5
Component/s: Backup, Storage Engine - InnoDB
Labels:
None

Description

--source include/have_innodb.inc

--source include/have_sequence.inc

CREATE TABLE t1 (a BINARY(149)) ENGINE=InnoDB;

INSERT INTO t1 SELECT 'foo' FROM seq_1_to_32768;

CREATE TABLE t2 (b INT) ENGINE=InnoDB;

--connect (con15_0,localhost,root,,test)

BACKUP STAGE START;

BACKUP STAGE BLOCK_COMMIT;

--connection default

SET lock_wait_timeout= 5;

--send

  INSERT INTO t1 SELECT * FROM t1;

--connect (con16_0,localhost,root,,test)

SET lock_wait_timeout= 5;

SET innodb_lock_wait_timeout= 30;

--error ER_LOCK_WAIT_TIMEOUT

INSERT INTO t2 VALUES (1),(2);

--error ER_LOCK_WAIT_TIMEOUT

INSERT INTO t1 SELECT * FROM t1 LIMIT 1;

--error ER_LOCK_WAIT_TIMEOUT

INSERT INTO t1 SELECT * FROM t1 LIMIT 1;

--disconnect con16_0

--disconnect con15_0

--connection default

--error ER_LOCK_WAIT_TIMEOUT

--reap

DROP TABLE t1, t2;

The test case above, if it's run with innodb_buffer_pool_size=128M (which is default outside MTR) causes InnoDB abort due to >95% buffer pool usage, even though it performs short operations on a relatively small table. It happens reliably for me, but some timing issues are possible, so it may fail with 67% warnings instead.

10.4 2b3f6ab4, MTR test runs with --mysqld=--innodb-buffer-pool-size=128M
2020-03-18 14:40:57 9 [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. innodb_buffer_pool_size=123M. Starting the InnoDB Monitor to print diagnostics.
2020-03-18 14:41:10 9 [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, or review if innodb_buffer_pool_size=123M could be bigger.
200318 14:41:10 [ERROR] mysqld got signal 6 ;

#5 0x00007fc07fe0242a in __GI_abort () at abort.c:89
#6 0x000055611bd0786d in ib::fatal::~fatal (this=0x7fc07999e470, __in_chrg=<optimized out>) at /data/src/10.4/storage/innobase/ut/ut0ut.cc:597
#7 0x000055611bdb4c3f in buf_LRU_check_size_of_non_data_objects (buf_pool=0x55611ec9fe80) at /data/src/10.4/storage/innobase/buf/buf0lru.cc:1008
#8 0x000055611bdb4f93 in buf_LRU_get_free_block (buf_pool=0x55611ec9fe80) at /data/src/10.4/storage/innobase/buf/buf0lru.cc:1098
#9 0x000055611bd7b0f5 in buf_block_alloc (buf_pool=0x55611ec9fe80) at /data/src/10.4/storage/innobase/buf/buf0buf.cc:763
#10 0x000055611bb5e794 in mem_heap_create_block_func (heap=0x55611ebb30e0, n=16184, file_name=0x55611ebb30e0 "0trx.cc", line=199, type=1) at /data/src/10.4/storage/innobase/mem/mem0mem.cc:294
#11 0x000055611bb5eb03 in mem_heap_add_block (heap=0x55611ebb30e0, n=108) at /data/src/10.4/storage/innobase/mem/mem0mem.cc:380
#12 0x000055611bb162d5 in mem_heap_alloc (heap=0x55611ebb30e0, n=108) at /data/src/10.4/storage/innobase/include/mem0mem.ic:191
#13 0x000055611bb1ecb4 in lock_rec_create_low (c_lock=0x0, thr=0x0, type_mode=34, space=5, page_no=565, page=0x7fc0653b0000 "\035\331\025\341", heap_no=1, index=0x7fc02019df80, trx=0x7fc079c3b140, holds_trx_mutex=false) at /data/src/10.4/storage/innobase/lock/lock0lock.cc:1393
#14 0x000055611bb18ee2 in lock_rec_create (c_lock=0x0, thr=0x0, type_mode=34, block=0x7fc06408f640, heap_no=1, index=0x7fc02019df80, trx=0x7fc079c3b140, caller_owns_trx_mutex=false) at /data/src/10.4/storage/innobase/include/lock0lock.ic:133
#15 0x000055611bb21084 in lock_rec_add_to_queue (type_mode=34, block=0x7fc06408f640, heap_no=1, index=0x7fc02019df80, trx=0x7fc079c3b140, caller_owns_trx_mutex=false) at /data/src/10.4/storage/innobase/lock/lock0lock.cc:1901
#16 0x000055611bb235cc in lock_rec_move_low (lock_hash=0x55611f5d2b00, receiver=0x7fc06408f640, donator=0x7fc06408f8a0, receiver_heap_no=1, donator_heap_no=1) at /data/src/10.4/storage/innobase/lock/lock0lock.cc:2541
#17 0x000055611bb237e7 in lock_rec_move (receiver=0x7fc06408f640, donator=0x7fc06408f8a0, receiver_heap_no=1, donator_heap_no=1) at /data/src/10.4/storage/innobase/lock/lock0lock.cc:2600
#18 0x000055611bb257d9 in lock_update_merge_left (left_block=0x7fc06408f640, orig_pred=0x7fc0653b3af2 "", right_block=0x7fc06408f8a0) at /data/src/10.4/storage/innobase/lock/lock0lock.cc:3217
#19 0x000055611bd1d5c8 in btr_compress (cursor=0x7fc02002ecd0, adjust=0, mtr=0x7fc07999f9f0) at /data/src/10.4/storage/innobase/btr/btr0btr.cc:3813
#20 0x000055611bd4cde4 in btr_cur_compress_if_useful (cursor=0x7fc02002ecd0, adjust=0, mtr=0x7fc07999f9f0) at /data/src/10.4/storage/innobase/btr/btr0cur.cc:5698
#21 0x000055611bd4ec31 in btr_cur_pessimistic_delete (err=0x7fc07999f990, has_reserved_extents=0, cursor=0x7fc02002ecd0, flags=0, rollback=true, mtr=0x7fc07999f9f0) at /data/src/10.4/storage/innobase/btr/btr0cur.cc:6135
#22 0x000055611beb5b46 in row_undo_ins_remove_clust_rec (node=0x7fc02002ec60) at /data/src/10.4/storage/innobase/row/row0uins.cc:188
#23 0x000055611beb7084 in row_undo_ins (node=0x7fc02002ec60, thr=0x7fc0201953f0) at /data/src/10.4/storage/innobase/row/row0uins.cc:587
#24 0x000055611bc76cf1 in row_undo (node=0x7fc02002ec60, thr=0x7fc0201953f0) at /data/src/10.4/storage/innobase/row/row0undo.cc:438
#25 0x000055611bc76fc6 in row_undo_step (thr=0x7fc0201953f0) at /data/src/10.4/storage/innobase/row/row0undo.cc:499
#26 0x000055611bbb8278 in que_thr_step (thr=0x7fc0201953f0) at /data/src/10.4/storage/innobase/que/que0que.cc:1035
#27 0x000055611bbb852b in que_run_threads_low (thr=0x7fc0201953f0) at /data/src/10.4/storage/innobase/que/que0que.cc:1099
#28 0x000055611bbb877b in que_run_threads (thr=0x7fc0201953f0) at /data/src/10.4/storage/innobase/que/que0que.cc:1139
#29 0x000055611bce07e3 in trx_rollback_to_savepoint_low (trx=0x7fc079c3b140, savept=0x0) at /data/src/10.4/storage/innobase/trx/trx0roll.cc:136
#30 0x000055611bce0c6e in trx_rollback_for_mysql_low (trx=0x7fc079c3b140) at /data/src/10.4/storage/innobase/trx/trx0roll.cc:210
#31 0x000055611bce112f in trx_rollback_for_mysql (trx=0x7fc079c3b140) at /data/src/10.4/storage/innobase/trx/trx0roll.cc:236
#32 0x000055611ba744ad in innobase_rollback (hton=0x55611eb8e3a0, thd=0x7fc020000af0, rollback_trx=false) at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:4721
#33 0x000055611b830496 in ha_rollback_trans (thd=0x7fc020000af0, all=false) at /data/src/10.4/sql/handler.cc:1885
#34 0x000055611b82eca1 in ha_commit_trans (thd=0x7fc020000af0, all=false) at /data/src/10.4/sql/handler.cc:1498
#35 0x000055611b66829b in trans_commit_stmt (thd=0x7fc020000af0) at /data/src/10.4/sql/transaction.cc:436
#36 0x000055611b4d71a4 in mysql_execute_command (thd=0x7fc020000af0) at /data/src/10.4/sql/sql_parse.cc:6158
#37 0x000055611b4dc255 in mysql_parse (thd=0x7fc020000af0, rawbuf=0x7fc020013198 "INSERT INTO t1 SELECT * FROM t1", length=31, parser_state=0x7fc0799a2160, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7900
#38 0x000055611b4c7438 in dispatch_command (command=COM_QUERY, thd=0x7fc020000af0, packet=0x7fc020137251 "INSERT INTO t1 SELECT * FROM t1", packet_length=31, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1842
#39 0x000055611b4c5ac5 in do_command (thd=0x7fc020000af0) at /data/src/10.4/sql/sql_parse.cc:1360
#40 0x000055611b64ef4b in do_handle_one_connection (connect=0x55611eb77280) at /data/src/10.4/sql/sql_connect.cc:1412
#41 0x000055611b64ec9a in handle_one_connection (arg=0x55611eb77280) at /data/src/10.4/sql/sql_connect.cc:1316
#42 0x000055611c0562fb in pfs_spawn_thread (arg=0x55611f78cdd0) at /data/src/10.4/storage/perfschema/pfs.cc:1869
#43 0x00007fc081d824a4 in start_thread (arg=0x7fc0799a3700) at pthread_create.c:456
#44 0x00007fc07feb6d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

It appears that by increasing innodb_lock_wait_timeout in the test, it can be made to either exhaust any arbitrary buffer pool or to fail with ER_LOCK_TABLE_FULL. For example, with innodb_buffer_pool_size=512M and innodb_lock_wait_timeout=180 it fails with 67% warnings, while innodb_buffer_pool_size=512M and innodb_lock_wait_timeout=240 cause ER_LOCK_TABLE_FULL (exact values may vary for different machines and builds).

Top shows that memory usage in the server keeps growing for the whole time when it waits for the locks, and CPU is at steady ~100%:

19020 elenst    20   0 2245844 265080  29320 S 100.0  0.8   0:29.82 mysqld

19020 elenst    20   0 2245844 274320  29320 S 100.7  0.8   0:32.84 mysqld

19020 elenst    20   0 2245844 283296  29320 S  99.7  0.9   0:35.84 mysqld

19020 elenst    20   0 2245844 289896  29320 S 100.3  0.9   0:38.85 mysqld

19020 elenst    20   0 2245844 295968  29320 S 100.3  0.9   0:41.86 mysqld

19020 elenst    20   0 2245844 302568  29320 S 100.3  0.9   0:44.87 mysqld

19020 elenst    20   0 2245844 308376  29320 S  99.0  0.9   0:47.85 mysqld

19020 elenst    20   0 2245844 312864  29320 S  97.7  1.0   0:50.78 mysqld

19020 elenst    20   0 2245844 318672  29320 S  98.7  1.0   0:53.74 mysqld

19020 elenst    20   0 2245844 323160  29320 S  98.7  1.0   0:56.70 mysqld

19020 elenst    20   0 2245844 328440  29320 S 100.3  1.0   0:59.71 mysqld

19020 elenst    20   0 2245844 334512  29320 S 100.0  1.0   1:02.72 mysqld

19020 elenst    20   0 2245844 340320  29320 S 100.3  1.0   1:05.73 mysqld

19020 elenst    20   0 2245844 346392  29320 S 100.3  1.1   1:08.74 mysqld

19020 elenst    20   0 2245844 350616  29320 S  99.3  1.1   1:11.72 mysqld

19020 elenst    20   0 2245844 355368  29320 S  97.7  1.1   1:14.66 mysqld

19020 elenst    20   0 2245844 360120  29320 S  99.3  1.1   1:17.64 mysqld

19020 elenst    20   0 2245844 364608  29320 S 100.0  1.1   1:20.64 mysqld

19020 elenst    20   0 2245844 369624  29320 S 100.3  1.1   1:23.65 mysqld

19020 elenst    20   0 2245844 374376  29320 S  99.7  1.1   1:26.65 mysqld

19020 elenst    20   0 2245844 380448  29320 S 100.0  1.2   1:29.65 mysqld

19020 elenst    20   0 2245844 386520  29320 S 100.3  1.2   1:32.66 mysqld

19020 elenst    20   0 2245844 392328  29320 S 100.3  1.2   1:35.67 mysqld

19020 elenst    20   0 2245844 397080  29320 S  99.7  1.2   1:38.67 mysqld

19020 elenst    20   0 2245844 401568  29320 S  99.3  1.2   1:41.65 mysqld

19020 elenst    20   0 2245844 405792  29320 S 100.3  1.2   1:44.66 mysqld

19020 elenst    20   0 2245844 411600  29320 S 100.3  1.3   1:47.67 mysqld

19020 elenst    20   0 2245844 417408  29320 S 100.0  1.3   1:50.68 mysqld

19020 elenst    20   0 2245844 422952  29320 S 100.0  1.3   1:53.68 mysqld

19020 elenst    20   0 2245844 427968  29320 S 100.3  1.3   1:56.69 mysqld

19020 elenst    20   0 2245844 431928  29320 S  98.0  1.3   1:59.63 mysqld

19020 elenst    20   0 2245844 436944  29320 S 100.7  1.3   2:02.65 mysqld

19020 elenst    20   0 2245844 442224  29320 S  99.7  1.3   2:05.65 mysqld

19020 elenst    20   0 2245844 448032  29320 S 100.3  1.4   2:08.66 mysqld

19020 elenst    20   0 2245844 452784  29320 S 100.0  1.4   2:11.66 mysqld

19020 elenst    20   0 2245844 458064  29320 S 100.3  1.4   2:14.67 mysqld

19020 elenst    20   0 2245844 463080  29320 S 100.3  1.4   2:17.68 mysqld

19020 elenst    20   0 2245844 468360  29320 S  99.7  1.4   2:20.68 mysqld

19020 elenst    20   0 2245844 471792  29320 S 100.0  1.4   2:23.68 mysqld

19020 elenst    20   0 2245844 476016  29320 S 100.0  1.5   2:26.68 mysqld

19020 elenst    20   0 2245844 479712  29320 S  99.7  1.5   2:29.68 mysqld

19020 elenst    20   0 2245844 483936  29320 S 100.3  1.5   2:32.69 mysqld

19020 elenst    20   0 2245844 488952  29320 S 100.3  1.5   2:35.70 mysqld

19020 elenst    20   0 2245844 493704  29320 S 100.0  1.5   2:38.71 mysqld

19020 elenst    20   0 2245844 498456  29320 S 100.0  1.5   2:41.71 mysqld

19020 elenst    20   0 2245844 503208  29320 S 100.3  1.5   2:44.72 mysqld

19020 elenst    20   0 2245844 507696  29320 S 100.0  1.5   2:47.72 mysqld

19020 elenst    20   0 2245844 512448  29320 S  99.7  1.6   2:50.72 mysqld

19020 elenst    20   0 2245844 517200  29320 S 100.0  1.6   2:53.72 mysqld

19020 elenst    20   0 2245844 521952  29320 S 100.3  1.6   2:56.73 mysqld

19020 elenst    20   0 2245844 526440  29320 S 100.0  1.6   2:59.74 mysqld

19020 elenst    20   0 2245844 530400  29320 S 100.3  1.6   3:02.75 mysqld

19020 elenst    20   0 2245844 534624  29320 S  99.7  1.6   3:05.74 mysqld

19020 elenst    20   0 2245844 538848  29320 S 100.3  1.6   3:08.75 mysqld

19020 elenst    20   0 2245844 543600  29320 S 100.0  1.7   3:11.76 mysqld

19020 elenst    20   0 2245844 547296  29320 S 100.0  1.7   3:14.76 mysqld

19020 elenst    20   0 2245844 550728  29320 S 100.0  1.7   3:17.76 mysqld

19020 elenst    20   0 2245844 553632  29320 S  98.0  1.7   3:20.70 mysqld

19020 elenst    20   0 2245844 557856  29320 S  99.3  1.7   3:23.69 mysqld

19020 elenst    20   0 2245844 562344  29320 S 100.7  1.7   3:26.71 mysqld

19020 elenst    20   0 2245844 566304  29320 S 100.0  1.7   3:29.71 mysqld

19020 elenst    20   0 2245844 571056  29320 S  99.7  1.7   3:32.71 mysqld

19020 elenst    20   0 2245844 573960  29320 S 100.0  1.7   3:35.71 mysqld

19020 elenst    20   0 2245844 577392  29320 S 100.3  1.8   3:38.72 mysqld

19020 elenst    20   0 2311380 581088  29320 S  99.7  1.8   3:41.71 mysqld

19020 elenst    20   0 2311380 584256  29320 S  99.3  1.8   3:44.69 mysqld

19020 elenst    20   0 2311380 587160  29320 S 100.0  1.8   3:47.70 mysqld

19020 elenst    20   0 2311380 591648  29320 S 100.0  1.8   3:50.70 mysqld

19020 elenst    20   0 2311380 595344  29320 S 100.3  1.8   3:53.71 mysqld

19020 elenst    20   0 2311380 600096  29320 S 100.0  1.8   3:56.71 mysqld

19020 elenst    20   0 2311380 603000  29320 S 100.0  1.8   3:59.72 mysqld

19020 elenst    20   0 2311380 605904  29320 S  99.7  1.8   4:02.71 mysqld

19020 elenst    20   0 2311380 608808  29320 S 100.0  1.9   4:05.71 mysqld

19020 elenst    20   0 2311380 612240  29320 S 100.0  1.9   4:08.71 mysqld

19020 elenst    20   0 2311380 615408  29320 S 100.0  1.9   4:11.71 mysqld

I couldn't replace backup locks with regular locks in the scenario, however it's possible that I just didn't find the right combination.

Attachments

Issue Links

duplicates

MDEV-24813 Locking full table scan fails to use table-level locking

In Review

relates to

MDEV-16232 Use fewer mini-transactions

Stalled

MDEV-16406 Refactor the InnoDB record locks

Open

InnoDB DML under backup locks make buffer pool usage grow permanently

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration