Sporadic bug in threadpool leading to handle_fatal_signal (sig=11) in set_null

[Roel Van de Paar]

[...]
InnoDB: DEBUG: update_statistics for test/ti.
InnoDB: DEBUG: update_statistics for test/t.
InnoDB: DEBUG: update_statistics for test/ti.
00:29:39 UTC - 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,

Core was generated by `/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld --no-de'.
Program terminated with signal 11, Segmentation fault.
#0 0x00007fdfce3729b1 in __pthread_kill (threadid=<optimized out>, signo=signo@entry=11)
    at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
61 val = INTERNAL_SYSCALL (tgkill, err, 3, THREAD_GETMEM (THREAD_SELF, pid),
(gdb) bt
#0 0x00007fdfce3729b1 in __pthread_kill (threadid=<optimized out>, signo=signo@entry=11)
    at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
#1 0x00000000007f9bc8 in my_write_core (sig=11) at /home/roel/PS-5.5.58_dbg/mysys/stacktrace.c:433
#2 0x00000000006b9803 in handle_fatal_signal (sig=11) at /home/roel/PS-5.5.58_dbg/sql/signal_handler.cc:250
#3 <signal handler called>
#4 0x00000000006b4d0c in set_null (row_offset=0, this=0x7fdfaa045420) at /home/roel/PS-5.5.58_dbg/sql/field.h:289
#5 set_field_to_null_with_conversions (field=0x7fdfaa045420, no_conversions=false)
    at /home/roel/PS-5.5.58_dbg/sql/field_conv.cc:164
#6 0x00000000006c94fc in Item_field::save_in_field (this=0x7fdfa681f770, to=<optimized out>, no_conversions=<optimized out>)
    at /home/roel/PS-5.5.58_dbg/sql/item.cc:5486
#7 0x00000000006d8cac in Item_insert_value::save_in_field (this=<optimized out>, field_arg=<optimized out>,
    no_conversions=<optimized out>) at /home/roel/PS-5.5.58_dbg/sql/item.h:3159
#8 0x0000000000553202 in fill_record (thd=thd@entry=0x7fdfb2bde000, ptr=0x7fdfaa045418, values=...,
    ignore_errors=ignore_errors@entry=true) at /home/roel/PS-5.5.58_dbg/sql/sql_base.cc:8821
#9 0x00000000005532a9 in fill_record_n_invoke_before_triggers (thd=0x7fdfb2bde000, ptr=<optimized out>, values=...,
    ignore_errors=ignore_errors@entry=true, triggers=0x0, event=event@entry=TRG_EVENT_INSERT)
    at /home/roel/PS-5.5.58_dbg/sql/sql_base.cc:8862
#10 0x000000000057ebc7 in select_create::store_values (this=<optimized out>, values=...)
    at /home/roel/PS-5.5.58_dbg/sql/sql_insert.cc:4099
#11 0x0000000000581414 in select_insert::send_data (this=0x7fdfa681fe18, values=...)
    at /home/roel/PS-5.5.58_dbg/sql/sql_insert.cc:3474
#12 0x00000000005d156e in end_send (join=0x7fdfa6838010, join_tab=<optimized out>, end_of_records=<optimized out>)
    at /home/roel/PS-5.5.58_dbg/sql/sql_select.cc:12891
#13 0x00000000005c5096 in evaluate_join_record (join=join@entry=0x7fdfa6838010, join_tab=join_tab@entry=0x7fdfa6820a40,
    error=<optimized out>) at /home/roel/PS-5.5.58_dbg/sql/sql_select.cc:12059
#14 0x00000000005c52d3 in sub_select (join=join@entry=0x7fdfa6838010, join_tab=join_tab@entry=0x7fdfa6820a40,
    end_of_records=end_of_records@entry=false) at /home/roel/PS-5.5.58_dbg/sql/sql_select.cc:11912
#15 0x00000000005ce925 in do_select (join=join@entry=0x7fdfa6838010, fields=fields@entry=0x7fdfb2be0458, table=table@entry=0x0,
    procedure=0x0) at /home/roel/PS-5.5.58_dbg/sql/sql_select.cc:11677
#16 0x00000000005e2a63 in JOIN::exec (this=this@entry=0x7fdfa6838010) at /home/roel/PS-5.5.58_dbg/sql/sql_select.cc:2443
#17 0x00000000005dca23 in mysql_select (thd=thd@entry=0x7fdfb2bde000, rref_pointer_array=rref_pointer_array@entry=0x7fdfb2be0530,
    tables=0x7fdfa681f8c8, wild_num=0, fields=..., conds=<optimized out>, og_num=0, order=0x0, group=0x0, having=0x0,
    proc_param=0x0, select_options=select_options@entry=2424572672, result=result@entry=0x7fdfa681fe18, unit=unit@entry=
    0x7fdfb2bdfd28, select_lex=select_lex@entry=0x7fdfb2be0348) at /home/roel/PS-5.5.58_dbg/sql/sql_select.cc:2662
#18 0x00000000005dcc61 in handle_select (thd=thd@entry=0x7fdfb2bde000, lex=lex@entry=0x7fdfb2bdfc68,
    result=result@entry=0x7fdfa681fe18, setup_tables_done_option=setup_tables_done_option@entry=0)
    at /home/roel/PS-5.5.58_dbg/sql/sql_select.cc:315
#19 0x00000000005981d2 in mysql_execute_command (thd=thd@entry=0x7fdfb2bde000) at /home/roel/PS-5.5.58_dbg/sql/sql_parse.cc:2851
#20 0x000000000059ec81 in mysql_parse (thd=thd@entry=0x7fdfb2bde000, rawbuf=<optimized out>, length=67,
    parser_state=parser_state@entry=0x7fdfcb1f63d0) at /home/roel/PS-5.5.58_dbg/sql/sql_parse.cc:6113
#21 0x00000000005a0721 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fdfb2bde000,
    packet=packet@entry=0x7fdfb2be2001 "CREATE TEMPORARY TABLE tmp ENGINE=MEMORY AS SELECT VALUES(a)FROM t1;",
    packet_length=packet_length@entry=68) at /home/roel/PS-5.5.58_dbg/sql/sql_parse.cc:1112
#22 0x00000000005a256f in do_command (thd=thd@entry=0x7fdfb2bde000) at /home/roel/PS-5.5.58_dbg/sql/sql_parse.cc:792
#23 0x0000000000674949 in threadpool_process_request (thd=0x7fdfb2bde000) at /home/roel/PS-5.5.58_dbg/sql/threadpool_common.cc:240
#24 0x0000000000694666 in handle_event (connection=0x7fdfbf3e20a0) at /home/roel/PS-5.5.58_dbg/sql/threadpool_unix.cc:1547
#25 worker_main (param=0x117e800 <all_groups+3072>) at /home/roel/PS-5.5.58_dbg/sql/threadpool_unix.cc:1595
#26 0x00007fdfce36de25 in start_thread (arg=0x7fdfcb1f7700) at pthread_create.c:308
#27 0x00007fdfccb6b34d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

[Roel Van de Paar (roel11)]

Testcase;

1) Note this bug is sporadic. However, it usually reproduces in 5-15 attempts (cursor up>enter>cursor up>enter etc. until status 256 output of pquery is seen instead of status 0)
2) Reproducibility may be different on different systems (i.e. >15 attempts may be needed, I included a while loop below for ease of use)
3) This only replays via mysqlclient API calls (i.e. pquery)
4) Actual testcase;

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

$ vi 1512603735_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
$ ./1512603735_init # STEP2: Initializes the data dir
$ ./1512603735_start # STEP3: Starts mysqld
$ ./1512603735_cl # STEP4: To check mysqld is up
$ ./1512603735_run_pquery # STEP5: Run the testcase with the pquery binary
$ vi /dev/shm/1512603735/error.log.out # STEP6: Verify the error log
$ ./1512603735_gdb # OPTIONAL: Brings you to a gdb prompt with gdb attached to the used mysqld and attached to the generated core
$ ./1512603735_parse_core # OPTIONAL: Creates 1512603735_STD.gdb and 1512603735_FULL.gdb; standard and full variables gdb stack traces

while [ 1 -eq 1 ]; do ./1512603735_run_pquery ;done # To loop (or just do manually 5-15 times)

[Roel Van de Paar (roel11)]

Perhaps related to
https://bugs.mysql.com/bug.php?id=81446 (previously sent through ref 25/8/17)
https://bugs.mysql.com/bug.php?id=81412 (previously sent through ref 25/8/17)

However this particular issue does not reproduce without thread pool enabled, and hence not on MS.

[Roel Van de Paar (roel11)]

The loop can be ended by CTRL+Z then kill %1

[Roel Van de Paar (roel11)]

The original trial run had a slightly different stack;

/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(handle_fatal_signal+0x30f)[0x6b9688]
/lib64/libpthread.so.0(+0xf5e0)[0x7f79559f55e0]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_Z34set_field_to_null_with_conversionsP5Fieldb+0x19)[0x6b4d0c]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_ZN10Item_field13save_in_fieldEP5Fieldb+0x4c)[0x6c94fc]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_ZN17Item_insert_value13save_in_fieldEP5Fieldb+0xc)[0x6d8cac]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_Z11fill_recordP3THDPP5FieldR4ListI4ItemEb+0x5c)[0x553202]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_Z36fill_record_n_invoke_before_triggersP3THDPP5FieldR4ListI4ItemEbP19Table_triggers_list14trg_event_type+0x1e)[0x5532a9]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_ZN13select_create12store_valuesER4ListI4ItemE+0x2d)[0x57ebc7]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_ZN13select_insert9send_dataER4ListI4ItemE+0x7a)[0x581414]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld[0x5d156e]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld[0x5c5096]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_Z10sub_selectP4JOINP13st_join_tableb+0x86)[0x5c52d3]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld[0x5ce925]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_ZN4JOIN4execEv+0x23bb)[0x5e2a63]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x686)[0x5dca23]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x17b)[0x5dcc61]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_Z21mysql_execute_commandP3THD+0x1794)[0x5981d2]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x20a)[0x59ec81]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xf4c)[0x5a0721]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_Z10do_commandP3THD+0x28b)[0x5a256f]

vs

/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(handle_fatal_signal+0x30f)[0x6b9688]
/lib64/libpthread.so.0(+0xf5e0)[0x7fb390cfd5e0]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_ZN10Item_field13save_in_fieldEP5Fieldb+0x5d)[0x6c950d]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_Z11fill_recordP3THDPP5FieldR4ListI4ItemEb+0x5c)[0x553202]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64-debug/bin/mysqld(_Z36fill_record_n_invoke_before_triggersP3THDPP5FieldR4ListI4ItemEbP19Table_triggers_list14trg_event_type+0x1e)[0x5532a9]
/sda/PS091117-percona-server-5.5.58-38.10-linux-x86_64...

[Laurynas Biveinis (laurynas-biveinis)]

Any output with the testcase on Valgrind/ASan?

[Shahriyar Rzayev (rzayev-sehriyar)]

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