Bug #100148 During a parallel read operation, the rollback of a table load operation causes
Submitted: 8 Jul 2020 3:07 Modified: 10 Aug 2020 12:22
Reporter: shangshang yu Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:8.0.18 OS:Red Hat
Assigned to: CPU Architecture:x86

[8 Jul 2020 3:07] shangshang yu
Description:
while load data into a table, I do select count(*) on the table, and the mysqld hang and crash finally, log as fllow:

2020-06-22T07:31:58.381793Z 0 [ERROR] [MY-012872] [InnoDB] [FATAL] Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.
2020-06-22T07:31:58.381811Z 0 [ERROR] [MY-013183] [InnoDB] Assertion failure: ut0ut.cc:532 thread 140071286073088
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/8.0/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
07:31:58 UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
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...

the load data operation failed and rollback:

[Switching to thread 20 (Thread 0x7f73855ee700 (LWP 91111))]
#0  0x00007f73d251d965 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#0  0x00007f73d251d965 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x000000000233d9e6 in wait (this=0x7f6d6a291258) at sql/storage/innobase/os/os0event.cc:189
#2  os_event::wait_low (this=0x7f6d6a291258, reset_sig_count=1) at sql/storage/innobase/os/os0event.cc:372
#3  0x000000000233dcea in os_event_wait_low (event=<optimized out>, reset_sig_count=<optimized out>) at sql/storage/innobase/os/os0event.cc:608
#4  0x0000000002417154 in sync_array_wait_event (arr=0x7f73a4e49018, cell=@0x7f73855e7040: 0x7f73a4400a18) at sql/storage/innobase/sync/sync0arr.cc:444
#5  0x000000000241afcc in rw_lock_x_lock_wait_func (line=233, file_name=0x3c0e460 "sql/storage/innobase/btr/btr0cur.cc", threshold=0, lock=0x7f6ce14fc018) at sql/storage/innobase/sync/sync0rw.cc:465
#6  rw_lock_x_lock_low (line=233, file_name=0x3c0e460 "sql/storage/innobase/btr/btr0cur.cc", pass=0, lock=0x7f6ce14fc018) at sql/storage/innobase/sync/sync0rw.cc:513
#7  rw_lock_x_lock_func (lock=lock@entry=0x7f6ce14fc018, pass=pass@entry=0, file_name=file_name@entry=0x3c0e460 "sql/storage/innobase/btr/btr0cur.cc", line=line@entry=233) at sql/storage/innobase/sync/sync0rw.cc:672
#8  0x000000000250ca79 in pfs_rw_lock_x_lock_func (line=233, file_name=0x3c0e460 "sql/storage/innobase/btr/btr0cur.cc", pass=0, lock=0x7f6ce14fc018) at sql/storage/innobase/include/sync0rw.ic:627
#9  Buf_fetch<Buf_fetch_normal>::mtr_add_page (this=this@entry=0x7f73855e7190, block=0x7f6ce14fbf60) at sql/storage/innobase/buf/buf0buf.cc:4053
#10 0x0000000002516076 in Buf_fetch<Buf_fetch_normal>::single_page (this=this@entry=0x7f73855e7190) at sql/storage/innobase/buf/buf0buf.cc:4317
#11 0x000000000251673d in buf_page_get_gen (page_id=..., page_size=..., rw_latch=rw_latch@entry=2, guess=guess@entry=0x0, mode=mode@entry=NORMAL, file=file@entry=0x3c0e460 "sql/storage/innobase/btr/btr0cur.cc", line=233, mtr=0x7f73855e82d0, dirty_with_no_latch=false) at sql/storage/innobase/buf/buf0buf.cc:4396
#12 0x00000000024e96db in btr_block_get_func (mtr=0x7f73855e82d0, line=233, file=0x3c0e460 "sql/storage/innobase/btr/btr0cur.cc", mode=2, page_size=..., page_id=...) at sql/storage/innobase/include/btr0btr.ic:73
#13 btr_cur_latch_leaves (block=block@entry=0x7f6d730ba1b8, page_id=..., page_size=..., latch_mode=latch_mode@entry=33, cursor=cursor@entry=0x7f64d6802700, mtr=0x7f73855e82d0) at sql/storage/innobase/btr/btr0cur.cc:233
#14 0x00000000024f3261 in btr_cur_search_to_nth_level (index=index@entry=0x7f64d6a37b10, level=level@entry=0, tuple=tuple@entry=0x7f64d6a895d0, mode=<optimized out>, latch_mode=<optimized out>, cursor=cursor@entry=0x7f64d6802700, has_search_latch=0, file=0x3c24a30 "sql/storage/innobase/row/row0uins.cc", line=133, mtr=0x7f73855e82d0) at sql/storage/innobase/btr/btr0cur.cc:1145
#15 0x00000000024f63ff in open_no_init (line=133, file=0x3c24a30 "sql/storage/innobase/row/row0uins.cc", mtr=0x7f73855e82d0, has_search_latch=0, latch_mode=<optimized out>, mode=<optimized out>, tuple=0x7f64d6a895d0, index=0x7f64d6a37b10, this=0x7f64d6802700) at sql/storage/innobase/include/btr0pcur.h:706
#16 btr_pcur_t::restore_position (this=this@entry=0x7f64d6802700, latch_mode=latch_mode@entry=65569, mtr=mtr@entry=0x7f73855e82d0, file=file@entry=0x3c24a30 "sql/storage/innobase/row/row0uins.cc", line=line@entry=133) at sql/storage/innobase/btr/btr0pcur.cc:239
#17 0x000000000265848d in row_undo_ins_remove_clust_rec (node=node@entry=0x7f64d6802690) at sql/storage/innobase/row/row0uins.cc:132
#18 0x0000000002659db1 in row_undo_ins (node=node@entry=0x7f64d6802690, thr=thr@entry=0x7f64d6887460) at sql/storage/innobase/row/row0uins.cc:495
#19 0x00000000023e73bb in row_undo (thr=0x7f64d6887460, node=0x7f64d6802690) at sql/storage/innobase/row/row0undo.cc:295
#20 row_undo_step (thr=thr@entry=0x7f64d6887460) at sql/storage/innobase/row/row0undo.cc:362
#21 0x000000000236ea01 in que_thr_step (thr=0x7f64d6887460) at sql/storage/innobase/que/que0que.cc:925
#22 que_run_threads_low (thr=0x7f64d6887460) at sql/storage/innobase/que/que0que.cc:978
#23 que_run_threads (thr=<optimized out>) at sql/storage/innobase/que/que0que.cc:1013
#24 0x0000000002442df5 in trx_rollback_to_savepoint_low (trx=trx@entry=0x7f73a3800b80, savept=savept@entry=0x0) at sql/storage/innobase/trx/trx0roll.cc:114
#25 0x0000000002443561 in trx_rollback_for_mysql_low (trx=0x7f73a3800b80) at sql/storage/innobase/trx/trx0roll.cc:168
#26 0x0000000002445866 in trx_rollback_low (trx=trx@entry=0x7f73a3800b80) at sql/storage/innobase/trx/trx0roll.cc:206
#27 0x0000000002447811 in trx_rollback_for_mysql (trx=trx@entry=0x7f73a3800b80) at sql/storage/innobase/trx/trx0roll.cc:282
#28 0x00000000022534b8 in innobase_rollback (hton=<optimized out>, thd=0x7f64d6a04000, rollback_trx=<optimized out>) at sql/storage/innobase/handler/ha_innodb.cc:6071
#29 0x0000000001256d2f in ha_rollback_low (thd=0x7f64d6a04000, all=false) at sql/sql/handler.cc:1922
#30 0x0000000001256fcd in ha_rollback_trans (thd=thd@entry=0x7f64d6a04000, all=all@entry=false) at sql/sql/handler.cc:2002
#31 0x00000000010eb029 in trans_rollback_stmt (thd=thd@entry=0x7f64d6a04000) at sql/sql/transaction.cc:577
#32 0x0000000000fec9a8 in mysql_execute_command (thd=thd@entry=0x7f64d6a04000, first_level=first_level@entry=true) at sql/sql/sql_parse.cc:4978
#33 0x0000000000ff07b0 in mysql_parse (thd=thd@entry=0x7f64d6a04000, parser_state=parser_state@entry=0x7f73855eae20) at sql/sql/sql_parse.cc:5726
#34 0x0000000000ff2791 in dispatch_command (thd=thd@entry=0x7f64d6a04000, com_data=com_data@entry=0x7f73855eb540, command=COM_QUERY) at sql/sql/sql_parse.cc:1840
#35 0x0000000000ff36a0 in do_command (thd=thd@entry=0x7f64d6a04000) at sql/sql/sql_parse.cc:1310
#36 0x000000000111fc88 in handle_connection (arg=arg@entry=0x7f73a9cb0520) at sql/sql/conn_handler/connection_handler_per_thread.cc:302
#37 0x00000000026e508f in pfs_spawn_thread (arg=0x7f73a9e16320) at sql/storage/perfschema/pfs.cc:2854
#38 0x00007f73d2519e45 in start_thread () from /lib64/libpthread.so.0
#39 0x00007f73cee91b3d in clone () from /lib64/libc.so.6

How to repeat:
hard to repeat
[8 Jul 2020 3:07] shangshang yu
innodb status show the lock info:

OS WAIT ARRAY INFO: reservation count 3114
--Thread 140070095931136 has waited at row0pread.cc line 245 for 254 seconds the semaphore:
S-lock on RW-latch at 0x7f738ea7c2e8 created in file buf0buf.cc line 777
a writer (thread id 140134135555840) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0row.cc line 919
Last time write locked in file /ci/taurus-root/src/sql/storage/innobase/include/mtr0mtr.ic line 142

--Thread 140133994104576 has waited at row0ins.cc line 2446 for 254 seconds the semaphore:
S-lock on RW-latch at 0x7f738ea7c2e8 created in file buf0buf.cc line 777
a writer (thread id 140134135555840) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0row.cc line 919
Last time write locked in file /ci/taurus-root/src/sql/storage/innobase/include/mtr0mtr.ic line 142

--Thread 140070112716544 has waited at row0pread.cc line 245 for 248 seconds the semaphore:
S-lock on RW-latch at 0x7f738ea7c2e8 created in file buf0buf.cc line 777
a writer (thread id 140134135555840) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0row.cc line 919
Last time write locked in file /ci/taurus-root/src/sql/storage/innobase/include/mtr0mtr.ic line 142

--Thread 140070121109248 has waited at row0pread.cc line 245 for 253 seconds the semaphore:
S-lock on RW-latch at 0x7f738ea7c2e8 created in file buf0buf.cc line 777
a writer (thread id 140134135555840) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0row.cc line 919
Last time write locked in file /ci/taurus-root/src/sql/storage/innobase/include/mtr0mtr.ic line 142

--Thread 140134135555840 has waited at btr0cur.cc line 233 for 254 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x7f6ce14fc018 created in file buf0buf.cc line 777
a writer (thread id 140134135555840) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
Last time read locked in file row0pread.cc line 336
Last time write locked in file /ci/taurus-root/src/sql/storage/innobase/btr/btr0cur.cc line 233

--Thread 140070104323840 has waited at row0pread.cc line 245 for 254 seconds the semaphore:
S-lock on RW-latch at 0x7f738ea7c2e8 created in file buf0buf.cc line 777
a writer (thread id 140134135555840) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0row.cc line 919
Last time write locked in file /ci/taurus-root/src/sql/storage/innobase/include/mtr0mtr.ic line 142
[8 Jul 2020 13:39] MySQL Verification Team
Hi Mr. yu,

Thank you for your bug report.

However, in order to verify it , we must be able to repeat it. Hence, we need a repeatable test case, which will always lead to this assert.

Let me point out that this is not a crash, but controlled assert. This is due to the long semaphore wait, which is expected behaviour.

Also, we need it repeated on the latest release of our 8.0 server.
[9 Jul 2020 3:41] shangshang yu
The scene is same as following bug, I think their have relations.

SHA-1: 48f2c0b55de952705c7fbcf308c2b6bf613223c4

* Bug#30060690 MYSQLD CRASH AFTER LOADING DATA

Issue
=====
During parallel read, if the entire load table is rolled back when autocommit
= 0 we hit an assertion.

Fix
===
The assertion is bogus as the point that the existing tree structure could be
changed during parallel read wasn't considered.

RB: 22847
Reviewed-by: Sunny Bains <sunny.bains@oracle.com>

Change-Id: I3b2a23a0fe0b398b254a76b3f60b284731d170fc
[9 Jul 2020 12:00] MySQL Verification Team
Hi Mr. yu,

If you think that it is a duplicate, then I will mark him as such. Otherwise, we need a full test case.

We leave it up to you .....
[10 Aug 2020 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".