[MDEV-10826] Assertion `thd->get_stmt_da()->is_eof()' failed in Query_cache::end_of_result Created: 2016-09-17  Updated: 2024-01-05

Status: Confirmed
Project: MariaDB Server
Component/s: Query Cache
Affects Version/s: 10.1, 10.2, 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10, 11.1, 11.3, 11.4
Fix Version/s: 10.4, 10.5, 10.6, 11.1, 11.3

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Oleksandr Byelkin
Resolution: Unresolved Votes: 1
Labels: affects-tests

Attachments: File log.err     File log.err     File log.err     File log.err     File mdev10777.yy     File my.cnf     File mysql-general.log     File mysql-general.log     File mysql-general.log.gz     File mysql-general.log.gz     File oltp.yy     HTML File threads1     HTML File threads2     HTML File threads4     HTML File threads5    
Issue Links:
Duplicate
duplicates MDEV-11622 Mariadb= 10.1.17-MariaDB get crashed... Closed
Relates
relates to MDEV-23127 Server crash in Query_cache::double_l... Confirmed
relates to MDEV-10498 10.1.9-MariaDB-log MariaDB Server cr... Closed
relates to MDEV-12156 10.1.21 crash Closed
relates to MDEV-16368 server crash when query_cache_type is... Confirmed

 Description   

Comments to this bug contain various observations, non-deterministic tests which could be no longer applicable, and so on.They are an optional read for whoever ends up fixing this bug, there is no need to check every test mentioned there, only the one here in the description; but I preserve them mainly to keep all the variety of stack traces searchable in JIRA. All attachments also relate to comments, not to the description.

10.4 0b8b11b0

mysqld: /data/src/10.4/sql/sql_cache.cc:1175: void Query_cache::end_of_result(THD*): Assertion `thd->get_stmt_da()->is_eof()' failed.
191204 17:25:26 [ERROR] mysqld got signal 6 ;
 
# 2019-12-04T17:25:40 [15637] #3  0x00007f38a5705f12 in __GI___assert_fail (assertion=0x55c90441007a "thd->get_stmt_da()->is_eof()", file=0x55c90440fbf0 "/data/src/10.4/sql/sql_cache.cc", line=1175, function=0x55c904412320 <Query_cache::end_of_result(THD*)::__PRETTY_FUNCTION__> "void Query_cache::end_of_result(THD*)") at assert.c:101
# 2019-12-04T17:25:40 [15637] #4  0x000055c9036a251b in Query_cache::end_of_result (this=0x55c9050ab260 <query_cache>, thd=0x7f3834000af0) at /data/src/10.4/sql/sql_cache.cc:1175
# 2019-12-04T17:25:40 [15637] #5  0x000055c903729696 in dispatch_command (command=COM_QUERY, thd=0x7f3834000af0, packet=0x7f3834008261 "", packet_length=40, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:2435
# 2019-12-04T17:25:40 [15637] #6  0x000055c903725bb9 in do_command (thd=0x7f3834000af0) at /data/src/10.4/sql/sql_parse.cc:1360
# 2019-12-04T17:25:40 [15637] #7  0x000055c9038ae6a7 in do_handle_one_connection (connect=0x55c90800ced0) at /data/src/10.4/sql/sql_connect.cc:1412
# 2019-12-04T17:25:40 [15637] #8  0x000055c9038ae3f6 in handle_one_connection (arg=0x55c90800ced0) at /data/src/10.4/sql/sql_connect.cc:1316
# 2019-12-04T17:25:40 [15637] #9  0x00007f38a727b4a4 in start_thread (arg=0x7f38a41f3700) at pthread_create.c:456
# 2019-12-04T17:25:40 [15637] #10 0x00007f38a57c2d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Steps to reproduce

git clone https://github.com/MariaDB/randgen --branch mdev10826 rqg-mdev10826
cd rqg-mdev10826
perl ./runall-new.pl --basedir=<basedir> --grammar=./mdev10826.yy --duration=350 --threads=8 --seed=1 --mysqld=--query-cache-type=1 --skip-gendata --vardir=/dev/shm/vardir-mdev10826

Remember to set the right basedir in the command line above.
Make sure you use the RQG version as described above. There is no guarantee that another one will work the same way.

Reproducible on current 10.1-10.5. Couldn't reproduce on 5.5.



 Comments   
Comment by Elena Stepanova [ 2016-09-17 ]

Note of 2019-12-04: The test case, sync point and further comments relate to an old build of 10.1 (of 2016, something around revision bb2c1a52c6). It doesn't look like this test case works with this sync point on the current 10.1 branch, I'm not sure what has changed, could be many things; and I can't build the 3-year old 10.1 on my machine to compare. So, I'm keeping it just for the record, if you attempt to use it, don't be surprised that it doesn't work.

Test case #1 (requires sync point #1) - this test case does not involve getting to "wreck" first

--source include/have_debug_sync.inc
--enable_connect_log
 
set @save_qc_type=@@global.query_cache_type;
set @save_qc_size=@@global.query_cache_size;
set global query_cache_type=1, query_cache_size=1024*1024;
 
CREATE TABLE t1 (id int(10) NOT NULL auto_increment PRIMARY KEY);
INSERT INTO t1 VALUES (NULL),(NULL);
 
--connect (con8,localhost,root,,test)
set debug_sync='in_qc_block_query SIGNAL set_free WAIT_FOR proceed EXECUTE 2';
--send
	SELECT * FROM t1;
 
--connection default
# We are interested in the 2nd time con8 hits the sync point
set debug_sync='now WAIT_FOR set_free';
set debug_sync='now SIGNAL proceed';
set debug_sync='now WAIT_FOR set_free';
 
SET GLOBAL query_cache_type = 0;
set debug_sync='now SIGNAL proceed';
 
--connection con8
--reap
DELETE FROM t1 LIMIT 1;
--disconnect con8
 
--connection default
drop table t1;
set debug_sync='RESET';
set global query_cache_type=@save_qc_type, query_cache_size=@save_qc_size;

Sync point #1

diff --git a/sql/sql_cache.cc b/sql/sql_cache.cc
index 91dd8ad..703bc1d 100644
--- a/sql/sql_cache.cc
+++ b/sql/sql_cache.cc
@@ -855,6 +855,7 @@ Query_cache_query * Query_cache_block::query()
   if (type != QUERY)
     query_cache.wreck(__LINE__, "incorrect block type");
 #endif
+  DEBUG_SYNC(current_thd,"in_qc_block_query");
   return (Query_cache_query *) data();
 }
 

Stack trace from 10.1 bb2c1a52c6 with the added sync point as above

mysqld: /data/src/10.1-bug-clean/sql/sql_cache.cc:1177: void Query_cache::end_of_result(THD*): Assertion `thd->get_stmt_da()->is_eof()' failed.
160920  3:02:17 [ERROR] mysqld got signal 6 ;
 
#7  0x00007f754db54312 in __GI___assert_fail (assertion=0x7f7550c66a4c "thd->get_stmt_da()->is_eof()", file=0x7f7550c66508 "/data/src/10.1-bug-clean/sql/sql_cache.cc", line=1177, function=0x7f7550c68f20 <Query_cache::end_of_result(THD*)::__PRETTY_FUNCTION__> "void Query_cache::end_of_result(THD*)") at assert.c:101
#8  0x00007f7550307979 in Query_cache::end_of_result (this=0x7f75515e8e40 <query_cache>, thd=0x7f7548406070) at /data/src/10.1-bug-clean/sql/sql_cache.cc:1177
#9  0x00007f75503583b0 in dispatch_command (command=COM_QUERY, thd=0x7f7548406070, packet=0x7f754840c071 "", packet_length=22) at /data/src/10.1-bug-clean/sql/sql_parse.cc:1941
#10 0x00007f7550355afe in do_command (thd=0x7f7548406070) at /data/src/10.1-bug-clean/sql/sql_parse.cc:1108
#11 0x00007f755048b9a3 in do_handle_one_connection (thd_arg=0x7f7548406070) at /data/src/10.1-bug-clean/sql/sql_connect.cc:1350
#12 0x00007f755048b707 in handle_one_connection (arg=0x7f7548406070) at /data/src/10.1-bug-clean/sql/sql_connect.cc:1262
#13 0x00007f755076e272 in pfs_spawn_thread (arg=0x7f754d0283f0) at /data/src/10.1-bug-clean/storage/perfschema/pfs.cc:1860
#14 0x00007f754fa560a4 in start_thread (arg=0x7f7551227b00) at pthread_create.c:309
#15 0x00007f754dc0e87d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

I've disabled the assertion failure to see what happens

--- a/sql/sql_cache.cc
+++ b/sql/sql_cache.cc
@@ -1173,7 +1173,9 @@ void Query_cache::end_of_result(THD *thd)
     DBUG_VOID_RETURN;
 
   /* Ensure that only complete results are cached. */
-  DBUG_ASSERT(thd->get_stmt_da()->is_eof());
+//  DBUG_ASSERT(thd->get_stmt_da()->is_eof());
+  if (!thd->get_stmt_da()->is_eof()) 
+    sql_print_warning("HERE: it should have been assertion failure. Thread %lu Query %s", thd->thread_id, thd->query());
 
   if (thd->killed)
   {

First, I've got quite a few log messages without any visible problems:

2016-09-17  2:32:56 139644252100480 [Note] /data/src/10.1-bug/sql/mysqld: ready for connections.
Version: '10.1.18-MariaDB-debug'  socket: '/data/src/10.1-bug/data/tmp/mysql.sock'  port: 3306  Source distribution
2016-09-17  2:36:25 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query DELETE FROM `t4` WHERE `id` = 26599
2016-09-17  2:36:25 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query DELETE FROM `t1` WHERE `id` = 42090
2016-09-17  2:36:25 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query DELETE FROM `t5` WHERE `id` = 45764
2016-09-17  2:36:25 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query UPDATE IGNORE `t2` SET `id` = `id` + 1 WHERE `id` = 30681
2016-09-17  2:36:25 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query DELETE FROM `t3` WHERE `id` = 56078
2016-09-17  2:36:25 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query INSERT IGNORE INTO `t3` ( `id` ) VALUES ( NULL )
2016-09-17  2:36:25 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query UPDATE IGNORE `t3` SET `id` = `k` + 1 WHERE `id` = 47896
2016-09-17  2:36:26 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query INSERT IGNORE INTO `t1` ( `c` ) VALUES ( 'm' )
2016-09-17  2:36:26 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query UPDATE IGNORE `t4` SET `id` = `k` + 1 WHERE `id` = 32416
2016-09-17  2:36:26 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query UPDATE IGNORE `t2` SET `k` = `id` + 1 WHERE `id` = 51497
2016-09-17  2:36:26 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query DELETE FROM `t5` WHERE `id` = 31627
2016-09-17  2:36:26 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query DELETE FROM `t4` WHERE `id` = 27110
2016-09-17  2:36:26 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query INSERT IGNORE INTO `t4` ( `id`, `id`) VALUES ( NULL, 710672384 )
2016-09-17  2:36:26 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query UPDATE `t1` SET `c` = 'n' WHERE `id` = 23714
2016-09-17  2:36:26 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query UPDATE IGNORE `t3` SET `k` = `id` + 1 WHERE `id` = 3234
2016-09-17  2:36:27 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query UPDATE `t5` SET `pad` = 'o' WHERE `id` = 5505
2016-09-17  2:36:27 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query UPDATE IGNORE `t4` SET `k` = `k` + 1 WHERE `id` = 20547
2016-09-17  2:36:27 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query UPDATE IGNORE `t5` SET `k` = `k` + 1 WHERE `id` = 14967
2016-09-17  2:36:27 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query DELETE FROM `t2` WHERE `id` = 25798
2016-09-17  2:36:27 139644230621952 [Note] InnoDB: Online DDL : Start
2016-09-17  2:36:27 139644230621952 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
2016-09-17  2:36:27 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query INSERT IGNORE INTO `t4` ( `id`, `id`) VALUES ( NULL, -1501298688 )
2016-09-17  2:36:27 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query DELETE FROM `t5` WHERE `id` = 56340
2016-09-17  2:36:27 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query UPDATE IGNORE `t2` SET `k` = `id` + 1 WHERE `id` = 26969
2016-09-17  2:36:27 139644230621952 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2016-09-17  2:36:27 139644230621952 [Note] InnoDB: Online DDL : Start merge-sorting index "PRIMARY" (1 / 2), estimated cost : 13.3333
2016-09-17  2:36:27 139644230621952 [Note] InnoDB: Online DDL : End of  merge-sorting index "PRIMARY" (1 / 2)
2016-09-17  2:36:27 139644230621952 [Note] InnoDB: Online DDL : Start building index "PRIMARY" (1 / 2), estimated cost : 20.0000
2016-09-17  2:36:27 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query INSERT IGNORE INTO `t5` ( `id`, `pad` ) VALUES ( NULL, 'y' )
2016-09-17  2:36:28 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query INSERT IGNORE INTO `t2` ( `id`, `c` ) VALUES ( NULL, 'l' )
2016-09-17  2:36:28 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query INSERT IGNORE INTO `t2` ( `pad` ) VALUES ( 'd' )
2016-09-17  2:36:28 139644230621952 [Note] InnoDB: Online DDL : End of building index "PRIMARY" (1 / 2)
2016-09-17  2:36:28 139644230621952 [Note] InnoDB: Online DDL : Completed
2016-09-17  2:36:28 139644230621952 [Note] InnoDB: Online DDL : Start merge-sorting index "k" (2 / 2), estimated cost : 13.3333
2016-09-17  2:36:28 139644230621952 [Note] InnoDB: Online DDL : End of  merge-sorting index "k" (2 / 2)
2016-09-17  2:36:28 139644230621952 [Note] InnoDB: Online DDL : Start building index "k" (2 / 2), estimated cost : 20.0000
2016-09-17  2:36:29 139644230621952 [Note] InnoDB: Online DDL : End of building index "k" (2 / 2)
2016-09-17  2:36:29 139644230621952 [Note] InnoDB: Online DDL : Completed

But then this happened:

2016-09-17  2:36:29 139644230621952 [Note] InnoDB: Online DDL : Completed
2016-09-17  2:36:29 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query UPDATE IGNORE `t5` SET `id` = `k` + 1 WHERE `id` = 33565
2016-09-17  2:36:29 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query DELETE FROM `t4` WHERE `id` = 41351
2016-09-17  2:36:29 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query DELETE FROM `t4` WHERE `id` = 49224
2016-09-17  2:36:30 139644229712640 [Warning] HERE: it should have been assertion failure. Thread 13 Query INSERT IGNORE INTO `t5` ( `id`, `k`) VALUES ( NULL, -1849950208 )
160917  2:36:30 [ERROR] mysqld got signal 11 ;
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.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
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.
 
Server version: 10.1.18-MariaDB-debug
key_buffer_size=67108864
read_buffer_size=1048576
max_used_connections=11
max_threads=1002
thread_count=11
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 3164802 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0x7f00337d1070
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 = 0x7f0174b4f280 thread_stack 0x48400
/data/src/10.1-bug/sql/mysqld(my_print_stacktrace+0x38)[0x7f0175991005]
/data/src/10.1-bug/sql/mysqld(handle_fatal_signal+0x399)[0x7f017533516a]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0)[0x7f01748018d0]
/data/src/10.1-bug/sql/mysqld(+0x477be3)[0x7f01750a9be3]
/data/src/10.1-bug/sql/mysqld(_ZN17Query_cache_query12lock_writingEv+0x55)[0x7f01750b7ead]
mysys/stacktrace.c:267(my_print_stacktrace)[0x7f01750ab4d9]
sql/sql_cache.cc:1058(query_cache_insert(void*, char const*, unsigned long, unsigned int))[0x7f01750ab38d]
sql/net_serv.cc:609(net_real_write)[0x7f0175040352]
sql/net_serv.cc:364(net_flush)[0x7f017503fc81]
sql/protocol.cc:300(net_send_eof(THD*, unsigned int, unsigned int))[0x7f017504647d]
sql/protocol.cc:571(Protocol::send_eof(unsigned int, unsigned int))[0x7f0175046c9a]
sql/protocol.cc:519(Protocol::end_statement())[0x7f0175046abb]
sql/sql_parse.cc:1941(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x7f01750fc36d]
sql/sql_parse.cc:1108(do_command(THD*))[0x7f01750f9ad4]
sql/sql_connect.cc:1350(do_handle_one_connection(THD*))[0x7f017522f979]
sql/sql_connect.cc:1263(handle_one_connection)[0x7f017522f6dd]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x80a4)[0x7f01747fa0a4]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f01729b287d]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f003088e088): SELECT SQL_CACHE SUM(`c`) FROM `t5` WHERE `id` BETWEEN 22885 AND 15016
Connection ID (thread ID): 13
Status: KILL_CONNECTION

# 2016-09-17T02:36:45 [1894] Thread 1 (Thread 0x7f0174b4fb00 (LWP 1918)):
# 2016-09-17T02:36:45 [1894] #0  0x00007f01747ff101 in __pthread_kill (threadid=<optimized out>, signo=11) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
# 2016-09-17T02:36:45 [1894] #1  0x00007f01759910f6 in my_write_core (sig=11) at /data/src/10.1-bug/mysys/stacktrace.c:477
# 2016-09-17T02:36:45 [1894] #2  0x00007f01753354f9 in handle_fatal_signal (sig=11) at /data/src/10.1-bug/sql/signal_handler.cc:294
# 2016-09-17T02:36:45 [1894] #3  <signal handler called>
# 2016-09-17T02:36:45 [1894] #4  0x00007f01750a9be3 in inline_mysql_rwlock_wrlock (that=0x7f0221cfe6b8, src_file=0x7f0175a0a378 "/data/src/10.1-bug/sql/sql_cache.cc", src_line=919) at /data/src/10.1-bug/include/mysql/psi/mysql_thread.h:931
# 2016-09-17T02:36:45 [1894] #5  0x00007f01750b7ead in Query_cache_query::lock_writing (this=0x7f0221cfe6b0) at /data/src/10.1-bug/sql/sql_cache.cc:919
# 2016-09-17T02:36:45 [1894] #6  0x00007f01750ab4d9 in Query_cache::insert (this=0x7f0176389e40 <query_cache>, thd=0x7f00337d1070, query_cache_tls=0x7f00337d1328, packet=0x7f004938c070 "\001", length=62, pkt_nr=6) at /data/src/10.1-bug/sql/sql_cache.cc:1095
# 2016-09-17T02:36:45 [1894] #7  0x00007f01750ab38d in query_cache_insert (thd_arg=0x7f00337d1070, packet=0x7f004938c070 "\001", length=62, pkt_nr=6) at /data/src/10.1-bug/sql/sql_cache.cc:1057
# 2016-09-17T02:36:45 [1894] #8  0x00007f0175040352 in net_real_write (net=0x7f00337d1330, packet=0x7f004938c070 "\001", len=62) at /data/src/10.1-bug/sql/net_serv.cc:606
# 2016-09-17T02:36:45 [1894] #9  0x00007f017503fc81 in net_flush (net=0x7f00337d1330) at /data/src/10.1-bug/sql/net_serv.cc:363
# 2016-09-17T02:36:45 [1894] #10 0x00007f017504647d in net_send_eof (thd=0x7f00337d1070, server_status=2, statement_warn_count=0) at /data/src/10.1-bug/sql/protocol.cc:300
# 2016-09-17T02:36:45 [1894] #11 0x00007f0175046c9a in Protocol::send_eof (this=0x7f00337d1600, server_status=2, statement_warn_count=0) at /data/src/10.1-bug/sql/protocol.cc:571
# 2016-09-17T02:36:45 [1894] #12 0x00007f0175046abb in Protocol::end_statement (this=0x7f00337d1600) at /data/src/10.1-bug/sql/protocol.cc:519
# 2016-09-17T02:36:45 [1894] #13 0x00007f01750fc36d in dispatch_command (command=COM_QUERY, thd=0x7f00337d1070, packet=0x7f004938c071 "", packet_length=70) at /data/src/10.1-bug/sql/sql_parse.cc:1940
# 2016-09-17T02:36:45 [1894] #14 0x00007f01750f9ad4 in do_command (thd=0x7f00337d1070) at /data/src/10.1-bug/sql/sql_parse.cc:1108
# 2016-09-17T02:36:45 [1894] #15 0x00007f017522f979 in do_handle_one_connection (thd_arg=0x7f00337d1070) at /data/src/10.1-bug/sql/sql_connect.cc:1350
# 2016-09-17T02:36:45 [1894] #16 0x00007f017522f6dd in handle_one_connection (arg=0x7f00337d1070) at /data/src/10.1-bug/sql/sql_connect.cc:1262
# 2016-09-17T02:36:45 [1894] #17 0x00007f01747fa0a4 in start_thread (arg=0x7f0174b4fb00) at pthread_create.c:309
# 2016-09-17T02:36:45 [1894] #18 0x00007f01729b287d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

All threads stack trace, general log and error log are attached.
threads1 mysql-general.log log.err

Comment by Elena Stepanova [ 2016-09-17 ]

Same approach, different stack trace. However, this time there was warning in the logs about the replaced assertion, so it might be a different thing.

# 2016-09-17T16:31:46 [6928] #3  <signal handler called>
# 2016-09-17T16:31:46 [6928] #4  0x00007f924635311d in Query_cache::double_linked_list_exclude (point=0x7f90e3993dc0, list_pointer=0x7f9247629fa0 <query_cache+352>) at /data/src/10.1-bug/sql/sql_cache.cc:3941
# 2016-09-17T16:31:46 [6928] #5  0x00007f9246350591 in Query_cache::free_query_internal (this=0x7f9247629e40 <query_cache>, query_block=0x7f90e3993dc0) at /data/src/10.1-bug/sql/sql_cache.cc:2889
# 2016-09-17T16:31:46 [6928] #6  0x00007f924635075a in Query_cache::free_query (this=0x7f9247629e40 <query_cache>, query_block=0x7f90e3993dc0) at /data/src/10.1-bug/sql/sql_cache.cc:2950
# 2016-09-17T16:31:46 [6928] #7  0x00007f924634b605 in Query_cache::insert (this=0x7f9247629e40 <query_cache>, thd=0x7f9104a3c070, query_cache_tls=0x7f9104a3c328, packet=0x7f9104a63070 "\n", length=14, pkt_nr=2) at /data/src/10.1-bug/sql/sql_cache.cc:1114
# 2016-09-17T16:31:46 [6928] #8  0x00007f924634b38d in query_cache_insert (thd_arg=0x7f9104a3c070, packet=0x7f9104a63070 "\n", length=14, pkt_nr=2) at /data/src/10.1-bug/sql/sql_cache.cc:1057
# 2016-09-17T16:31:46 [6928] #9  0x00007f92462e0352 in net_real_write (net=0x7f9104a3c330, packet=0x7f9104a63070 "\n", len=14) at /data/src/10.1-bug/sql/net_serv.cc:606
# 2016-09-17T16:31:46 [6928] #10 0x00007f92462dfc81 in net_flush (net=0x7f9104a3c330) at /data/src/10.1-bug/sql/net_serv.cc:363
# 2016-09-17T16:31:46 [6928] #11 0x00007f92462e6357 in net_send_ok (thd=0x7f9104a3c070, server_status=2, statement_warn_count=0, affected_rows=1, id=67444, message=0x7f9104a40e7a "") at /data/src/10.1-bug/sql/protocol.cc:254
# 2016-09-17T16:31:46 [6928] #12 0x00007f92462e6c2c in Protocol::send_ok (this=0x7f9104a3c600, server_status=2, statement_warn_count=0, affected_rows=1, last_insert_id=67444, message=0x7f9104a40e7a "") at /data/src/10.1-bug/sql/protocol.cc:557
# 2016-09-17T16:31:46 [6928] #13 0x00007f92462e6b58 in Protocol::end_statement (this=0x7f9104a3c600) at /data/src/10.1-bug/sql/protocol.cc:526
# 2016-09-17T16:31:46 [6928] #14 0x00007f924639c36d in dispatch_command (command=COM_QUERY, thd=0x7f9104a3c070, packet=0x7f9104a63071 "", packet_length=46) at /data/src/10.1-bug/sql/sql_parse.cc:1940
# 2016-09-17T16:31:46 [6928] #15 0x00007f9246399ad4 in do_command (thd=0x7f9104a3c070) at /data/src/10.1-bug/sql/sql_parse.cc:1108
# 2016-09-17T16:31:46 [6928] #16 0x00007f92464cf979 in do_handle_one_connection (thd_arg=0x7f9104a3c070) at /data/src/10.1-bug/sql/sql_connect.cc:1350
# 2016-09-17T16:31:46 [6928] #17 0x00007f92464cf6dd in handle_one_connection (arg=0x7f9104a3c070) at /data/src/10.1-bug/sql/sql_connect.cc:1262
# 2016-09-17T16:31:46 [6928] #18 0x00007f9245a9a0a4 in start_thread (arg=0x7f9245e39b00) at pthread_create.c:309
# 2016-09-17T16:31:46 [6928] #19 0x00007f9243c5287d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
# 2016-09-17T16:31:46 [6928] Test completed with failure status STATUS_SERVER_CRASHED (101)

threads2 mysql-general.log.gz log.err

It's also strange that in both cases the error reporter says that the status is KILL_CONNECTION. There were no KILLs.

Comment by Elena Stepanova [ 2016-09-17 ]

160917 16:52:33 [ERROR] mysqld got signal 11 ;
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.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
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.
 
Server version: 10.1.18-MariaDB-debug
key_buffer_size=67108864
read_buffer_size=1048576
max_used_connections=6
max_threads=1002
thread_count=6
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 3164802 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0x7f721ca2a070
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 = 0x7f735db2c280 thread_stack 0x48400
/data/src/10.1-bug/sql/mysqld(my_print_stacktrace+0x38)[0x7f735e924005]
/data/src/10.1-bug/sql/mysqld(handle_fatal_signal+0x399)[0x7f735e2c816a]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0)[0x7f735d7948d0]
/data/src/10.1-bug/sql/mysqld(_ZN11Query_cache26double_linked_list_excludeEP17Query_cache_blockPS1_+0x87)[0x7f735e04611d]
/data/src/10.1-bug/sql/mysqld(_ZN11Query_cache19free_query_internalEP17Query_cache_block+0xe7)[0x7f735e043591]
mysys/stacktrace.c:267(my_print_stacktrace)[0x7f735e04375a]
sql/sql_cache.cc:1115(Query_cache::insert(THD*, Query_cache_tls*, char const*, unsigned long, unsigned int))[0x7f735e03e605]
sql/sql_cache.cc:1058(query_cache_insert(void*, char const*, unsigned long, unsigned int))[0x7f735e03e38d]
sql/net_serv.cc:609(net_real_write)[0x7f735dfd3352]
sql/net_serv.cc:364(net_flush)[0x7f735dfd2c81]
sql/protocol.cc:300(net_send_eof(THD*, unsigned int, unsigned int))[0x7f735dfd947d]
sql/protocol.cc:571(Protocol::send_eof(unsigned int, unsigned int))[0x7f735dfd9c9a]
sql/protocol.cc:519(Protocol::end_statement())[0x7f735dfd9abb]
/data/src/10.1-bug/sql/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x2341)[0x7f735e08f36d]
sql/sql_parse.cc:1941(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x7f735e08cad4]
sql/sql_connect.cc:1350(do_handle_one_connection(THD*))[0x7f735e1c2979]
sql/sql_connect.cc:1263(handle_one_connection)[0x7f735e1c26dd]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x80a4)[0x7f735d78d0a4]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f735b94587d]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f720bc26088): SELECT SQL_CACHE `id` FROM `t4` WHERE `id` BETWEEN 4588 AND 26862
Connection ID (thread ID): 12
Status: KILL_CONNECTION

# 2016-09-17T16:52:46 [7624] #3  <signal handler called>
# 2016-09-17T16:52:46 [7624] #4  0x00007f735e04611d in Query_cache::double_linked_list_exclude (point=0x7f720b5d5cb0, list_pointer=0x7f735f31cfa0 <query_cache+352>) at /data/src/10.1-bug/sql/sql_cache.cc:3941
# 2016-09-17T16:52:46 [7624] #5  0x00007f735e043591 in Query_cache::free_query_internal (this=0x7f735f31ce40 <query_cache>, query_block=0x7f720b5d5cb0) at /data/src/10.1-bug/sql/sql_cache.cc:2889
# 2016-09-17T16:52:46 [7624] #6  0x00007f735e04375a in Query_cache::free_query (this=0x7f735f31ce40 <query_cache>, query_block=0x7f720b5d5cb0) at /data/src/10.1-bug/sql/sql_cache.cc:2950
# 2016-09-17T16:52:46 [7624] #7  0x00007f735e03e605 in Query_cache::insert (this=0x7f735f31ce40 <query_cache>, thd=0x7f721ca2a070, query_cache_tls=0x7f721ca2a328, packet=0x7f721ca30070 "", length=16129, pkt_nr=5428) at /data/src/10.1-bug/sql/sql_cache.cc:1114
# 2016-09-17T16:52:46 [7624] #8  0x00007f735e03e38d in query_cache_insert (thd_arg=0x7f721ca2a070, packet=0x7f721ca30070 "", length=16129, pkt_nr=5428) at /data/src/10.1-bug/sql/sql_cache.cc:1057
# 2016-09-17T16:52:46 [7624] #9  0x00007f735dfd3352 in net_real_write (net=0x7f721ca2a330, packet=0x7f721ca30070 "", len=16129) at /data/src/10.1-bug/sql/net_serv.cc:606
# 2016-09-17T16:52:46 [7624] #10 0x00007f735dfd2c81 in net_flush (net=0x7f721ca2a330) at /data/src/10.1-bug/sql/net_serv.cc:363
# 2016-09-17T16:52:46 [7624] #11 0x00007f735dfd947d in net_send_eof (thd=0x7f721ca2a070, server_status=2, statement_warn_count=0) at /data/src/10.1-bug/sql/protocol.cc:300
# 2016-09-17T16:52:46 [7624] #12 0x00007f735dfd9c9a in Protocol::send_eof (this=0x7f721ca2a600, server_status=2, statement_warn_count=0) at /data/src/10.1-bug/sql/protocol.cc:571
# 2016-09-17T16:52:46 [7624] #13 0x00007f735dfd9abb in Protocol::end_statement (this=0x7f721ca2a600) at /data/src/10.1-bug/sql/protocol.cc:519
# 2016-09-17T16:52:46 [7624] #14 0x00007f735e08f36d in dispatch_command (command=COM_QUERY, thd=0x7f721ca2a070, packet=0x7f721ca30071 "", packet_length=65) at /data/src/10.1-bug/sql/sql_parse.cc:1940
# 2016-09-17T16:52:46 [7624] #15 0x00007f735e08cad4 in do_command (thd=0x7f721ca2a070) at /data/src/10.1-bug/sql/sql_parse.cc:1108
# 2016-09-17T16:52:46 [7624] #16 0x00007f735e1c2979 in do_handle_one_connection (thd_arg=0x7f721ca2a070) at /data/src/10.1-bug/sql/sql_connect.cc:1350
# 2016-09-17T16:52:46 [7624] #17 0x00007f735e1c26dd in handle_one_connection (arg=0x7f721ca2a070) at /data/src/10.1-bug/sql/sql_connect.cc:1262
# 2016-09-17T16:52:46 [7624] #18 0x00007f735d78d0a4 in start_thread (arg=0x7f735db2cb00) at pthread_create.c:309
# 2016-09-17T16:52:46 [7624] #19 0x00007f735b94587d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

log.err mysql-general.log.gz

Comment by Elena Stepanova [ 2016-09-17 ]

160917 17:18:25 [ERROR] mysqld got signal 11 ;
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.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
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.
 
Server version: 10.1.18-MariaDB-debug
key_buffer_size=67108864
read_buffer_size=1048576
max_used_connections=4
max_threads=1002
thread_count=4
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 3164802 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

/data/src/10.1-bug/sql/mysqld(my_print_stacktrace+0x38)[0x7fa5b14cafbb]
/data/src/10.1-bug/sql/mysqld(handle_fatal_signal+0x399)[0x7fa5b0e6f106]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0)[0x7fa5b033b8d0]
/data/src/10.1-bug/sql/mysqld(_ZN11Query_cache26double_linked_list_excludeEP17Query_cache_blockPS1_+0x87)[0x7fa5b0bed0d3]
/data/src/10.1-bug/sql/mysqld(_ZN11Query_cache19free_query_internalEP17Query_cache_block+0xe7)[0x7fa5b0bea547]
/data/src/10.1-bug/sql/mysqld(_ZN11Query_cache10free_queryEP17Query_cache_block+0x9c)[0x7fa5b0bea710]
/data/src/10.1-bug/sql/mysqld(_ZN11Query_cache6insertEP3THDP15Query_cache_tlsPKcmj+0x275)[0x7fa5b0be5605]
/data/src/10.1-bug/sql/mysqld(_Z18query_cache_insertPvPKcmj+0x60)[0x7fa5b0be538d]
/data/src/10.1-bug/sql/mysqld(net_real_write+0x83)[0x7fa5b0b7a352]
mysys/stacktrace.c:267(my_print_stacktrace)[0x7fa5b0b7a1cf]
sql/sql_cache.cc:2952(Query_cache::free_query(Query_cache_block*))[0x7fa5b0b79e10]
sql/protocol.cc:888(Protocol::write())[0x7fa5b0b81d1c]
sql/sql_class.cc:2838(select_send::send_data(List<Item>&))[0x7fa5b0bf98a1]
sql/sql_select.cc:19432(end_send)[0x7fa5b0ca4a6b]
sql/sql_select.cc:18521(evaluate_join_record)[0x7fa5b0ca27e4]
sql/sql_select.cc:18335(sub_select(JOIN*, st_join_table*, bool))[0x7fa5b0ca2296]
sql/sql_select.cc:17951(do_select)[0x7fa5b0ca1976]
sql/sql_select.cc:3215(JOIN::exec_inner())[0x7fa5b0c7c6ef]
2016-09-17 17:18:26 140349606886144 [Note] InnoDB: Online DDL : Start
2016-09-17 17:18:26 140349606886144 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
sql/sql_select.cc:2506(JOIN::exec())[0x7fa5b0c79999]
sql/sql_select.cc:3440(mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*))[0x7fa5b0c7cf07]
2016-09-17 17:18:26 140349606886144 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2016-09-17 17:18:26 140349606886144 [Note] InnoDB: Online DDL : Start merge-sorting index "PRIMARY" (1 / 2), estimated cost : 13.3333
2016-09-17 17:18:26 140349606886144 [Note] InnoDB: Online DDL : End of  merge-sorting index "PRIMARY" (1 / 2)
2016-09-17 17:18:26 140349606886144 [Note] InnoDB: Online DDL : Start building index "PRIMARY" (1 / 2), estimated cost : 20.0000
sql/sql_select.cc:384(handle_select(THD*, LEX*, select_result*, unsigned long))[0x7fa5b0c729f8]
/data/src/10.1-bug/sql/mysqld(+0x4d6bd7)[0x7fa5b0c42bd7]
sql/sql_parse.cc:5895(execute_sqlcom_select)[0x7fa5b0c38ae4]
sql/sql_parse.cc:7318(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x7fa5b0c46330]
sql/sql_parse.cc:1489(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x7fa5b0c34d39]
sql/sql_parse.cc:1108(do_command(THD*))[0x7fa5b0c33a70]
sql/sql_connect.cc:1350(do_handle_one_connection(THD*))[0x7fa5b0d69915]
sql/sql_connect.cc:1263(handle_one_connection)[0x7fa5b0d69679]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x80a4)[0x7fa5b03340a4]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fa5ae4ec87d]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fa473026088): SELECT SQL_CACHE `id` FROM `t5` WHERE `id` BETWEEN 26315 AND 37282 ORDER BY `c`
Connection ID (thread ID): 9
Status: KILL_CONNECTION

# 2016-09-17T17:18:38 [9951] #3  <signal handler called>
# 2016-09-17T17:18:38 [9951] #4  0x00007fa5b0bed0d3 in Query_cache::double_linked_list_exclude (point=0x7fa45e1741d8, list_pointer=0x7fa5b1ec3fa0 <query_cache+352>) at /data/src/10.1-bug/sql/sql_cache.cc:3941
# 2016-09-17T17:18:38 [9951] #5  0x00007fa5b0bea547 in Query_cache::free_query_internal (this=0x7fa5b1ec3e40 <query_cache>, query_block=0x7fa45e1741d8) at /data/src/10.1-bug/sql/sql_cache.cc:2889
# 2016-09-17T17:18:38 [9951] #6  0x00007fa5b0bea710 in Query_cache::free_query (this=0x7fa5b1ec3e40 <query_cache>, query_block=0x7fa45e1741d8) at /data/src/10.1-bug/sql/sql_cache.cc:2950
# 2016-09-17T17:18:38 [9951] #7  0x00007fa5b0be5605 in Query_cache::insert (this=0x7fa5b1ec3e40 <query_cache>, thd=0x7fa46f60a070, query_cache_tls=0x7fa46f60a328, packet=0x7fa4853fb070 "\001", length=16384, pkt_nr=1638) at /data/src/10.1-bug/sql/sql_cache.cc:1114
# 2016-09-17T17:18:38 [9951] #8  0x00007fa5b0be538d in query_cache_insert (thd_arg=0x7fa46f60a070, packet=0x7fa4853fb070 "\001", length=16384, pkt_nr=1638) at /data/src/10.1-bug/sql/sql_cache.cc:1057
# 2016-09-17T17:18:38 [9951] #9  0x00007fa5b0b7a352 in net_real_write (net=0x7fa46f60a330, packet=0x7fa4853fb070 "\001", len=16384) at /data/src/10.1-bug/sql/net_serv.cc:606
# 2016-09-17T17:18:38 [9951] #10 0x00007fa5b0b7a1cf in net_write_buff (net=0x7fa46f60a330, packet=0x7fa5b1a6f060 "\006", len=4) at /data/src/10.1-bug/sql/net_serv.cc:553
# 2016-09-17T17:18:38 [9951] #11 0x00007fa5b0b79e10 in my_net_write (net=0x7fa46f60a330, packet=0x7fa473018070 "\005\062\067\067\070\063est\002t5\002t5\002id\002id\f?", len=6) at /data/src/10.1-bug/sql/net_serv.cc:419
# 2016-09-17T17:18:38 [9951] #12 0x00007fa5b0b81d1c in Protocol::write (this=0x7fa46f60a600) at /data/src/10.1-bug/sql/protocol.cc:888
# 2016-09-17T17:18:38 [9951] #13 0x00007fa5b0bf98a1 in select_send::send_data (this=0x7fa473026e78, items=...) at /data/src/10.1-bug/sql/sql_class.cc:2838
# 2016-09-17T17:18:38 [9951] #14 0x00007fa5b0ca4a6b in end_send (join=0x7fa473026e98, join_tab=0x7fa473028b28, end_of_records=false) at /data/src/10.1-bug/sql/sql_select.cc:19432
# 2016-09-17T17:18:38 [9951] #15 0x00007fa5b0ca27e4 in evaluate_join_record (join=0x7fa473026e98, join_tab=0x7fa4730287e0, error=0) at /data/src/10.1-bug/sql/sql_select.cc:18521
# 2016-09-17T17:18:38 [9951] #16 0x00007fa5b0ca2296 in sub_select (join=0x7fa473026e98, join_tab=0x7fa4730287e0, end_of_records=false) at /data/src/10.1-bug/sql/sql_select.cc:18335
# 2016-09-17T17:18:38 [9951] #17 0x00007fa5b0ca1976 in do_select (join=0x7fa473026e98, fields=0x7fa46f60e2d0, table=0x0, procedure=0x0) at /data/src/10.1-bug/sql/sql_select.cc:17951
# 2016-09-17T17:18:38 [9951] #18 0x00007fa5b0c7c6ef in JOIN::exec_inner (this=0x7fa473026e98) at /data/src/10.1-bug/sql/sql_select.cc:3215
# 2016-09-17T17:18:38 [9951] #19 0x00007fa5b0c79999 in JOIN::exec (this=0x7fa473026e98) at /data/src/10.1-bug/sql/sql_select.cc:2505
# 2016-09-17T17:18:38 [9951] #20 0x00007fa5b0c7cf07 in mysql_select (thd=0x7fa46f60a070, rref_pointer_array=0x7fa46f60e430, tables=0x7fa4730262e8, wild_num=0, fields=..., conds=0x7fa473026b10, og_num=1, order=0x7fa473026d68, group=0x0, having=0x0, proc_param=0x0, select_options=2147748672, result=0x7fa473026e78, unit=0x7fa46f60dab8, select_lex=0x7fa46f60e1b8) at /data/src/10.1-bug/sql/sql_select.cc:3438
# 2016-09-17T17:18:38 [9951] #21 0x00007fa5b0c729f8 in handle_select (thd=0x7fa46f60a070, lex=0x7fa46f60d9f0, result=0x7fa473026e78, setup_tables_done_option=0) at /data/src/10.1-bug/sql/sql_select.cc:384
# 2016-09-17T17:18:38 [9951] #22 0x00007fa5b0c42bd7 in execute_sqlcom_select (thd=0x7fa46f60a070, all_tables=0x7fa4730262e8) at /data/src/10.1-bug/sql/sql_parse.cc:5895
# 2016-09-17T17:18:38 [9951] #23 0x00007fa5b0c38ae4 in mysql_execute_command (thd=0x7fa46f60a070) at /data/src/10.1-bug/sql/sql_parse.cc:2961
# 2016-09-17T17:18:38 [9951] #24 0x00007fa5b0c46330 in mysql_parse (thd=0x7fa46f60a070, rawbuf=0x7fa473026088 "SELECT SQL_CACHE `id` FROM `t5` WHERE `id` BETWEEN 26315 AND 37282 ORDER BY `c`", length=79, parser_state=0x7fa5b1a70630) at /data/src/10.1-bug/sql/sql_parse.cc:7318
# 2016-09-17T17:18:38 [9951] #25 0x00007fa5b0c34d39 in dispatch_command (command=COM_QUERY, thd=0x7fa46f60a070, packet=0x7fa4853fb071 "", packet_length=79) at /data/src/10.1-bug/sql/sql_parse.cc:1487
# 2016-09-17T17:18:38 [9951] #26 0x00007fa5b0c33a70 in do_command (thd=0x7fa46f60a070) at /data/src/10.1-bug/sql/sql_parse.cc:1108
# 2016-09-17T17:18:38 [9951] #27 0x00007fa5b0d69915 in do_handle_one_connection (thd_arg=0x7fa46f60a070) at /data/src/10.1-bug/sql/sql_connect.cc:1350
# 2016-09-17T17:18:38 [9951] #28 0x00007fa5b0d69679 in handle_one_connection (arg=0x7fa46f60a070) at /data/src/10.1-bug/sql/sql_connect.cc:1262
# 2016-09-17T17:18:38 [9951] #29 0x00007fa5b03340a4 in start_thread (arg=0x7fa5b1a71b00) at pthread_create.c:309
# 2016-09-17T17:18:38 [9951] #30 0x00007fa5ae4ec87d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

log.err mysql-general.log threads4

Comment by Elena Stepanova [ 2016-09-17 ]

Also, it can hang:

Thread 3 (Thread 0x7f60e2928b00 (LWP 15833)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x00007f60e231b5ae in safe_cond_wait (cond=0x7f60e2d0ee98 <query_cache+88>, mp=0x7f60e2d0eee0 <query_cache+160>, file=0x7f60e238f240 "/data/src/10.1-bug
/include/mysql/psi/mysql_thread.h", line=1165) at /data/src/10.1-bug/mysys/thr_mutex.c:493
#2  0x00007f60e1a2eec9 in inline_mysql_cond_wait (that=0x7f60e2d0ee98 <query_cache+88>, mutex=0x7f60e2d0eee0 <query_cache+160>, src_file=0x7f60e238f338 "/data/src/10.1-bug/sql/sql_cache.cc", src_line=696) at /data/src/10.1-bug/include/mysql/psi/mysql_thread.h:1165
#3  0x00007f60e1a2f852 in Query_cache::lock_and_suspend (this=0x7f60e2d0ee40 <query_cache>) at /data/src/10.1-bug/sql/sql_cache.cc:696
#4  0x00007f60e1a30f1c in Query_cache::resize (this=0x7f60e2d0ee40 <query_cache>, query_cache_size_arg=262144) at /data/src/10.1-bug/sql/sql_cache.cc:1300
#5  0x00007f60e1bce180 in fix_query_cache_size (self=0x7f60e2d27400 <Sys_query_cache_size>, thd=0x7f60bb75f070, type=SHOW_OPT_GLOBAL) at /data/src/10.1-bug/sql/sys_vars.cc:2741
#6  0x00007f60e19d59d6 in sys_var::update (this=0x7f60e2d27400 <Sys_query_cache_size>, thd=0x7f60bb75f070, var=0x7f60b1022358) at /data/src/10.1-bug/sql/set_var.cc:199
#7  0x00007f60e19d7512 in set_var::update (this=0x7f60b1022358, thd=0x7f60bb75f070) at /data/src/10.1-bug/sql/set_var.cc:795
#8  0x00007f60e19d70fa in sql_set_variables (thd=0x7f60bb75f070, var_list=0x7f60bb763758, free=true) at /data/src/10.1-bug/sql/set_var.cc:696
#9  0x00007f60e1a87c22 in mysql_execute_command (thd=0x7f60bb75f070) at /data/src/10.1-bug/sql/sql_parse.cc:4295
#10 0x00007f60e1a91330 in mysql_parse (thd=0x7f60bb75f070, rawbuf=0x7f60b1022088 "SET GLOBAL query_cache_size = 256 * 1024", length=40, parser_state=0x7f60e2927630) at /data/src/10.1-bug/sql/sql_parse.cc:7318
#11 0x00007f60e1a7fd39 in dispatch_command (command=COM_QUERY, thd=0x7f60bb75f070, packet=0x7f60bb775071 "SET GLOBAL query_cache_size = 256 * 1024", packet_length=40) at /data/src/10.1-bug/sql/sql_parse.cc:1487
#12 0x00007f60e1a7ea70 in do_command (thd=0x7f60bb75f070) at /data/src/10.1-bug/sql/sql_parse.cc:1108
#13 0x00007f60e1bb4915 in do_handle_one_connection (thd_arg=0x7f60bb75f070) at /data/src/10.1-bug/sql/sql_connect.cc:1350
#14 0x00007f60e1bb4679 in handle_one_connection (arg=0x7f60bb75f070) at /data/src/10.1-bug/sql/sql_connect.cc:1262
#15 0x00007f60e117f0a4 in start_thread (arg=0x7f60e2928b00) at pthread_create.c:309
#16 0x00007f60df33787d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 2 (Thread 0x7f60e28deb00 (LWP 15835)):
#0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1  0x00007f60e1182a41 in pthread_rwlock_wrlock () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_rwlock_wrlock.S:120
#2  0x00007f60e1a2ec2d in inline_mysql_rwlock_wrlock (that=0x7f60b0d6b1a0, src_file=0x7f60e238f338 "/data/src/10.1-bug/sql/sql_cache.cc", src_line=919) at /data/src/10.1-bug/include/mysql/psi/mysql_thread.h:940
#3  0x00007f60e1a3ce49 in Query_cache_query::lock_writing (this=0x7f60b0d6b198) at /data/src/10.1-bug/sql/sql_cache.cc:919
#4  0x00007f60e1a304d9 in Query_cache::insert (this=0x7f60e2d0ee40 <query_cache>, thd=0x7f60bb780070, query_cache_tls=0x7f60bb780328, packet=0x7f60bb786070 "\t", length=13, pkt_nr=2) at /data/src/10.1-bug/sql/sql_cache.cc:1095
#5  0x00007f60e1a3038d in query_cache_insert (thd_arg=0x7f60bb780070, packet=0x7f60bb786070 "\t", length=13, pkt_nr=2) at /data/src/10.1-bug/sql/sql_cache.cc:1057
#6  0x00007f60e19c5352 in net_real_write (net=0x7f60bb780330, packet=0x7f60bb786070 "\t", len=13) at /data/src/10.1-bug/sql/net_serv.cc:606
#7  0x00007f60e19c4c81 in net_flush (net=0x7f60bb780330) at /data/src/10.1-bug/sql/net_serv.cc:363
#8  0x00007f60e19cb357 in net_send_ok (thd=0x7f60bb780070, server_status=2, statement_warn_count=0, affected_rows=1, id=1002, message=0x7f60bb784e7a "") at /data/src/10.1-bug/sql/protocol.cc:254
#9  0x00007f60e19cbc2c in Protocol::send_ok (this=0x7f60bb780600, server_status=2, statement_warn_count=0, affected_rows=1, last_insert_id=1002, message=0x7f60bb784e7a "") at /data/src/10.1-bug/sql/protocol.cc:557
#10 0x00007f60e19cbb58 in Protocol::end_statement (this=0x7f60bb780600) at /data/src/10.1-bug/sql/protocol.cc:526
#11 0x00007f60e1a81309 in dispatch_command (command=COM_QUERY, thd=0x7f60bb780070, packet=0x7f60bb786071 "", packet_length=60) at /data/src/10.1-bug/sql/sql_parse.cc:1940
#12 0x00007f60e1a7ea70 in do_command (thd=0x7f60bb780070) at /data/src/10.1-bug/sql/sql_parse.cc:1108
#13 0x00007f60e1bb4915 in do_handle_one_connection (thd_arg=0x7f60bb780070) at /data/src/10.1-bug/sql/sql_connect.cc:1350
#14 0x00007f60e1bb4679 in handle_one_connection (arg=0x7f60bb780070) at /data/src/10.1-bug/sql/sql_connect.cc:1262
#15 0x00007f60e117f0a4 in start_thread (arg=0x7f60e28deb00) at pthread_create.c:309
#16 0x00007f60df33787d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

MariaDB [test]> show processlist;
+----+------+-----------------+------+---------+------+------------------------------+--------------------------------------------------------------+----------+
| Id | User | Host            | db   | Command | Time | State                        | Info                                                         | Progress |
+----+------+-----------------+------+---------+------+------------------------------+--------------------------------------------------------------+----------+
|  3 | root | localhost:40404 | test | Query   |    0 | init                         | show processlist                                             |    0.000 |
|  8 | root | localhost:44682 | test | Query   |  551 | Waiting for query cache lock | SET GLOBAL query_cache_size = 256 * 1024                     |    0.000 |
|  9 | root | localhost:44683 | test | Killed  |  551 | updating status              | INSERT IGNORE INTO `t1` ( `id`, `pad` ) VALUES ( NULL, 'j' ) |    0.000 |
+----+------+-----------------+------+---------+------+------------------------------+--------------------------------------------------------------+----------+
3 rows in set (0.00 sec)

Comment by Elena Stepanova [ 2016-09-17 ]

Another one, with a non-deterministic MTR test:

160917 23:37:56 [ERROR] mysqld got signal 11 ;
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f87ac822088): SELECT SQL_CACHE `c` FROM `t1` WHERE `id` BETWEEN 29182 AND 5584
Connection ID (thread ID): 7
Status: NOT_KILLED

#3  <signal handler called>
#4  __memcpy_sse2_unaligned () at ../sysdeps/x86_64/multiarch/memcpy-sse2-unaligned.S:118
#5  0x00007f87b885ce89 in Query_cache::write_result_data (this=0x7f87b9b35e40 <query_cache>, result_block=0x7f87b96df1f0, data_len=59, data=0x7f87af0f3070 "\001", query_block=0x7f87adc2d148, type=Query_cache_block::RES_BEG) at /data/src/10.1-bug/sql/sql_cache.cc:3105
#6  0x00007f87b885cabb in Query_cache::append_result_data (this=0x7f87b9b35e40 <query_cache>, current_block=0x7f87b96df1f0, data_len=59, data=0x7f87af0f3070 "\001", query_block=0x7f87adc2d148) at /data/src/10.1-bug/sql/sql_cache.cc:3010
#7  0x00007f87b88575ad in Query_cache::insert (this=0x7f87b9b35e40 <query_cache>, thd=0x7f87af0df070, query_cache_tls=0x7f87af0df328, packet=0x7f87af0f3070 "\001", length=59, pkt_nr=5) at /data/src/10.1-bug/sql/sql_cache.cc:1109
#8  0x00007f87b885738d in query_cache_insert (thd_arg=0x7f87af0df070, packet=0x7f87af0f3070 "\001", length=59, pkt_nr=5) at /data/src/10.1-bug/sql/sql_cache.cc:1057
#9  0x00007f87b87ec352 in net_real_write (net=0x7f87af0df330, packet=0x7f87af0f3070 "\001", len=59) at /data/src/10.1-bug/sql/net_serv.cc:606
#10 0x00007f87b87ebc81 in net_flush (net=0x7f87af0df330) at /data/src/10.1-bug/sql/net_serv.cc:363
#11 0x00007f87b87f247d in net_send_eof (thd=0x7f87af0df070, server_status=2, statement_warn_count=0) at /data/src/10.1-bug/sql/protocol.cc:300
#12 0x00007f87b87f2c9a in Protocol::send_eof (this=0x7f87af0df600, server_status=2, statement_warn_count=0) at /data/src/10.1-bug/sql/protocol.cc:571
#13 0x00007f87b87f2abb in Protocol::end_statement (this=0x7f87af0df600) at /data/src/10.1-bug/sql/protocol.cc:519
#14 0x00007f87b88a83d5 in dispatch_command (command=COM_QUERY, thd=0x7f87af0df070, packet=0x7f87af0f3071 "", packet_length=64) at /data/src/10.1-bug/sql/sql_parse.cc:1940
#15 0x00007f87b88a5b3c in do_command (thd=0x7f87af0df070) at /data/src/10.1-bug/sql/sql_parse.cc:1108
#16 0x00007f87b89db9e1 in do_handle_one_connection (thd_arg=0x7f87af0df070) at /data/src/10.1-bug/sql/sql_connect.cc:1350
#17 0x00007f87b89db745 in handle_one_connection (arg=0x7f87af0df070) at /data/src/10.1-bug/sql/sql_connect.cc:1262
#18 0x00007f87b8cbe2ca in pfs_spawn_thread (arg=0x7f87b5824cf0) at /data/src/10.1-bug/storage/perfschema/pfs.cc:1860
#19 0x00007f87b7fa60a4 in start_thread (arg=0x7f87b96e0b00) at pthread_create.c:309
#20 0x00007f87b615e87d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

test case

--enable_connect_log
 
--connect (con2,localhost,root,,)
--disconnect con2
 
--connect (con3,localhost,root,,test)
CREATE TABLE `t1` (
 `id` int(10) unsigned NOT NULL auto_increment,
 `c` char(120) NOT NULL default '',
 `pad` char(60) NOT NULL default '',
 `k` int(10) unsigned NOT NULL default '0',
 /*Indices*/
 KEY `k` (`k`),
 PRIMARY KEY (`id`));
	INSERT /*! IGNORE */ INTO t1 VALUES  (NULL, 'o', 'know', -144375808) ,  (NULL, 'with', 'iqvdirlbf', NULL) ,  (NULL, 'b', 'n', NULL) ,  (NULL, 'that', 'qvdirlb', 9) ,  (NULL, 'vdi', 'tell', 0) ,  (NULL, 'dir', 'j', 2068578304) ,  (NULL, 'with', 'i', -1006632960) ,  (NULL, 'h', 'well', 3) ,  (NULL, 'don\'t', 'l', NULL) ,  (NULL, 'oh', 'm', -207224832) ,  (NULL, 'can', 'n', -437387264) ,  (NULL, 'on', 'y', 2) ,  (NULL, 'a', 'rlbfrpwdy', 1641086976) ,  (NULL, 'c', 'lbfrpwdy', 9) ,  (NULL, 'x', 't', 5) ,  (NULL, 'and', 'now', -971702272) ,  (NULL, 'bfrpwdyfxtix', 'frpwdyfxti', 8) ,  (NULL, 'rp', 'pwdyfx', NULL) ,  (NULL, 'wdyfxtixkzub', 'no', 1200750592) ,  (NULL, 'v', 'dy', NULL) ,  (NULL, 'at', 'was', 2) ,  (NULL, 'yfxtix', 'something', 7) ,  (NULL, 'fxtixkzuboml', 't', NULL) ,  (NULL, 't', 'x', NULL) ,  (NULL, 'as', 'e', 264044544) ,  (NULL, 'xtixkzuboml', 'got', -1222901760) ,  (NULL, 'ti', 'i', -1191116800) ,  (NULL, 'ixk', 'no', NULL) ,  (NULL, 'could', 'a', 1757413376) ,  (NULL, 'xkzubom', 'kzubomla', NULL) ,  (NULL, 'back', 'n', 2490368) ,  (NULL, 'zubo', 'w', 0) ,  (NULL, 'w', 'u', -417071104) ,  (NULL, 'g', 'or', -1366622208) ,  (NULL, 'oh', 'we', 3) ,  (NULL, 'got', 'ubomlaq', NULL) ,  (NULL, 'I\'m', 'there', NULL) ,  (NULL, 'if', 'boml', -1197932544) ,  (NULL, 'if', 'omlaqbnxmybb', 2) ,  (NULL, 'mlaqbnxmybbk', 'we', 6) ,  (NULL, 'laqbnxmybb', 'o', -470024192) ,  (NULL, 'aqbnx', 'qbnxmybbkx', NULL) ,  (NULL, 'just', 'one', NULL) ,  (NULL, 'bnxmyb', 'nxmybb', NULL) ,  (NULL, 'xmy', 'mybbkxanzlle', 5) ,  (NULL, 'f', 'm', -54460416) ,  (NULL, 'one', 'n', NULL) ,  (NULL, 'ybbkxanzll', 'q', -1036910592) ,  (NULL, 'who', 's', NULL) ,  (NULL, 'yes', 'j', 7);
	COMMIT;
--disconnect con3
 
--connect (con5,localhost,root,,test)
 
--connect (con7,localhost,root,,test)
--connect (con8,localhost,root,,test)
	SET GLOBAL query_cache_type = 1;
	SET optimizer_switch=(SELECT variable_value FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='optimizer_switch');
	SELECT SQL_CACHE `c` FROM `t1` WHERE `id` BETWEEN 61855 AND 18328 ORDER BY `pad`;
--connection con7
	SET GLOBAL query_cache_type = 0;
	SET GLOBAL query_cache_size = 64 * 1024;
	SET GLOBAL query_cache_type = 0;
	SET GLOBAL query_cache_type = 1;
	SET GLOBAL query_cache_type = 1;
--connection con8
--send
	SELECT SQL_CACHE `c` FROM `t1` WHERE `id` BETWEEN 29182 AND 5584;
--connection con7
	SET GLOBAL query_cache_type = 0;
	SET GLOBAL query_cache_type = 1;
--connection con8
--reap

perl ./mtr --nocheck-testcases --mysqld=--query-cache-type=1 --mysqld=--query-cache-size=1M bug.t7 --nowarnings

Comment by Elena Stepanova [ 2016-09-17 ]

#3  <signal handler called>
#4  0x00007f134cb441b1 in start_rwlock_wait_v1 (state=0x7f134d5643d0, rwlock=0xa5a5a5a5a5a5a5a5, op=PSI_RWLOCK_WRITELOCK, src_file=0x7f134d03b3f8 "/data/src/10.1-bug/sql/sql_cache.cc", src_line=919) at /data/src/10.1-bug/storage/perfschema/pfs.cc:2308
#5  0x00007f134c6dac1d in inline_mysql_rwlock_wrlock (that=0x7f134182d188, src_file=0x7f134d03b3f8 "/data/src/10.1-bug/sql/sql_cache.cc", src_line=919) at /data/src/10.1-bug/include/mysql/psi/mysql_thread.h:937
#6  0x00007f134c6e8f15 in Query_cache_query::lock_writing (this=0x7f134182d180) at /data/src/10.1-bug/sql/sql_cache.cc:919
#7  0x00007f134c6dca82 in Query_cache::end_of_result (this=0x7f134d9bae40 <query_cache>, thd=0x7f1342cdf070) at /data/src/10.1-bug/sql/sql_cache.cc:1206
#8  0x00007f134c72d3ee in dispatch_command (command=COM_QUIT, thd=0x7f1342cdf070, packet=0x7f1342cf3071 "", packet_length=0) at /data/src/10.1-bug/sql/sql_parse.cc:1941
#9  0x00007f134c72ab3c in do_command (thd=0x7f1342cdf070) at /data/src/10.1-bug/sql/sql_parse.cc:1108
#10 0x00007f134c8609e1 in do_handle_one_connection (thd_arg=0x7f1342cdf070) at /data/src/10.1-bug/sql/sql_connect.cc:1350
#11 0x00007f134c860745 in handle_one_connection (arg=0x7f1342cdf070) at /data/src/10.1-bug/sql/sql_connect.cc:1262
#12 0x00007f134cb432ca in pfs_spawn_thread (arg=0x7f1349424cf0) at /data/src/10.1-bug/storage/perfschema/pfs.cc:1860
#13 0x00007f134be2b0a4 in start_thread (arg=0x7f134d565b00) at pthread_create.c:309
#14 0x00007f1349fe387d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Comment by Elena Stepanova [ 2016-09-17 ]

Stack trace from a clean not tampered 10.1 build (bb2c1a52c61). Line numbers should be okay here.

#3  <signal handler called>
#4  0x00007fda408b711d in start_rwlock_wait_v1 (state=0x7fda412d3ee0, rwlock=0xa5a5a5a5a5a5a5a5, op=PSI_RWLOCK_WRITELOCK, src_file=0x7fda40dae1e0 "/data/src/10.1/sql/sql_cache.cc", src_line=919) at /data/src/10.1/storage/perfschema/pfs.cc:2308
#5  0x00007fda4044dc1d in inline_mysql_rwlock_wrlock (that=0x7fda3582f188, src_file=0x7fda40dae1e0 "/data/src/10.1/sql/sql_cache.cc", src_line=919) at /data/src/10.1/include/mysql/psi/mysql_thread.h:937
#6  0x00007fda4045be9b in Query_cache_query::lock_writing (this=0x7fda3582f180) at /data/src/10.1/sql/sql_cache.cc:919
#7  0x00007fda4044f4d9 in Query_cache::insert (this=0x7fda4172ae40 <query_cache>, thd=0x7fda36cdf070, query_cache_tls=0x7fda36cdf328, packet=0x7fda38816070 "\a", length=11, pkt_nr=2) at /data/src/10.1/sql/sql_cache.cc:1095
#8  0x00007fda4044f38d in query_cache_insert (thd_arg=0x7fda36cdf070, packet=0x7fda38816070 "\a", length=11, pkt_nr=2) at /data/src/10.1/sql/sql_cache.cc:1057
#9  0x00007fda403e4352 in net_real_write (net=0x7fda36cdf330, packet=0x7fda38816070 "\a", len=11) at /data/src/10.1/sql/net_serv.cc:606
#10 0x00007fda403e3c81 in net_flush (net=0x7fda36cdf330) at /data/src/10.1/sql/net_serv.cc:363
#11 0x00007fda403ea357 in net_send_ok (thd=0x7fda36cdf070, server_status=2, statement_warn_count=0, affected_rows=0, id=0, message=0x7fda36ce3e7a "") at /data/src/10.1/sql/protocol.cc:254
#12 0x00007fda403eac2c in Protocol::send_ok (this=0x7fda36cdf600, server_status=2, statement_warn_count=0, affected_rows=0, last_insert_id=0, message=0x7fda36ce3e7a "") at /data/src/10.1/sql/protocol.cc:557
#13 0x00007fda403eab58 in Protocol::end_statement (this=0x7fda36cdf600) at /data/src/10.1/sql/protocol.cc:526
#14 0x00007fda404a035b in dispatch_command (command=COM_QUERY, thd=0x7fda36cdf070, packet=0x7fda38816071 "", packet_length=17) at /data/src/10.1/sql/sql_parse.cc:1940
#15 0x00007fda4049dac2 in do_command (thd=0x7fda36cdf070) at /data/src/10.1/sql/sql_parse.cc:1108
#16 0x00007fda405d3967 in do_handle_one_connection (thd_arg=0x7fda36cdf070) at /data/src/10.1/sql/sql_connect.cc:1350
#17 0x00007fda405d36cb in handle_one_connection (arg=0x7fda36cdf070) at /data/src/10.1/sql/sql_connect.cc:1262
#18 0x00007fda408b6236 in pfs_spawn_thread (arg=0x7fda36ceb5f0) at /data/src/10.1/storage/perfschema/pfs.cc:1860
#19 0x00007fda3fb9e0a4 in start_thread (arg=0x7fda412d5b00) at pthread_create.c:309
#20 0x00007fda3dd5687d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

160918  0:26:05 [ERROR] mysqld got signal 11 ;
...
Server version: 10.1.18-MariaDB-debug
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=4
max_threads=153
thread_count=4
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 62983 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0x7fda36cdf070
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 = 0x7fda412d5230 thread_stack 0x48400
/data/bld/10.1/bin/mysqld(my_print_stacktrace+0x38)[0x7fda40d34ff3]
/data/bld/10.1/bin/mysqld(handle_fatal_signal+0x399)[0x7fda406d9158]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0)[0x7fda3fba58d0]
/data/bld/10.1/bin/mysqld(+0x8e111d)[0x7fda408b711d]
mysys/stacktrace.c:267(my_print_stacktrace)[0x7fda4044dc1d]
sql/sql_cache.cc:919(Query_cache_query::lock_writing())[0x7fda4045be9b]
sql/sql_cache.cc:1096(Query_cache::insert(THD*, Query_cache_tls*, char const*, unsigned long, unsigned int))[0x7fda4044f4d9]
sql/sql_cache.cc:1058(query_cache_insert(void*, char const*, unsigned long, unsigned int))[0x7fda4044f38d]
sql/net_serv.cc:609(net_real_write)[0x7fda403e4352]
sql/net_serv.cc:364(net_flush)[0x7fda403e3c81]
sql/protocol.cc:254(net_send_ok(THD*, unsigned int, unsigned int, unsigned long long, unsigned long long, char const*))[0x7fda403ea357]
sql/protocol.cc:557(Protocol::send_ok(unsigned int, unsigned int, unsigned long long, unsigned long long, char const*))[0x7fda403eac2c]
sql/protocol.cc:526(Protocol::end_statement())[0x7fda403eab58]
sql/sql_parse.cc:1941(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x7fda404a035b]
sql/sql_parse.cc:1108(do_command(THD*))[0x7fda4049dac2]
sql/sql_connect.cc:1350(do_handle_one_connection(THD*))[0x7fda405d3967]
sql/sql_connect.cc:1263(handle_one_connection)[0x7fda405d36cb]
perfschema/pfs.cc:1862(pfs_spawn_thread)[0x7fda408b6236]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x80a4)[0x7fda3fb9e0a4]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fda3dd5687d]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fda3442d088): RESET QUERY CACHE
Connection ID (thread ID): 13
Status: KILL_CONNECTION

Test case

--disable_abort_on_error
--enable_connect_log
 
--connect (con2,localhost,root,,)
--disconnect con2
 
--connect (con3,localhost,root,,test)
CREATE TABLE `t1` (
 `id` int(10) unsigned NOT NULL auto_increment,
 `c` char(120) NOT NULL default '',
 `pad` char(60) NOT NULL default '',
 `k` int(10) unsigned NOT NULL default '0',
 /*Indices*/
 KEY `k` (`k`),
 PRIMARY KEY (`id`));
	INSERT /*! IGNORE */ INTO t1 VALUES  (NULL, 'o', 'know', -144375808) ,  (NULL, 'with', 'iqvdirlbf', NULL) ,  (NULL, 'b', 'n', NULL) ,  (NULL, 'that', 'qvdirlb', 9) ,  (NULL, 'vdi', 'tell', 0) ,  (NULL, 'dir', 'j', 2068578304) ,  (NULL, 'with', 'i', -1006632960) ,  (NULL, 'h', 'well', 3) ,  (NULL, 'don\'t', 'l', NULL) ,  (NULL, 'oh', 'm', -207224832) ,  (NULL, 'can', 'n', -437387264) ,  (NULL, 'on', 'y', 2) ,  (NULL, 'a', 'rlbfrpwdy', 1641086976) ,  (NULL, 'c', 'lbfrpwdy', 9) ,  (NULL, 'x', 't', 5) ,  (NULL, 'and', 'now', -971702272) ,  (NULL, 'bfrpwdyfxtix', 'frpwdyfxti', 8) ,  (NULL, 'rp', 'pwdyfx', NULL) ,  (NULL, 'wdyfxtixkzub', 'no', 1200750592) ,  (NULL, 'v', 'dy', NULL) ,  (NULL, 'at', 'was', 2) ,  (NULL, 'yfxtix', 'something', 7) ,  (NULL, 'fxtixkzuboml', 't', NULL) ,  (NULL, 't', 'x', NULL) ,  (NULL, 'as', 'e', 264044544) ,  (NULL, 'xtixkzuboml', 'got', -1222901760) ,  (NULL, 'ti', 'i', -1191116800) ,  (NULL, 'ixk', 'no', NULL) ,  (NULL, 'could', 'a', 1757413376) ,  (NULL, 'xkzubom', 'kzubomla', NULL) ,  (NULL, 'back', 'n', 2490368) ,  (NULL, 'zubo', 'w', 0) ,  (NULL, 'w', 'u', -417071104) ,  (NULL, 'g', 'or', -1366622208) ,  (NULL, 'oh', 'we', 3) ,  (NULL, 'got', 'ubomlaq', NULL) ,  (NULL, 'I\'m', 'there', NULL) ,  (NULL, 'if', 'boml', -1197932544) ,  (NULL, 'if', 'omlaqbnxmybb', 2) ,  (NULL, 'mlaqbnxmybbk', 'we', 6) ,  (NULL, 'laqbnxmybb', 'o', -470024192) ,  (NULL, 'aqbnx', 'qbnxmybbkx', NULL) ,  (NULL, 'just', 'one', NULL) ,  (NULL, 'bnxmyb', 'nxmybb', NULL) ,  (NULL, 'xmy', 'mybbkxanzlle', 5) ,  (NULL, 'f', 'm', -54460416) ,  (NULL, 'one', 'n', NULL) ,  (NULL, 'ybbkxanzll', 'q', -1036910592) ,  (NULL, 'who', 's', NULL) ,  (NULL, 'yes', 'j', 7);
	COMMIT;
--disconnect con3
 
--connect (con5,localhost,root,,test)
 
--connect (con7,localhost,root,,test)
--connect (con8,localhost,root,,test)
	SET GLOBAL query_cache_type = 1;
	SET optimizer_switch=(SELECT variable_value FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='optimizer_switch');
	SELECT SQL_CACHE `c` FROM `t1` WHERE `id` BETWEEN 61855 AND 18328 ORDER BY `pad`;
--connection con7
	SET GLOBAL query_cache_type = 0;
	SET GLOBAL query_cache_size = 64 * 1024;
	SET GLOBAL query_cache_type = 0;
	SET GLOBAL query_cache_type = 1;
	SET GLOBAL query_cache_type = 1;
--connection con8
--send
	SELECT SQL_CACHE `c` FROM `t1` WHERE `id` BETWEEN 29182 AND 5584;
--connection con7
	SET GLOBAL query_cache_type = 0;
	SET GLOBAL query_cache_type = 1;
--connection con8
--reap
	RESET QUERY CACHE;

threads5

Comment by Elena Stepanova [ 2016-09-19 ]

Got another one worth storing (I'll re-arrange comments later to make sure test cases are not lost). It was on a heavily tampered version, so line numbers don't make much sense.

# 2016-09-20T00:17:37 [25991] Program terminated with signal SIGSEGV, Segmentation fault.
# 2016-09-20T00:17:37 [25991] #0  __GI___pthread_mutex_lock (mutex=0x0) at ../nptl/pthread_mutex_lock.c:66
# 2016-09-20T00:17:37 [25991] #0  __GI___pthread_mutex_lock (mutex=0x0) at ../nptl/pthread_mutex_lock.c:66
# 2016-09-20T00:17:37 [25991] #1  0x00007fce13d704b2 in ?? () from /usr/lib/x86_64-linux-gnu/libjemalloc.so.1
# 2016-09-20T00:17:37 [25991] #2  0x00007fce13d8c92f in ?? () from /usr/lib/x86_64-linux-gnu/libjemalloc.so.1
# 2016-09-20T00:17:37 [25991] #3  0x00007fce13d69172 in malloc () from /usr/lib/x86_64-linux-gnu/libjemalloc.so.1
# 2016-09-20T00:17:37 [25991] #4  0x00007fce1301f2e8 in operator new(unsigned long) () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
# 2016-09-20T00:17:37 [25991] #5  0x00007fce154d7c6e in __gnu_cxx::new_allocator<sync_level_t>::allocate (this=0x7fcde2c61040, __n=1) at /usr/include/c++/4.9/ext/new_allocator.h:104
# 2016-09-20T00:17:37 [25991] #6  0x00007fce154d7aa2 in __gnu_cxx::__alloc_traits<std::allocator<sync_level_t> >::allocate (__a=..., __n=1) at /usr/include/c++/4.9/ext/alloc_traits.h:182
# 2016-09-20T00:17:37 [25991] #7  0x00007fce154d7884 in std::_Vector_base<sync_level_t, std::allocator<sync_level_t> >::_M_allocate (this=0x7fcde2c61040, __n=1) at /usr/include/c++/4.9/bits/stl_vector.h:170
# 2016-09-20T00:17:37 [25991] #8  0x00007fce154d73ce in std::vector<sync_level_t, std::allocator<sync_level_t> >::_M_insert_aux (this=0x7fcde2c61040, __position=<error reading variable: Cannot access memory at address 0x0>, __x=...) at /usr/include/c++/4.9/bits/vector.tcc:353
# 2016-09-20T00:17:37 [25991] #9  0x00007fce154d7018 in std::vector<sync_level_t, std::allocator<sync_level_t> >::push_back (this=0x7fcde2c61040, __x=...) at /usr/include/c++/4.9/bits/stl_vector.h:925
# 2016-09-20T00:17:37 [25991] #10 0x00007fce154d6672 in sync_thread_add_level (latch=0x7fce11c2d478, level=135, relock=0) at /data/src/10.1-bug/storage/xtradb/sync/sync0sync.cc:1443
# 2016-09-20T00:17:37 [25991] #11 0x00007fce154d4f42 in mutex_set_debug_info (mutex=0x7fce11c2d478, file_name=0x7fce159ec8a0 "/data/src/10.1-bug/storage/xtradb/fil/fil0fil.cc", line=6248) at /data/src/10.1-bug/storage/xtradb/sync/sync0sync.cc:732
# 2016-09-20T00:17:37 [25991] #12 0x00007fce155cb407 in mutex_enter_func (mutex=0x7fce11c2d478, file_name=0x7fce159ec8a0 "/data/src/10.1-bug/storage/xtradb/fil/fil0fil.cc", line=6248) at /data/src/10.1-bug/storage/xtradb/include/sync0sync.ic:271
# 2016-09-20T00:17:37 [25991] #13 0x00007fce155cb505 in pfs_mutex_enter_func (mutex=0x7fce11c2d478, file_name=0x7fce159ec8a0 "/data/src/10.1-bug/storage/xtradb/fil/fil0fil.cc", line=6248) at /data/src/10.1-bug/storage/xtradb/include/sync0sync.ic:381
# 2016-09-20T00:17:37 [25991] #14 0x00007fce155d8e95 in fil_flush (space_id=4294967280) at /data/src/10.1-bug/storage/xtradb/fil/fil0fil.cc:6248
# 2016-09-20T00:17:37 [25991] #15 0x00007fce153d6bbb in log_write_up_to (lsn=3039836, wait=92, flush_to_disk=1) at /data/src/10.1-bug/storage/xtradb/log/log0log.cc:1739
# 2016-09-20T00:17:37 [25991] #16 0x00007fce154fc21c in trx_flush_log_if_needed_low (lsn=3039836, trx=0x7fcde2c8f678) at /data/src/10.1-bug/storage/xtradb/trx/trx0trx.cc:1362
# 2016-09-20T00:17:37 [25991] #17 0x00007fce154fc289 in trx_flush_log_if_needed (lsn=3039836, trx=0x7fcde2c8f678) at /data/src/10.1-bug/storage/xtradb/trx/trx0trx.cc:1386
# 2016-09-20T00:17:37 [25991] #18 0x00007fce154fdbb9 in trx_commit_complete_for_mysql (trx=0x7fcde2c8f678) at /data/src/10.1-bug/storage/xtradb/trx/trx0trx.cc:1975
# 2016-09-20T00:17:37 [25991] #19 0x00007fce1535e4a6 in innobase_commit (hton=0x7fce11c24a70, thd=0x7fcdeeb8b070, commit_trx=false) at /data/src/10.1-bug/storage/xtradb/handler/ha_innodb.cc:4881
# 2016-09-20T00:17:37 [25991] #20 0x00007fce1516ecc7 in commit_one_phase_2 (thd=0x7fcdeeb8b070, all=false, trans=0x7fcdeeb8e1c8, is_real_trans=true) at /data/src/10.1-bug/sql/handler.cc:1556
# 2016-09-20T00:17:37 [25991] #21 0x00007fce1516ebec in ha_commit_one_phase (thd=0x7fcdeeb8b070, all=false) at /data/src/10.1-bug/sql/handler.cc:1537
# 2016-09-20T00:17:37 [25991] #22 0x00007fce1516e4d9 in ha_commit_trans (thd=0x7fcdeeb8b070, all=false) at /data/src/10.1-bug/sql/handler.cc:1404
# 2016-09-20T00:17:37 [25991] #23 0x00007fce1507a55e in trans_commit_stmt (thd=0x7fcdeeb8b070) at /data/src/10.1-bug/sql/transaction.cc:434
# 2016-09-20T00:17:37 [25991] #24 0x00007fce14f3de31 in mysql_execute_command (thd=0x7fcdeeb8b070) at /data/src/10.1-bug/sql/sql_parse.cc:5739
# 2016-09-20T00:17:37 [25991] #25 0x00007fce14f41f86 in mysql_parse (thd=0x7fcdeeb8b070, rawbuf=0x7fcde2c22088 "", length=58, parser_state=0x7fce14a60630) at /data/src/10.1-bug/sql/sql_parse.cc:7341
# 2016-09-20T00:17:37 [25991] #26 0x00007fce14f3054d in dispatch_command (command=COM_QUERY, thd=0x7fcdeeb8b070, packet=0x7fcdeeb91071 "INSERT IGNORE INTO `t1` ( `id`, `c` ) VALUES ( NULL, 'p' )", packet_length=58) at /data/src/10.1-bug/sql/sql_parse.cc:1492
# 2016-09-20T00:17:37 [25991] #27 0x00007fce14f2f1f6 in do_command (thd=0x7fcdeeb8b070) at /data/src/10.1-bug/sql/sql_parse.cc:1110
# 2016-09-20T00:17:37 [25991] #28 0x00007fce150658e3 in do_handle_one_connection (thd_arg=0x7fcdeeb8b070) at /data/src/10.1-bug/sql/sql_connect.cc:1350
# 2016-09-20T00:17:37 [25991] #29 0x00007fce15065647 in handle_one_connection (arg=0x7fcdeeb8b070) at /data/src/10.1-bug/sql/sql_connect.cc:1262
# 2016-09-20T00:17:37 [25991] #30 0x00007fce1462e0a4 in start_thread (arg=0x7fce14a61b00) at pthread_create.c:309
# 2016-09-20T00:17:37 [25991] #31 0x00007fce127e687d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Comment by Elena Stepanova [ 2017-09-18 ]

10.0 725e47bfb52

mysqld: /data/src/10.0-bug/sql/sql_cache.cc:1180: void Query_cache::end_of_result(THD*): Assertion `thd->get_stmt_da()->is_eof()' failed.
170919  0:52:58 [ERROR] 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.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
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.
 
Server version: 10.0.31-MariaDB-debug
key_buffer_size=33554432
read_buffer_size=2097152
max_used_connections=47
max_threads=501
thread_count=48
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 3113992 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x7f0a13e27070
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 = 0x7f0a25c88d68 thread_stack 0x48000
mysys/stacktrace.c:267(my_print_stacktrace)[0xe2430b]
sql/signal_handler.cc:161(handle_fatal_signal)[0x836415]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x110c0)[0x7f0a43b8c0c0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcf)[0x7f0a41c17fcf]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f0a41c193fa]
/lib/x86_64-linux-gnu/libc.so.6(+0x2be37)[0x7f0a41c10e37]
/lib/x86_64-linux-gnu/libc.so.6(+0x2bee2)[0x7f0a41c10ee2]
sql/sql_cache.cc:1182(Query_cache::end_of_result(THD*))[0x5fea0b]
sql/sql_parse.cc:1736(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x649c24]
sql/sql_parse.cc:999(do_command(THD*))[0x647ab1]
sql/threadpool_common.cc:271(threadpool_process_request(THD*))[0x7bb864]
sql/threadpool_unix.cc:1450(handle_event(connection_t*))[0x7fd340]
sql/threadpool_unix.cc:1499(worker_main(void*))[0x7fd50a]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7494)[0x7f0a43b82494]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f0a41ccd93f]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f0a1e392088): UNLOCK TABLES /* QNO 63 CON_ID 55 */
Connection ID (thread ID): 65
Status: NOT_KILLED

perl ./runall-new.pl --redefine=mdev13828.yy --grammar=conf/runtime/WL5004_sql.yy --gendata=conf/runtime/WL5004_data.zz   --basedir=/data/src/10.0-bug --duration=400 --threads=64 --queries=100M --vardir=/data/logs/analyze1 --mysqld=--optimizer-switch='index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on' --engine=MyISAM --mysqld=--log-bin=master-bin --mysqld=--binlog_format=ROW --mysqld=--binlog_annotate_row_events=1 --mysqld=--binlog_commit_wait_count=10 --mysqld=--binlog_commit_wait_usec=10000 --mysqld=--transaction_isolation=READ-COMMITTED --mysqld=--thread_handling=pool-of-threads --mysqld=--event_scheduler=ON --mysqld=--thread_cache_size=128 --mysqld=--sort_buffer_size=4M --mysqld=--bulk_insert_buffer_size=16M --mysqld=--tmp_table_size=32M --mysqld=--max_heap_table_size=32M --mysqld=--myisam_recover=BACKUP --mysqld=--key_buffer_size=32M --mysqld=--table_open_cache=1024 --mysqld=--table_definition_cache=1024 --mysqld=--myisam_sort_buffer_size=512M --mysqld=--concurrent_insert=2 --mysqld=--read_buffer_size=2M --mysqld=--read_rnd_buffer_size=1M --mysqld=--query_cache_limit=128K --mysqld=--query_cache_size=4M --mysqld=--log_warnings=1 --mysqld=--slow_query_log=1 --mysqld=--long_query_time=0.1 --mysqld=--log_slow_verbosity=innodb,query_plan --mysqld=--server-id=111

mdev13828.yy

thread5_init:
  CREATE TABLE IF NOT EXISTS `market_orders` (
  `label` CHAR(20) NOT NULL,
  `ordertype` TINYINT(4) NOT NULL,
  `price` DECIMAL(20,10) NOT NULL,
  `quantity` DECIMAL(20,10) NOT NULL,
  `total` DECIMAL(20,10) NOT NULL,
  `timestamp` TIMESTAMP NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  KEY `idx_ob_extract` (`label`,`ordertype`)
  ) ENGINE=MyISAM;
 
 
thread3_init:
  thread5_init;
  
thread4_init:
  thread5_init;
 
thread6_init:
  thread5_init;
 
thread7_init:
  thread5_init;
 
thread8_init:
  thread5_init;
 
thread5:
    select | 
    update |
    delete |
    insert
;
 
thread6:
  thread5;
 
thread7:
  thread5;
  
thread8:
  thread5;
 
insert:
    INSERT IGNORE INTO `market_orders` ( `ordertype` ) VALUES ( _digit ) |
    INSERT IGNORE INTO `market_orders` ( `price` ) VALUES ( _smallint_unsigned ) |
    INSERT IGNORE INTO `market_orders` ( `label` ) VALUES ( _string ) |
    INSERT IGNORE INTO `market_orders` ( `ordertype`, `price`)  VALUES ( _digit, _smallint_unsigned ) |
    INSERT IGNORE INTO `market_orders` ( `ordertype`, `label` ) VALUES ( _digit, _string ) 
;
 
update:
    index_update |
    non_index_update
;
 
delete:
    DELETE FROM `market_orders` WHERE `ordertype` = _digit ;
 
index_update:
    UPDATE IGNORE `market_orders` SET `price` = `price` + 1 WHERE `ordertype` = _digit ;
 
non_index_update:
    UPDATE `market_orders` SET `label` = _string WHERE `price` = _smallint_unsigned ;
 
select:
    point_select |
    simple_range |
    sum_range |
    order_range 
;
 
point_select:
    SELECT * FROM `market_orders` WHERE `price` = _smallint_unsigned ;
 
simple_range:
    SELECT * FROM `market_orders` WHERE `ordertype` BETWEEN _digit_ AND 10 ;
 
sum_range:
    SELECT SUM(`price`) FROM `market_orders` WHERE `price` BETWEEN _smallint_unsigned AND _smallint_unsigned ;
 
order_range:
    SELECT * FROM `market_orders` WHERE `ordertype` BETWEEN _digit AND 10 ORDER BY `label` ;
 
thread3:
  CREATE TABLE `market_orders_new` LIKE `market_orders` ; RENAME TABLE `market_orders`  TO `market_orders_atomic`, `market_orders_new` TO `market_orders` ; INSERT INTO `market_orders` SELECT * FROM `market_orders_atomic` LIMIT 1000; DROP TABLE `market_orders_atomic`
;
 
thread4:
  thread3
;

Comment by Alice Sherepa [ 2022-07-14 ]

still reproducible:

10.10

 
mysqld: /10.10/sql/sql_cache.cc:1175: void Query_cache::end_of_result(THD*): Assertion `thd->get_stmt_da()->is_eof()' failed.
220714 12:44:56 [ERROR] mysqld got signal 6 ;
 
Server version: 10.10.0-MariaDB-debug-log
 
??:0(__restore_rt)[0x7f2c992f9730]
linux/raise.c:51(__GI_raise)[0x7f2c98e367bb]
stdlib/abort.c:81(__GI_abort)[0x7f2c98e21535]
??:0(__assert_fail)[0x7f2c98e2f102]
sql/sql_cache.cc:1177(Query_cache::end_of_result(THD*))[0x56166bfd0685]
sql/sql_parse.cc:2404(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool))[0x56166c13b2db]
sql/sql_parse.cc:1407(do_command(THD*, bool))[0x56166c134f31]
sql/sql_connect.cc:1418(do_handle_one_connection(CONNECT*, bool))[0x56166c5d4c8d]
sql/sql_connect.cc:1314(handle_one_connection)[0x56166c5d4512]
perfschema/pfs.cc:2203(pfs_spawn_thread)[0x56166d27341b]
nptl/pthread_create.c:487(start_thread)[0x7f2c992eefa3]
x86_64/clone.S:97(clone)[0x7f2c98ef7eff]
 
Query (0x6290016262a8): SELECT  MAX( `id` ) FROM `E` WHERE ( ( `pk` = 255 ) AND `col_int_key` IN ( 0, 1, 255 ) ) AND ( ( ( `col_int_nokey` = 5 ) OR `col_int_nokey` IN ( 32, 255, 255 ) ) AND ( `col_varchar_key` LIKE CONCAT ('New Hampshire', '%' ) OR `col_varchar_nokey` BETWEEN 'ihmmynr' AND 'v' ) AND ( `col_varchar_key` BETWEEN 'hmmynr' AND 'mmy' OR `col_varchar_nokey` BETWEEN 'Georgia' AND 'mynrqex' ) ) AND ( `col_int_key` IN ( 0, 0 ) AND ( `pk` = 1 ) ) AND ( ( `col_varchar_key` LIKE CONCAT ('gather', '%' ) AND ( `col_varchar_key` = 'y' ) ) AND ( NOT ( `col_varchar_key` = 'w' ) OR `col_varchar_nokey` LIKE CONCAT ('s', '%' ) ) )

Comment by Roel Van de Paar [ 2024-01-05 ]

Seen in 11.1

11.1.4 50799752dc6306c35a47405c8f556d0b9639a1a9 (Debug)

mariadbd: /test/11.1_dbg/sql/sql_cache.cc:1178: void Query_cache::end_of_result(THD*): Assertion `thd->get_stmt_da()->is_eof()' failed.

11.1.4 50799752dc6306c35a47405c8f556d0b9639a1a9 (Debug)

Core was generated by `/test/MD271223-mariadb-11.1.4-linux-x86_64-dbg/bin/mariadbd --no-defaults --max'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=22729820096064)
    at ./nptl/pthread_kill.c:44
[Current thread is 1 (Thread 0x14ac32da4640 (LWP 655920))]
(gdb) bt
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=22729820096064) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=22729820096064) at ./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=22729820096064, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3  0x000014b091042476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4  0x000014b0910287f3 in __GI_abort () at ./stdlib/abort.c:79
#5  0x000014b09102871b in __assert_fail_base (fmt=0x14b0911dd130 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55924e11f142 "thd->get_stmt_da()->is_eof()", file=0x55924e11f180 "/test/11.1_dbg/sql/sql_cache.cc", line=1178, function=<optimized out>) at ./assert/assert.c:92
#6  0x000014b091039e96 in __GI___assert_fail (assertion=0x55924e11f142 "thd->get_stmt_da()->is_eof()", file=0x55924e11f180 "/test/11.1_dbg/sql/sql_cache.cc", line=1178, function=0x55924e11f788 "void Query_cache::end_of_result(THD*)") at ./assert/assert.c:101
#7  0x000055924d4c552a in Query_cache::end_of_result (this=0x55924eb8dde0 <query_cache>, thd=thd@entry=0x14acb418ab88) at /test/11.1_dbg/sql/sql_cache.cc:1178
#8  0x000055924d540c8b in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14acb418ab88, packet=<optimized out>, packet@entry=0x14acb41bf6c9 "", packet_length=packet_length@entry=180, blocking=blocking@entry=true) at /test/11.1_dbg/sql/sql_parse.cc:2402
#9  0x000055924d5415f4 in do_command (thd=0x14acb418ab88, blocking=blocking@entry=true) at /test/11.1_dbg/sql/sql_parse.cc:1405
#10 0x000055924d6a4139 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x5592503203e8, put_in_cache=put_in_cache@entry=true) at /test/11.1_dbg/sql/sql_connect.cc:1415
#11 0x000055924d6a442e in handle_one_connection (arg=arg@entry=0x5592503203e8) at /test/11.1_dbg/sql/sql_connect.cc:1317
#12 0x000055924dad72d2 in pfs_spawn_thread (arg=0x559250320458) at /test/11.1_dbg/storage/perfschema/pfs.cc:2201
#13 0x000014b091094ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#14 0x000014b091126660 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

And

11.1.4 50799752dc6306c35a47405c8f556d0b9639a1a9 (Debug)

Core was generated by `/test/MD271223-mariadb-11.1.4-linux-x86_64-dbg/bin/mariadbd --no-defaults --max'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  inline_mysql_rwlock_wrlock (src_line=921,
    src_file=0x557d1d305180 "/test/11.1_dbg/sql/sql_cache.cc",
    that=0x1480361448c0) at /test/11.1_dbg/include/mysql/psi/mysql_thread.h:931
[Current thread is 1 (Thread 0x1482ccc8c640 (LWP 180966))]
(gdb) bt
#0  inline_mysql_rwlock_wrlock (src_line=921, src_file=0x557d1d305180 "/test/11.1_dbg/sql/sql_cache.cc", that=0x1480361448c0) at /test/11.1_dbg/include/mysql/psi/mysql_thread.h:931
#1  Query_cache_query::lock_writing (this=0x1480361448b8) at /test/11.1_dbg/sql/sql_cache.cc:921
#2  Query_cache::insert (this=0x557d1dd73de0 <query_cache>, thd=thd@entry=0x148084000d58, query_cache_tls=query_cache_tls@entry=0x148084001098, packet=packet@entry=0x14808400b158 "\002", length=258, pkt_nr=10) at /test/11.1_dbg/sql/sql_cache.cc:1097
#3  0x0000557d1c6ab1e4 in query_cache_insert (thd_arg=thd_arg@entry=0x148084000d58, packet=packet@entry=0x14808400b158 "\002", length=<optimized out>, pkt_nr=<optimized out>) at /test/11.1_dbg/sql/sql_cache.cc:1057
#4  0x0000557d1cb9ef64 in net_real_write (net=net@entry=0x1480840010a0, packet=0x14808400b158 "\002", len=<optimized out>) at /test/11.1_dbg/sql/net_serv.cc:660
#5  0x0000557d1cb9f2af in net_flush (net=0x1480840010a0) at /test/11.1_dbg/sql/net_serv.cc:402
#6  0x0000557d1c62ca26 in Protocol::net_send_eof (this=<optimized out>, thd=0x148084000d58, server_status=<optimized out>, statement_warn_count=<optimized out>) at /test/11.1_dbg/sql/protocol.cc:351
#7  0x0000557d1c62c516 in Protocol::send_eof (this=<optimized out>, server_status=<optimized out>, statement_warn_count=<optimized out>) at /test/11.1_dbg/sql/protocol.cc:657
#8  0x0000557d1c62e752 in Protocol::end_statement (this=0x148084001370) at /test/11.1_dbg/sql/sql_error.h:1091
#9  0x0000557d1c726c7c in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x148084000d58, packet=<optimized out>, packet@entry=0x14808400b159 "", packet_length=packet_length@entry=110, blocking=blocking@entry=true) at /test/11.1_dbg/sql/sql_parse.cc:2401
#10 0x0000557d1c7275f4 in do_command (thd=0x148084000d58, blocking=blocking@entry=true) at /test/11.1_dbg/sql/sql_parse.cc:1405
#11 0x0000557d1c88a139 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x557d209ff338, put_in_cache=put_in_cache@entry=true) at /test/11.1_dbg/sql/sql_connect.cc:1415
#12 0x0000557d1c88a42e in handle_one_connection (arg=arg@entry=0x557d209ff338) at /test/11.1_dbg/sql/sql_connect.cc:1317
#13 0x0000557d1ccbd2d2 in pfs_spawn_thread (arg=0x557d209ff3a8) at /test/11.1_dbg/storage/perfschema/pfs.cc:2201
#14 0x00001482f7894ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#15 0x00001482f7926660 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

And (new stack)

11.1.4 50799752dc6306c35a47405c8f556d0b9639a1a9 (Debug)

Core was generated by `/test/MD271223-mariadb-11.1.4-linux-x86_64-dbg/bin/mariadbd --no-defaults --max'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x0000556090655ccd in my_hash_sort_bin (cs=<optimized out>,
    key=0x14904023b000 "", len=93873217384309, nr1=0x148e1bb1df20,
    nr2=0x148e1bb1df28) at /test/11.1_dbg/strings/ctype-bin.c:302
[Current thread is 1 (Thread 0x148e1bb1f640 (LWP 2992370))]
(gdb) bt
#0  0x0000556090655ccd in my_hash_sort_bin (cs=<optimized out>, key=0x14904023b000 "", len=93873217384309, nr1=0x148e1bb1df20, nr2=0x148e1bb1df28) at /test/11.1_dbg/strings/ctype-bin.c:302
#1  0x000055609061a3da in my_ci_hash_sort (nr2=0x148e1bb1df28, nr1=0x148e1bb1df20, len=<optimized out>, key=<optimized out>, ci=<optimized out>) at /test/11.1_dbg/include/m_ctype.h:1354
#2  my_hash_sort (cs=<optimized out>, key=<optimized out>, length=<optimized out>) at /test/11.1_dbg/mysys/hash.c:48
#3  0x000055609061abd4 in rec_hashnr (record=0x1490401f74c0 "j\265ȏ`U", hash=0x55609126af68 <query_cache+392>) at /test/11.1_dbg/mysys/hash.c:229
#4  my_hash_delete (hash=0x55609126af68 <query_cache+392>, record=0x1490401f74c0 "j\265ȏ`U") at /test/11.1_dbg/mysys/hash.c:575
#5  0x000055608fb9e7bd in Query_cache::free_query (this=this@entry=0x55609126ade0 <query_cache>, query_block=0x1490401f74c0) at /test/11.1_dbg/sql/sql_cache.cc:3016
#6  0x000055608fba2190 in Query_cache::insert (this=0x55609126ade0 <query_cache>, thd=thd@entry=0x148f94119048, query_cache_tls=query_cache_tls@entry=0x148f94119388, packet=packet@entry=0x148f941200b8 "\002", length=258, pkt_nr=10) at /test/11.1_dbg/sql/sql_cache.cc:1116
#7  0x000055608fba21e4 in query_cache_insert (thd_arg=thd_arg@entry=0x148f94119048, packet=packet@entry=0x148f941200b8 "\002", length=<optimized out>, pkt_nr=<optimized out>) at /test/11.1_dbg/sql/sql_cache.cc:1057
#8  0x0000556090095f64 in net_real_write (net=net@entry=0x148f94119390, packet=0x148f941200b8 "\002", len=<optimized out>) at /test/11.1_dbg/sql/net_serv.cc:660
#9  0x00005560900962af in net_flush (net=0x148f94119390) at /test/11.1_dbg/sql/net_serv.cc:402
#10 0x000055608fb23a26 in Protocol::net_send_eof (this=<optimized out>, thd=0x148f94119048, server_status=<optimized out>, statement_warn_count=<optimized out>) at /test/11.1_dbg/sql/protocol.cc:351
#11 0x000055608fb23516 in Protocol::send_eof (this=<optimized out>, server_status=<optimized out>, statement_warn_count=<optimized out>) at /test/11.1_dbg/sql/protocol.cc:657
#12 0x000055608fb25752 in Protocol::end_statement (this=0x148f94119660) at /test/11.1_dbg/sql/sql_error.h:1091
#13 0x000055608fc1dc7c in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x148f94119048, packet=<optimized out>, packet@entry=0x148f941200b9 "", packet_length=packet_length@entry=142, blocking=blocking@entry=true) at /test/11.1_dbg/sql/sql_parse.cc:2401
#14 0x000055608fc1e5f4 in do_command (thd=0x148f94119048, blocking=blocking@entry=true) at /test/11.1_dbg/sql/sql_parse.cc:1405
#15 0x000055608fd81139 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55609433d588, put_in_cache=put_in_cache@entry=true) at /test/11.1_dbg/sql/sql_connect.cc:1415
#16 0x000055608fd8142e in handle_one_connection (arg=arg@entry=0x55609433d588) at /test/11.1_dbg/sql/sql_connect.cc:1317
#17 0x00005560901b42d2 in pfs_spawn_thread (arg=0x55609433d5f8) at /test/11.1_dbg/storage/perfschema/pfs.cc:2201
#18 0x000014925f694ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#19 0x000014925f726660 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

NTS: mariadb-qa/BUGS/MDEV-10826.sql (readily reproducible using pquery w/ 8k threads)

Comment by Roel Van de Paar [ 2024-01-05 ]

Also in 11.3

11.3.2 63fb478f88e0061d149f5cdd3c4d21d4a35c7bd9 (Debug)

Core was generated by `/test/MD271223-mariadb-11.3.2-linux-x86_64-dbg/bin/mariadbd --no-defaults --max'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  inline_mysql_rwlock_wrlock (src_line=921, 
    src_file=0x557a8f123d60 "/test/11.3_dbg/sql/sql_cache.cc", 
    that=0x14c41df89070) at /test/11.3_dbg/include/mysql/psi/mysql_thread.h:931
931	  if (psi_likely(that->m_psi != NULL))
[Current thread is 1 (Thread 0x14c3b688f640 (LWP 2606873))]
(gdb) bt
#0  inline_mysql_rwlock_wrlock (src_line=921, src_file=0x557a8f123d60 "/test/11.3_dbg/sql/sql_cache.cc", that=0x14c41df89070) at /test/11.3_dbg/include/mysql/psi/mysql_thread.h:931
#1  Query_cache_query::lock_writing (this=0x14c41df89068) at /test/11.3_dbg/sql/sql_cache.cc:921
#2  Query_cache::insert (this=0x557a8fb953e0 <query_cache>, thd=thd@entry=0x14c2a8025fc8, query_cache_tls=query_cache_tls@entry=0x14c2a8026308, packet=packet@entry=0x14c2a802fd58 "\002", length=158, pkt_nr=18) at /test/11.3_dbg/sql/sql_cache.cc:1097
#3  0x0000557a8e4ade6a in query_cache_insert (thd_arg=thd_arg@entry=0x14c2a8025fc8, packet=packet@entry=0x14c2a802fd58 "\002", length=<optimized out>, pkt_nr=<optimized out>) at /test/11.3_dbg/sql/sql_cache.cc:1057
#4  0x0000557a8e9b8ff0 in net_real_write (net=net@entry=0x14c2a8026310, packet=0x14c2a802fd58 "\002", len=<optimized out>) at /test/11.3_dbg/sql/net_serv.cc:660
#5  0x0000557a8e9b933b in net_flush (net=0x14c2a8026310) at /test/11.3_dbg/sql/net_serv.cc:402
#6  0x0000557a8e43531e in Protocol::net_send_eof (this=<optimized out>, thd=0x14c2a8025fc8, server_status=<optimized out>, statement_warn_count=<optimized out>) at /test/11.3_dbg/sql/protocol.cc:351
#7  0x0000557a8e434e0e in Protocol::send_eof (this=<optimized out>, server_status=<optimized out>, statement_warn_count=<optimized out>) at /test/11.3_dbg/sql/protocol.cc:657
#8  0x0000557a8e43704a in Protocol::end_statement (this=0x14c2a80265e0) at /test/11.3_dbg/sql/sql_error.h:1110
#9  0x0000557a8e52a622 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14c2a8025fc8, packet=<optimized out>, packet@entry=0x14c2a802fd59 "", packet_length=packet_length@entry=26, blocking=blocking@entry=true) at /test/11.3_dbg/sql/sql_parse.cc:2402
#10 0x0000557a8e52afa3 in do_command (thd=0x14c2a8025fc8, blocking=blocking@entry=true) at /test/11.3_dbg/sql/sql_parse.cc:1406
#11 0x0000557a8e691003 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x557a91ca99d8, put_in_cache=put_in_cache@entry=true) at /test/11.3_dbg/sql/sql_connect.cc:1417
#12 0x0000557a8e6912f8 in handle_one_connection (arg=arg@entry=0x557a91ca99d8) at /test/11.3_dbg/sql/sql_connect.cc:1319
#13 0x0000557a8ead8e14 in pfs_spawn_thread (arg=0x557a91ca9a48) at /test/11.3_dbg/storage/perfschema/pfs.cc:2201
#14 0x000014c68fc94ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#15 0x000014c68fd26660 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Comment by Roel Van de Paar [ 2024-01-05 ]

And in 11.4 (new stack)

11.4.0 9bd95e914f3f12d0d9d93e7a1f2c49e6e8841f17 (Debug)

Core was generated by `/test/MD271223-mariadb-11.4.0-linux-x86_64-dbg/bin/mariadbd --no-defaults --max'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  inline_mysql_rwlock_unlock (that=0x14db1214cb00)
    at /test/11.4_dbg/include/mysql/psi/mysql_thread.h:986
[Current thread is 1 (Thread 0x14d6a9c77640 (LWP 2960251))]
(gdb) bt
#0  inline_mysql_rwlock_unlock (that=0x14db1214cb00) at /test/11.4_dbg/include/mysql/psi/mysql_thread.h:986
#1  Query_cache_query::unlock_writing (this=0x14db1214caf8) at /test/11.4_dbg/sql/sql_cache.cc:953
#2  Query_cache::store_query (this=0x562ab9c7d420 <query_cache>, thd=thd@entry=0x14d82c12d7d8, tables_used=tables_used@entry=0x14d82c13d798) at /test/11.4_dbg/sql/sql_cache.cc:1579
#3  0x0000562ab8604f0f in execute_sqlcom_select (thd=thd@entry=0x14d82c12d7d8, all_tables=0x14d82c13d798) at /test/11.4_dbg/sql/sql_parse.cc:6028
#4  0x0000562ab8610f7a in mysql_execute_command (thd=thd@entry=0x14d82c12d7d8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/11.4_dbg/sql/sql_parse.cc:3924
#5  0x0000562ab86174bb in mysql_parse (thd=thd@entry=0x14d82c12d7d8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14d6a9c761e0) at /test/11.4_dbg/sql/sql_parse.cc:7748
#6  0x0000562ab8619831 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14d82c12d7d8, packet=packet@entry=0x14d82c134639 "select evend_id,server_id FROM t1  order by evend_id;#ERROR: 1054 - Unknown column 'evend_id' in 'field list'", packet_length=packet_length@entry=109, blocking=blocking@entry=true) at /test/11.4_dbg/sql/sql_class.h:253
#7  0x0000562ab861b956 in do_command (thd=0x14d82c12d7d8, blocking=blocking@entry=true) at /test/11.4_dbg/sql/sql_parse.cc:1406
#8  0x0000562ab87808b7 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x562abb91b0d8, put_in_cache=put_in_cache@entry=true) at /test/11.4_dbg/sql/sql_connect.cc:1418
#9  0x0000562ab8780bac in handle_one_connection (arg=arg@entry=0x562abb91b0d8) at /test/11.4_dbg/sql/sql_connect.cc:1320
#10 0x0000562ab8bc573a in pfs_spawn_thread (arg=0x562abb91b148) at /test/11.4_dbg/storage/perfschema/pfs.cc:2201
#11 0x000014daf2494ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#12 0x000014daf2526660 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Comment by Roel Van de Paar [ 2024-01-05 ]

Observed stacks:

SIGSEGV|inline_mysql_rwlock_wrlock|Query_cache_query::lock_writing|Query_cache::insert|query_cache_insert
SIGSEGV|inline_mysql_rwlock_unlock|Query_cache_query::unlock_writing|Query_cache::store_query|execute_sqlcom_select
SIGSEGV|my_hash_sort_bin|my_ci_hash_sort|my_hash_sort|rec_hashnr
SIGSEGV|Query_cache::free_query_internal|Query_cache::free_query|Query_cache::insert|query_cache_insert
!query_cache.is_disable_in_progress()|SIGABRT|fix_query_cache_type|sys_var::update|set_var::update|sql_set_variables
thd->get_stmt_da()->is_eof()|SIGABRT|Query_cache::end_of_result|dispatch_command|do_command|do_handle_one_connection

Generated at Thu Feb 08 07:45:13 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.