Assertion `! is_set() || m_can_overwrite_status' failed in sql_error.cc:521 | sig6 in Diagnostics_area::set_error_status

[Roel Van de Paar]

2013-12-26 06:43:22 27565 [Note] /ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld: ready for connections.
Version: '5.6.14-rel62.0-debug-log' socket: '/ssd/1387872678/subreducer/4/socket.sock' port: 42731 Percona Server with XtraDB (GPL), Release rel62.0, Revision 508-debug
2013-12-26 06:43:22 27565 [Note] Event Scheduler: scheduler thread started with id 1
mysqld: /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/sql_error.cc:521: void Diagnostics_area::set_error_status(uint, const char*, const char*, const Sql_condition*): Assertion `! is_set() || m_can_overwrite_status' failed.
19:44:07 UTC - mysqld got signal 6 ;
[...]
key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=1
max_threads=501
thread_count=2
connection_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 202782 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x368fc00

[Roel Van de Paar (roel11)]

Some Occurrences:

Query (7f94600162d0): UPDATE `table100_innodb_dynamic_int` t1, `view_table100_innodb_default_key_pk_parts_2_int_autoinc` t2 SET t1.`c26` = NULL WHERE t1.`c23` > 4513169776578658304
Connection ID (thread ID): 6
Status: NOT_KILLED

Query (7f0204014250): SET @id:=(SELECT id FROM INFORMATION_SCHEMA.PROCESSLIST WHERE ID<>CONNECTION_ID() AND STATE<>'killed' AND TIME>90 ORDER BY TIME DESC LIMIT 1)
Connection ID (thread ID): 5
Status: NOT_KILLED

Assert is sporadic, SINGLE THREADED REPRODUCIBLE, seen about 1% of the time when executing about 1.1K lines of SQL.
Always on queries above, at least as far as that testcase is concerned.

[Roel Van de Paar (roel11)]

Crashing stack from error log

/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(my_print_stacktrace+0x2e)[0x96905e]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(handle_fatal_signal+0x4a1)[0x6a64f1]
/lib64/libpthread.so.0[0x362fa0f500]
/lib64/libc.so.6(gsignal+0x35)[0x362f2328e5]
/lib64/libc.so.6(abort+0x175)[0x362f2340c5]
/lib64/libc.so.6[0x362f22ba0e]
/lib64/libc.so.6(__assert_perror_fail+0x0)[0x362f22bad0]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(Diagnostics_area::set_error_status(unsigned int, char const*, char const*, Sql_condition co
nst*)+0xfa)[0x708b5a]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(THD::raise_condition(unsigned int, char const*, Sql_condition::enum_warning_level, char con
st*)+0x2b6)[0x6f7096]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(my_message_sql+0xc0)[0x5ce030]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(my_error+0xfd)[0x9604ad]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(my_delete+0x13b)[0x9602ab]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(my_delete_with_symlink+0x56)[0x9660e6]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(mi_delete_table+0xf3)[0xc3b0a3]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(free_tmp_table(THD*, TABLE*)+0x1fd)[0x79262d]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(multi_update::~multi_update()+0xba)[0x79f08a]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(multi_update::~multi_update()+0x11)[0x79f2c1]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(mysql_execute_command(THD*)+0x35c8)[0x733f68]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(mysql_parse(THD*, char*, unsigned int, Parser_state*)+0x6b8)[0x736c38]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0xcc1)[0x737991]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(do_command(THD*)+0x17b)[0x7387ab]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(threadpool_process_request(THD*)+0x77)[0x7d76e7]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld[0x7d891f]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(pfs_spawn_thread+0x143)[0x9bbd73]
/lib64/libpthread.so.0[0x362fa07851]
/lib64/libc.so.6(clone+0x6d)[0x362f2e894d]

[Roel Van de Paar (roel11)]

Crashing stack from SET query (one above is from UPDATE query), again from error log

/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(my_print_stacktrace+0x2e)[0x96905e]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(handle_fatal_signal+0x4a1)[0x6a64f1]
/lib64/libpthread.so.0[0x362fa0f500]
/lib64/libc.so.6(gsignal+0x35)[0x362f2328e5]
/lib64/libc.so.6(abort+0x175)[0x362f2340c5]
/lib64/libc.so.6[0x362f22ba0e]
/lib64/libc.so.6(__assert_perror_fail+0x0)[0x362f22bad0]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(Diagnostics_area::set_error_status(unsigned int, char const*, char const*, Sql_condition co
nst*)+0xfa)[0x708b5a]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(THD::raise_condition(unsigned int, char const*, Sql_condition::enum_warning_level, char con
st*)+0x2b6)[0x6f7096]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(my_message_sql+0xc0)[0x5ce030]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(my_error+0xfd)[0x9604ad]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(my_delete+0x13b)[0x9602ab]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(my_delete_with_symlink+0x56)[0x9660e6]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(mi_delete_table+0xf3)[0xc3b0a3]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(free_tmp_table(THD*, TABLE*)+0x1fd)[0x79262d]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(close_thread_tables(THD*)+0x134)[0x6d7f94]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(mysql_execute_command(THD*)+0x78c)[0x73112c]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(sp_instr_stmt::exec_core(THD*, unsigned int*)+0x60)[0x87de50]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(sp_lex_instr::reset_lex_and_exec_core(THD*, unsigned int*, bool)+0x264)[0x87f804]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(sp_lex_instr::validate_lex_and_execute_core(THD*, unsigned int*, bool)+0x9b)[0x8800bb]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(sp_instr_stmt::execute(THD*, unsigned int*)+0x270)[0x880580]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(sp_head::execute(THD*, bool)+0x71b)[0x6ae98b]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(sp_head::execute_procedure(THD*, List<Item>*)+0x7e6)[0x6af566]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(Event_job_data::execute(THD*, bool)+0x604)[0x7e9f84]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(Event_worker_thread::run(THD*, Event_queue_element_for_exec*)+0x20c)[0x8cdf4c]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(event_worker_thread+0x56)[0x8ce016]
/ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld(pfs_spawn_thread+0x143)[0x9bbd73]
/lib64/libpthread.so.0[0x362fa07851]
/lib64/libc.so.6(clone+0x6d)[0x362f2e894d]

[Roel Van de Paar (roel11)]

There is limited info available atm about this crash due to where it was seen in test setup. Is the above enough to know what the issue is? See also bug 1234421

[Laurynas Biveinis (laurynas-biveinis)]

Does it reproduce if a crashing query is run manually on the datadir from the crashed RQG run?

[Roel Van de Paar (roel11)]

Further analysis on this issue.

1. Issue is confirmed sporadic
2014-09-03 23:31:48 [Init] Looking for this string: 'm_can_overwrite_status' in mysqld error log output...
[...]
2014-09-03 23:33:21 [*] [Stage V] [MULTI] Only 3 out of 20 threads reproduced the issue: this issue is sporadic
(and this is after already 10 threads were tried just before it)
2. Issue can likely be reproduced without any specific SQL. I could reproduce it using the one-line default from reducer.sh "DROP DATABASE transforms;CREATE DATABASE transforms;DROP DATABASE test;CREATE DATABASE test;USE test;" - but it is likely that not even this SQL (or all of it) is really required to reproduce the issue. It may be a general outside-of-sql-parsing issue.
3. Issue may require fast memory storage (reducer.sh uses /dev/shm by default) to reproduce - thinking race condition or something.
4. Issue does not require ANY specific mysqld parameters to be set - works on vanilla PS.
5. Issue is annoying and causes RQG runs to fail and reducer.sh runs to be cut short/be misled (due to hitting this in general-crash simplification method) - warrants adding qablock

Will now add a number of occurences for core analysis.

[Roel Van de Paar (roel11)]

Another run with what is a completely empty SQL file (so we're just talking mysqld starts and client connections).

2014-09-03 23:45:23 [*] [Stage V] [MULTI] Only 1 out of 30 threads reproduced the issue: this issue is sporadic

This is after 10, then 20 tries. So, one in 60 mysqld startups + connect should cause it. That is when the server is loaded.

[Roel Van de Paar (roel11)]

Actually, it's more then the above as reducer tries 6 times per mysqld, so it's more in the area of 1/200-400.

But, here is finally a testcase which works reasonably consistently.

[roel@localhost 598892]$ ./reducer10.sh sql.sql
2014-09-03 23:42:40 [Init] Workdir: /dev/shm/1409751760 <--- note workdir
[...]
2014-09-03 23:42:56 [Init] Looking for this string: 'm_can_overwrite_status' in mysqld error log output
[...wait for issue to reproduce... if it fails, restart reducer after rm -Rf /dev/shm/* ...]
2014-09-03 23:45:23 [] [Stage V] [MULTI] All verification subreducer threads have finished/terminated
2014-09-03 23:45:23 [*] [Stage V] [MULTI] Threads which reproduced the issue: #16
2014-09-03 23:45:23 [*] [Stage V] [MULTI] Only 1 out of 30 threads reproduced the issue: this issue is sporadic
Got it!

As soon as you see this "Got it!" you can see the occurence:

[roel@localhost 598892]$ cd /dev/shm/1409751760 <---- workdir from above
[roel@localhost 1409751760]$ grep 'm_can_overwrite_status' */*/error.log.out
mysqld: /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_error.cc:521: void Diagnostics_area::set_error_status(uint, const char*, const char*, const Sql_condition*): Assertion `! is_set() || m_can_overwrite_status' failed.

To kill all, press ctrl-c on reducer.sh then execute
ps -ef | grep mysqld | grep -v grep | awk '{print $2}' | xargs kill -9;

--core is passed in reducer10.sh so core file etc. are present in that directory found above. Uploading one set, as well as testcase files. Note that path for mysqld is set in reducer10.sh

[Roel Van de Paar (roel11)]

Use -l to find out crashed directory in question

[roel@localhost 1409752425]$ grep -l 'm_can_overwrite_status' */*/error.log.out
subreducer/5/error.log.out

[Roel Van de Paar (roel11)]

Ah. QA assertion :) There is a query which is causing it, in this case one executed by reducer.sh

Query (7fa864014250): SET @id:=(SELECT id FROM INFORMATION_SCHEMA.PROCESSLIST WHERE ID<>CONNECTION_ID() AND STATE<>'killed' AND TIME>90 ORDER BY TIME DESC LIMIT 1)

[Roel Van de Paar (roel11)]

This issue is upstream!
Bug http://bugs.mysql.com/bug.php?id=74026
Assertion `! is_set() || m_can_overwrite_status' failed.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1465