MySQL Bugs: #60682: deadlock from thd_security

Bug #60682	deadlock from thd_security_context
Submitted:	28 Mar 2011 21:25	Modified:	24 Jul 2012 14:44
Reporter:	Mark Callaghan	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server	Severity:	S1 (Critical)
Version:	5.1.47, 5.1.57	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	Contribution, deadlock

Description:
I will describe two instances of deadlock that have the same root cause. While executing SHOW INNODB STATUS, a thread locks kernel_mutex and then calls thd_security_context and thd_security_context may block on "pthread_mutex_lock(&thd->LOCK_thd_data);" when LOCK_thd_data points to LOCK_open.

I am able to reproduce this after adding finite sleep calls to a few places in the server to expose the race condition.

The pthread_mutex_lock call was added to thd_security_context by this change:

mark-i7MBP:5.1 mcallaghan$ bzr log -r3234.1.1
------------------------------------------------------------
revno: 3234.1.1 [merge]
committer: Gleb Shchepa <gshchepa@mysql.com>
branch nick: mysql-5.1-bugteam
timestamp: Tue 2009-12-01 14:38:40 +0400
message:
  Bug #38883 (reopened): thd_security_context is not thread safe, crashes?
  
  manual merge 5.0-->5.1, updating InnoDB plugin.
------------------------------------------------------------
Use --include-merges or -n0 to see merged revisions.

How to repeat:
A reproduction case is with connection names. A real test case would use SIGNAL and WAIT_FOR ...

c1) begin, select from innodb table to start transaction
    - this gets the connection on the list of open innodb transactions
c3) RENAME TABLE
    - add 5 second sleep after pthread_mutex_unlock prior to calling write_bin_log
    - this marks the table so that needs_reopen_or_name_lock returns TRUE in open_table
c1) SELECT on old name of renamed table
    - add 15 second sleep in wait_for_condition after pthread_cond_wait returns
    - use 15 second sleep, must be the last to wake of all the sleeps
    - this calls wait_for_condition because of the RENAME
    - these are set while waiting -- mysys_var->current_cond, mysys_var->current_mutex
c2) drop renamed table
    - use 5 second sleep before calling ha_delete_table
    - holds LOCK_open while sleeping
    - will try to get kernel_mutex after waking up, but blocked by statement in next step
c4) SHOW INNODB STATUS
    - use 5 second sleep in thd_security_context right before locking LOCK_thd_data
    - while sleeping holds kernel_mutex from lock_print_info_summary
    - after waking will block on LOCK_thd_data which is locked by next statement
5) run KILL on c1 (SELECT statement)
    - locks LOCK_thd_data
   - waits on LOCK_open via mysys_var->current_mutex

----------

# This test suite depends on a server modified to sleep in a few places.

-- source include/have_innodb_plugin.inc

connect (c1,127.0.0.1,root,,test,$MASTER_MYPORT,);
connect (c2,127.0.0.1,root,,test,$MASTER_MYPORT,);
connect (c3,127.0.0.1,root,,test,$MASTER_MYPORT,);
connect (c4,127.0.0.1,root,,test,$MASTER_MYPORT,);

connection default;

create table t1(i int) engine=innodb;
create table t2(i int) engine=innodb;
insert into t1 values(1);
insert into t2 values(1);

connection c1;
let $ID= `SELECT connection_id()`
begin;
select * from t2;

connection c3;
sleep 1;
--send rename table t2 to t3

connection c1;
sleep 1;
--send select i from t2

connection c3;
reap;
--send drop table t1

connection c2;
sleep 1;
--send SHOW INNODB STATUS

connection c4;
sleep 1;
--eval KILL QUERY 3

Suggested fix:
First, make life easy for support. See http://bugs.mysql.com/bug.php?id=60679. MySQL makes it too hard to monitor/debug hangs on mutexes and rw-locks and anything else that can get locked. MySQL doesn't detect such hangs.

--------

This particular problem can be fixed by adding an argument to thd_security_context so that pthread_mutex_trylock is used and the following code is skipped when the server cannot get the lock. Or jsut always use pthread_mutex_trylock.

  pthread_mutex_lock(&thd->LOCK_thd_data);

  if (thd->query())
  {
    if (max_query_len < 1)
      len= thd->query_length();
    else
      len= min(thd->query_length(), max_query_len);
    str.append('\n');
    str.append(thd->query(), len);
  }

  pthread_mutex_unlock(&thd->LOCK_thd_data);

Thread stacks for the hang from poor mans profiler:

     10 pthread_cond_wait@@GLIBC_2.3.2,safe_cond_wait,os_event_wait_low,os_aio_simulated_handle,fil_aio_wait,io_handler_thread,start_thread,clone
      1 select,os_thread_sleep,srv_monitor_thread,start_thread,clone
      1 select,handle_connections_sockets,main,select
      1 read,vio_read,my_real_read,my_net_read,do_command,handle_one_connection,start_thread,clone
      1 pthread_cond_wait@@GLIBC_2.3.2,safe_cond_wait,os_event_wait_low,sync_array_wait_event,mutex_spin_wait,mutex_enter_func,trx_allocate_for_mysql,innobase_trx_allocate,ha_innodb::delete_table,handler::ha_delete_table,ha_delete_table,mysql_rm_table_part2,mysql_rm_table,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_one_connection,start_thread,clone
      1 pthread_cond_wait@@GLIBC_2.3.2,safe_cond_wait,os_event_wait_low,sync_array_wait_event,mutex_spin_wait,mutex_enter_func,srv_refresh_innodb_monitor_stats,srv_error_monitor_thread,start_thread,clone
      1 pthread_cond_wait@@GLIBC_2.3.2,safe_cond_wait,os_event_wait_low,sync_array_wait_event,mutex_spin_wait,mutex_enter_func,srv_lock_timeout_thread,start_thread,clone
      1 pthread_cond_wait@@GLIBC_2.3.2,safe_cond_wait,os_event_wait_low,sync_array_wait_event,mutex_spin_wait,mutex_enter_func,row_drop_tables_for_mysql_in_background,srv_master_thread,start_thread,clone
      1 __lll_mutex_lock_wait,_L_mutex_lock_1133,pthread_mutex_lock,safe_mutex_lock,wait_for_condition,open_table,open_tables,open_and_lock_tables_derived,open_and_lock_tables,execute_sqlcom_select,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_one_connection,start_thread,clone
      1 __lll_mutex_lock_wait,_L_mutex_lock_1133,pthread_mutex_lock,safe_mutex_lock,thd_security_context,innobase_mysql_print_thd,trx_print,lock_print_info_all_transactions,srv_printf_innodb_monitor,innodb_show_status,innobase_show_status,ha_show_status,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_one_connection,start_thread,clone
      1 __lll_mutex_lock_wait,_L_mutex_lock_1133,pthread_mutex_lock,safe_mutex_lock,THD::awake,kill_one_thread,sql_kill,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_one_connection,start_thread,clone
      1 do_sigwait,sigwait,signal_hand,start_thread,clone

Argh, I posted these in the wrong bug

There was another problem that shows up in a variation of this deadlock:

connection doing row_drop_table_for_mysql
-- has dictionary lock
-- waiting for kernel_mutex

connection doing SELECT from renamed table (without deadlock statement should error)
-- has LOCK_open
-- waiting for dictionary lock in dict_table_get

connection doing SHOW INNODB STATUS
-- has kernel_mutex
-- waiting for LOCK_thd_data in thd_security_context

connection doing KILL tid
-- has LOCK_thd_data
-- waiting for LOCK_open

purge_thread
-- waiting in row_mysql_free_data_dictionary

pthread_cond_wait@@GLIBC_2.3.2,os_event_wait_low,sync_array_wait_event,rw_lock_s_lock_spin,row_mysql_freeze_data_dictionary_func,row_purge_step,que_run_threads,trx_purge,srv_master_thread,start_thread,clone
-- waiting on rw_lock_s_lock_func(&dict_operation_lock, ...

pthread_cond_wait@@GLIBC_2.3.2,os_event_wait_low,sync_array_wait_event,mutex_spin_wait,dict_table_get,ha_innobase::open_internal,handler::ha_open,open_table_from_share,open_unireg_entry,open_table,open_tables,open_and_lock_tables_derived,execute_sqlcom_select,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_one_connection,start_thread,clone
-- waiting on dict->sys_mutex

__lll_mutex_lock_wait,_L_mutex_lock_1133,pthread_mutex_lock,thd_security_context,innobase_mysql_print_thd,lock_print_info_all_transactions,srv_printf_innodb_transaction,innodb_show_status,innobase_show_status,ha_show_status,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_one_connection,start_thread,clone

__lll_mutex_lock_wait,_L_mutex_lock_1133,pthread_mutex_lock,THD::awake,kill_one_thread,sql_kill,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_one_connection,start_thread,clone

These are from unmodified MySQL 5.1.47

Stack for thread stuck doing KILL

Thread 2 (Thread 1230346560 (LWP 28363)):
#0  0x00000031ef20c888 in __lll_mutex_lock_wait () from /lib64/libpthread.so.0
#1  0x00000031ef208911 in _L_mutex_lock_1133 () from /lib64/libpthread.so.0
#2  0x00000031ef20886a in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x0000000000908301 in safe_mutex_lock (mp=0xebc780, try_lock=0 '\0', file=0x9fa378
"sql_class.cc", line=1154) at thr_mutex.c:149
#4  0x0000000000619ecf in THD::awake (this=0x3e686d0, state_to_set=THD::KILL_QUERY) at
sql_class.cc:1154
#5  0x000000000063d7bf in kill_one_thread (thd=0x3eae310, id=3, only_kill_query=true) at
sql_parse.cc:7038
#6  0x000000000063d866 in sql_kill (thd=0x3eae310, id=3, only_kill_query=true) at
sql_parse.cc:7063
#7  0x0000000000649561 in mysql_execute_command (thd=0x3eae310) at sql_parse.cc:4031
#8  0x000000000064c899 in mysql_parse (thd=0x3eae310, inBuf=0x3e682c0 "KILL QUERY 3",
length=12, found_semicolon=0x49558ee0) at sql_parse.cc:5986
#9  0x000000000064e155 in dispatch_command (command=COM_QUERY, thd=0x3eae310,
packet=0x3eb0db1 "KILL QUERY 3", packet_length=12) at sql_parse.cc:1233
#10 0x000000000064f5b1 in do_command (thd=0x3eae310) at sql_parse.cc:874
#11 0x000000000063b89b in handle_one_connection (arg=0x3eae310) at sql_connect.cc:1134
#12 0x00000031ef2062f7 in start_thread () from /lib64/libpthread.so.0
#13 0x00000031ee6d1e3d in clone () from /lib64/libc.so.6

stack for thread running DROP TABLE

Thread 3 (Thread 1230080320 (LWP 28362)):
#0  0x00000031ef20a496 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x0000000000908674 in safe_cond_wait (cond=0x32d7648, mp=0x32d75d0,
file=0x2aaaaadefa30 "os/os0sync.c", line=399) at thr_mutex.c:237
#2  0x00002aaaaad50235 in os_event_wait_low (event=0x32d75d0, reset_sig_count=1) at
os/os0sync.c:399
#3  0x00002aaaaadb461a in sync_array_wait_event (arr=0x32d6920, index=2) at
sync/sync0arr.c:451
#4  0x00002aaaaadb6777 in mutex_spin_wait (mutex=0x32d7588, file_name=0x2aaaaae000e8
"trx/trx0trx.c", line=200) at sync/sync0sync.c:609
#5  0x00002aaaaadcae46 in mutex_enter_func (mutex=0x32d7588, file_name=0x2aaaaae000e8
"trx/trx0trx.c", line=200) at ./include/sync0sync.ic:221
#6  0x00002aaaaadcad04 in trx_allocate_for_mysql () at trx/trx0trx.c:200
#7  0x00002aaaaad1dc14 in innobase_trx_allocate (thd=0x3e7dc50) at
handler/ha_innodb.cc:1314
#8  0x00002aaaaad22cae in ha_innodb::delete_table (this=0x3e85370, name=0x49516090
"./test/t1") at handler/ha_innodb.cc:6906
#9  0x00000000007816fd in handler::ha_delete_table (this=0x3e85370, name=0x49516090
"./test/t1") at handler.cc:3373
#10 0x00000000007876f3 in ha_delete_table (thd=0x3e7dc50, table_type=0x32d9eb0,
path=0x49516090 "./test/t1", db=0x3e85a60 "test", alias=0x3e8c910 "t1",
generate_warning=true) at handler.cc
:1996
#11 0x00000000007b27cc in mysql_rm_table_part2 (thd=0x3e7dc50, tables=0x3ec1310,
if_exists=false, drop_temporary=false, drop_view=false, dont_log_query=false) at
sql_table.cc:2059
#12 0x00000000007b2dc6 in mysql_rm_table (thd=0x3e7dc50, tables=0x3ec1310, if_exists=0
'\0', drop_temporary=0 '\0') at sql_table.cc:1833
#13 0x0000000000647318 in mysql_execute_command (thd=0x3e7dc50) at sql_parse.cc:3400
#14 0x000000000064c899 in mysql_parse (thd=0x3e7dc50, inBuf=0x3e81d40 "drop table t1",
length=13, found_semicolon=0x49517ee0) at sql_parse.cc:5986
#15 0x000000000064e155 in dispatch_command (command=COM_QUERY, thd=0x3e7dc50,
packet=0x3ea62f1 "drop table t1", packet_length=13) at sql_parse.cc:1233
#16 0x000000000064f5b1 in do_command (thd=0x3e7dc50) at sql_parse.cc:874
#17 0x000000000063b89b in handle_one_connection (arg=0x3e7dc50) at sql_connect.cc:1134

stack for SHOW INNODB STATUS

Thread 4 (Thread 1229814080 (LWP 28361)):
#0  0x00000031ef20c888 in __lll_mutex_lock_wait () from /lib64/libpthread.so.0
#1  0x00000031ef208911 in _L_mutex_lock_1133 () from /lib64/libpthread.so.0
#2  0x00000031ef20886a in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x0000000000908301 in safe_mutex_lock (mp=0x3e69440, try_lock=0 '\0', file=0x9fa378
"sql_class.cc", line=413) at thr_mutex.c:149
#4  0x000000000061c350 in thd_security_context (thd=0x3e686d0, buffer=0x494d4800 "MySQL
thread id 3, query id 17 localhost 127.0.0.1 root Waiting for table", length=1024,
max_query_len=600
) at sql_class.cc:413
#5  0x00002aaaaad21583 in innobase_mysql_print_thd (f=0x3885da0, thd=0x3e686d0,
max_query_len=600) at handler/ha_innodb.cc:894
#6  0x00002aaaaadce313 in trx_print (f=0x3885da0, trx=0x3ebd818, max_query_len=600) at
trx/trx0trx.c:1747
#7  0x00002aaaaad393cb in lock_print_info_all_transactions (file=0x3885da0) at
lock/lock0lock.c:4462
#8  0x00002aaaaadae1a4 in srv_printf_innodb_monitor (file=0x3885da0, nowait=0,
trx_start=0x494d5310, trx_end=0x494d5308) at srv/srv0srv.c:1761
#9  0x00002aaaaad1de0d in innodb_show_status (hton=0x32d9eb0, thd=0x3e73190,
stat_print=0x77f52a <stat_print>) at handler/ha_innodb.cc:8671
#10 0x00002aaaaad1e104 in innobase_show_status (hton=0x32d9eb0, thd=0x3e73190,
stat_print=0x77f52a <stat_print>, stat_type=HA_ENGINE_STATUS) at
handler/ha_innodb.cc:8914
#11 0x0000000000780f12 in ha_show_status (thd=0x3e73190, db_type=0x32d9eb0,
stat=HA_ENGINE_STATUS) at handler.cc:4448
#12 0x00000000006446a4 in mysql_execute_command (thd=0x3e73190) at sql_parse.cc:2482
#13 0x000000000064c899 in mysql_parse (thd=0x3e73190, inBuf=0x3ec1660 "SHOW INNODB
STATUS", length=18, found_semicolon=0x494d6ee0) at sql_parse.cc:5986
#14 0x000000000064e155 in dispatch_command (command=COM_QUERY, thd=0x3e73190,
packet=0x3e75c31 "", packet_length=18) at sql_parse.cc:1233
#15 0x000000000064f5b1 in do_command (thd=0x3e73190) at sql_parse.cc:874
#16 0x000000000063b89b in handle_one_connection (arg=0x3e73190) at sql_connect.cc:1134

Stack for SELECT

Thread 5 (Thread 1229547840 (LWP 28360)):
#0  0x00000031ef20c888 in __lll_mutex_lock_wait () from /lib64/libpthread.so.0
#1  0x00000031ef208911 in _L_mutex_lock_1133 () from /lib64/libpthread.so.0
#2  0x00000031ef20886a in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x0000000000908301 in safe_mutex_lock (mp=0x3e66b88, try_lock=0 '\0', file=0xa5d235
"sql_base.cc", line=2195) at thr_mutex.c:149
#4  0x0000000000694f49 in wait_for_condition (thd=0x3e686d0, mutex=0xebc780,
cond=0xebd280) at sql_base.cc:2195
#5  0x000000000069b324 in open_table (thd=0x3e686d0, table_list=0x3ec0ef0,
mem_root=0x49493e30, refresh=0x49493ebf, flags=0) at sql_base.cc:2847
#6  0x000000000069c751 in open_tables (thd=0x3e686d0, start=0x49493f30,
counter=0x49493f74, flags=0) at sql_base.cc:4605
#7  0x000000000069d0db in open_and_lock_tables_derived (thd=0x3e686d0, tables=0x3ec0ef0,
derived=true) at sql_base.cc:5023
#8  0x0000000000650802 in open_and_lock_tables (thd=0x3e686d0, tables=0x3ec0ef0) at
mysql_priv.h:1564
#9  0x0000000000642ee3 in execute_sqlcom_select (thd=0x3e686d0, all_tables=0x3ec0ef0) at
sql_parse.cc:5032
#10 0x0000000000643dae in mysql_execute_command (thd=0x3e686d0) at sql_parse.cc:2263
#11 0x000000000064c899 in mysql_parse (thd=0x3e686d0, inBuf=0x3e66a90 "select i from t2",
length=16, found_semicolon=0x49495ee0) at sql_parse.cc:5986
#12 0x000000000064e155 in dispatch_command (command=COM_QUERY, thd=0x3e686d0,
packet=0x3e6b171 "select i from t2", packet_length=16) at sql_parse.cc:1233
#13 0x000000000064f5b1 in do_command (thd=0x3e686d0) at sql_parse.cc:874
#14 0x000000000063b89b in handle_one_connection (arg=0x3e686d0) at sql_connect.cc:1134

diff to add sleeps

Attachment: bd1 (application/octet-stream, text), 4.28 KiB.

suggested fix applied to facebook pached version of 5.1.52

Attachment: b60682.patch (application/octet-stream, text), 1.80 KiB.

repeated a hangup., some info from my case. I'll migrate bug to oracle bugdb soon.

Attachment: bug60682_preliminary_info.txt (text/plain), 9.67 KiB.

testcase. run against unpatched server to repeat in seconds. edit hardcoded ip, user, password in file.

Attachment: bug60682.c (text/plain), 7.07 KiB.

https://github.com/twitter/mysql/wiki/Change-History#wiki-5.5.21.t4

"Bug#60682: deadlock from thd_security_context

In order to avoid a deadlock-prone lock order, the query of a session associated with an active transaction is no longer displayed in the output of SHOW ENGINE INNODB STATUS.
"

hi, Shane

i had run your testcase on mysql5.5.18,and  server was crashed 

here is part of error log:

1584376 connection_count=31
1584377 It is possible that mysqld could use up to
1584378 key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 180418 K
1584379 bytes of memory
1584380 Hope that's ok; if not, decrease some variables in the equation.
1584381 
1584382 Thread pointer: 0x7fbf18060dd0
1584383 Attempting backtrace. You can use the following information to find out
1584384 where mysqld died. If you see no messages after this, something went
1584385 terribly wrong...
1584386 stack_bottom = 0x4c22a0f8 thread_stack 0x80000
1584387 /u01/mysql/bin/mysqld(my_print_stacktrace+0x39)[0x7cac19]
1584388 /u01/mysql/bin/mysqld(handle_segfault+0x36d)[0x4ebf5d]
1584389 /lib64/libpthread.so.0[0x3e6380e7c0]
1584390 /lib64/libc.so.6(memcpy+0xa0)[0x3e6307be50]
1584391 /u01/mysql/bin/mysqld(_mi_rec_pack+0x2bc)[0x93b42c]
1584392 /u01/mysql/bin/mysqld(_mi_write_blob_record+0x9d)[0x93e23d]
1584393 /u01/mysql/bin/mysqld(mi_write+0x86f)[0x95719f]
1584394 /u01/mysql/bin/mysqld(_ZN9ha_myisam9write_rowEPh+0x43)[0x925b43]
1584395 /u01/mysql/bin/mysqld(_ZN7handler12ha_write_rowEPh+0x5f)[0x689c7f]
1584396 /u01/mysql/bin/mysqld(_Z23fill_schema_processlistP3THDP10TABLE_LISTP4Item+0x44d)[0x5c000d]
1584397 /u01/mysql/bin/mysqld(_Z24get_schema_tables_resultP4JOIN23enum_schema_table_state+0x211)[0x5ac7a1]
1584398 /u01/mysql/bin/mysqld(_ZN4JOIN4execEv+0x406)[0x5a7a16]
1584399 /u01/mysql/bin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x192)        [0x5a9d52]
1584400 /u01/mysql/bin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x1cb)[0x5aa77b]
1584401 /u01/mysql/bin/mysqld[0x566370]
1584402 /u01/mysql/bin/mysqld(_Z21mysql_execute_commandP3THD+0x17b0)[0x569130]
1584403 /u01/mysql/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x3ad)[0x56e63d]
1584404 /u01/mysql/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x13ca)[0x56fa1a]
1584405 /u01/mysql/bin/mysqld(_Z10do_commandP3THD+0x106)[0x56fd76]
1584406 /u01/mysql/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x125)[0x60c8a5]
1584407 /u01/mysql/bin/mysqld(handle_one_connection+0x4c)[0x60c9cc]
1584408 /lib64/libpthread.so.0[0x3e638064a7]
1584409 /lib64/libc.so.6(clone+0x6d)[0x3e630d3c2d]
1584410 
1584411 Trying to get some variables.
1584412 Some pointers may be invalid and cause the dump to abort.
1584413 Query (0x7fbf1402a6c0): select id from information_schema.processlist where id<>connection_id()  and info like 'select%' order by rand() limit 1 into @a
1584414 Connection ID (thread ID): 535231
1584415 Status: NOT_KILLED

Then it seems bugs like http://bugs.mysql.com/bug.php?id=53822 are still in the wild..

But i'll not trust 5.5.18. Let's wait until this bug is fixed and test 5.5.24 or 5.5.25..

Still repeatable on 5.1.62 builtin innodb, even when running in valgrind.
I haven't repeated this in 5.5.23 yet.

Noted in 5.1.64, 5.5.26, 5.6.6 changelogs.

Sessions could end up deadlocked when executing a combination of 
SELECT, DROP TABLE, KILL, and SHOW ENGINE INNODB STATUS.

hi Shane 
I've tested MySQL5.5.27 using your test case and the server was crashed again.

part of backtrace:
Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7fff90439700 (LWP 28546)]
0x00000038888885d0 in memcpy () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install glibc-2.12-1.25.el6.x86_64 libgcc-4.4.5-6.el6.x86_64 nss-softokn-freebl-3.12.9-3.el6.x86_64
(gdb) bt
#0  0x00000038888885d0 in memcpy () from /lib64/libc.so.6
#1  0x00000000008df488 in _mi_rec_pack (info=0x7fff6400d660, to=0x7ffec396821b "Writ", from=0x7fff6400cff2 "Writing to net")
    at /u01/project/mysql-5.5.27/storage/myisam/mi_dynrec.c:997
#2  0x00000000008e26ad in _mi_write_blob_record (info=0x7fff6400d660, record=0x7fff6400ce00 "\374\022\251\002")
    at /u01/project/mysql-5.5.27/storage/myisam/mi_dynrec.c:289
#3  0x00000000008fb3d3 in mi_write (info=0x7fff6400d660, record=<value optimized out>) at /u01/project/mysql-5.5.27/storage/myisam/mi_write.c:142
#4  0x000000000067fc29 in handler::ha_write_row (this=0x7fff640057d8, buf=0x7fff6400ce00 "\374\022\251\002") at /u01/project/mysql-5.5.27/sql/handler.cc:5128
#5  0x00000000005c7ede in schema_table_store_record (thd=0x40f9990, tables=<value optimized out>, cond=<value optimized out>)
    at /u01/project/mysql-5.5.27/sql/sql_show.cc:2403
#6  fill_schema_processlist (thd=0x40f9990, tables=<value optimized out>, cond=<value optimized out>) at /u01/project/mysql-5.5.27/sql/sql_show.cc:1981
#7  0x00000000005b9c1e in do_fill_table (join=0x7fff64010970, executed_place=PROCESSED_BY_JOIN_EXEC) at /u01/project/mysql-5.5.27/sql/sql_show.cc:6851
#8  get_schema_tables_result (join=0x7fff64010970, executed_place=PROCESSED_BY_JOIN_EXEC) at /u01/project/mysql-5.5.27/sql/sql_show.cc:6957
#9  0x00000000005b54bd in JOIN::exec (this=0x7fff64010970) at /u01/project/mysql-5.5.27/sql/sql_select.cc:1911
#10 0x00000000005b1839 in mysql_select (thd=0x40f9990, rref_pointer_array=<value optimized out>, tables=<value optimized out>, wild_num=0, 
    fields=<value optimized out>, conds=<value optimized out>, og_num=1, order=0x7fff64001b48, group=0x0, having=0x0, proc_param=0x0, select_options=2684619520, 
    result=0x7fff64001c10, unit=0x40fb380, select_lex=0x40fb9a0) at /u01/project/mysql-5.5.27/sql/sql_select.cc:2585
#11 0x00000000005b73d5 in handle_select (thd=0x40f9990, lex=0x40fb2d0, result=0x7fff64001c10, setup_tables_done_option=0)
    at /u01/project/mysql-5.5.27/sql/sql_select.cc:297
#12 0x00000000005753b8 in execute_sqlcom_select (thd=0x40f9990, all_tables=0x7fff64000ce8) at /u01/project/mysql-5.5.27/sql/sql_parse.cc:4590
#13 0x0000000000579612 in mysql_execute_command (thd=0x40f9990) at /u01/project/mysql-5.5.27/sql/sql_parse.cc:2151
#14 0x000000000057cbfb in mysql_parse (thd=0x40f9990, rawbuf=<value optimized out>, length=128, parser_state=0x7fff90438bd0)
    at /u01/project/mysql-5.5.27/sql/sql_parse.cc:5627
#15 0x000000000057dfa8 in dispatch_command (command=COM_QUERY, thd=0x40f9990, packet=<value optimized out>, packet_length=2420346040)
    at /u01/project/mysql-5.5.27/sql/sql_parse.cc:1037
#16 0x0000000000618d8d in do_handle_one_connection (thd_arg=<value optimized out>) at /u01/project/mysql-5.5.27/sql/sql_connect.cc:840
#17 0x0000000000618eac in handle_one_connection (arg=0x4100b80) at /u01/project/mysql-5.5.27/sql/sql_connect.cc:759
#18 0x0000003888c077e1 in start_thread () from /lib64/libpthread.so.0
#19 0x00000038888e68ed in clone () from /lib64/libc.so.6

I'll have to retest current sources with that testcase and report back... Most likely I'll file a new bug report, it looks like another problem.

5.5.26 change log notes that this bug was fixed in this version, but bzr history shows only a null-merge from 5.1 (5.1 rev 2661.810.18 and 5.5 rev 3835). Bzr history search does not show any other results for neither public nor internal bug number.

So was 5.5 fixed in some other revision that did not mention the bug number? Or is this a case similar to bug 64432 where null merge lost a fix of bug 54330?

hi, Shane, I've filed the bug here(http://bugs.mysql.com/bug.php?id=66412) and it was verified recently

I can repeat similar crash on MySQL 5.5.33 community, official tarball, after about 20 minutes running the test case provided in bug60682.c.

Thread pointer: 0x27ada80
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 = 7f1349cf2e58 thread_stack 0x40000
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(my_print_stacktrace+0x35)[0x7a2e65]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(handle_fatal_signal+0x403)[0x671393]
/lib64/libpthread.so.0[0x31b960f000]
/lib64/libc.so.6[0x31b934b100]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(_mi_rec_pack+0x323)[0x905973]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(_mi_write_blob_record+0x53)[0x906eb3]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(mi_write+0x848)[0x920df8]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(_ZN7handler12ha_write_rowEPh+0x5c)[0x6766ec]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(_Z25schema_table_store_recordP3THDP5TABLE+0x23)[0x5bb1e3]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(_Z23fill_schema_processlistP3THDP10TABLE_LISTP4Item+0x5db)[0x5cb36b]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(_Z24get_schema_tables_resultP4JOIN23enum_schema_table_state+0x256)[0x5baac6]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(_ZN4JOIN4execEv+0x5ed)[0x5b588d]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x1c3)[0x5b1913]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x179)[0x5b76a9]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld[0x574b51]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(_Z21mysql_execute_commandP3THD+0x250b)[0x57a50b]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x18a)[0x57c84a]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1363)[0x57e433]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x167)[0x6161a7]
/home/sandbox/tarballs/oracle5.5.33/bin/mysqld(handle_one_connection+0x54)[0x616214]
/lib64/libpthread.so.0[0x31b9607d15]
/lib64/libc.so.6(clone+0x6d)[0x31b92f253d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f12f80008d0): select id from information_schema.processlist where id<>connection_id()  and info like 'select%' order by rand() limit 1 into @a
Connection ID (thread ID): 1045965
Status: NOT_KILLED

The other bug #66412 is already not visible, so how can I follow it's progress for 5.5.x?

I can not repeat any problems with the testcase on 5.6.20.

Something has been fixed in 5.7.5:

revno: 7646
committer: Jon Olav Hauglid <jon.hauglid@oracle.com>
branch nick: mysql-trunk-bug17606098
timestamp: Thu 2014-03-06 12:15:07 +0100
message:
  Bug#17606098: DEADLOCK INVOLVING SRV_MONITOR_THREAD AND LOCK_THD_DATA
  
  This deadlock involved LOCK_thd_data and InnoDB's trx_sys mutex.
  It could occur if InnoDB code (e.g. the srv_monitor_thread) called 
  thd_security_context() while having trx_sys locked and at the same time
  the server tried to notify InnoDB about a deadlock (which involves calling
  mysql_lock_abort_for_thread() while holding LOCK_thd_data).
  This could lead to deadlock if mysql_lock_abort_for_thread() lead to 
  trx_allocate_for_mysql() being called inside InnoDB.
  
  This very rarely happens - the problem was found with RQG and is very
  difficult to reproduce.
  
  This patch solves the problem by splitting LOCK_thd_data so that a
  separate new mutex LOCK_thd_query protects the query string
  accessed by thd_security_context().
  
  The patch also strengthens the protection of the query string by 
  enforcing that it can only be set by the owner thread and that this
  requires locking of LOCK_thd_query. Reading the query string can
  be done by the owner thread without holding LOCK_thd_query but
  other threads reading the query string have to have LOCK_thd_query
  locked.
  
  This also solves a separate problem where other threads could 
  read the query string while it was being deleted by the owner thread.
  
  Finally, the patch updates the performance schema mutex 
  heuristics - including correcting an issue introduced by WL#6369.

A few months ago I wrote "I can not repeat any problems with the testcase on 5.6.20."  however this is not true. I got a crash on 5.6.20+ASAN today.  I will need to test latest 5.6.23 next.

==17860==ERROR: AddressSanitizer: heap-use-after-free on address 0x6020000df270 at pc 0x7ffff7156118 bp 0x7fffb877a790 sp 0x7fffb877a768
READ of size 2 at 0x6020000df270 thread T1275
#0 0x7ffff7156117 in __interceptor_strlen ../../.././libsanitizer/asan/asan_interceptors.cc:518
#1 0xadda69 in fill_schema_processlist(THD*, TABLE_LIST*, Item*) ./mysqlcom-pro-5.6.20/sql/sql_show.cc:2215
#2 0xad9d2f in do_fill_table ./mysqlcom-pro-5.6.20/sql/sql_show.cc:7330
#3 0xad9d2f in get_schema_tables_result(JOIN*, enum_schema_table_state) ./mysqlcom-pro-5.6.20/sql/sql_show.cc:7431
#4 0xa75cb4 in JOIN::prepare_result(List<Item>**) ./mysqlcom-pro-5.6.20/sql/sql_select.cc:823
#5 0x994b3b in JOIN::exec() ./mysqlcom-pro-5.6.20/sql/sql_executor.cc:116
#6 0xcf8372 in subselect_single_select_engine::exec() ./mysqlcom-pro-5.6.20/sql/item_subselect.cc:2819
#7 0xcfd0b3 in Item_subselect::exec() ./mysqlcom-pro-5.6.20/sql/item_subselect.cc:642
#8 0xcfaaea in Item_singlerow_subselect::val_int() ./mysqlcom-pro-5.6.20/sql/item_subselect.cc:1081
#9 0x751a85 in Item_func_set_user_var::check(bool) ./mysqlcom-pro-5.6.20/sql/item_func.cc:4951
#10 0x88dfa2 in set_var_user::check(THD*) ./mysqlcom-pro-5.6.20/sql/set_var.cc:706
#11 0x891837 in sql_set_variables(THD*, List<set_var_base>*) ./mysqlcom-pro-5.6.20/sql/set_var.cc:566
#12 0xa1268c in mysql_execute_command(THD*) ./mysqlcom-pro-5.6.20/sql/sql_parse.cc:3713
#13 0xa1e607 in mysql_parse(THD*, char*, unsigned int, Parser_state*) ./mysqlcom-pro-5.6.20/sql/sql_parse.cc:6245
#14 0xa22439 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ./mysqlcom-pro-5.6.20/sql/sql_parse.cc:1332
#15 0x979601 in do_handle_one_connection(THD*) ./mysqlcom-pro-5.6.20/sql/sql_connect.cc:982
#16 0x979830 in handle_one_connection ./mysqlcom-pro-5.6.20/sql/sql_connect.cc:898
#17 0x1595267 in pfs_spawn_thread ./mysqlcom-pro-5.6.20/storage/perfschema/pfs.cc:1860
#18 0x3537607d13 in start_thread (/lib64/libpthread.so.0+0x3537607d13)
#19 0x35372f168c in clone (/lib64/libc.so.6+0x35372f168c)