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 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.