Bug #99578 Assertion "srv0start.cc line 1525"
Submitted: 14 May 2020 18:51 Modified: 15 May 2020 7:06
Reporter: Hrvoje Matijakovic Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S6 (Debug Builds)
Version:5.7.30, 5.7.34, 5.7.35 OS:Linux
Assigned to: CPU Architecture:x86

[14 May 2020 18:51] Hrvoje Matijakovic
Description:
Running the following query results in a crash on a debug build. Release build doesn't seem to be affected as `innodb_buf_flush_list_now` is only available in the debug builds

gdb from the debug build:

(gdb) bt
+bt
#0  0x00007f8b93e2eaa1 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000018cac2f in my_write_core (sig=6) at /sdc/MS-5.7.30_dbg/mysys/stacktrace.c:261
#2  0x0000000000f01107 in handle_fatal_signal (sig=6) at /sdc/MS-5.7.30_dbg/sql/signal_handler.cc:227
#3  <signal handler called>
#4  0x00007f8b91f2f387 in raise () from /lib64/libc.so.6
#5  0x00007f8b91f30a78 in abort () from /lib64/libc.so.6
#6  0x0000000001b5635b in ut_dbg_assertion_failed (expr=0x219071c "0", file=0x2190c60 "/sdc/MS-5.7.30_dbg/storage/innobase/srv/srv0start.cc", line=1323) at /sdc/MS-5.7.30_dbg/storage/innobase/ut/ut0dbg.cc:75
#7  0x0000000001af2503 in srv_shutdown_all_bg_threads () at /sdc/MS-5.7.30_dbg/storage/innobase/srv/srv0start.cc:1323
#8  0x0000000001aec34d in srv_fatal_error () at /sdc/MS-5.7.30_dbg/storage/innobase/srv/srv0srv.cc:2994
#9  0x00000000019e1b39 in os_file_handle_error_cond_exit (name=0x7f8b5602a178 "./test/../bad.ibd", operation=0x21572b9 "open", should_exit=true, on_error_silent=false) at /sdc/MS-5.7.30_dbg/storage/innobase/os/os0file.cc:5830
#10 0x00000000019e1bcd in os_file_handle_error (name=0x7f8b5602a178 "./test/../bad.ibd", operation=0x21572b9 "open") at /sdc/MS-5.7.30_dbg/storage/innobase/os/os0file.cc:5848
#11 0x00000000019dfc63 in os_file_create_func (name=0x7f8b5602a178 "./test/../bad.ibd", create_mode=51, purpose=61, type=100, read_only=false, success=0x7f8b94421fe7) at /sdc/MS-5.7.30_dbg/storage/innobase/os/os0file.cc:3630
#12 0x0000000001c3738d in pfs_os_file_create_func (key=..., name=0x7f8b5602a178 "./test/../bad.ibd", create_mode=51, purpose=61, type=100, read_only=false, success=0x7f8b94421fe7, src_file=0x21d3f98 "/sdc/MS-5.7.30_dbg/storage/innobase/fil/fil0fil.cc", src_line=903) at /sdc/MS-5.7.30_dbg/storage/innobase/include/os0file.ic:182
#13 0x0000000001c3a4dd in fil_node_open_file (node=0x7f8b56085118) at /sdc/MS-5.7.30_dbg/storage/innobase/fil/fil0fil.cc:903
#14 0x0000000001c46979 in fil_node_prepare_for_io (node=0x7f8b56085118, system=0x7f8b8bfdc618, space=0x7f8b56011598) at /sdc/MS-5.7.30_dbg/storage/innobase/fil/fil0fil.cc:5364
#15 0x0000000001c476fb in fil_io (type=..., sync=false, page_id=..., page_size=..., byte_offset=0, len=16384, buf=0x7f8b7b3b0000, message=0x7f8b7a9de8e0) at /sdc/MS-5.7.30_dbg/storage/innobase/fil/fil0fil.cc:5668
#16 0x0000000001bc96a3 in buf_dblwr_write_block_to_datafile (bpage=0x7f8b7a9de8e0, sync=false) at /sdc/MS-5.7.30_dbg/storage/innobase/buf/buf0dblwr.cc:935
#17 0x0000000001bc9d93 in buf_dblwr_flush_buffered_writes () at /sdc/MS-5.7.30_dbg/storage/innobase/buf/buf0dblwr.cc:1081
#18 0x0000000001bd3cd2 in buf_flush_end (buf_pool=0x7f8b90044b18, flush_type=BUF_FLUSH_LIST) at /sdc/MS-5.7.30_dbg/storage/innobase/buf/buf0flu.cc:1959
#19 0x0000000001bd3e81 in buf_flush_do_batch (buf_pool=0x7f8b90044b18, type=BUF_FLUSH_LIST, min_n=18446744073709551614, lsn_limit=18446744073709551615, n_processed=0x7f8b944231d8) at /sdc/MS-5.7.30_dbg/storage/innobase/buf/buf0flu.cc:2028
#20 0x0000000001bd414d in buf_flush_lists (min_n=18446744073709551614, lsn_limit=18446744073709551615, n_processed=0x0) at /sdc/MS-5.7.30_dbg/storage/innobase/buf/buf0flu.cc:2132
#21 0x0000000001bd866d in buf_flush_sync_all_buf_pools () at /sdc/MS-5.7.30_dbg/storage/innobase/buf/buf0flu.cc:3539
#22 0x000000000192fe7c in buf_flush_list_now_set (thd=0x7f8b56019000, var=0x2b81e80 <mysql_sysvar_buf_flush_list_now>, var_ptr=0x2b81814 <innodb_buf_flush_list_now>, save=0x7f8b56027ba8) at /sdc/MS-5.7.30_dbg/storage/innobase/handler/ha_innodb.cc:19071
#23 0x00000000015c0795 in sys_var_pluginvar::global_update (this=0x7f8b863ea990, thd=0x7f8b56019000, var=0x7f8b56027b88) at /sdc/MS-5.7.30_dbg/sql/sql_plugin.cc:3722
#24 0x00000000014ca04e in sys_var::update (this=0x7f8b863ea990, thd=0x7f8b56019000, var=0x7f8b56027b88) at /sdc/MS-5.7.30_dbg/sql/set_var.cc:190
#25 0x00000000014cb726 in set_var::update (this=0x7f8b56027b88, thd=0x7f8b56019000) at /sdc/MS-5.7.30_dbg/sql/set_var.cc:829
#26 0x00000000014cb014 in sql_set_variables (thd=0x7f8b56019000, var_list=0x7f8b5601b6f8) at /sdc/MS-5.7.30_dbg/sql/set_var.cc:669
#27 0x000000000158fc0c in mysql_execute_command (thd=0x7f8b56019000, first_level=true) at /sdc/MS-5.7.30_dbg/sql/sql_parse.cc:3717
#28 0x0000000001594f4f in mysql_parse (thd=0x7f8b56019000, parser_state=0x7f8b944244f0) at /sdc/MS-5.7.30_dbg/sql/sql_parse.cc:5584
#29 0x000000000158a6d4 in dispatch_command (thd=0x7f8b56019000, com_data=0x7f8b94424c90, command=COM_QUERY) at /sdc/MS-5.7.30_dbg/sql/sql_parse.cc:1491
#30 0x00000000015895fa in do_command (thd=0x7f8b56019000) at /sdc/MS-5.7.30_dbg/sql/sql_parse.cc:1032
#31 0x00000000016bac2e in handle_connection (arg=0x7f8b69348a40) at /sdc/MS-5.7.30_dbg/sql/conn_handler/connection_handler_per_thread.cc:313
#32 0x0000000001d62b98 in pfs_spawn_thread (arg=0x7f8b7a7c1c20) at /sdc/MS-5.7.30_dbg/storage/perfschema/pfs.cc:2197
#33 0x00007f8b93e29ea5 in start_thread () from /lib64/libpthread.so.0
#34 0x00007f8b91ff78dd in clone () from /lib64/libc.so.6

How to repeat:
CREATE DATABASE test;
CREATE TABLESPACE bad ADD DATAFILE './test/../bad.ibd';
DROP DATABASE test;
set global innodb_buf_flush_list_now=1;
[15 May 2020 7:06] MySQL Verification Team
Hello Hrvoje Matijakovic,

Thank you for the bug report and test case.
Observed that 5.7.30 debug build is affected.

regards,
Umesh
[29 Sep 2021 11:30] MySQL Verification Team
- Pls ignore earlier messages, I can see the issue on 5.7.35 debug build as well.

rm -rf 99578/
bin/mysqld-debug --initialize-insecure --basedir=$PWD --datadir=$PWD/99578 --log-error-verbosity=3
bin/mysqld-debug --no-defaults --basedir=$PWD --datadir=$PWD/99578 --core-file --socket=/tmp/mysql_ushastry.sock --port=3333 --log-error=$PWD/99578/log.err --log-error-verbosity=3 --secure-file-priv="" --skip-name-resolve --performance-schema=ON 2>&1 &

[umshastr@support-el8:~/work/binaries/ga/mysql-5.7.35]$ bin/mysql -uroot -S /tmp/mysql_ushastry.sock
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.7.35-debug MySQL Community Server - Debug (GPL)

Copyright (c) 2000, 2021, Oracle and/or its affiliates.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> CREATE DATABASE test;
Query OK, 1 row affected (0.02 sec)

mysql> CREATE TABLESPACE bad ADD DATAFILE './test/../bad.ibd';
Query OK, 0 rows affected (0.03 sec)

mysql> DROP DATABASE test;
Query OK, 0 rows affected (0.02 sec)

mysql> set global innodb_buf_flush_list_now=1;
^C^Z
[2]+  Stopped                 bin/mysql -uroot -S /tmp/mysql_ushastry.sock
[umshastr@support-el8:~/work/binaries/ga/mysql-5.7.35]$
[umshastr@support-el8:~/work/binaries/ga/mysql-5.7.35]$
[umshastr@support-el8:~/work/binaries/ga/mysql-5.7.35]$ bin/mysql -uroot -S /tmp/mysql_ushastry.sock
ERROR 2013 (HY000): Lost connection to MySQL server at 'reading initial communication packet', system error: 95
[umshastr@support-el8:~/work/binaries/ga/mysql-5.7.35]$
[1]-  Aborted                 (core dumped) bin/mysqld-debug --no-defaults --basedir=$PWD --datadir=$PWD/99578 --core-file --socket=/tmp/mysql_ushastry.sock --port=3333 --log-error=$PWD/99578/log.err --log-error-verbosity=3 --secure-file-priv="" --skip-name-resolve --performance-schema=ON 2>&1
[umshastr@support-el8:~/work/binaries/ga/mysql-5.7.35]$

-bt
(gdb) bt
#0  0x00007f623b0aca55 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000019182d5 in my_write_core (sig=6) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/mysys/stacktrace.c:261
#2  0x0000000000f0476d in handle_fatal_signal (sig=6) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/sql/signal_handler.cc:227
#3  <signal handler called>
#4  0x00007f623999d8df in raise () from /lib64/libc.so.6
#5  0x00007f6239987cf5 in abort () from /lib64/libc.so.6
#6  0x0000000001cf8d8b in ut_dbg_assertion_failed (expr=0x24c5a0c "0", file=0x24c5f78 "/var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/srv/srv0start.cc", line=1323)
    at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/ut/ut0dbg.cc:75
#7  0x0000000001c94314 in srv_shutdown_all_bg_threads () at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/srv/srv0start.cc:1323
#8  0x0000000001c8db44 in srv_fatal_error () at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/srv/srv0srv.cc:3002
#9  0x0000000001b8296c in os_file_handle_error_cond_exit (name=0x4e0b438 "./test/../bad.ibd", operation=0x2488329 "open", should_exit=true, on_error_silent=false)
    at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/os/os0file.cc:5832
#10 0x0000000001b829ab in os_file_handle_error (name=0x4e0b438 "./test/../bad.ibd", operation=0x2488329 "open") at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/os/os0file.cc:5850
#11 0x0000000001b80a20 in os_file_create_func (name=0x4e0b438 "./test/../bad.ibd", create_mode=51, purpose=61, type=100, read_only=false, success=0x7f6230230917)
    at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/os/os0file.cc:3632
#12 0x0000000001ddb946 in pfs_os_file_create_func (key=..., name=0x4e0b438 "./test/../bad.ibd", create_mode=51, purpose=61, type=100, read_only=false, success=0x7f6230230917,
    src_file=0x250e6b8 "/var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/fil/fil0fil.cc", src_line=903) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/include/os0file.ic:182
#13 0x0000000001ddebf1 in fil_node_open_file (node=0x4e0c098) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/fil/fil0fil.cc:903
#14 0x0000000001deb49a in fil_node_prepare_for_io (node=0x4e0c098, system=0x459b1d8, space=0x4e0bd38) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/fil/fil0fil.cc:5360
#15 0x0000000001dec1c5 in fil_io (type=..., sync=false, page_id=..., page_size=..., byte_offset=0, len=16384, buf=0x7f62244bc000, message=0x7f62239ebc58)
    at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/fil/fil0fil.cc:5664
#16 0x0000000001d6d977 in buf_dblwr_write_block_to_datafile (bpage=0x7f62239ebc58, sync=false) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/buf/buf0dblwr.cc:935
#17 0x0000000001d6e147 in buf_dblwr_flush_buffered_writes () at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/buf/buf0dblwr.cc:1081
#18 0x0000000001d78189 in buf_flush_end (buf_pool=0x459b818, flush_type=BUF_FLUSH_LIST) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/buf/buf0flu.cc:1966
#19 0x0000000001d78343 in buf_flush_do_batch (buf_pool=0x459b818, type=BUF_FLUSH_LIST, min_n=18446744073709551614, lsn_limit=18446744073709551615, n_processed=0x7f6230231bb8)
    at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/buf/buf0flu.cc:2035
#20 0x0000000001d785ec in buf_flush_lists (min_n=18446744073709551614, lsn_limit=18446744073709551615, n_processed=0x0) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/buf/buf0flu.cc:2139
#21 0x0000000001d7c931 in buf_flush_sync_all_buf_pools () at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/buf/buf0flu.cc:3558
#22 0x0000000001ad18f2 in buf_flush_list_now_set (thd=0x4d7ee80, var=0x2f5d280 <mysql_sysvar_buf_flush_list_now>, var_ptr=0x2f5cc1c <innodb_buf_flush_list_now>, save=0x4d94f28)
    at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/innobase/handler/ha_innodb.cc:19118
#23 0x00000000015f870f in sys_var_pluginvar::global_update (this=0x42862a8, thd=0x4d7ee80, var=0x4d94f08) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/sql/sql_plugin.cc:3722
#24 0x00000000014fb056 in sys_var::update (this=0x42862a8, thd=0x4d7ee80, var=0x4d94f08) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/sql/set_var.cc:201
#25 0x00000000014fca48 in set_var::update (this=0x4d94f08, thd=0x4d7ee80) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/sql/set_var.cc:897
#26 0x00000000014fc19d in sql_set_variables (thd=0x4d7ee80, var_list=0x4d813f8) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/sql/set_var.cc:715
#27 0x00000000015c6edb in mysql_execute_command (thd=0x4d7ee80, first_level=true) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/sql/sql_parse.cc:3718
#28 0x00000000015cc9f4 in mysql_parse (thd=0x4d7ee80, parser_state=0x7f6230233610) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/sql/sql_parse.cc:5597
#29 0x00000000015c1151 in dispatch_command (thd=0x4d7ee80, com_data=0x7f6230233de0, command=COM_QUERY) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/sql/sql_parse.cc:1491
#30 0x00000000015bfdfa in do_command (thd=0x4d7ee80) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/sql/sql_parse.cc:1032
#31 0x00000000016f9cb5 in handle_connection (arg=0x4f83590) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/sql/conn_handler/connection_handler_per_thread.cc:313
#32 0x0000000001f00ba0 in pfs_spawn_thread (arg=0x4d54c50) at /var/lib/pb2/sb_1-3452660-1623075169.27/mysql-5.7.35/storage/perfschema/pfs.cc:2197
#33 0x00007f623b0a52de in start_thread () from /lib64/libpthread.so.0
#34 0x00007f6239a62143 in clone () from /lib64/libc.so.6
(gdb)