Bug #16593 Deadlock or crash in stress test for case where triggers starting trigger
Submitted: 18 Jan 2006 3:14 Modified: 23 Feb 2006 3:24
Reporter: Alexey Stroganov Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server Severity:S1 (Critical)
Version:5.0.17a-cert,5.0.18 OS:Any (ALL)
Assigned to: Dmitry Lenev CPU Architecture:Any

[18 Jan 2006 3:14] Alexey Stroganov
Description:
Server crashed or deadlock happened during execution of test case where triggers starting another trigger in stress mode. 

This issue could be related to BUG#16077 but as it has a bit different symptoms so 
I add it as separate bug.

I observed both deadlock and crash in case when only 3 client threads were running
only 1-5min:

Deadlock
-----------

mysqladmin proc 
| 2104 | root | qa-suse9-x86.mysql.com:33617 | test | Query   | 234  | Waiting for table | drop table t1, t2_3, t2_4, t3                                                                    |
| 2105 | root | qa-suse9-x86.mysql.com:33618 | test | Query   | 234  | Waiting for table | create trigger tr2_4 after insert on t2_4 for each row
insert into t3 (f1) values (new.f1+10000) |
| 2106 | root | qa-suse9-x86.mysql.com:33619 | test | Sleep   | 233  |                   |                     

I killed server and below are backtraces for each thread:
(gdb) info threads
*  2115 system thread 825997  0xc0000000001017b0:0 in _lwp_kill+0x30 ()
   from /usr/lib/hpux64/libpthread.so.1
   2114 system thread 825996  0xc0000000002ff2f0:0 in __ksleep+0x30 ()
   from /usr/lib/hpux64/libc.so.1
   2113 system thread 825995  0xc0000000002ff2f0:0 in __ksleep+0x30 ()
   from /usr/lib/hpux64/libc.so.1

2115
------
#0  0xc0000000001017b0:0 in _lwp_kill+0x30 ()
   from /usr/lib/hpux64/libpthread.so.1
#1  0xc0000000000b0cb0:0 in __vp_kill+0xb0 ()
   from /usr/lib/hpux64/libpthread.so.1
#2  0xc0000000000c0b90:0 in __pthread_internal_kill+0xb0 ()
   from /usr/lib/hpux64/libpthread.so.1
#3  0xc0000000000c0a20:0 in pthread_kill+0x2e0 ()
   from /usr/lib/hpux64/libpthread.so.1
#4  0x40000000008a3880:0 in write_core+0xe0 ()
   from /home/alexey/mysql-pro-cert-5.0.17a-hpux11.23-ia64-64bit/bin/mysqld
#5  0x4000000000514000:0 in handle_segfault (sig=0) at mysqld.cc:2057
#6  <signal handler called>
#7  0xc0000000003022f0:0 in _read_sys+0x30 () from /usr/lib/hpux64/libc.so.1
#8  0xc0000000003137f0:0 in read+0xb0 () from /usr/lib/hpux64/libc.so.1
#9  0x4000000000bae2a0:0 in vio_read+0x300 ()
   from /home/alexey/mysql-pro-cert-5.0.17a-hpux11.23-ia64-64bit/bin/mysqld
#10 0x40000000004f2880:0 in my_real_read (net=0x0, complen=0x2000000000000)
    at net_serv.cc:700
#11 0x40000000004f3ed0:0 in my_net_read (net=0x0) at net_serv.cc:874
#12 0x400000000054c1c0:0 in do_command (thd=0x0) at sql_parse.cc:1479
#13 0x400000000054b750:0 in handle_one_connection (arg=0x0)
    at sql_parse.cc:1158
#14 0xc0000000000a1b20:0 in __pthread_bound_body+0x180 ()

2114
------
#0  0xc0000000002ff2f0:0 in __ksleep+0x30 () from /usr/lib/hpux64/libc.so.1
#1  0xc0000000000f2380:0 in __mxn_sleep+0xde0 ()
   from /usr/lib/hpux64/libpthread.so.1
#2  0xc000000000093b80:0 in <unknown_procedure> + 0xc20 ()
   from /usr/lib/hpux64/libpthread.so.1
#3  0xc000000000092f00:0 in pthread_cond_wait+0x80 ()
   from /usr/lib/hpux64/libpthread.so.1
#4  0x4000000000c14d30:0 in safe_cond_wait+0x560 ()+0x560 at sp_pcontext.cc:405
#5  0x40000000005e3810:0 in wait_for_refresh (thd=0xa061ec8fb)
    at sql_base.cc:969
#6  0x4000000000503370:0 in wait_for_locked_table_names (thd=0x900000000,
    table_list=0x0) at lock.cc:682
#7  0x4000000000503f30:0 in lock_table_names (thd=0x0, table_list=0x0)
    at lock.cc:762
#8  0x400000000091a9e0:0 in st_table_list::prepare_security (this=0x0, thd=0x0)
    at table.cc:2420
#9  0x4000000000565b90:0 in mysql_execute_command (thd=0x60000000021cf140)
    at sql_parse.cc:4646
#10 0x400000000054dd10:0 in mysql_parse (thd=0x0, inBuf=0x0, length=0)
    at sql_parse.cc:5628
#11 0x4000000000548660:0 in dispatch_command+0x20c0 ()
   from /home/alexey/mysql-pro-cert-5.0.17a-hpux11.23-ia64-64bit/bin/mysqld
#12 0x400000000054c270:0 in do_command (thd=0x0) at sql_parse.cc:1514
#13 0x400000000054b750:0 in handle_one_connection (arg=0x0)
    at sql_parse.cc:1158
#14 0xc0000000000a1b20:0 in __pthread_bound_body+0x180 ()
   from /usr/lib/hpux64/libpthread.so.1

2113
------
#0  0xc0000000002ff2f0:0 in __ksleep+0x30 () from /usr/lib/hpux64/libc.so.1
#1  0xc0000000000f2380:0 in __mxn_sleep+0xde0 ()
   from /usr/lib/hpux64/libpthread.so.1
#2  0xc000000000093b80:0 in <unknown_procedure> + 0xc20 ()
   from /usr/lib/hpux64/libpthread.so.1
#3  0xc000000000092f00:0 in pthread_cond_wait+0x80 ()
   from /usr/lib/hpux64/libpthread.so.1
#4  0x4000000000c14d30:0 in safe_cond_wait+0x560 ()+0x560 at sp_pcontext.cc:405
#5  0x40000000005e3810:0 in wait_for_refresh (thd=0xa4165e5b2)
    at sql_base.cc:969
#6  0x4000000000503370:0 in wait_for_locked_table_names (thd=0x800000000,
    table_list=0x0) at lock.cc:682
#7  0x4000000000503f30:0 in lock_table_names (thd=0x0, table_list=0x0)
    at lock.cc:762
#8  0x40000000007ce5b0:0 in mysql_rm_table_part2 (thd=0x9fffffffef77dd9c,
    tables=0x9fffffffef77dd9c, if_exists=-97, drop_temporary=-97,
    drop_view=-97, dont_log_query=-97) at sql_table.cc:229
#9  0x40000000007ce170:0 in mysql_rm_table (thd=0x9fffffffef3fa6f5,
    tables=0x9fffffffef3fa6f5, if_exists=-97 '\237', drop_temporary=-97 '\237')
    at sql_table.cc:126
#10 0x400000000055bc80:0 in mysql_execute_command (thd=0x60000000021d3210)
    at sql_parse.cc:3430
#11 0x400000000054dd10:0 in mysql_parse (thd=0x0, inBuf=0x0, length=0)
    at sql_parse.cc:5628
#12 0x4000000000548660:0 in dispatch_command+0x20c0 ()
   from /home/alexey/mysql-pro-cert-5.0.17a-hpux11.23-ia64-64bit/bin/mysqld
#13 0x400000000054c270:0 in do_command (thd=0x0) at sql_parse.cc:1514
#14 0x400000000054b750:0 in handle_one_connection (arg=0x0)
    at sql_parse.cc:1158
#15 0xc0000000000a1b20:0 in __pthread_bound_body+0x180 ()

How to repeat:
Run conc_sys test with HP box as server and a Linux as client
[18 Jan 2006 3:15] Alexey Stroganov
details in case of  crash 
------------------------------

thread 74
------------
(gdb) bt
#0  0xc0000000001017b0:0 in _lwp_kill+0x30 ()
   from /usr/lib/hpux64/libpthread.so.1
#1  0xc0000000000b0cb0:0 in __vp_kill+0xb0 ()
   from /usr/lib/hpux64/libpthread.so.1
#2  0xc0000000000c0b90:0 in __pthread_internal_kill+0xb0 ()
   from /usr/lib/hpux64/libpthread.so.1
#3  0xc0000000000c0a20:0 in pthread_kill+0x2e0 ()
   from /usr/lib/hpux64/libpthread.so.1
#4  0x40000000008a3880:0 in write_core+0xe0 ()
   from /home/alexey/mysql-pro-cert-5.0.17a-hpux11.23-ia64-64bit/bin/mysqld
#5  0x4000000000514000:0 in handle_segfault (sig=0) at mysqld.cc:2057
#6  <signal handler called>
#7  0xc0000000003015b0:0 in kill+0x30 () from /usr/lib/hpux64/libc.so.1
#8  0xc0000000002267f0:0 in raise+0x30 () from /usr/lib/hpux64/libc.so.1
#9  0xc0000000002c2f50:0 in abort+0x250 () from /usr/lib/hpux64/libc.so.1
#10 0xc0000000001c13b0:0 in _assert+0x260 () from /usr/lib/hpux64/libc.so.1
#11 0x40000000004fe310:0 in wait_if_global_read_lock (thd=0x60000000021cec28,
    abort_on_refresh=96, is_not_commit=96) at lock.cc:948
#12 0x40000000007ce330:0 in mysql_rm_table (thd=0x303ffffff,
    tables=0x303ffffff, if_exists=0 '\000', drop_temporary=0 '\000')
    at sql_table.cc:108
#13 0x400000000055bc80:0 in mysql_execute_command (thd=0x60000000021ce800)
    at sql_parse.cc:3430

thread 73
------------
[Switching to thread 73 (system thread 823807)]
#0  0x40000000002e4130:2 in st_lex::link_first_table_back (this=0x303ffffff,
    first=0x303ffffff, link_to_local=false) at sql_lex.cc:1991
1991    sql_lex.cc: No such file or directory.
(gdb) bt
#0  0x40000000002e4130:2 in st_lex::link_first_table_back (this=0x303ffffff,
    first=0x303ffffff, link_to_local=false) at sql_lex.cc:1991
#1  0x40000000005578f0:0 in mysql_execute_command (thd=0x60000000021c62d0)
    at sql_parse.cc:2909
#2  0x400000000054dd10:0 in mysql_parse (thd=0x0, inBuf=0x0, length=0)
    at sql_parse.cc:5628

#3  0x4000000000548660:0 in dispatch_command+0x20c0 ()
   from /home/alexey/mysql-pro-cert-5.0.17a-hpux11.23-ia64-64bit/bin/mysqld
#4  0x400000000054c270:0 in do_command (thd=0x0) at sql_parse.cc:1514
#5  0x400000000054b750:0 in handle_one_connection (arg=0x0)
    at sql_parse.cc:1158
#6  0xc0000000000a1b20:0 in __pthread_bound_body+0x180 ()
   from /usr/lib/hpux64/libpthread.so.1
thread 72
------------
[Switching to thread 72 (system thread 823806)]
#0  0xc0000000000a96e0:0 in pthread_self+0 ()
   from /usr/lib/hpux64/libpthread.so.1
(gdb) bt
#0  0xc0000000000a96e0:0 in pthread_self+0 ()
   from /usr/lib/hpux64/libpthread.so.1
#1  0x4000000000c14140:0 in sp_pcontext::find_cond (this=0x0, name=0x0,
    scoped=0 '\000') at sp_pcontext.cc:291
#2  0x400000000091a9c0:0 in st_table_list::prepare_security (this=0x0, thd=0x0)
    at table.cc:2417
#3  0x4000000000565b90:0 in mysql_execute_command (thd=0x60000000021b42d0)
    at sql_parse.cc:4646
#4  0x400000000054dd10:0 in mysql_parse (thd=0x0, inBuf=0x0, length=0)
    at sql_parse.cc:5628
#5  0x4000000000548660:0 in dispatch_command+0x20c0 ()
   from /home/alexey/mysql-pro-cert-5.0.17a-hpux11.23-ia64-64bit/bin/mysqld
#6  0x400000000054c270:0 in do_command (thd=0x0) at sql_parse.cc:1514
#7  0x400000000054b750:0 in handle_one_connection (arg=0x0)
    at sql_parse.cc:1158
#8  0xc0000000000a1b20:0 in __pthread_bound_body+0x180 ()
   from /usr/lib/hpux64/libpthread.so.1
[18 Jan 2006 3:17] Alexey Stroganov
Below is test case that cause deadlock or crash when it executed in stress mode:

let $engine_type=myisam;
--disable_abort_on_error
# Checking for triggers starting triggers (no direct requirement)
use test;
--disable_warnings
drop table if exists t1;
drop table if exists t2_3;
drop table if exists t2_4;
drop table if exists t3;
--enable_warnings

eval create table t1 (f1 integer) engine=$engine_type;
eval create table t2_3 (f1 integer) engine=$engine_type;
eval create table t2_4 (f1 integer) engine=$engine_type;
eval create table t3 (f1 integer) engine=$engine_type;
insert into t1 values (1);
delimiter //;
create trigger tr1 after insert on t1 for each row
BEGIN
    insert into t2_3 (f1) values (new.f1+1);
    insert into t2_4 (f1) values (new.f1+1);
END//
delimiter ;//
create trigger tr2_3 after insert on t2_3 for each row
         insert into t3 (f1) values (new.f1+1000);
create trigger tr2_4 after insert on t2_4 for each row
         insert into t3 (f1) values (new.f1+10000);
insert into t1 values (1);
select * from t3;
#Cleanup
--disable_warnings
drop trigger tr1;
drop trigger tr2_3;
drop trigger tr2_4;
drop table t1, t2_3, t2_4, t3;
--enable_warnings
[19 Jan 2006 2:24] Alexey Stroganov
Ran test case against servers on Win and RHAS4. In both cases got deadlock.
[23 Jan 2006 12:30] Alexey Stroganov
Added test suite for reproducing of registered issue.

To run it you need:

1. Unpack attached archive in mysql-test directory 
tar xzfv suite-bug16593.tar.gz

2. Run following command:

./mysql-test-run --stress --stress-threads=10 --stress-test-count=1000 --stress-suite=bug16593 deadlock
[4 Feb 2006 9:40] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/2148
[16 Feb 2006 13:20] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/2728
[22 Feb 2006 20:09] Dmitry Lenev
Hi!

This bug was fixed in versions 5.0.19 and 5.1.8.

In short, the deadlock/crash happened when execution of statement, which used
stored functions or activated triggers, coincided with alteration of the
tables used by these functions or triggers (in highly concurrent environment).
[23 Feb 2006 3:24] Paul Dubois
Noted in 5.0.19, 5.1.8 changelogs.

          In a highly concurrent environment, a server crash or deadlock
          could result from execution of a statement that used stored
          functions or activated triggers coincident with alteration of
          the tables used by these functions or triggers. (Bug #16593)