Bug #71343 InnoDB lock monitor crashes if table dropped at the right time on debug build

Submitted: 10 Jan 2014 15:49 Modified: 10 Dec 2014 13:10
Reporter: Laurynas Biveinis (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S6 (Debug Builds)
Version:5.6.15 OS:Any
Assigned to: CPU Architecture:Any
Tags: crash, debug

[10 Jan 2014 15:49] Laurynas Biveinis
Description:
Found while trying to create a testcase for bug 68116.

If InnoDB lock monitor is enabled, and a table is dropped at a precisely right moment, an assertion will happen:

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffeae91700 (LWP 4943)]
0x00007ffff69cef77 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56	../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) up
#1  0x00007ffff69d25e8 in __GI_abort () at abort.c:90
90	abort.c: No such file or directory.
(gdb) up
#2  0x0000000000d5d7cf in buf_page_get_gen (space=7, zip_size=0, offset=3, rw_latch=3, guess=0x0, mode=14, file=0x1022c60 "/home/laurynas/percona/src/5.6/storage/innobase/lock/lock0lock.cc", line=5383, 
    mtr=0x7fffeae8e120) at /home/laurynas/percona/src/5.6/storage/innobase/buf/buf0buf.cc:2461
2461		ut_ad(zip_size == fil_space_get_zip_size(space));
(gdb) print zip_size
$1 = 0
(gdb) print fil_space_get_zip_size(space)
$2 = 18446744073709551615
(gdb) bt
#0  0x00007ffff69cef77 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007ffff69d25e8 in __GI_abort () at abort.c:90
#2  0x0000000000d5d7cf in buf_page_get_gen (space=7, zip_size=0, offset=3, rw_latch=3, guess=0x0, mode=14, file=0x1022c60 "/home/laurynas/percona/src/5.6/storage/innobase/lock/lock0lock.cc", line=5383, 
    mtr=0x7fffeae8e120) at /home/laurynas/percona/src/5.6/storage/innobase/buf/buf0buf.cc:2461
#3  0x0000000000beea8a in lock_print_info_all_transactions (file=0x1971e00) at /home/laurynas/percona/src/5.6/storage/innobase/lock/lock0lock.cc:5383
#4  0x0000000000cd564f in srv_printf_innodb_monitor (file=0x1971e00, nowait=0, trx_start_pos=0x7fffeae8e6f0, trx_end=0x7fffeae8e6f8) at /home/laurynas/percona/src/5.6/storage/innobase/srv/srv0srv.cc:1191
#5  0x0000000000ba2acb in innodb_show_status (hton=0x1956fa0, thd=0x1bce410, stat_print=0x634707 <stat_print(THD*, char const*, uint, char const*, uint, char const*, uint)>)
    at /home/laurynas/percona/src/5.6/storage/innobase/handler/ha_innodb.cc:12401
#6  0x0000000000ba354f in innobase_show_status (hton=0x1956fa0, thd=0x1bce410, stat_print=0x634707 <stat_print(THD*, char const*, uint, char const*, uint, char const*, uint)>, stat_type=HA_ENGINE_STATUS)
    at /home/laurynas/percona/src/5.6/storage/innobase/handler/ha_innodb.cc:12632
#7  0x0000000000634a89 in ha_show_status (thd=0x1bce410, db_type=0x1956fa0, stat=HA_ENGINE_STATUS) at /home/laurynas/percona/src/5.6/sql/handler.cc:6928
#8  0x00000000007ccd96 in mysql_execute_command (thd=0x1bce410) at /home/laurynas/percona/src/5.6/sql/sql_parse.cc:2822
#9  0x00000000007d61f0 in mysql_parse (thd=0x1bce410, rawbuf=0x7fffd0004c70 "SHOW ENGINE INNODB STATUS", length=25, parser_state=0x7fffeae8fe40) at /home/laurynas/percona/src/5.6/sql/sql_parse.cc:6235
#10 0x00000000007c966a in dispatch_command (command=COM_QUERY, thd=0x1bce410, packet=0x1bd21d1 "", packet_length=25) at /home/laurynas/percona/src/5.6/sql/sql_parse.cc:1334
#11 0x00000000007c87ba in do_command (thd=0x1bce410) at /home/laurynas/percona/src/5.6/sql/sql_parse.cc:1036
#12 0x000000000078f438 in do_handle_one_connection (thd_arg=0x1bce410) at /home/laurynas/percona/src/5.6/sql/sql_connect.cc:982
#13 0x000000000078ef4e in handle_one_connection (arg=0x1bce410) at /home/laurynas/percona/src/5.6/sql/sql_connect.cc:898
#14 0x0000000000b7e4c8 in pfs_spawn_thread (arg=0x1b455c0) at /home/laurynas/percona/src/5.6/storage/perfschema/pfs.cc:1858
#15 0x00007ffff7585f6e in start_thread (arg=0x7fffeae91700) at pthread_create.c:311
#16 0x00007ffff6a929cd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

How to repeat:
=== modified file 'storage/innobase/lock/lock0lock.cc'
--- storage/innobase/lock/lock0lock.cc	2013-06-10 20:44:22 +0000
+++ storage/innobase/lock/lock0lock.cc	2014-01-10 15:26:31 +0000
@@ -5375,6 +5375,8 @@
 			lock_mutex_exit();
 			mutex_exit(&trx_sys->mutex);
 
+			DEBUG_SYNC_C("innodb_monitor_before_lock_page_read");
+
 			mtr_start(&mtr);
 
 			buf_page_get_with_no_latch(

--source include/have_debug.inc
--source include/have_innodb.inc
--source include/count_sessions.inc

CREATE TABLE innodb_lock_monitor (a INT) ENGINE=INNODB;

CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=InnoDB;

INSERT INTO t1 VALUES (0);

BEGIN;
SELECT * FROM t1 LOCK IN SHARE MODE;

--connect(con1,localhost,root,,)

--connection con1

SET DEBUG_SYNC='innodb_monitor_before_lock_page_read SIGNAL monitor_ready WAIT_FOR finish';

send SHOW ENGINE INNODB STATUS;

--connection default

SET DEBUG_SYNC='now WAIT_FOR monitor_ready';

COMMIT;
DROP TABLE t1;

SET DEBUG_SYNC='now SIGNAL finish';

--connection con1

REAP;

--disconnect con1

--connection default

SET DEBUG_SYNC='RESET';
DROP TABLE innodb_lock_monitor;

--source include/wait_until_count_sessions.inc

Suggested fix:
Pass BUF_GET_POSSIBLY_FREED to buf_page_get_gen() from lock_print_info_all_transactions(), and make ut_ad(zip_size == fil_space_get_zip_size(space)) conditional on that flag absence. This will happen to fix bug 68116 too.
[10 Jan 2014 18:26] MySQL Verification Team
Hello Laurynas,

Thank you for the bug report and the test case. 
Verified as described.

Thanks,
Umesh
[10 Jan 2014 18:28] MySQL Verification Team
Test case with results...

Attachment: 71343.txt (text/plain), 31.01 KiB.

[22 Sep 2014 18:33] Daniel Price
Fixed as of the upcoming 5.6.22, 5.7.6 releases, and here's the changelog entry:

In debug builds, the "InnoDB" Lock Monitor asserted after a "DROP TABLE"
operation, and the "InnoDB" Monitor encountered an assertion in
"buf_page_get_gen". 

Thank you for the bug report.

Note: This bug patch also addresses Bug #18173184 / MySQL Bug #68116.
[10 Dec 2014 13:10] Laurynas Biveinis
The commit does not contain the testcase :(

$ bzr log -r 6171                         
------------------------------------------------------------
revno: 6171
committer: Allen lai <zheng.lai@oracle.com>
branch nick: mysql-5.6
timestamp: Mon 2014-09-22 18:43:17 +0800
message:
  Bug#18062698 - INNODB LOCK MONITOR CRASHES IF TABLE DROPPED AT THE RIGHT
  TIME ON DEBUG BUILD
  
  When buf_page_get_with_no_latch is called in lock_print_info_all_transactions,
  the space maybe deleted by drop table.
  So, we need to check if the space is deleted or not before getting a
  page, and prevent the space be deleted as well.
  
  This patch also fixed bug18173184.
  
  rb#6509 Approved by Jimmy.

Portions of this website are copyright © 2001, 2002 The PHP Group

Page generated in 0.060 sec. using MySQL 8.4.7-u6-cloud

Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the respective copyright holders.
It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.