handle_fatal_signal (sig=11) in ha_innobase::open on SELECT I_S query

[Roel Van de Paar]

Thread 1 (LWP 6919):
+bt
#0 0x000000340cc0c69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000686bde in handle_fatal_signal (sig=11) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/signal_handler.cc:251
#2 <signal handler called>
#3 ha_innobase::open (this=0x7fce800252d0, name=0x7fce800ae6f8 "/ssd/209184/current1_1/tmp/#sql1ad7_9_0", mode=<optimized out>, test_if_locked=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/handler/ha_innodb.cc:4998
#4 0x00000000005b76fa in handler::ha_open (this=0x7fce800252d0, table_arg=<optimized out>, name=0x7fce800ae6f8 "/ssd/209184/current1_1/tmp/#sql1ad7_9_0", mode=7, test_if_locked=2) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/handler.cc:2478
#5 0x00000000005b9ab1 in handler::clone (this=0x7fce800a73b0, name=0x7fce800ae6f8 "/ssd/209184/current1_1/tmp/#sql1ad7_9_0", mem_root=0x20c96a8) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/handler.cc:2394
#6 0x00000000009f7ffe in ha_innobase::clone (this=0x7fce800a73b0, name=0x7fce800ae6f8 "/ssd/209184/current1_1/tmp/#sql1ad7_9_0", mem_root=0x20c96a8) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/handler/ha_innodb.cc:5344
#7 0x000000000075559d in store_temporary_table_record (thd=0x20c6080, table=0x7fce580134f0, tmp_table=0x7fce800adb00, db=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_show.cc:3958
#8 0x0000000000764b39 in fill_global_temporary_tables (thd=0x20f29c0, tables=0x7fce58005e60, cond=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_show.cc:4043
#9 0x0000000000759219 in do_fill_table (join_table=<optimized out>, table_list=0x7fce58005e60, thd=0x20f29c0) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_show.cc:7714
#10 get_schema_tables_result (join=0x7fce58018a80, executed_place=PROCESSED_BY_JOIN_EXEC) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_show.cc:7815
#11 0x0000000000746425 in JOIN::prepare_result (this=0x7fce58018a80, columns_list=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_select.cc:823
#12 0x00000000006fd211 in JOIN::exec (this=0x7fce58018a80) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_executor.cc:116
#13 0x00000000007492d0 in mysql_execute_select (free_join=true, select_lex=0x20f5498, thd=0x20f29c0) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_select.cc:1101
#14 mysql_select (thd=0x20f29c0, tables=0x7fce58005838, wild_num=1, fields=..., conds=0x7fce5800f778, order=<optimized out>, group=0x20f5598, having=0x0, select_options=2684619520, result=0x7fce58010608, unit=0x20f4e50, select_lex=0x20f5498) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_select.cc:1222
#15 0x0000000000749dbb in handle_select (thd=0x20f29c0, result=0x7fce58010608, setup_tables_done_option=0) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_select.cc:111
#16 0x000000000071ecdd in execute_sqlcom_select (thd=0x20f29c0, all_tables=0x7fce58005838) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc:5305
#17 0x00000000007217b7 in mysql_execute_command (thd=0x20f29c0) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc:2762
#18 0x0000000000727818 in mysql_parse (thd=0x20f29c0, rawbuf=0x20f4d88 "\360R7\001", length=<optimized out>, parser_state=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc:6477
#19 0x000000000072871f in dispatch_command (command=COM_QUERY, thd=0x20f29c0, packet=0x20f6951 " SELECT * FROM (test . `table1000_innodb` AS table1 RIGHT JOIN INFORMATION_SCHEMA . `GLOBAL_TEMPORARY_TABLES` AS table2 ON ( table2 . `TABLE_ROWS` = table1 . `col_bigint_not_null` ) ) WHERE ( (NOT table1 . `col_varchar_255_binary_not_null` <> table2 . `AVG_ROW_LENGTH` AND table1 . `col_bigint_not_null` <> '2001-07-03 05:17:25.054696') AND table1 . `col_set_utf8_not_null` = '2003-01-22 02:20:07.002866') LIMIT 8", packet_length=414) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc:1374
#20 0x0000000000729a47 in do_command (thd=0x20f29c0) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc:1049
#21 0x00000000006ed63f in do_handle_one_connection (thd_arg=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_connect.cc:1615
#22 0x00000000006ed727 in handle_one_connection (arg=0x20f29c0) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_connect.cc:1526
#23 0x00000000009dd6c9 in pfs_spawn_thread (arg=0x20bbdb0) at /bzr/5.6_dbg/Percona-Server-5.6.12-rc60.4/storage/perfschema/pfs.cc:1855
#24 0x000000340cc07851 in start_thread () from /lib64/libpthread.so.0
#25 0x000000340c4e890d in clone () from /lib64/libc.so.6

2013-07-20 19:24:09 6871 [Note] /ssd/Percona-Server-5.6.12-rc60.4-405-debug.Linux.x86_64/bin/mysqld: ready for connections.
Version: '5.6.12-rc60.4-debug-log' socket: '/ssd/209184/current1_1/tmp/master.sock' port: 13000 Percona Server with XtraDB (GPL), Release rc60.4, Revision 405-debug
2013-07-20 19:24:22 6871 [Note] Event Scheduler: scheduler thread started with id 10
2013-07-20 19:24:28 6871 [ERROR] /ssd/Percona-Server-5.6.12-rc60.4-405-debug.Linux.x86_64/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
2013-07-20 19:24:28 6871 [ERROR] /ssd/Percona-Server-5.6.12-rc60.4-405-debug.Linux.x86_64/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; tryrestarting transaction
16:25:52 UTC - mysqld got signal 11 ;
[...]
Some pointers may be invalid and cause the dump to abort.
Query (7fce58004c50): SELECT * FROM (test . `table1000_innodb` AS table1 RIGHT JOIN INFORMATION_SCHEMA . `GLOBAL_TEMPORARY_TABLES` AS table2 ON ( table2 . `TABLE_ROWS` = table1 . `col_bigint_not_null` ) ) WHERE ( (NOT table1 . `col_varchar_255_binary_not_null` <> table2 . `AVG_ROW_LENGTH` AND table1 . `col_bigint_not_null` <> '2001-07-03 05:17:25.054696') AND table1 . `col_set_utf8_not_null` = '2003-01-22 02:20:07.002866') LIMIT 8
Connection ID (thread ID): 18
Status: NOT_KILLED

[Roel Van de Paar (roel11)]

See bug 1113388 - comments #12 (similar non-crashing stack) + #14

[Roel Van de Paar (roel11)]

[roel@qaserver 209184]$ cat cmd217
ps -ef | grep 'cmdrun_217' | grep -v grep | awk '{print $2}' | xargs sudo kill -9
rm -Rf /ssd/209184/cmdrun_217
mkdir /ssd/209184/cmdrun_217
cd /ssd/randgen
bash -c "set -o pipefail; perl /ssd/randgen/runall.pl --queries=100000000 --seed=9627 --duration=300 --querytimeout=60 --reporter=Shutdown,Backtrace,QueryTimeout,ErrorLog,ErrorLogAlarm --mysqld=--log-output=none --mysqld=--sql_mode=ONLY_FULL_GROUP_BY --mysqld=--slow_query_log --mysqld=--userstat --threads=25 --notnull --basedir=/ssd/Percona-Server-5.6.12-rc60.4-405-debug.Linux.x86_64 --grammar=/tmp/976291/42.yy --gendata=/ssd/randgen/conf/replication/rpl_transactions_nopk.zz --mtr-build-thread=775 --mask=32738 --vardir1=/ssd/209184/cmdrun_217 > /ssd/209184/cmdrun217.log 2>&1"

[Laurynas Biveinis (laurynas-biveinis)]

This looks like it could be a duplicate of bug 1193308 covered under the same fix, but not everything adds up.

Roel, is there a core dump available for inspection?

[Roel Van de Paar (roel11)]

Adding another occurence

[Roel Van de Paar (roel11)]

==21284== Thread 62:
==21284== Invalid read of size 8
==21284== at 0xA08520: ha_innobase::open(char const*, int, unsigned int) (ha_innodb.cc:4998)
==21284== by 0x643049: handler::ha_open(TABLE*, char const*, int, int) (handler.cc:2488)
==21284== by 0x645A2A: handler::clone(char const*, st_mem_root*) (handler.cc:2402)
==21284== by 0xA0157D: ha_innobase::clone(char const*, st_mem_root*) (ha_innodb.cc:5344)
==21284== by 0x7AC60F: store_temporary_table_record(THD*, TABLE*, TABLE*, char const*) (sql_show.cc:3958)
==21284== by 0x7AC969: fill_global_temporary_tables(THD*, TABLE_LIST*, Item*) (sql_show.cc:4046)
==21284== by 0x7A74FC: do_fill_table(THD*, TABLE_LIST*, st_join_table*) (sql_show.cc:7715)
==21284== by 0x7A77E5: get_schema_tables_result(JOIN*, enum_schema_table_state) (sql_show.cc:7816)
==21284== by 0x79F284: JOIN::prepare_result(List<Item>**) (sql_select.cc:823)
==21284== by 0x7564B9: JOIN::exec() (sql_executor.cc:116)
==21284== by 0x79F697: mysql_execute_select(THD*, st_select_lex*, bool) (sql_select.cc:1101)
==21284== by 0x79FDF3: mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, SQL_I_List<st_order>*, SQL_I_List<st_order>*, Item*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) (sql_select.cc:1222)
==21284== by 0x79FFA7: handle_select(THD*, select_result*, unsigned long) (sql_select.cc:111)
==21284== by 0x7744CC: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_parse.cc:5305)
==21284== by 0x777B9D: mysql_execute_command(THD*) (sql_parse.cc:2762)
==21284== by 0x77BCB7: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:6477)
==21284== Address 0x22395010 is 32 bytes inside a block of size 8,160 free'd
==21284== at 0x4A063F0: free (vg_replace_malloc.c:446)
==21284== by 0x990D25: my_free (my_malloc.c:137)
==21284== by 0x98AD9F: free_root (my_alloc.c:383)
==21284== by 0x77C013: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1794)
==21284== by 0x77D524: do_command(THD*) (sql_parse.cc:1049)
==21284== by 0x81ADBE: threadpool_process_request(THD*) (threadpool_common.cc:312)
==21284== by 0x81D70F: handle_event(connection_t*) (threadpool_unix.cc:1466)
==21284== by 0x81D7D7: worker_main(void*) (threadpool_unix.cc:1519)
==21284== by 0x9E4D68: pfs_spawn_thread (pfs.cc:1855)
==21284== by 0x340CC07850: start_thread (in /lib64/libpthread-2.12.so)
==21284== by 0x340C4E890C: clone (in /lib64/libc-2.12.so)
==21284==
==21284== Invalid read of size 8
==21284== at 0xA08527: ha_innobase::open(char const*, int, unsigned int) (ha_innodb.cc:4998)
==21284== by 0x643049: handler::ha_open(TABLE*, char const*, int, int) (handler.cc:2488)
==21284== by 0x645A2A: handler::clone(char const*, st_mem_root*) (handler.cc:2402)
==21284== by 0xA0157D: ha_innobase::clone(char const*, st_mem_root*) (ha_innodb.cc:5344)
==21284== by 0x7AC60F: store_temporary_table_record(THD*, TABLE*, TABLE*, char const*) (sql_show.cc:3958)
==21284== by 0x7AC969: fill_global_temporary_tables(THD*, TABLE_LIST*, Item*) (sql_show.cc:4046)
==21284== by 0x7A74FC: do_fill_table(THD*, TABLE_LIST*, st_join_table*) (s...

[Roel Van de Paar (roel11)]

If the Valgrind is not related, let me know (irc) and I'll split it into a new bug. Looks related though

[Roel Van de Paar (roel11)]

(gdb)t 23
[Switching to thread 23 (LWP 21632)]
#20 0x000000000077d525 in do_command (thd=0x218aaf60) at /bzr/5.6-QA_val/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc:1049
1049 in /bzr/5.6-QA_val/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc
(gdb)f 20
#20 0x000000000077d525 in do_command (thd=0x218aaf60) at /bzr/5.6-QA_val/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc:1049
1049 in /bzr/5.6-QA_val/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc
(gdb) p thd->query_string.string.str
$1 = 0x218d1550 "SELECT * FROM (mysql . `slave_relay_log_info` AS table1 INNER JOIN INFORMATION_SCHEMA . `GLOBAL_TEMPORARY_TABLES` AS table2 ON ( table2 . `INDEX_LENGTH` = table1 . `Master_log_name` ) ) WHERE ( ( ( (NOT ( table2 . `DATA_LENGTH` = 'e' OR table1 . `Number_of_lines` > table1 . `Number_of_lines`) OR table2 . `TABLE_NAME` < table1 . `Relay_log_name`) AND table2 . `AVG_ROW_LENGTH` <> 8) OR table1 . `Number_of_lines` > table1 . `Number_of_lines`) AND table1 . `Relay_log_pos` = table1 . `Master_log_name`) LIMIT 3"

[Roel Van de Paar (roel11)]

Core and bin stored in /sde/KEEP/1205200/ for future chat with Laurynas as discussed on IRC

[Roel Van de Paar (roel11)]

Seen in 5.6 GA release branch

[Roel Van de Paar (roel11)]

Added qablock as it's seen in a fair number of runs.

[Roel Van de Paar (roel11)]

Also seen once in prospective 5.6 GA QA tree, in handler::ha_table_share_psi ... Attaching logs.

[Roel Van de Paar (roel11)]

[roel@qaserver 873186]$ cat /ssd/randgen/.bzr/branch/last-revision
894 <email address hidden>

[Roel Van de Paar (roel11)]

Also see on this query;
Query (7fdb24004d70): SELECT * FROM INFORMATION_SCHEMA.TEMPORARY_TABLES
Adding logs

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.1 because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.6 because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.5 because there has been no activity for 60 days.]

[Shahriyar Rzayev (rzayev-sehriyar)]

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