MySQL Bugs: #81448: Sig from Query_cache::end_of_result in sql/sql

Bug #81448	Sig from Query_cache::end_of_result in sql/sql_cache.cc:1041
Submitted:	17 May 2016 5:16	Modified:	29 Jul 2016 6:52
Reporter:	Roel Van de Paar	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: Query Cache	Severity:	S6 (Debug Builds)
Version:	5.5.49, 5.5.50	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
160517 14:58:59 [Note] Event Scheduler: scheduler thread started with id 1
mysqld: /git/mysql-server/sql/sql_cache.cc:1041: void Query_cache::end_of_result(THD*): Assertion `0' failed.
04:59:07 UTC - mysqld got signal 6 ;

+bt
#0  0x00007f9b095eb741 in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
#1  0x00000000007de0c8 in my_write_core (sig=6) at /git/mysql-server/mysys/stacktrace.c:433
#2  0x00000000006a1088 in handle_fatal_signal (sig=6) at /git/mysql-server/sql/signal_handler.cc:247
#3  <signal handler called>
#4  0x00007f9b0860c5f7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#5  0x00007f9b0860dce8 in __GI_abort () at abort.c:90
#6  0x00007f9b08605566 in __assert_fail_base (fmt=0x7f9b08755228 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0xb0df21 "0", file=file@entry=0xa7d638 "/git/mysql-server/sql/sql_cache.cc", line=line@entry=1041, function=function@entry=0xa7fdc0 <Query_cache::end_of_result(THD*)::__PRETTY_FUNCTION__> "void Query_cache::end_of_result(THD*)") at assert.c:92
#7  0x00007f9b08605612 in __GI___assert_fail (assertion=0xb0df21 "0", file=0xa7d638 "/git/mysql-server/sql/sql_cache.cc", line=1041, function=0xa7fdc0 <Query_cache::end_of_result(THD*)::__PRETTY_FUNCTION__> "void Query_cache::end_of_result(THD*)") at assert.c:101
#8  0x0000000000559a3c in Query_cache::end_of_result (this=0x1150e00 <query_cache>, thd=thd@entry=0x7f9aec000b40) at /git/mysql-server/sql/sql_cache.cc:1041
#9  0x0000000000785755 in sp_instr_stmt::execute (this=<optimized out>, thd=0x7f9aec000b40, nextp=0x7f9b043dd674) at /git/mysql-server/sql/sp_head.cc:3150
#10 0x000000000078159d in sp_head::execute (this=this@entry=0x7f9adc000f00, thd=thd@entry=0x7f9aec000b40, merge_da_on_success=merge_da_on_success@entry=true) at /git/mysql-server/sql/sp_head.cc:1434
#11 0x0000000000782fd9 in sp_head::execute_procedure (this=this@entry=0x7f9adc000f00, thd=thd@entry=0x7f9aec000b40, args=args@entry=0x7f9b043dd9f0) at /git/mysql-server/sql/sp_head.cc:2198
#12 0x0000000000625855 in Event_job_data::execute (this=this@entry=0x7f9b043ddde0, thd=thd@entry=0x7f9aec000b40, drop=<optimized out>) at /git/mysql-server/sql/event_data_objects.cc:1434
#13 0x00000000007b6d52 in Event_worker_thread::run (this=this@entry=0x7f9b043ddeef, thd=thd@entry=0x7f9aec000b40, event=event@entry=0x7f9aec000a00) at /git/mysql-server/sql/event_scheduler.cc:325
#14 0x00000000007b6e6f in event_worker_thread (arg=0x7f9aec000a00) at /git/mysql-server/sql/event_scheduler.cc:282
#15 0x00007f9b095e6dc5 in start_thread (arg=0x7f9b043de700) at pthread_create.c:308
#16 0x00007f9b086cd21d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

How to repeat:
The attached tarball (1463460856_bug_bundle.tar.gz) gives the testcase as an exact match of our system, including some handy utilities

$ vi 1463460856_mybase         # STEP1: Update the base path in this file (usually the only change required!). If you use a non-binary distribution, please update SOURCE_DIR location also
$ ./1463460856_init            # STEP2: Initializes the data dir
$ ./1463460856_start           # STEP3: Starts mysqld
$ ./1463460856_cl              # STEP4: To check mysqld is up
$ ./1463460856_run_pquery      # STEP5: Run the testcase with the pquery binary
$ ./1463460856_run             # OPTIONAL: Run the testcase with the mysql CLI (may not reproduce the issue, as the pquery binary was used for the original testcase reduction)
$ vi /dev/shm/1463460856/error.log.out  # STEP6: Verify the error log
$ ./1463460856_gdb             # OPTIONAL: Brings you to a gdb prompt with gdb attached to the used mysqld and attached to the generated core
$ ./1463460856_parse_core      # OPTIONAL: Creates 1463460856_STD.gdb and 1463460856_FULL.gdb; standard and full variables gdb stack traces

Hello Roel,

Thank you for the report.
It seems you forgot to upload the tarball :)  
Could you please upload it to the bug report? 

Thanks,
Umesh

Thanks Umesh, looks like I missed it (and it was deleted). Can you verify based on trust? Then dev could have a look and place back to "need feedback" if it's not clear from stack vs code review. Thanks.

-- 5.5.50 and Shane's test case/steps from 47378
-- only debug build affected
-- didn't notice this on 5.6/5.7

(gdb) bt
#0  0x00007f77b432d771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000007ee356 in my_write_core (sig=6) at /pb2/build/sb_0-18916074-1463392611.14/mysqlcom-pro-5.5.50/mysys/stacktrace.c:433
#2  0x00000000006a625c in handle_fatal_signal (sig=6) at /pb2/build/sb_0-18916074-1463392611.14/mysqlcom-pro-5.5.50/sql/signal_handler.cc:247
#3  <signal handler called>
#4  0x00007f77b34505d7 in raise () from /lib64/libc.so.6
#5  0x00007f77b3451cc8 in abort () from /lib64/libc.so.6
#6  0x00007f77b3449546 in __assert_fail_base () from /lib64/libc.so.6
#7  0x00007f77b34495f2 in __assert_fail () from /lib64/libc.so.6
#8  0x000000000055a82a in Query_cache::end_of_result (this=0x103e4e0 <query_cache>, thd=0x7f7794000b40) at /pb2/build/sb_0-18916074-1463392611.14/mysqlcom-pro-5.5.50/sql/sql_cache.cc:1041
#9  0x0000000000793e2e in sp_instr_stmt::execute (this=0x7f7790009640, thd=0x7f7794000b40, nextp=0x7f77b08018f8)
    at /pb2/build/sb_0-18916074-1463392611.14/mysqlcom-pro-5.5.50/sql/sp_head.cc:3151
#10 0x0000000000791cc0 in sp_head::execute (this=0x7f77900010b0, thd=0x7f7794000b40, merge_da_on_success=true) at /pb2/build/sb_0-18916074-1463392611.14/mysqlcom-pro-5.5.50/sql/sp_head.cc:1435
#11 0x00000000007927d7 in sp_head::execute_procedure (this=0x7f77900010b0, thd=0x7f7794000b40, args=0x7f77b0801d20)
    at /pb2/build/sb_0-18916074-1463392611.14/mysqlcom-pro-5.5.50/sql/sp_head.cc:2199
#12 0x0000000000625f1a in Event_job_data::execute (this=0x7f77b0801db0, thd=0x7f7794000b40, drop=false)
    at /pb2/build/sb_0-18916074-1463392611.14/mysqlcom-pro-5.5.50/sql/event_data_objects.cc:1434
#13 0x00000000007c839f in Event_worker_thread::run (this=0x7f77b0801ef7, thd=0x7f7794000b40, event=0x7f7794000a00)
    at /pb2/build/sb_0-18916074-1463392611.14/mysqlcom-pro-5.5.50/sql/event_scheduler.cc:325
#14 0x00000000007c84c9 in event_worker_thread (arg=<optimized out>) at /pb2/build/sb_0-18916074-1463392611.14/mysqlcom-pro-5.5.50/sql/event_scheduler.cc:282
#15 0x00007f77b4328df5 in start_thread () from /lib64/libpthread.so.0
#16 0x00007f77b351160d in clone () from /lib64/libc.so.6
(gdb)

Fixed in 5.6.8 by the patch for Bug#47378