Bug #50786 Assertion `thd->mdl_context.trans_sentinel() == __null' failed in open_ltable()
Submitted: 1 Feb 2010 9:56 Modified: 7 Mar 2010 1:04
Reporter: Philip Stoev Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Locking Severity:S1 (Critical)
Version:mysql-next-4284-stage OS:Any
Assigned to: Jon Olav Hauglid CPU Architecture:Any

[1 Feb 2010 9:56] Philip Stoev
Description:
When executing the usual concurrent RQG MDL workload, mysqld asserted as follows:

mysqld: sql_base.cc:5041: TABLE* open_ltable(THD*, TABLE_LIST*, thr_lock_type, uint): Assertion `thd->mdl_context.trans_sentinel() == __null' failed.

# 11:30:21 #6  0x000000315a42bec9 in __assert_fail () from /lib64/libc.so.6
# 11:30:21 #7  0x0000000000698b5f in open_ltable (thd=0x7f39a0093168, table_list=0x7f39a44158d0, lock_type=TL_WRITE_CONCURRENT_INSERT, lock_flags=27)
# 11:30:21     at sql_base.cc:5041
# 11:30:21 #8  0x0000000000698c37 in open_performance_schema_table (thd=0x7f39a0093168, one_table=0x7f39a44158d0, backup=0x7f39a4415fd0) at sql_base.cc:9028
# 11:30:21 #9  0x000000000070f357 in Log_to_csv_event_handler::log_general (this=0x16462c0, thd=0x7f39a0093168, event_time=1265016619,
# 11:30:21     user_host=0x7f39a44160f0 "root[root] @ localhost [127.0.0.1]", user_host_len=34, thread_id=41, command_type=0xacc895 "Query", command_type_len=5,
# 11:30:21     sql_text=0x22f6998 "LOCK TABLES testdb_S . t1_part1_S  AS o READ LOCAL", sql_text_len=50, client_cs=0xfad1a0) at log.cc:445
# 11:30:21 #10 0x000000000070dd41 in LOGGER::general_log_write (this=0xfbe660, thd=0x7f39a0093168, command=COM_QUERY,
# 11:30:21     query=0x22f6998 "LOCK TABLES testdb_S . t1_part1_S  AS o READ LOCAL", query_length=50) at log.cc:1086
# 11:30:21 #11 0x000000000070ddf1 in general_log_write (thd=0x7f39a0093168, command=COM_QUERY, query=0x22f6998 "LOCK TABLES testdb_S . t1_part1_S  AS o READ LOCAL",
# 11:30:21     query_length=50) at log.cc:4363
# 11:30:21 #12 0x000000000064e100 in dispatch_command (command=COM_QUERY, thd=0x7f39a0093168,
# 11:30:21     packet=0x7f39a0058f89 "LOCK TABLES testdb_S . t1_part1_S  AS o READ LOCAL", packet_length=50) at sql_parse.cc:1005
# 11:30:21 #13 0x000000000064f662 in do_command (thd=0x7f39a0093168) at sql_parse.cc:695
# 11:30:21 #14 0x000000000063de31 in handle_one_connection (arg=0x7f39a0093168) at sql_connect.cc:1163
# 11:30:21 #15 0x000000315b0073da in start_thread () from /lib64/libpthread.so.0
# 11:30:21 #16 0x000000315a4e627d in clone () from /lib64/libc.so.6

there is another thread that appears to operate on the CSV log table as well:

# 11:30:23 #0  0x000000315b00db14 in __lll_lock_wait () from /lib64/libpthread.so.0
# 11:30:23 #1  0x000000315b00921c in _L_lock_1078 () from /lib64/libpthread.so.0
# 11:30:23 #2  0x000000315b0090f0 in pthread_mutex_lock () from /lib64/libpthread.so.0
# 11:30:23 #3  0x00000000009c7bec in safe_mutex_lock (mp=0xfd1220, try_lock=0 '\0', file=0xb9a7e0 "safemalloc.c", line=508) at thr_mutex.c:149
# 11:30:23 #4  0x00000000009a1f3c in _sanity (filename=0xabd260 "lock.cc", lineno=865) at safemalloc.c:508
# 11:30:23 #5  0x00000000009a10fb in _mymalloc (size=48, filename=0xabd260 "lock.cc", lineno=865, MyFlags=0) at safemalloc.c:130
# 11:30:23 #6  0x000000000062a6b7 in get_lock_data (thd=0x7f39a00c1758, table_ptr=0x7f39a461d960, count=1, flags=2, write_lock_used=0x7f39a461d758) at lock.cc:861
# 11:30:23 #7  0x000000000062b627 in mysql_lock_tables (thd=0x7f39a00c1758, tables=0x7f39a461d960, count=1, flags=27, need_reopen=0x7f39a461d7ff) at lock.cc:263
# 11:30:23 #8  0x0000000000698adb in open_ltable (thd=0x7f39a00c1758, table_list=0x7f39a461d8d0, lock_type=TL_WRITE_CONCURRENT_INSERT, lock_flags=27)
# 11:30:23     at sql_base.cc:5032
# 11:30:23 #9  0x0000000000698c37 in open_performance_schema_table (thd=0x7f39a00c1758, one_table=0x7f39a461d8d0, backup=0x7f39a461dfd0) at sql_base.cc:9028
# 11:30:23 #10 0x000000000070f357 in Log_to_csv_event_handler::log_general (this=0x16462c0, thd=0x7f39a00c1758, event_time=1265016619,
# 11:30:23     user_host=0x7f39a461e0f0 "root[root] @ localhost [127.0.0.1]", user_host_len=34, thread_id=20, command_type=0xacc895 "Query", command_type_len=5,
# 11:30:23     sql_text=0x221dd58 "SHOW DATABASES", sql_text_len=14, client_cs=0xfad1a0) at log.cc:445
# 11:30:23 #11 0x000000000070dd41 in LOGGER::general_log_write (this=0xfbe660, thd=0x7f39a00c1758, command=COM_QUERY, query=0x221dd58 "SHOW DATABASES", query_length=14)
# 11:30:23     at log.cc:1086
# 11:30:23 #12 0x000000000070ddf1 in general_log_write (thd=0x7f39a00c1758, command=COM_QUERY, query=0x221dd58 "SHOW DATABASES", query_length=14) at log.cc:4363
# 11:30:23 #13 0x000000000064e100 in dispatch_command (command=COM_QUERY, thd=0x7f39a00c1758, packet=0x7f39a00c4409 "SHOW DATABASES", packet_length=14)
# 11:30:23     at sql_parse.cc:1005
# 11:30:23 #14 0x000000000064f662 in do_command (thd=0x7f39a00c1758) at sql_parse.cc:695
# 11:30:23 #15 0x000000000063de31 in handle_one_connection (arg=0x7f39a00c1758) at sql_connect.cc:1163
# 11:30:23 #16 0x000000315b0073da in start_thread () from /lib64/libpthread.so.0
# 11:30:23 #17 0x000000315a4e627d in clone () from /lib64/libc.so.6

How to repeat:
If this is repeatable, a test case will be provided. In the meantime, the core and the binary will be uplodaded.
[1 Feb 2010 10:04] Philip Stoev
Core and binary:

http://mysql-systemqa.s3.amazonaws.com/var-bug50786.zip

source:

revision-id: kostja@sun.com-20100129154650-wmq5gczzj868s66r
date: 2010-01-29 18:46:50 +0300
build-date: 2010-02-01 12:04:43 +0200
revno: 3084
branch-nick: mysql-next-4284-stage
[1 Feb 2010 17:27] Philip Stoev
grammar for bug 50786

Attachment: bug50786.yy (application/octet-stream, text), 31.71 KiB.

[1 Feb 2010 17:29] Philip Stoev
To reproduce :

$ perl runall.pl \
  --gendata=conf/WL5004_data.zz \
  --duration=60 \
  --queries=10000000 \
  --basedir=/build/bzr/mysql-next-4284-stage \
  --mysqld=--innodb-lock-wait-timeout=1 \
  --mysqld=--table-lock-wait-timeout=1 \
  --grammar=conf/bug50786.yy \
  --mem

next-4284 is also affected. The grammar produces the following queries:

CREATE TABLE IF NOT EXISTS . t1_base2_S  LIKE test.table0_int_autoinc ; ALTER TABLE  . t1_base2_S ENGINE = MEMORY ; INSERT INTO  . t1_base2_S SELECT * FROM test.table0_int_autoinc ; COMMIT ; ; DROP TABLE  . t1_base2_S;

LOCK TABLES . t1_base2_S  AS j READ
[3 Feb 2010 6:13] Dmitry Lenev
Hello!

The same assert can be triggered using the following test case for mysqltest tool.

connect (con1,localhost,root,,test,,);
connect (con2,localhost,root,,test,,);
connect (con3,localhost,root,,test,,);
connection default;

create table t1 (i int);
create table t2 (i int);

select @@global.general_log, @@global.log_output;

set @@global.log_output= 'TABLE';

--echo connection: con1
connection con1;
handler t1 open;

--echo connection: con3
connection con3;
set @@session.sql_log_off= 1;

--echo connection: con2
connection con2;
set debug_sync='thr_multi_lock_after_thr_lock SIGNAL parked WAIT_FOR go';

# The below statement will be blocked on debug sync point
# after it will get write lock on mysql.general_log table.
--send select 1;

--echo connection: con3
connection con3;
set debug_sync= 'now WAIT_FOR parked';

--echo connection: con1
connection con1;
# Again this statement will be blocked in open_ltable() when
# trying to write into mysql.general_log.
--send select 1;

--echo connection: con3
connection con3;
--sleep 1
show processlist;
# The below ALTER will try to abort statement in connection con1,
# since the latter waits on table-level lock while having HANDLER
# open. This will cause mysql_lock_tables() in con1 fail and will
# trigger assert.
--send alter table t1 add column j int;
[3 Feb 2010 10:05] 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/99032

3064 Jon Olav Hauglid	2010-02-03
      Bug #50786 Assertion `thd->mdl_context.trans_sentinel() == __null' 
                 failed in open_ltable()
      
      The problem was too restrictive asserts that enforced that 
      open_ltable() was called without any active HANDLERs, LOCK TABLES
      or global read locks. However, this can happen when opening
      a system table (such as mysql.general_log) since we there
      backup the current open tables context and use a separate context.
      
      This patch adjusts the assert to check for the presence of
      backed up contexts.
      
      The patch also fixes set_needs_thr_lock_abort() that before 
      ignored its parameter and always set the member variable to TRUE.
      
      Test case added to mdl_sync.test.
      Thanks to Dmitry Lenev for help with this bug!
[3 Feb 2010 13: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/99056

3064 Jon Olav Hauglid	2010-02-03
      Bug #50786 Assertion `thd->mdl_context.trans_sentinel() == __null' 
                 failed in open_ltable()
      
      The problem was too restrictive asserts that enforced that 
      open_ltable() was called without any active HANDLERs, LOCK TABLES
      or global read locks. 
      
      However, this can happen in several cases when opening system
      tables. The assert would, for example, be triggered when drop
      function was called from a connection with active HANDLERs as
      this would cause open_ltable() to be called for mysql.proc.
      The assert could also be triggered when using table-based
      general log (mysql.general_log).
      
      This patch removes the asserts since they will be triggered in
      several legitimate cases and because the asserts are no longer
      relevant due to changes in how locks are released.
      
      The patch also fixes set_needs_thr_lock_abort() that before 
      ignored its parameter and always set the member variable to TRUE.
      
      Test case added to mdl_sync.test.
      Thanks to Dmitry Lenev for help with this bug!
[3 Feb 2010 14:09] 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/99065

3067 Jon Olav Hauglid	2010-02-03
      Bug #50786 Assertion `thd->mdl_context.trans_sentinel() == __null' 
                 failed in open_ltable()
      
      The problem was too restrictive asserts that enforced that 
      open_ltable() was called without any active HANDLERs, LOCK TABLES
      or global read locks. 
      
      However, this can happen in several cases when opening system
      tables. The assert would, for example, be triggered when drop
      function was called from a connection with active HANDLERs as
      this would cause open_ltable() to be called for mysql.proc.
      The assert could also be triggered when using table-based
      general log (mysql.general_log).
      
      This patch removes the asserts since they will be triggered in
      several legitimate cases and because the asserts are no longer
      relevant due to changes in how locks are released.
      
      The patch also fixes set_needs_thr_lock_abort() that before 
      ignored its parameter and always set the member variable to TRUE.
      
      Test case added to mdl_sync.test.
      Thanks to Dmitry Lenev for help with this bug!
[3 Feb 2010 14:12] Jon Olav Hauglid
Pushed into the mysql-next-4284 tree.

Setting the bug to Closed since it was reported against an internal tree
and therefore does not require any documentation changes.
[16 Feb 2010 16:49] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100216101445-2ofzkh48aq2e0e8o) (version source revid:kostja@sun.com-20100210211106-nq8ztcq2z9o4csit) (merge vers: 6.0.14-alpha) (pib:16)
[16 Feb 2010 16:59] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100216101208-33qkfwdr0tep3pf2) (version source revid:kostja@sun.com-20100203151239-ok17dv0sgw4x0oeu) (pib:16)
[6 Mar 2010 11:08] Bugs System
Pushed into 5.5.3-m3 (revid:alik@sun.com-20100306103849-hha31z2enhh7jwt3) (version source revid:vvaintroub@mysql.com-20100216221947-luyhph0txl2c5tc8) (merge vers: 5.5.99-m3) (pib:16)
[7 Mar 2010 1:04] Paul DuBois
No changelog entry needed.