handle_fatal_signal (sig=11) in MDL_ticket::has_pending_conflicting_lock | sql/mdl.cc:3031

Bug #1384570 reported by Ramesh Sivaraman on 2014-10-23
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server
Status tracked in 5.7
5.1
Undecided
Unassigned
5.5
Undecided
Unassigned
5.6
High
Unassigned
5.7
High
Unassigned

Bug Description

**** GDB info

#0 0x00007fc97c079771 in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000ab7586 in my_write_core (sig=11) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/mysys/stacktrace.c:422
#2 0x000000000072f9ff in handle_fatal_signal (sig=11) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/signal_handler.cc:236
#3 <signal handler called>
#4 0x000000000071e27e in MDL_ticket::has_pending_conflicting_lock (this=0x8f8f8f8f8f8f8f8f) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/mdl.cc:3031
#5 0x00000000007be997 in mysql_ha_flush (thd=0x28b95e0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_handler.cc:982
#6 0x0000000000774586 in open_tables (thd=0x28b95e0, start=0x7fc95c8a1840, counter=0x28bbbe8, flags=0, prelocking_strategy=0x7fc95c8a1880) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_base.cc:5137
#7 0x0000000000775932 in open_normal_and_derived_tables (thd=0x28b95e0, tables=0x7fc920005190, flags=0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_base.cc:5913
#8 0x00000000007c1296 in mysql_insert (thd=0x28b95e0, table_list=0x7fc920005190, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_insert.cc:750
#9 0x00000000007e5262 in mysql_execute_command (thd=0x28b95e0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_parse.cc:3851
#10 0x00000000007ed193 in mysql_parse (thd=0x28b95e0, rawbuf=0x7fc9200050a0 "INSERT INTO t1 VALUES(0xAFB2)", length=29, parser_state=0x7fc95c8a2e30) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_parse.cc:6773
#11 0x00000000007df5fc in dispatch_command (command=COM_QUERY, thd=0x28b95e0, packet=0x30b5781 "INSERT INTO t1 VALUES(0xAFB2);", packet_length=30) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_parse.cc:1432
#12 0x00000000007de528 in do_command (thd=0x28b95e0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_parse.cc:1049
#13 0x00000000007a64e5 in do_handle_one_connection (thd_arg=0x28b95e0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_connect.cc:1532
#14 0x00000000007a5fed in handle_one_connection (arg=0x28b95e0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_connect.cc:1443
#15 0x0000000000dc5bac in pfs_spawn_thread (arg=0x3071030) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/perfschema/pfs.cc:1860
#16 0x00007fc97c074df3 in start_thread () from /lib64/libpthread.so.0
#17 0x00007fc97ad3e01d in clone () from /lib64/libc.so.6

**** Crashing query

INSERT INTO t1 VALUES(0xAFB2)

Tags: qa Edit Tag help
tags: added: qa
summary: - handle_fatal_signal (sig=11) in MDL_ticket::has_pending_conflicting_lock
- | sql/mdl.cc:3031
+ qhandle_fatal_signal (sig=11) in
+ MDL_ticket::has_pending_conflicting_lock | sql/mdl.cc:3031

core, gdb, error log etc..

There was no master (single threaded, single mysqld run)

Ramesh Sivaraman (rameshvs02) wrote :

s/There was no master (single threaded, single mysqld run)/Single threaded run, single mysqld involved/

description: updated
Roel Van de Paar (roel11) wrote :

Likely related to bug 1384656

Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :

This bug is very hard to reproduce. Established sporadic. When the testcase is reduced, if you execute the testcase at the CLI or via pquery, you end up with the stack from bug 1384656. However, using the reducer script itself, it is possible, even with a very small base testcase to produce this testcase. To do so;

#1 Change reducer125.sh - these variables (scroll about one page down from top of script);

MYBASE="/sda/Percona-Server-5.6.21-rel69.0-681.Linux.x86_64-debug"
INPUTFILE="/sda/883801/125/pquery_thread-0.sql_out_out_out_out_out_out"

Simply change path's to match your machine

#2 Excute reducer125.sh and observe output. It will start reproducing the bug. You can hack the script to stop at the required moments (simply search for output text in script) to for example allow time to attach debugger, or to write core file (add --core to MYEXTRA) etc.

[roel@localhost 883801]$ ./reducer125.sh
2014-11-05 01:59:12 [Init] Workdir: /dev/shm/1415113152
[...]
2014-11-05 01:59:28 [Init] Run mode: MODE3: mysqld error log
2014-11-05 01:59:28 [Init] Looking for this string: 'ZNK10MDL_ticket28has_pending_conflicting_lockEv' in mysqld error log output
[...]
2014-11-05 01:59:28 [] [Stage V] Verifying the bug/issue really exists (duration depends on initial input file size)
2014-11-05 01:59:28 [] [Stage V] [MULTI] Starting 10 verification subreducer threads to verify if the issue is sporadic (/dev/shm/1415113152/subreducer/)
2014-11-05 01:59:28 [] [Stage V] [MULTI] Ensuring any old subreducer processes are terminated
2014-11-05 01:59:30 [] [Stage V] [MULTI] Forking subreducer threads [PIDs]: #1 [18425] #2 [18682] #3 [18879] #4 [19024] #5 [19234] #6 [19389] #7 [19535] #8 [19699] #9 [19868] #10 [20029]
2014-11-05 01:59:30 [] [Stage V] [MULTI] Waiting for all forked verification subreducer threads to finish/terminate
2014-11-05 02:00:09 [] [Stage V] [MULTI] Finished/Terminated verification subreducer threads: #1 #2 #3 #4 #5 #6 #7 #8 #9 #10
2014-11-05 02:00:09 [] [Stage V] [MULTI] All verification subreducer threads have finished/terminated
2014-11-05 02:00:09 [*] [Stage V] [MULTI] Threads which reproduced the issue: #3 #4 #5 #7 #8 #10
2014-11-05 02:00:09 [*] [Stage V] [MULTI] Only 6 out of 10 threads reproduced the issue: this issue is sporadic

summary: - qhandle_fatal_signal (sig=11) in
- MDL_ticket::has_pending_conflicting_lock | sql/mdl.cc:3031
+ handle_fatal_signal (sig=11) in MDL_ticket::has_pending_conflicting_lock
+ | sql/mdl.cc:3031
Roel Van de Paar (roel11) wrote :

Just for clarify, #6 has good/small testcase, even if it regrettably is not as simple as few lines of SQL.

I have no idea how to triage without fully analysing this, due to the testcase being very much a black box.

Can you at least confirm whether this is upstream?

Roel Van de Paar (roel11) wrote :

Bug has testcase. Setting to high ftm until we have time to review further.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers