Bug #54747 Deadlock between REORGANIZE PARTITION and SELECT is not detected
Submitted: 23 Jun 2010 16:06 Modified: 10 Sep 2010 2:47
Reporter: Elena Stepanova Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Locking Severity:S3 (Non-critical)
Version:5.5.3-m3, 5.5.5-m3 OS:Any
Assigned to: Mattias Jonsson CPU Architecture:Any

[23 Jun 2010 16:06] Elena Stepanova
Description:
With the test case provided in 'How to repeat' section, ALTER thread falls into timedwait (which with default lock_wait_timeout value means forever), while SELECT stays in cond_wait until ALTER gets timed out.

Not sure if it is related to bug#53770 group, or is an independent issue.

The test case is based on sleep() and hence is not completely deterministic, although it always failed for me. There are 5 selects with sleep because it might clash with ALTER at different moments.

innodb_thread_concurrency = 1 seems significant for the test case, although it might be just because it allows to hit the race condition more easily.

Thread 3 (Thread 1166858560 (LWP 19994)):
#0  0x00002b6aede0f1c6 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000008928d4 in os_event_wait_low (event=0x11bfe00, reset_sig_count=24)
    at mysql-5.5.5-m3/storage/innobase/os/os0sync.c:399
#2  0x00000000007d9de9 in srv_conc_enter_innodb (trx=0x14a25b8)
    at mysql-5.5.5-m3/storage/innobase/srv/srv0srv.c:1220
#3  0x00000000007abafa in ha_innobase::general_fetch (this=0x149fea0, buf=0x1465422 "ЩхЁ4\212", direction=1, match_mode=0)
    at mysql-5.5.5-m3/storage/innobase/handler/ha_innodb.cc:716
#4  0x0000000000689469 in ha_partition::handle_ordered_next (this=0x145e3e0, buf=0x145e708 "ЩхЁ4\212", is_next_same=255)
    at mysql-5.5.5-m3/sql/ha_partition.h:480
#5  0x00000000005a7fcd in join_read_next (info=0x145b4c0)
    at mysql-5.5.5-m3/sql/sql_select.cc:12354
#6  0x00000000005a68cb in sub_select (join=0x14a5030, join_tab=0x145b440, end_of_records=<value optimized out>)
    at mysql-5.5.5-m3/sql/sql_select.cc:11587
#7  0x00000000005a6d4e in do_select (join=0x14a5030, fields=0x14a6698, table=0x0, procedure=0x0)
    at mysql-5.5.5-m3/sql/sql_select.cc:11334
#8  0x00000000005b89d3 in JOIN::exec (this=0x14a5030)
    at mysql-5.5.5-m3/sql/sql_select.cc:2354
#9  0x00000000005b9c2b in mysql_select (thd=0x144f640, rref_pointer_array=0x1451700, tables=0x145a8d8, wild_num=0,
    fields=<value optimized out>, conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=0,
    result=0x145ae78, unit=0x1450f30, select_lex=0x1451530)
    at mysql-5.5.5-m3/sql/sql_select.cc:2549
#10 0x00000000005ba399 in handle_select (thd=0x144f640, lex=0x1450e88, result=0x145ae78, setup_tables_done_option=0)
    at mysql-5.5.5-m3/sql/sql_select.cc:278
#11 0x0000000000576f36 in execute_sqlcom_select (thd=0x144f640, all_tables=0x145a8d8)
    at mysql-5.5.5-m3/sql/sql_parse.cc:4882
#12 0x000000000057e218 in mysql_execute_command (thd=0x144f640)
    at mysql-5.5.5-m3/sql/sql_parse.cc:2329
#13 0x0000000000582add in mysql_parse (thd=0x144f640,
    inBuf=0x145a2d0 "SELECT NOW(), COUNT(*), SLEEP(1) FROM betony_features.t_part_range", length=<value optimized out>,
    parser_state=0x458cc7e0) at mysql-5.5.5-m3/sql/sql_parse.cc:5911
#14 0x0000000000583847 in dispatch_command (command=COM_QUERY, thd=0x144f640, packet=<value optimized out>, packet_length=66)
    at mysql-5.5.5-m3/sql/sql_class.h:724
#15 0x000000000058410d in do_command (thd=0x144f640)
    at mysql-5.5.5-m3/sql/sql_parse.cc:807
#16 0x000000000061c659 in do_handle_one_connection (thd_arg=0x144f640)
    at mysql-5.5.5-m3/sql/sql_connect.cc:1196
#17 0x000000000061d0c4 in handle_one_connection (arg=<value optimized out>)
    at mysql-5.5.5-m3/sql/sql_connect.cc:1135
#18 0x0000000000908b7b in pfs_spawn_thread (arg=<value optimized out>)
    at mysql-5.5.5-m3/storage/perfschema/pfs.cc:1015
#19 0x00002b6aede0b143 in start_thread () from /lib64/libpthread.so.0
#20 0x00002b6aee47a8cd in clone () from /lib64/libc.so.6
#21 0x0000000000000000 in ?? ()

Thread 2 (Thread 1167124800 (LWP 19995)):
#0  0x00002b6aede0f3b7 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000006243ab in MDL_wait::timed_wait (this=0x1490528, thd=0x1490460, abs_timeout=0x459089e0, set_status_on_timeout=false)
    at mysql-5.5.5-m3/include/mysql/psi/mysql_thread.h:1092
#2  0x0000000000625f61 in MDL_context::acquire_lock (this=0x1490528, mdl_request=0x45908a70,
    lock_wait_timeout=<value optimized out>) at mysql-5.5.5-m3/sql/mdl.cc:1820
#3  0x0000000000626289 in MDL_context::upgrade_shared_lock_to_exclusive (this=0x1490528, mdl_ticket=0x1464110,
    lock_wait_timeout=200) at mysql-5.5.5-m3/sql/mdl.cc:2003
#4  0x000000000054581f in wait_while_table_is_used (thd=0x1490460, table=0x14774f0, function=HA_EXTRA_FORCE_REOPEN)
    at mysql-5.5.5-m3/sql/sql_base.cc:2197
#5  0x0000000000545956 in abort_and_upgrade_lock_and_close_table (lpt=0x459096e0)
    at mysql-5.5.5-m3/sql/sql_base.cc:9025
#6  0x000000000078d173 in fast_alter_partition_table (thd=0x1490460, table=<value optimized out>,
    alter_info=<value optimized out>, create_info=<value optimized out>, table_list=0x149b298, db=<value optimized out>,
    table_name=0x149b250 "t_part_range", fast_alter_partition=1)
    at mysql-5.5.5-m3/sql/sql_partition.cc:6164
#7  0x00000000005de506 in mysql_alter_table (thd=0x1490460, new_db=0x149b7a0 "betony_features", new_name=0x149b250 "t_part_range",
    create_info=0x4590c230, table_list=0x149b298, alter_info=0x4590c190, order_num=0, order=0x0, ignore=false)
    at mysql-5.5.5-m3/sql/sql_table.cc:7092
#8  0x000000000057f1d9 in mysql_execute_command (thd=0x1490460)
    at mysql-5.5.5-m3/sql/sql_parse.cc:2917
#9  0x0000000000582add in mysql_parse (thd=0x1490460,
    inBuf=0x149b0f0 "ALTER TABLE t_part_range \nREORGANIZE PARTITION hour_003, hour_004 INTO\n( PARTITION oldest VALUES LESS THAN (4) )", length=<value optimized out>, parser_state=0x4590d7e0)
    at mysql-5.5.5-m3/sql/sql_parse.cc:5911
#10 0x0000000000583847 in dispatch_command (command=COM_QUERY, thd=0x1490460, packet=<value optimized out>, packet_length=112)
    at mysql-5.5.5-m3/sql/sql_class.h:724
#11 0x000000000058410d in do_command (thd=0x1490460)
    at mysql-5.5.5-m3/sql/sql_parse.cc:807
#12 0x000000000061c659 in do_handle_one_connection (thd_arg=0x1490460)
    at mysql-5.5.5-m3/sql/sql_connect.cc:1196
#13 0x000000000061d0c4 in handle_one_connection (arg=<value optimized out>)
    at mysql-5.5.5-m3/sql/sql_connect.cc:1135
#14 0x0000000000908b7b in pfs_spawn_thread (arg=<value optimized out>)
    at mysql-5.5.5-m3/storage/perfschema/pfs.cc:1015
#15 0x00002b6aede0b143 in start_thread () from /lib64/libpthread.so.0
#16 0x00002b6aee47a8cd in clone () from /lib64/libc.so.6
#17 0x0000000000000000 in ?? ()

How to repeat:
# Run with --lock_wait_timeout of your choice
#
#------------------------------------------------------------------
# Init

--source include/have_innodb.inc
--disable_warnings

--connect (con18,localhost,root,,test)

let $thread_concurrency = `SELECT @@innodb_thread_concurrency`;
SET GLOBAL innodb_thread_concurrency = 1;

DROP DATABASE IF EXISTS betony_features;
CREATE DATABASE betony_features;
USE betony_features;

CREATE TABLE betony_features.t_part_range (user_num BIGINT,
	hours SMALLINT,
	KEY user_num (user_num)) ENGINE = InnoDB   
	PARTITION BY RANGE COLUMNS (hours)
 (  
 PARTITION hour_003 VALUES LESS THAN (3),
 PARTITION hour_004 VALUES LESS THAN (4),
 PARTITION hour_005 VALUES LESS THAN (5),
 PARTITION hour_last VALUES LESS THAN (MAXVALUE) );

--perl
open( DATA, ">$ENV{MYSQLTEST_VARDIR}/t_part_range.load" ) 
	|| die "Could not open file $ENV{MYSQLTEST_VARDIR}/t_part_range.load for writing: $!";
for ( 1..10000 )
{
	print DATA ( int(rand(9000000000))+1000000000 ), "\t", ( int(rand(5)) ), "\n";
}
close( DATA );
EOF

eval LOAD DATA LOCAL INFILE '$MYSQLTEST_VARDIR/t_part_range.load' 
	INTO TABLE betony_features.t_part_range (user_num, hours);

--disconnect con18

#------------------------------------------------------------------
# Concurrency

--connect (con72,localhost,root,,test)

--connect (con44,localhost,root,,test)
	USE betony_features;
	let $start = `SELECT NOW()`;
--send
	ALTER TABLE t_part_range 
 REORGANIZE PARTITION hour_003, hour_004 INTO
 ( PARTITION oldest VALUES LESS THAN (4) );

#--------------

--connection con72

SELECT NOW(), COUNT(*), SLEEP(1) FROM betony_features.t_part_range;
SELECT NOW(), COUNT(*), SLEEP(1) FROM betony_features.t_part_range;
SELECT NOW(), COUNT(*), SLEEP(1) FROM betony_features.t_part_range;
SELECT NOW(), COUNT(*), SLEEP(1) FROM betony_features.t_part_range;
SELECT NOW(), COUNT(*), SLEEP(1) FROM betony_features.t_part_range;

--connection con44
--error 0,ER_LOCK_DEADLOCK
--reap

#------------------------------------------------------------------
# Cleanup

--disconnect con44
--disconnect con72

--connection default

DROP DATABASE betony_features;
eval SET GLOBAL innodb_thread_concurrency = $thread_concurrency;

--exit

# End of test
#------------------------------------------------------------------
[23 Jun 2010 16:51] Elena Stepanova
Also tried the patch for bug#53770 group (http://lists.mysql.com/commits/110773).

With the patch, deadlock is still not detected, but the timeout does not cause disasters as it happens with current trunk, where the continuation of the original test case would be 

DROP DATABASE betony_features;
DROP DATABASE betony_features' failed: 1010: Error dropping database (can't rmdir './betony_features', errno: 39)

Since the patch for bug#53676 fixes this part, it was not filed in the original bug (the test case in 'How to repeat' does not reach this point as it fails on reap due to wrong error code).
[17 Aug 2010 11:03] Mattias Jonsson
Seems to be solved by this patch:
=== modified file 'sql/sql_partition.cc'
--- sql/sql_partition.cc	2010-08-13 07:50:25 +0000
+++ sql/sql_partition.cc	2010-08-17 10:52:31 +0000
@@ -5535,9 +5535,20 @@
   char path[FN_REFLEN+1];
   int error;
   handler *file= lpt->table->file;
+  THD *thd= lpt->thd;
   DBUG_ENTER("mysql_change_partitions");
 
   build_table_filename(path, sizeof(path) - 1, lpt->db, lpt->table_name, "", 0);
+
+  /*
+    Turn off recovery logging since rollback of an alter table is to
+    delete the new table so there is no need to log the changes to it.
+
+    This needs to be done before external_lock
+  */
+  if(ha_enable_transaction(thd, FALSE))
+    DBUG_RETURN(TRUE);
+
   if ((error= file->ha_change_partitions(lpt->create_info, path, &lpt->copied,
                                          &lpt->deleted, lpt->pack_frm_data,
                                          lpt->pack_frm_len)))
@@ -5545,6 +5556,13 @@
     file->print_error(error, MYF(error != ER_OUTOFMEMORY ? 0 : ME_FATALERROR));
     DBUG_RETURN(TRUE);
   }
+
+  if (ha_enable_transaction(thd, TRUE))
+    DBUG_RETURN(TRUE);
+  if (trans_commit_stmt(thd))
+    DBUG_RETURN(TRUE);
+  if (trans_commit_implicit(thd))
+    DBUG_RETURN(TRUE);
   DBUG_RETURN(FALSE);
 }
[17 Aug 2010 12:37] Mattias Jonsson
seems related to bug#51263, the test case in this bug also deadlocks with REBUILD instead of REORGANIZE.
[17 Aug 2010 15:36] Mattias Jonsson
The problem is that the alter still having internal innodb latches, which could be solved with the minimalistic patch:
=== modified file 'sql/sql_partition.cc'
--- sql/sql_partition.cc	2010-08-13 07:50:25 +0000
+++ sql/sql_partition.cc	2010-08-17 15:32:07 +0000
@@ -5545,6 +5545,7 @@
     file->print_error(error, MYF(error != ER_OUTOFMEMORY ? 0 : ME_FATALERROR));
     DBUG_RETURN(TRUE);
   }
+  ha_release_temporary_latches(lpt->thd);
   DBUG_RETURN(FALSE);
 }
 

But I will do a patch inline with the current copy_data_between_tables() function to be consistent.
[17 Aug 2010 15:54] 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/115991

3183 Mattias Jonsson	2010-08-17
      Bug#54747: Deadlock between REORGANIZE PARTITION and SELECT is not detected
      
      Problem was that there was unreleased latches
      in the ALTER PARTITION thread which was needed
      by the SELECT thread to be able to continue.
      
      Solution was to release the latches before
      requesting upgrade to exclusive MDL lock.
     @ mysql-test/r/partition_debug_sync.result
        updated result
     @ mysql-test/t/partition_debug_sync.test
        added test
     @ sql/sql_base.cc
        New DEBUG_SYNC point
     @ sql/sql_partition.cc
        moved implicit commit into mysql_change_partition
        so that if latches are taken, they are always released
        before waiting on exclusive lock.
     @ sql/sql_table.cc
        Clarifying the comment.
[20 Aug 2010 10:08] 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/116357

3184 Mattias Jonsson	2010-08-20
      Bug#54747: Deadlock between REORGANIZE PARTITION and SELECT is not detected
      
      Problem was that there was unreleased latches
      in the ALTER PARTITION thread which was needed
      by the SELECT thread to be able to continue.
      
      Solution was to release the latches by commit 
      before requesting upgrade to exclusive MDL lock.
      
      Updated according to reviewers comments.
     @ mysql-test/r/partition_debug_sync.result
        updated result
     @ mysql-test/t/partition_debug_sync.test
        added test
     @ sql/sql_base.cc
        added debug sync for easier testing
     @ sql/sql_partition.cc
        Moved implicit commit into mysql_change_partition
        so that if latches are taken, they are always released
        before waiting on exclusive lock.
     @ sql/sql_table.cc
        refactored the code to prepare and commit
        around copy_data_between_tables, to be able
        to reuse it in mysql_change_partitions
     @ sql/sql_table.h
        exporting mysql_prepare/commit_alter_copy_data
[20 Aug 2010 15:25] 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/116430

3184 Mattias Jonsson	2010-08-20
      Bug#54747: Deadlock between REORGANIZE PARTITION and SELECT is not detected
      
      The ALTER PARTITION and SELECT seemed to be deadlocked
      when having innodb_thread_concurrency = 1.
      
      Problem was that there was unreleased latches
      in the ALTER PARTITION thread which was needed
      by the SELECT thread to be able to continue.
      
      Solution was to release the latches by commit 
      before requesting upgrade to exclusive MDL lock.
      
      Updated according to reviewers comments (2).
     @ mysql-test/r/partition_innodb.result
        updated test result
     @ mysql-test/t/partition_innodb.test
        added test
     @ sql/sql_partition.cc
        Moved implicit commit into mysql_change_partition
        so that if latches are taken, they are always released
        before waiting on exclusive lock.
     @ sql/sql_table.cc
        refactored the code to prepare and commit
        around copy_data_between_tables, to be able
        to reuse it in mysql_change_partitions
     @ sql/sql_table.h
        exporting mysql_trans_prepare/commit_alter_copy_data
[20 Aug 2010 17:16] 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/116441

3190 Mattias Jonsson	2010-08-20
      Bug#54747: Deadlock between REORGANIZE PARTITION and SELECT is not detected
      
      The ALTER PARTITION and SELECT seemed to be deadlocked
      when having innodb_thread_concurrency = 1.
      
      Problem was that there was unreleased latches
      in the ALTER PARTITION thread which was needed
      by the SELECT thread to be able to continue.
      
      Solution was to release the latches by commit 
      before requesting upgrade to exclusive MDL lock.
      
      Updated according to reviewers comments (3).
     @ mysql-test/r/partition_innodb.result
        updated test result
     @ mysql-test/t/partition_innodb.test
        added test
     @ sql/sql_partition.cc
        Moved implicit commit into mysql_change_partition
        so that if latches are taken, they are always released
        before waiting on exclusive lock.
     @ sql/sql_table.cc
        refactored the code to prepare and commit
        around copy_data_between_tables, to be able
        to reuse it in mysql_change_partitions
     @ sql/sql_table.h
        exporting mysql_trans_prepare/commit_alter_copy_data
[20 Aug 2010 19:06] Mattias Jonsson
pushed into mysql-5.5-bugfixing
[25 Aug 2010 9:23] Bugs System
Pushed into mysql-5.5 5.5.6-m3 (revid:alik@ibmvm-20100825092002-2yvkb3iwu43ycpnm) (version source revid:alik@ibmvm-20100825092002-2yvkb3iwu43ycpnm) (merge vers: 5.5.6-m3) (pib:20)
[30 Aug 2010 8:32] Bugs System
Pushed into mysql-trunk 5.6.1-m4 (revid:alik@sun.com-20100830082732-n2eyijnv86exc5ci) (version source revid:alik@sun.com-20100830082732-n2eyijnv86exc5ci) (merge vers: 5.6.1-m4) (pib:21)
[30 Aug 2010 8:35] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100830082745-n6sh01wlwh3itasv) (version source revid:alik@sun.com-20100830082745-n6sh01wlwh3itasv) (pib:21)
[10 Sep 2010 2:47] Paul DuBois
Noted in 5.5.6, 5.6.1 changelogs.

With innodb_thread_concurrency = 1, ALTER TABLE ... REORGANIZE
PARTITION and SELECT could deadlock. There were unreleased latches in
the ALTER TABLE ... REORGANIZE PARTITION thread which were needed by
the SELECT thread to be able to continue.