Bug #91973 InnoDB: Assertion failure: srv0start.cc:1482:0
Submitted: 10 Aug 2018 22:53 Modified: 21 Sep 2018 14:11
Reporter: Roel Van de Paar (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S6 (Debug Builds)
Version:8.0.12 OS:Any
Assigned to: CPU Architecture:Any
Tags: debug

[10 Aug 2018 22:53] Roel Van de Paar
Description:
8.0.12 on shutdown: 

Core was generated by `/sda/MS300718-mysql-8.0.12-linux-x86_64-debug/bin/mysqld --no-defaults --core-f'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
[Current thread is 1 (Thread 0x7f3d723da880 (LWP 18994))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x000055904de5078d in my_write_core (sig=6) at /git/MS-8.0.12_dbg/mysys/stacktrace.cc:278
#2  0x000055904cba4d94 in handle_fatal_signal (sig=6) at /git/MS-8.0.12_dbg/sql/signal_handler.cc:249
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5  0x00007f3d7038d801 in __GI_abort () at abort.c:79
#6  0x000055904e23a239 in ut_dbg_assertion_failed (expr=0x55904f48d62c "0", 
    file=0x55904f48dfd8 "/git/MS-8.0.12_dbg/storage/innobase/srv/srv0start.cc", line=1482)
    at /git/MS-8.0.12_dbg/storage/innobase/ut/ut0dbg.cc:90
#7  0x000055904e1c1f45 in srv_shutdown_all_bg_threads () at /git/MS-8.0.12_dbg/storage/innobase/srv/srv0start.cc:1482
#8  0x000055904e1c623b in srv_shutdown () at /git/MS-8.0.12_dbg/storage/innobase/srv/srv0start.cc:3044
#9  0x000055904df6a833 in innodb_shutdown () at /git/MS-8.0.12_dbg/storage/innobase/handler/ha_innodb.cc:1283
#10 0x000055904cd233e0 in ha_finalize_handlerton (plugin=0x7f3d5d31a210) at /git/MS-8.0.12_dbg/sql/handler.cc:711
#11 0x000055904ca24ff8 in plugin_deinitialize (plugin=0x7f3d5d31a210, ref_check=true) at /git/MS-8.0.12_dbg/sql/sql_plugin.cc:1025
#12 0x000055904ca256fd in reap_plugins () at /git/MS-8.0.12_dbg/sql/sql_plugin.cc:1101
#13 0x000055904ca2830b in plugin_shutdown () at /git/MS-8.0.12_dbg/sql/sql_plugin.cc:1857
#14 0x000055904c88f139 in clean_up (print_message=true) at /git/MS-8.0.12_dbg/sql/mysqld.cc:2003
#15 0x000055904c89e0ca in mysqld_main (argc=11, argv=0x7f3d6f846120) at /git/MS-8.0.12_dbg/sql/mysqld.cc:6431
#16 0x000055904c88bb9a in main (argc=11, argv=0x7ffffed36d08) at /git/MS-8.0.12_dbg/sql/main.cc:30

2018-08-10T21:32:42.844689Z 10 [System] [MY-013172] [Server] Received SHUTDOWN from user root. Shutting down mysqld (Version: 8.0.12-debug).
2018-08-10T21:34:23.553479Z 0 [Warning] [MY-012928] [InnoDB] InnoDB: 2 threads created by InnoDB had not exited at shutdown!
Pending normal aio reads: 0
Pending normal aio writes: 0
Pending ibuf aio reads: 0
Pending log i/o's: 0
Pending sync i/o's: 0
2018-08-10T21:34:23.553570Z 0 [ERROR] [MY-000000] [InnoDB] InnoDB: Assertion failure: srv0start.cc:1482:0
InnoDB: thread 139901886376064

5.7.21 on startup: 

2018-08-10T22:45:15.921217Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-08-10T22:45:15.933873Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
  ---- Hangs at this point of the log (i.e. the next message is never shown, it is just shown here as an example of where it hangs)
2018-08-10T22:45:15.989040Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables

How to repeat:
Start mysqld with --innodb-spin-wait-delay=1125899906842624 then shutdown mysqld using mysqladmin shutdown (8.0.12). The failure to shutdown in certain configuration situations where a startup is successful is a bug.
[10 Aug 2018 23:32] Miguel Solorzano
Thank you for the bug report. Repeatable only with debug build:

miguel@izalco:~/dbs/8.0 $ bin/mysqld --innodb-spin-wait-delay=1125899906842624
]2018-08-10T23:15:22.546963Z 0 [Warning] [MY-010139] [Server] Changed limits: max_open_files: 1024 (requested 8161)
2018-08-10T23:15:22.547057Z 0 [Warning] [MY-010142] [Server] Changed limits: table_open_cache: 431 (requested 4000)
2018-08-10T23:15:22.756016Z 0 [System] [MY-010116] [Server] /home/miguel/dbs/8.0/bin/mysqld (mysqld 8.0.13) starting as process 7964
2018-08-10T23:15:25.653634Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2018-08-10T23:15:25.807693Z 0 [System] [MY-010931] [Server] /home/miguel/dbs/8.0/bin/mysqld: ready for connections. Version: '8.0.13'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution BUILD: 2018-JUL-20.
2018-08-10T23:15:26.137908Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: '/tmp/mysqlx.sock' bind-address: '::' port: 33060
2018-08-10T23:18:16.920459Z 8 [System] [MY-013172] [Server] Received SHUTDOWN from user root. Shutting down mysqld (Version: 8.0.13).
2018-08-10T23:18:18.934975Z 0 [System] [MY-010910] [Server] /home/miguel/dbs/8.0/bin/mysqld: Shutdown complete (mysqld 8.0.13)  Source distribution BUILD: 2018-JUL-20.
miguel@izalco:~/dbs/8.0 $ cd
miguel@izalco:~ $ cd dbsd/8.0/
miguel@izalco:~/dbsd/8.0 $ bin/mysqld --innodb-spin-wait-delay=1125899906842624
2018-08-10T23:27:54.844675Z 0 [Warning] [MY-010139] [Server] Changed limits: max_open_files: 1024 (requested 8161)
2018-08-10T23:27:54.855413Z 0 [Warning] [MY-010142] [Server] Changed limits: table_open_cache: 431 (requested 4000)
2018-08-10T23:27:55.174371Z 0 [System] [MY-010116] [Server] /home/miguel/dbsd/8.0/bin/mysqld (mysqld 8.0.13-debug) starting as process 8301
2018-08-10T23:27:59.488480Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2018-08-10T23:27:59.702369Z 0 [System] [MY-010931] [Server] /home/miguel/dbsd/8.0/bin/mysqld: ready for connections. Version: '8.0.13-debug'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution BUILD: 2018-JUL-20.
2018-08-10T23:27:59.964982Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: '/tmp/mysqlx.sock' bind-address: '::' port: 33060
2018-08-10T23:28:09.977333Z 8 [System] [MY-013172] [Server] Received SHUTDOWN from user root. Shutting down mysqld (Version: 8.0.13-debug).
2018-08-10T23:29:52.074733Z 0 [Warning] [MY-012928] [InnoDB] 1 threads created by InnoDB had not exited at shutdown!
Pending normal aio reads: 0
Pending normal aio writes: 0
Pending ibuf aio reads: 0
Pending log i/o's: 0
Pending sync i/o's: 0
2018-08-10T23:29:52.074848Z 0 [ERROR] [MY-013183] [InnoDB] Assertion failure: srv0start.cc:1485:0 thread 140583611677056
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.
23:29:52 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=1
max_threads=151
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 67870 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

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...
stack_bottom = 0 thread_stack 0x46000
/home/miguel/dbsd/8.0/bin/mysqld(my_print_stacktrace(unsigned char*, unsigned long)+0x43) [0x4148f2c]
/home/miguel/dbsd/8.0/bin/mysqld(handle_fatal_signal+0x3f5) [0x2f1d23e]
/lib64/libpthread.so.0(+0xf6d0) [0x7fdc2bfce6d0]
/lib64/libc.so.6(gsignal+0x37) [0x7fdc2a2e5277]
/lib64/libc.so.6(abort+0x148) [0x7fdc2a2e6968]
/home/miguel/dbsd/8.0/bin/mysqld(ut_dbg_assertion_failed(char const*, char const*, unsigned long)+0x187) [0x450a010]
/home/miguel/dbsd/8.0/bin/mysqld(srv_shutdown_all_bg_threads()+0x2a1) [0x4494093]
/home/miguel/dbsd/8.0/bin/mysqld(srv_shutdown()+0xbe) [0x4498100]
/home/miguel/dbsd/8.0/bin/mysqld() [0x4256496]
/home/miguel/dbsd/8.0/bin/mysqld(ha_finalize_handlerton(st_plugin_int*)+0xc3) [0x308aaaa]
/home/miguel/dbsd/8.0/bin/mysqld() [0x2da80ec]
/home/miguel/dbsd/8.0/bin/mysqld() [0x2da87ae]
/home/miguel/dbsd/8.0/bin/mysqld(plugin_shutdown()+0x86) [0x2dab196]
/home/miguel/dbsd/8.0/bin/mysqld() [0x2c080a4]
/home/miguel/dbsd/8.0/bin/mysqld(mysqld_main(int, char**)+0x31d1) [0x2c17391]
/home/miguel/dbsd/8.0/bin/mysqld(main+0x20) [0x2c04d1d]
/lib64/libc.so.6(__libc_start_main+0xf5) [0x7fdc2a2d1445]
/home/miguel/dbsd/8.0/bin/mysqld() [0x2c04c39]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
miguel@izalco:~/dbsd/8.0 $
[21 Sep 2018 14:11] Daniel Price
Posted by developer:
 
Fixed as of the upcoming 8.0.14 release, and here's the changelog entry:

Setting innodb_spin_wait_delay to a high value caused an assertion
failure when attempting to shut down the server. To prevent this failure
from occurring, the innodb_spin_wait_delay maximum value was reduced to
1000.