Bug #73913 On Shutdown - InnoDB: Failing assertion: purge_sys->n_stop == 0
Submitted: 14 Sep 2014 20:49 Modified: 9 May 2017 6:48
Reporter: Roel Van de Paar (OCA) Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.6.20, 5.6.22, 5.7.6 OS:Any
Assigned to: CPU Architecture:Any
Tags: debug builds

[14 Sep 2014 20:49] Roel Van de Paar
Description:
(gdb) bt
#0  0x00007fe643115771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000a9035e in my_write_core (sig=6) at /bzr/mysql-5.6/mysys/stacktrace.c:422
#2  0x0000000000723688 in handle_fatal_signal (sig=6) at /bzr/mysql-5.6/sql/signal_handler.cc:230
#3  <signal handler called>
#4  0x00007fe641f21989 in raise () from /lib64/libc.so.6
#5  0x00007fe641f23098 in abort () from /lib64/libc.so.6
#6  0x0000000000caa9bf in srv_purge_coordinator_suspend (slot=0x7fe627bf0880, rseg_history_len=0) at /bzr/mysql-5.6/storage/innobase/srv/srv0srv.cc:2664
#7  0x0000000000caad42 in srv_purge_coordinator_thread (arg=0x0) at /bzr/mysql-5.6/storage/innobase/srv/srv0srv.cc:2750
#8  0x00007fe643110df3 in start_thread () from /lib64/libpthread.so.0
#9  0x00007fe641fe23dd in clone () from /lib64/libc.so.6

How to repeat:
============ Testcase
./start
./cl
mysql> SET GLOBAL INNODB_PURGE_STOP_NOW=ON;
./stop
# core will be generated and mysqladmin will not terminate correctly

============ cat start
/sda/mysql-5.6.20-linux-x86_64-debug/bin/mysqld --innodb_buffer_pool_size=2147483648 --basedir=/sda/mysql-5.6.20-linux-x86_64-debug --datadir=/sda/mysql-5.6.20-linux-x86_64-debug/data --core --socket=/sda/mysql-5.6.20-linux-x86_64-debug/socket.sock --port=17011 --log-error=/sda/mysql-5.6.20-linux-x86_64-debug/log/master.err 2>&1 &
echo 'Server socket: /sda/mysql-5.6.20-linux-x86_64-debug/socket.sock with datadir: /sda/mysql-5.6.20-linux-x86_64-debug/data'

============ cat cl
/sda/mysql-5.6.20-linux-x86_64-debug/bin/mysql -A -uroot -S/sda/mysql-5.6.20-linux-x86_64-debug/socket.sock test

============ cat stop
/sda/mysql-5.6.20-linux-x86_64-debug/bin/mysqladmin -uroot -S/sda/mysql-5.6.20-linux-x86_64-debug/socket.sock shutdown
echo 'Server on socket /sda/mysql-5.6.20-linux-x86_64-debug/socket.sock with datadir /sda/mysql-5.6.20-linux-x86_64-debug/data halted'
[14 Sep 2014 21:03] Roel Van de Paar
re: mysqladmin not terminating properly even when mysqld process is gone see bug #73914
[15 Sep 2014 7:00] Umesh Shastry
Hello Roel,

Thank you for the bug report and test case.

Thanks,
Umesh
[15 Sep 2014 7:48] Umesh Shastry
// 5.6.20

2014-09-17 01:30:22 7fd0ec939700  InnoDB: Assertion failure in thread 140535299020544 in file srv0srv.cc line 2664
InnoDB: Failing assertion: purge_sys->n_stop == 0
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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
20:00:22 UTC - mysqld got signal 6 ;

[root@cluster-repo mysql-advanced-5.6.20]# gdb bin/mysqld-debug /tmp/73913/core.26070
GNU gdb (GDB) Red Hat Enterprise Linux (7.2-64.el6_5.2)
Copyright (C) 2010 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /data/ushastry/server/mysql-advanced-5.6.20/bin/mysqld-debug...done.
[New Thread 26088]
[New Thread 26093]
[New Thread 26089]
[New Thread 26070]
[New Thread 26072]
[New Thread 26073]
[New Thread 26074]
[New Thread 26075]
[New Thread 26076]
[New Thread 26077]
[New Thread 26078]
[New Thread 26079]
[New Thread 26080]
[New Thread 26081]
[New Thread 26087]
[New Thread 26106]
Missing separate debuginfo for
Try: yum --disablerepo='*' --enablerepo='*-debug*' install /usr/lib/debug/.build-id/23/dcd11f478b82724ef49c9a495c81dff5bc8bf2
Reading symbols from /lib64/libpthread.so.0...(no debugging symbols found)...done.
[Thread debugging using libthread_db enabled]
Loaded symbols for /lib64/libpthread.so.0
Reading symbols from /lib64/libaio.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libaio.so.1
Reading symbols from /lib64/librt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/librt.so.1
Reading symbols from /lib64/libcrypt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libcrypt.so.1
Reading symbols from /lib64/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libdl.so.2
Reading symbols from /usr/lib64/libstdc++.so.6...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libstdc++.so.6
Reading symbols from /lib64/libm.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libm.so.6
Reading symbols from /lib64/libgcc_s.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libgcc_s.so.1
Reading symbols from /lib64/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libc.so.6
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /lib64/libfreebl3.so...(no debugging symbols found)...done.
Loaded symbols for /lib64/libfreebl3.so
Core was generated by `/data/ushastry/server/mysql-advanced-5.6.20/bin/mysqld-debug --innodb_buffer_po'.
Program terminated with signal 6, Aborted.
#0  0x0000003b3ba0c8ac in pthread_kill () from /lib64/libpthread.so.0
Missing separate debuginfos, use: debuginfo-install glibc-2.12-1.132.el6_5.3.x86_64 libaio-0.3.107-10.el6.x86_64 libgcc-4.4.7-4.el6.x86_64 libstdc++-4.4.7-4.el6.x86_64 nss-softokn-freebl-3.14.3-10.el6_5.x86_64
(gdb) bt
#0  0x0000003b3ba0c8ac in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000af33ce in my_write_core (sig=6) at /pb2/build/sb_0-12284633-1401293889.47/mysqlcom-pro-5.6.20/mysys/stacktrace.c:422
#2  0x0000000000776863 in handle_fatal_signal (sig=6) at /pb2/build/sb_0-12284633-1401293889.47/mysqlcom-pro-5.6.20/sql/signal_handler.cc:248
#3  <signal handler called>
#4  0x0000003b3b632925 in raise () from /lib64/libc.so.6
#5  0x0000003b3b634105 in abort () from /lib64/libc.so.6
#6  0x0000000000d1162d in srv_purge_coordinator_suspend (slot=0x3837a00, rseg_history_len=0) at /pb2/build/sb_0-12284633-1401293889.47/mysqlcom-pro-5.6.20/storage/innobase/srv/srv0srv.cc:2664
#7  0x0000000000d119b0 in srv_purge_coordinator_thread (arg=0x0) at /pb2/build/sb_0-12284633-1401293889.47/mysqlcom-pro-5.6.20/storage/innobase/srv/srv0srv.cc:2750
#8  0x0000003b3ba079d1 in start_thread () from /lib64/libpthread.so.0
#9  0x0000003b3b6e8b5d in clone () from /lib64/libc.so.6
(gdb)
[15 Sep 2014 7:48] Umesh Shastry
// 5.6.22

- error log

2014-09-17 01:59:32 7f77c25e8700  InnoDB: Assertion failure in thread 140152338810624 in file srv0srv.cc line 2666
InnoDB: Failing assertion: purge_sys->n_stop == 0
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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
20:29:32 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.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

[root@cluster-repo mysql-advanced-5.6.22]# gdb bin/mysqld-debug /tmp/73913/core.26239
GNU gdb (GDB) Red Hat Enterprise Linux (7.2-64.el6_5.2)
Copyright (C) 2010 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /data/ushastry/server/mysql-advanced-5.6.22/bin/mysqld-debug...done.
[New Thread 26255]
[New Thread 26256]
[New Thread 26260]
[New Thread 26239]
[New Thread 26240]
[New Thread 26241]
[New Thread 26242]
[New Thread 26243]
[New Thread 26244]
[New Thread 26245]
[New Thread 26254]
[New Thread 26264]
[New Thread 26249]
[New Thread 26248]
[New Thread 26246]
[New Thread 26247]
Missing separate debuginfo for
Try: yum --disablerepo='*' --enablerepo='*-debug*' install /usr/lib/debug/.build-id/23/dcd11f478b82724ef49c9a495c81dff5bc8bf2
Reading symbols from /lib64/libpthread.so.0...(no debugging symbols found)...done.
[Thread debugging using libthread_db enabled]
Loaded symbols for /lib64/libpthread.so.0
Reading symbols from /lib64/libaio.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libaio.so.1
Reading symbols from /lib64/librt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/librt.so.1
Reading symbols from /lib64/libcrypt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libcrypt.so.1
Reading symbols from /lib64/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libdl.so.2
Reading symbols from /usr/lib64/libstdc++.so.6...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libstdc++.so.6
Reading symbols from /lib64/libm.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libm.so.6
Reading symbols from /lib64/libgcc_s.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libgcc_s.so.1
Reading symbols from /lib64/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libc.so.6
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /lib64/libfreebl3.so...(no debugging symbols found)...done.
Loaded symbols for /lib64/libfreebl3.so
Core was generated by `/data/ushastry/server/mysql-advanced-5.6.22/bin/mysqld-debug --innodb_buffer_po'.
Program terminated with signal 6, Aborted.
#0  0x0000003b3ba0c8ac in pthread_kill () from /lib64/libpthread.so.0
Missing separate debuginfos, use: debuginfo-install glibc-2.12-1.132.el6_5.3.x86_64 libaio-0.3.107-10.el6.x86_64 libgcc-4.4.7-4.el6.x86_64 libstdc++-4.4.7-4.el6.x86_64 nss-softokn-freebl-3.14.3-10.el6_5.x86_64
(gdb) bt
#0  0x0000003b3ba0c8ac in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000afe982 in my_write_core (sig=6) at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/mysys/stacktrace.c:422
#2  0x000000000077e6cc in handle_fatal_signal (sig=6) at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/sql/signal_handler.cc:230
#3  <signal handler called>
#4  0x0000003b3b632925 in raise () from /lib64/libc.so.6
#5  0x0000003b3b634105 in abort () from /lib64/libc.so.6
#6  0x0000000000cdd23e in srv_purge_coordinator_suspend (slot=0x3aa1b80, rseg_history_len=0)
    at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/storage/innobase/srv/srv0srv.cc:2666
#7  0x0000000000cdd5c1 in srv_purge_coordinator_thread (arg=0x0) at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/storage/innobase/srv/srv0srv.cc:2752
#8  0x0000003b3ba079d1 in start_thread () from /lib64/libpthread.so.0
#9  0x0000003b3b6e8b5d in clone () from /lib64/libc.so.6
(gdb)
[15 Sep 2014 8:04] Umesh Shastry
// 5.7.6

2014-09-17 04:29:41 0x7fa91517f700  InnoDB: Assertion failure in thread 140364180092672 in file srv0srv.cc line 2562
InnoDB: Failing assertion: purge_sys->n_stop == 0
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.
22:59:41 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.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

(gdb) bt
#0  0x0000003b3ba0c8ac in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000e794c5 in my_write_core (sig=6) at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/mysys/stacktrace.c:247
#2  0x000000000086cb4e in handle_fatal_signal (sig=6) at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/sql/signal_handler.cc:219
#3  <signal handler called>
#4  0x0000003b3b632925 in raise () from /lib64/libc.so.6
#5  0x0000003b3b634105 in abort () from /lib64/libc.so.6
#6  0x00000000010663db in ut_dbg_assertion_failed (expr=0x15cfdbb "purge_sys->n_stop == 0",
    file=0x15cf120 "/pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/storage/innobase/srv/srv0srv.cc", line=2562)
    at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/storage/innobase/ut/ut0dbg.cc:68
#7  0x000000000101318b in srv_purge_coordinator_suspend (slot=0x267b978, rseg_history_len=0)
    at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/storage/innobase/srv/srv0srv.cc:2562
#8  0x000000000101351c in srv_purge_coordinator_thread (arg=0x0) at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/storage/innobase/srv/srv0srv.cc:2648
#9  0x0000003b3ba079d1 in start_thread () from /lib64/libpthread.so.0
#10 0x0000003b3b6e8b5d in clone () from /lib64/libc.so.6
[15 Sep 2014 8:06] Umesh Shastry
Related Bug #73914
[17 Sep 2014 17:31] Shane Bester
Actually this is not a bug. I already filed it internally and innodb devs rejected it.

See Bug 18487869 - INNODB: FAILING ASSERTION: PURGE_SYS->N_STOP == 0
[17 Sep 2014 21:26] Roel Van de Paar
Shane, thanks! What was the reason for rejection (we have no access to internal bug db)?
[18 Sep 2014 2:34] Shane Bester
"
This is expected behaviour, server should not be shutdown if purge is
stopped. There is little value in changing this behaviour unless purge
stop/start is made part of non-debug builds.
"
[16 Oct 2014 10:18] Roel Van de Paar
Bug 74418, same assert, almost same location, very different stack/test setup
[16 Oct 2014 10:26] Roel Van de Paar
Correction; same location, but likely completely different bug
[9 May 2017 6:48] Roel Van de Paar
Shane, Devs, there is something I do not understand about this bug;

> "server should not be shutdown if purge is stopped"

But the server is shutdown (debug build, not tested optimized)?

> "unless purge stop/start is made part of non-debug builds."

Could you elaborate please?

Thanks
[9 May 2017 7:24] Shane Bester
Stopping/starting innodb purge is only an option in debug builds, to make for better testing.  In non-debug builds:

mysql> SET GLOBAL INNODB_PURGE_STOP_NOW=ON;
ERROR 1193 (HY000): Unknown system variable 'INNODB_PURGE_STOP_NOW'

On debug builds, I am guessing that this is testing the assertion itself.
It should assert as that is what it is designed to do?  Sinisa/innodb devs could surely explain it better ;)