| Bug #77976 | InnoDB: Failing assertion: event in file os0sync.cc line 419 | ||
|---|---|---|---|
| Submitted: | 7 Aug 2015 9:08 | Modified: | 22 Sep 2017 14:35 |
| Reporter: | Ramesh Sivaraman | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: Options | Severity: | S3 (Non-critical) |
| Version: | 5.6.23, 5.6.26, 5.6.37 | OS: | CentOS (CentOS 7) |
| Assigned to: | CPU Architecture: | Any | |
[7 Aug 2015 9:11]
Ramesh Sivaraman
Testcase bundle
Attachment: 1438934015_bug_bundle.tar.gz (application/gzip, text), 1004.45 KiB.
[7 Aug 2015 10:00]
MySQL Verification Team
Hello Ramesh, Thank you for the report. Observed that 5.6.26 debug build is affected. Thanks, Umesh
[7 Aug 2015 10:00]
MySQL Verification Team
test results
Attachment: 77976_5.6.26.results (application/octet-stream, text), 19.54 KiB.
[7 Aug 2015 10:01]
MySQL Verification Team
// 5.6.26/5.6.27 tarball binary builds(tried both release and debug) but couldn't see the crash reported
[7 Aug 2015 20:25]
Roel Van de Paar
Umesh, please also check against 5.7
[20 Feb 2017 3:53]
Roel Van de Paar
Likely related to bug 85067
[21 Feb 2017 5:59]
MySQL Verification Team
This issue is no longer seen with 5.6.35(release/debug builds), could you please confirm if you are still seeing this?
[22 Mar 2017 1:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
[23 Mar 2017 7:31]
Ramesh Sivaraman
Could not reproduce the issue with 5.6.35
[23 Mar 2017 7:32]
Ramesh Sivaraman
Closing this issue
[22 Sep 2017 14:04]
Calvin Wong
testcase
Attachment: 1506004727_bug_bundle.tar.gz (application/gzip, text), 2.84 MiB.
[22 Sep 2017 14:07]
Calvin Wong
I reproduced the same issue on 5.6.37, test bundle is uploaded Calvin
[22 Sep 2017 14:17]
Calvin Wong
/usr/local/5.6-optimzed/bin/mysqld(my_print_stacktrace+0x2c)[0x901aac]
/usr/local/5.6-optimzed/bin/mysqld(handle_fatal_signal+0x357)[0x673237]
/lib64/libpthread.so.0(+0xf370)[0x7fa29fa0d370]
/lib64/libc.so.6(gsignal+0x37)[0x7fa29e80e1d7]
/lib64/libc.so.6(abort+0x148)[0x7fa29e80f8c8]
/usr/local/5.6-optimzed/bin/mysqld[0x96b4a0]
/usr/local/5.6-optimzed/bin/mysqld(_ZN17sys_var_pluginvar13global_updateEP3THDP7set_var+0x70)[0x703a70]
/usr/local/5.6-optimzed/bin/mysqld(_ZN7set_var6updateEP3THD+0x6a)[0x6722ca]
/usr/local/5.6-optimzed/bin/mysqld(_Z17sql_set_variablesP3THDP4ListI12set_var_baseE+0x71)[0x672ae1]
/usr/local/5.6-optimzed/bin/mysqld(_Z21mysql_execute_commandP3THD+0x3a90)[0x6fafb0]
/usr/local/5.6-optimzed/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x408)[0x6fd228]
/usr/local/5.6-optimzed/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xe5e)[0x6fe6be]
/usr/local/5.6-optimzed/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x1fd)[0x6c5ecd]
/usr/local/5.6-optimzed/bin/mysqld(handle_one_connection+0x39)[0x6c5f19]
/usr/local/5.6-optimzed/bin/mysqld(pfs_spawn_thread+0x143)[0xb44853]
/lib64/libpthread.so.0(+0x7dc5)[0x7fa29fa05dc5]
/lib64/libc.so.6(clone+0x6d)[0x7fa29e8d073d]
The codes are triggered because of the following statement
SET GLOBAL innodb_buffer_pool_load_now=ON;
From the stack, sys_var_pluginvar::global_update calls plugin_var->update which is a function pointer. From gdb this function pointer is buffer_pool_load_now, which ultimately calls buf_load_start->os_event with srv_buf_dump_event as the parameter.
(gdb) p plugin_var->update
$3 = (mysql_var_update_func) 0x920460 <buffer_pool_load_now(THD*, st_mysql_sys_var*, void*, void const*)>
srv_buf_dump_event is null so that trips the assert.
(gdb) p srv_buf_dump_event
$5 = (os_event_t) 0x0
srv_buf_dump_event is initialized here:
UNIV_INTERN
void
srv_init(void)
/*==========*/
{
...
if (!srv_read_only_mode) {
...
srv_buf_dump_event = os_event_create();
UT_LIST_INIT(srv_sys->tasks);
}
The server is in read only mode, so srv_buf_dump_event was never initialized.
(gdb) p srv_read_only_mode
$8 = 1 '\001'
The server is only set to read only when force_recovery is set to SRV_FORCE_NO_LOG_REDO. From the mysqld settings, innodb-force-recovery has been set to 2047, which gets capped to 6 internally since 6 is the max valid setting.
UNIV_INTERN
dberr_t
innobase_start_or_create_for_mysql(void)
/*====================================*/
{
...
if (srv_force_recovery == SRV_FORCE_NO_LOG_REDO) {
srv_read_only_mode = 1;
}
}
enum {
...
SRV_FORCE_NO_LOG_REDO = 6 /*!< do not do the log roll-forward
in connection with recovery */
};
--innodb-force-recovery=2047
So I think both a combination of setting innodb-force-recovery >= 6 and innodb_buffer_pool_load_now=ON would trigger the core dump.
Calvin
[22 Sep 2017 14:35]
MySQL Verification Team
## 5.6.37
[umshastr@hod03]/export/umesh/server/binaries/GABuilds/mysql-5.6.37/mysql-test: ./mtr --mysqld='--innodb-force-recovery=6' 77976
Logging: ./mtr --mysqld=--innodb-force-recovery=6 77976
2017-09-22 16:33:30 0 [Warning] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.
2017-09-22 16:33:30 0 [Note] /export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld (mysqld 5.6.37) starting as process 7294 ...
2017-09-22 16:33:31 7294 [Note] Plugin 'FEDERATED' is disabled.
2017-09-22 16:33:31 7294 [Note] Binlog end
2017-09-22 16:33:31 7294 [Note] Shutting down plugin 'CSV'
2017-09-22 16:33:31 7294 [Note] Shutting down plugin 'MyISAM'
MySQL Version 5.6.37
Checking supported features...
- SSL connections supported
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory '/export/umesh/server/binaries/GABuilds/mysql-5.6.37/mysql-test/var'...
Installing system database...
Using parallel: 1
==============================================================================
TEST RESULT TIME (ms) or COMMENT
--------------------------------------------------------------------------
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
DROP DATABASE test;
CREATE DATABASE test;
USE test;
main.77976 [ fail ]
Test ended at 2017-09-22 16:33:33
CURRENT_TEST: main.77976
mysqltest: At line 4: query 'SET GLOBAL innodb_buffer_pool_load_now=ON' failed: 2013: Lost connection to MySQL server during query
.
.
/export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld: ready for connections.
Version: '5.6.37-log' socket: '/export/umesh/server/binaries/GABuilds/mysql-5.6.37/mysql-test/var/tmp/mysqld.1.sock' port: 13000 MySQL Community Server (GPL)
2017-09-22 17:33:33 7fac3b0d4700 InnoDB: Assertion failure in thread 140377701828352 in file os0sync.cc line 419
InnoDB: Failing assertion: event
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.
14:33:33 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.
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=1
max_threads=151
thread_count=1
connection_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 60940 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
Thread pointer: 0x33ae1b0
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 = 7fac3b0d3e98 thread_stack 0x40000
/export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld(my_print_stacktrace+0x35)[0x8d6f55]
/export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld(handle_fatal_signal+0x494)[0x664af4]
/lib64/libpthread.so.0(+0xf130)[0x7fac4280a130]
/lib64/libc.so.6(gsignal+0x37)[0x7fac412015d7]
/lib64/libc.so.6(abort+0x148)[0x7fac41202cc8]
/export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld[0x942144]
/export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld(_ZN17sys_var_pluginvar13global_updateEP3THDP7set_var+0x55)[0x6edf45]
/export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld(_ZN7sys_var6updateEP3THDP7set_var+0x69)[0x663b79]
/export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld(_ZN7set_var6updateEP3THD+0x17)[0x6640b7]
/export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld(_Z17sql_set_variablesP3THDP4ListI12set_var_baseE+0x89)[0x6633a9]
/export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld(_Z21mysql_execute_commandP3THD+0x100d)[0x6e080d]
/export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x378)[0x6e4598]
/export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x110e)[0x6e574e]
/export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld(_Z24do_handle_one_connectionP3THD+0xcf)[0x6b1d4f]
/export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld(handle_one_connection+0x47)[0x6b1e77]
/export/umesh/server/binaries/GABuilds/mysql-5.6.37/bin/mysqld(pfs_spawn_thread+0x12d)[0xb0921d]
/lib64/libpthread.so.0(+0x7df5)[0x7fac42802df5]
/lib64/libc.so.6(clone+0x6d)[0x7fac412c260d]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7fac2c004f50): SET GLOBAL innodb_buffer_pool_load_now=ON
Connection ID (thread ID): 2
Status: NOT_KILLED
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.
Writing a core file
----------SERVER LOG END-------------
- saving '/export/umesh/server/binaries/GABuilds/mysql-5.6.37/mysql-test/var/log/main.77976/' to '/export/umesh/server/binaries/GABuilds/mysql-5.6.37/mysql-test/var/log/main.77976/'
- found 'core.7320' (0/5)
Trying 'dbx' to get a backtrace
Description: When we start mysql server with --innodb-force-recovery=6 option, SET GLOBAL innodb_buffer_pool_load_now=ON statement crashing server. GDB #0 0x00007f09e70b1771 in pthread_kill () from /lib64/libpthread.so.0 #1 0x000000000066c05d in handle_fatal_signal (sig=6) at /sda/mysql-server-5.6/sql/signal_handler.cc:230 #2 <signal handler called> #3 0x00007f09e5ebd5d7 in raise () from /lib64/libc.so.6 #4 0x00007f09e5ebecc8 in abort () from /lib64/libc.so.6 #5 0x0000000000996e57 in os_event_set (event=0x0) at /sda/mysql-server-5.6/storage/innobase/os/os0sync.cc:419 #6 0x00000000006f5f20 in sys_var_pluginvar::global_update (this=0x7f09e07fd7b8, thd=0x7f09d6b78000, var=<optimized out>) at /sda/mysql-server-5.6/sql/sql_plugin.cc:3267 #7 0x000000000066ab08 in sys_var::update (this=0x7f09e07fd7b8, thd=0x7f09d6b78000, var=0x7f09d201d1a8) at /sda/mysql-server-5.6/sql/set_var.cc:193 #8 0x000000000066af37 in set_var::update (this=<optimized out>, thd=<optimized out>) at /sda/mysql-server-5.6/sql/set_var.cc:670 #9 0x000000000066b7a1 in sql_set_variables (thd=thd@entry=0x7f09d6b78000, var_list=var_list@entry=0x7f09d6b7aa48) at /sda/mysql-server-5.6/sql/set_var.cc:573 #10 0x00000000006e8371 in mysql_execute_command (thd=thd@entry=0x7f09d6b78000) at /sda/mysql-server-5.6/sql/sql_parse.cc:3720 #11 0x00000000006eb328 in mysql_parse (thd=thd@entry=0x7f09d6b78000, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f09e767a6f0) at /sda/mysql-server-5.6/sql/sql_parse.cc:6386 #12 0x00000000006ecac3 in dispatch_command (command=COM_QUERY, thd=0x7f09d6b78000, packet=<optimized out>, packet_length=<optimized out>) at /sda/mysql-server-5.6/sql/sql_parse.cc:1340 #13 0x00000000006ee7b4 in do_command (thd=<optimized out>) at /sda/mysql-server-5.6/sql/sql_parse.cc:1037 #14 0x00000000006ba7f2 in do_handle_one_connection (thd_arg=thd_arg@entry=0x7f09d6b78000) at /sda/mysql-server-5.6/sql/sql_connect.cc:982 #15 0x00000000006ba8a0 in handle_one_connection (arg=arg@entry=0x7f09d6b78000) at /sda/mysql-server-5.6/sql/sql_connect.cc:898 #16 0x0000000000b120c3 in pfs_spawn_thread (arg=0x7f09e43ecc00) at /sda/mysql-server-5.6/storage/perfschema/pfs.cc:1860 #17 0x00007f09e70acdf5 in start_thread () from /lib64/libpthread.so.0 #18 0x00007f09e5f7e1ad in clone () from /lib64/libc.so.6 How to repeat: Testcase DROP DATABASE test;CREATE DATABASE test;USE test; SET GLOBAL innodb_buffer_pool_load_now=ON; The attached tarball gives the testcase as an exact match of our system, including some handy utilities $ vi {epoch}_mybase # Update base path in this file (the only change required!). For non-binary distribution please update SOURCE_DIR location also. $ ./{epoch}_init # Initializes the data dir $ ./{epoch}_start # Starts mysqld $ ./{epoch}_cl # To check mysqld is up $ ./{epoch}_run # Run the testcase with pquery binary(produces output) $ vi /dev/shm/{epoch}/error.log.out # Verify the error log $ ./{epoch}_gdb # Brings you to a gdb prompt attached to correct mysqld & generated core $ ./{epoch}_parse_core # Create {epoch}_STD.gdb and {epoch}_FULL.gdb; standard and full var gdb stack traces etc.