MySQL Bugs: #40661: Maria: crash in embedded server (when detecting deadlock?)

Bug #40661	Maria: crash in embedded server (when detecting deadlock?)
Submitted:	12 Nov 2008 9:08	Modified:	9 Jan 2009 15:15
Reporter:	Guilhem Bichot	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Maria storage engine	Severity:	S3 (Non-critical)
Version:	5.1-maria, 6.0-maria	OS:	Linux
Assigned to:	Guilhem Bichot	CPU Architecture:	Any

Description:
I have not checked 5.1-maria.
./mtr --mem --embedded maria
fails in 6.0-maria.
A small testcase extracted from it, gives a segmentation fault where info->trn seems to be NULL in maria_write() at this line:
        while (keyinfo->ck_insert(info,
                                  (*keyinfo->make_key)(info, &int_key, i,
                                                       buff, record, filepos,
                                                       info->trn->trid)))
see the testcase in how-to-repeat

How to repeat:
# an example of a deadlock
#
create table t1 (a int unique) transactional=1 engine=maria;
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;

I put it in bug.test and I run
./mtr --mem --embedded bug
a few times at most, and see in master.err the crash.

I tried investigate the case and found that it stuck even on normal server if isolate the test (it stuck on lock table concurent):

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;

Hi Sanja. About your previous post: are you sure the table is Maria (it could be a MyISAM table, you don't have engine=maria in CREATE TABLE) ?

Here is what happens, with this test portion of maria.test:

# an example of a deadlock
#
create table t1 (a int unique) transactional=1 engine=maria;
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;

Running with --mem --embedded --valgrind:
==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. Thus I will close it as "not a bug" and move the crashing portion of maria.test to maria_notembedded.test .

http://lists.mysql.com/maria/294
Setting Serg as reviewer to also check that there is no code change which could remove the dependency of pins on thread-specific data (I'm almost sure, but...)

queued to 5.1-maria and 6.0-maria

Pushed into 6.0.9-alpha  (revid:guilhem@mysql.com-20081127151302-xfo8wjw93fzb2f9d) (version source revid:guilhem@mysql.com-20081213204800-0nubni3t4ihn4hv9) (pib:5)

Testcase only. No documentation needed.