List:Maria Storage Engine« Previous MessageNext Message »
From:Guilhem Bichot Date:November 20 2008 4:28pm
Subject:bzr commit into MySQL/Maria:mysql-maria branch (guilhem:2701) Bug#40661
View as plain text  
#At bzr+ssh://bk-internal.mysql.com/bzrroot/server/mysql-maria/ based on revid:guilhem@stripped

 2701 Guilhem Bichot	2008-11-20
      Fix for BUG#40661 "Maria: crash in embedded server (when detecting deadlock?)"
      bug is actually a weirdness in test system, so moving test portion into maria_notembedded.test
modified:
  mysql-test/suite/maria/r/maria.result
  mysql-test/suite/maria/r/maria_notembedded.result
  mysql-test/suite/maria/t/maria.test
  mysql-test/suite/maria/t/maria_notembedded.test

per-file messages:
  mysql-test/suite/maria/r/maria.result
    result update
  mysql-test/suite/maria/r/maria_notembedded.result
    result update
  mysql-test/suite/maria/t/maria.test
    Removing test portion into maria_notembedded.test. Explanation below.
    Running maria.test with --mem --embedded --valgrind I got:
    ==378== Invalid read of size 4
    ==378==    at 0x857C755: _lf_pinbox_real_free (lf_alloc-pin.c:342)
    ==378==    by 0x857C640: _lf_pinbox_free (lf_alloc-pin.c:267)
    ==378==    by 0x857D50C: ldelete (lf_hash.c:226)
    ==378==    by 0x857DBC1: lf_hash_delete (lf_hash.c:429)
    ==378==    by 0x8243D82: unlock_lock_and_free_resource
    (waiting_threads.c:676)
    ==378==    by 0x8244A79: wt_thd_release (waiting_threads.c:948)
    ==378==    by 0x83F301D: wt_thd_release_self (trnman.c:98)
    ==378==    by 0x83F3D49: trnman_end_trn (trnman.c:431)
    ==378==    by 0x837C437: ma_commit (ma_commit.c:60)
    ==378==    by 0x835F082: ha_maria::external_lock(THD*, int)
    (ha_maria.cc:2387)
    ==378==    by 0x84D1011: handler::ha_external_lock(THD*, int)
    (handler.cc:4433)
    ==378==    by 0x856DA92: unlock_external(THD*, st_table**, unsigned)
    (lock.cc:786)
    ==378==    by 0x856DD6F: mysql_unlock_tables(THD*, st_mysql_lock*)
    (lock.cc:389)
    ==378==    by 0x8274A57: close_thread_tables(THD*) (sql_base.cc:1307)
    ==378==    by 0x82ABEC3: unlock_locked_tables(THD*) (sql_parse.cc:99)
    ==378==    by 0x82B0BB3: mysql_execute_command(THD*)
    (sql_parse.cc:3372)
    ==378==  Address 0x5894a0c is 164 bytes inside a block of size 184
    free'd
    ==378==    at 0x40233FC: free (vg_replace_malloc.c:323)
    ==378==    by 0x823CF92: my_thread_end (my_thr_init.c:348)
    ==378==    by 0x8200FEE: mysql_thread_end (libmysql.c:250)
    ==378==    by 0x81A9487: send_one_query (mysqltest.c:535)
    ==378==    by 0x4050111: start_thread (in /lib/libpthread-2.5.so)
    ==378==    by 0x41A52ED: clone (in /lib/libc-2.5.so)
    
    (among other errors). The line where the invalid read happens is:
      if (available_stack_size(&pinbox, *pins->stack_ends_here) >
    alloca_size)
    and stack_ends_here was previously set here:
      el->stack_ends_here= & my_thread_var->stack_ends_here;
    The mysqltest "send" command, in embedded mode, is implemented this way
    (mysqltest.c:do_send_query()): a *new OS thread* is created in
    mysqltest, and does this:
    
      mysql_thread_init();
      VOID(mysql_send_query(&cn->mysql, cn->cur_query,
    cn->cur_query_len));
      mysql_thread_end();
    
    So, con_d "send insert t1 values (2)" creates a new OS thread, which
    gets a thread-specific data (mysql_thread_init()), then sends the
    query; in particular, this sets el->stack_ends_here to a pointer inside
    the thread-specific data (see my_thread_var above), that is, thd->pins
    depends on the thread-specific data.
    This sent "insert" blocks as expected, thread-specific data is free()d
    (my_thread_end() above), OS thread terminates.
    Then "default" connection runs "insert t1 values (3)"
    which blocks on the 3 already inserted by the con_d.
    This blocking (see waiting_threads.c) creates a WT_RESOURCE, which has,
    as owner, con_d's WT_THD.
    When con_d calls "unlock tables" (see stack trace), it wants to release
    this resource, which involves con_d's thd->pins, so it ends up reading
    stack_ends_here which points inside the freed thread-specific data =>
    Valgrind error, crashes...
    So this is an effect of having one single connection (con_d) for which
    two queries:
    send insert t1 values (2)
    unlock tables
    are done by different OS threads. That is indeed weird design of
    mysqltest, and it breaks on the dependency of lf_alloc-pin.c on
    thread-specific data. It is maybe already explained in those comments
    in lf_alloc-pin.c:
    "  It is assumed that pins belong to a THD and are not transferable
      between THD's (LF_PINS::stack_ends_here being a primary reason
      for this limitation)."
    "    It is assumed that pins belong to a thread and are not
    transferable
        between threads."
    
    In correct usage of libmysqld (no two queries sent for one connection
    by two threads), this problem would not happen, so I call it a
    deficiency of the test system.
  mysql-test/suite/maria/t/maria_notembedded.test
    moving test portion into maria_notembedded.test
=== modified file 'mysql-test/suite/maria/r/maria.result'
--- a/mysql-test/suite/maria/r/maria.result	2008-10-15 12:44:31 +0000
+++ b/mysql-test/suite/maria/r/maria.result	2008-11-20 16:28:27 +0000
@@ -2203,19 +2203,6 @@ check table t2 extended;
 Table	Op	Msg_type	Msg_text
 test.t2	check	status	OK
 drop table t2;
-create table t1 (a int unique) transactional=1;
-insert t1 values (1);
-lock table t1 write concurrent;
-insert t1 values (2);
-lock table t1 write concurrent;
-insert t1 values (3);
-insert t1 values (2);
-insert t1 values (3);
-ERROR 40001: Deadlock found when trying to get lock; try restarting transaction
-unlock tables;
-ERROR 23000: Duplicate entry '2' for key 'a'
-unlock tables;
-drop table t1;
 CREATE TABLE t1 (
 col0 float DEFAULT NULL,
 col1 date DEFAULT NULL,   

=== modified file 'mysql-test/suite/maria/r/maria_notembedded.result'
--- a/mysql-test/suite/maria/r/maria_notembedded.result	2008-10-11 08:27:03 +0000
+++ b/mysql-test/suite/maria/r/maria_notembedded.result	2008-11-20 16:28:27 +0000
@@ -23,3 +23,16 @@ select count(*) from t1;
 count(*)
 1
 drop table t1;
+create table t1 (a int unique) transactional=1;
+insert t1 values (1);
+lock table t1 write concurrent;
+insert t1 values (2);
+lock table t1 write concurrent;
+insert t1 values (3);
+insert t1 values (2);
+insert t1 values (3);
+ERROR 40001: Deadlock found when trying to get lock; try restarting transaction
+unlock tables;
+ERROR 23000: Duplicate entry '2' for key 'a'
+unlock tables;
+drop table t1;

=== modified file 'mysql-test/suite/maria/t/maria.test'
--- a/mysql-test/suite/maria/t/maria.test	2008-10-15 12:44:31 +0000
+++ b/mysql-test/suite/maria/t/maria.test	2008-11-20 16:28:27 +0000
@@ -1469,31 +1469,6 @@ insert into t2 values (repeat('x',28)), 
 check table t2 extended;
 drop table t2;
 
-#
-# an example of a deadlock
-#
-create table t1 (a int unique) transactional=1;
-insert t1 values (1);
-lock table t1 write concurrent;
-insert t1 values (2);
-connect(con_d,localhost,root,,);
-lock table t1 write concurrent;
-insert t1 values (3);
-send insert t1 values (2);
-connection default;
-let $wait_condition=select count(*) = 1 from information_schema.processlist where state="waiting for a resource";
---source include/wait_condition.inc
---error ER_LOCK_DEADLOCK
-insert t1 values (3);
-unlock tables;
-connection con_d;
---error ER_DUP_ENTRY
-reap;
-unlock tables;
-disconnect con_d;
-connection default;
-drop table t1;
-
 CREATE TABLE t1 (
 col0 float DEFAULT NULL,
 col1 date DEFAULT NULL,   

=== modified file 'mysql-test/suite/maria/t/maria_notembedded.test'
--- a/mysql-test/suite/maria/t/maria_notembedded.test	2008-10-11 08:27:03 +0000
+++ b/mysql-test/suite/maria/t/maria_notembedded.test	2008-11-20 16:28:27 +0000
@@ -26,6 +26,34 @@ select * from t1;
 select count(*) from t1;
 drop table t1;
 
+# This cannot be run in embedded server, see BUG#40661, because
+# mysqltest runs "send" commands in separate OS thread.
+#
+# an example of a deadlock
+#
+create table t1 (a int unique) transactional=1;
+insert t1 values (1);
+lock table t1 write concurrent;
+insert t1 values (2);
+connect(con_d,localhost,root,,);
+lock table t1 write concurrent;
+insert t1 values (3);
+send insert t1 values (2);
+connection default;
+let $wait_condition=select count(*) = 1 from information_schema.processlist where state="waiting for a resource";
+--source include/wait_condition.inc
+--error ER_LOCK_DEADLOCK
+insert t1 values (3);
+unlock tables;
+connection con_d;
+--error ER_DUP_ENTRY
+reap;
+unlock tables;
+disconnect con_d;
+connection default;
+drop table t1;
+
+
 --disable_result_log
 --disable_query_log
 eval set session storage_engine=$default_engine;

Thread
bzr commit into MySQL/Maria:mysql-maria branch (guilhem:2701) Bug#40661Guilhem Bichot20 Nov
  • Re: bzr commit into MySQL/Maria:mysql-maria branch (guilhem:2701)Bug#40661Sergei Golubchik27 Nov