Bug #48538 Assertion in thr_lock() on LOAD DATA CONCURRENT INFILE
Submitted: 4 Nov 2009 17:40 Modified: 7 Mar 2010 1:35
Reporter: Philip Stoev Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Locking Severity:S3 (Non-critical)
Version:6.0-codebase-bugfixing OS:Any
Assigned to: Dmitry Lenev CPU Architecture:Any
Tags: locking

[4 Nov 2009 17:40] Philip Stoev
Description:
When executing a non-concurrent, MDL and DDL-oriented workload (a version of Matthias's MDL grammar), mysqld asserted as follows:

mysqld: thr_lock.c:724: thr_lock: Assertion `! has_old_lock(lock->write.data, data->owner) || (lock_type <= lock->write.data->type && ! ((lock_type < TL_WRITE_CONCURRENT_INSERT && lock->write.data->type == TL_WRITE_CONCURRENT_INSERT) || (lock_type < TL_WRITE_ALLOW_READ && lock->write.data->type == TL_WRITE_ALLOW_READ) || lock->write.data->type == TL_WRITE_DELAYED))' failed.

# 19:28:51 #6  0x000000315a42bec9 in __assert_fail () from /lib64/libc.so.6
# 19:28:51 #7  0x0000000000b322d1 in thr_lock (data=0x3369668, owner=0x33ddae0, lock_type=TL_WRITE) at thr_lock.c:718
# 19:28:51 #8  0x0000000000b33162 in thr_multi_lock (data=0x34344b0, count=2, owner=0x33ddae0) at thr_lock.c:1059
# 19:28:51 #9  0x00000000006bffb1 in mysql_lock_tables (thd=0x33dcd68, tables=0x33e0ae0, count=2, flags=0, need_reopen=0x7fdd18866b2f) at lock.cc:321
# 19:28:51 #10 0x0000000000732bc8 in lock_tables (thd=0x33dcd68, tables=0x33dfd50, count=2, flags=0, need_reopen=0x7fdd18866b2f) at sql_base.cc:5082
# 19:28:51 #11 0x000000000073a40a in open_and_lock_tables_derived (thd=0x33dcd68, tables=0x33dfd50, derived=true, flags=0, prelocking_strategy=0x7fdd18866b70)
# 19:28:51     at sql_base.cc:4771
# 19:28:51 #12 0x00000000006e7cc8 in open_and_lock_tables_derived (thd=0x33dcd68, tables=0x33dfd50, derived=true, flags=0) at ../mysql_priv.h:1518
# 19:28:51 #13 0x00000000006e7d03 in open_and_lock_tables (thd=0x33dcd68, tables=0x33dfd50) at ../../sql/mysql_priv.h:1528
# 19:28:51 #14 0x0000000000867102 in mysql_load (thd=0x33dcd68, ex=0x33dfca8, table_list=0x33dfd50, fields_vars=@0x33df268, set_fields=@0x33df298,
# 19:28:51     set_values=@0x33df280, handle_duplicates=DUP_ERROR, ignore=false, read_file_from_client=false) at sql_load.cc:198
# 19:28:51 #15 0x00000000006dff9d in mysql_execute_command (thd=0x33dcd68) at sql_parse.cc:3534
# 19:28:51 #16 0x00000000006e4b41 in mysql_parse (thd=0x33dcd68,
# 19:28:51     inBuf=0x33dfb70 "LOAD DATA CONCURRENT INFILE '/tmp/gentest28084.tmp'  INTO TABLE testdb_A . t1_all_2_A", length=85, found_semicolon=0x7fdd18868f00)
# 19:28:51     at sql_parse.cc:5979
# 19:28:51 #17 0x00000000006e57aa in dispatch_command (command=COM_QUERY, thd=0x33dcd68,
# 19:28:51     packet=0x33cd429 " LOAD DATA CONCURRENT INFILE '/tmp/gentest28084.tmp'  INTO TABLE testdb_A . t1_all_2_A ", packet_length=87) at sql_parse.cc:1076
# 19:28:51 #18 0x00000000006e6d1c in do_command (thd=0x33dcd68) at sql_parse.cc:758
# 19:28:51 #19 0x00000000006d3a88 in handle_one_connection (arg=0x33dcd68) at sql_connect.cc:1164
# 19:28:51 #20 0x000000315b0073da in start_thread () from /lib64/libpthread.so.0
# 19:28:51 #21 0x000000315a4e627d in clone () from /lib64/libc.so.6

How to repeat:
Run attached grammar as follows:

 perl runall.pl \
 --basedir=/build/bzr/mysql-6.0-codebase-bugfixing/ \
 --threads=1 \
 --queries=300000 \
 --duration=6000 \
 --mysqld=--table-lock-wait-timeout=1 \
 --mysqld=--innodb-lock-wait-timeout=1 \
 --mysqld=--log-output=file \
 --reporter=Deadlock,Backtrace,Shutdown \
 --gendata=conf/WL5004_data.zz \
 --grammar=/path/to/bug.yy \
 --mem \
 --seed=117
[4 Nov 2009 17:40] Philip Stoev
bug 48538 grammar

Attachment: bug48538.yy (application/octet-stream, text), 29.62 KiB.

[10 Nov 2009 10:29] Matthias Leich
The simplification attempts were till now not successfull
because of tool weaknesses. But the already existing
information should be sufficient to find the failure.
Maybe I will try again to generate a small replay testcase
in future.
[10 Nov 2009 21:11] Matthias Leich
Replay test case without LOAD DATA:
-----------------------------------
--disable_warnings
DROP TABLE IF EXISTS t1;
--enable_warnings
CREATE TABLE t1 ( f1 INTEGER, f2 INTEGER) ENGINE = MyISAM;
delimiter |;
CREATE TRIGGER tr1 AFTER INSERT ON t1 FOR EACH ROW BEGIN UPDATE LOW_PRIORITY t1 SET column_not_exists = 7 ; END|
delimiter ;|
ALTER TABLE t1 ENGINE = MEMORY;
INSERT INTO t1 VALUES(0,0);

DROP TABLE t1;

Result on mysql-6.0-codebase-bugfixing
revno: 3692 2009-10-31
--------------------------------------
Thread 1 (process 13150):
#0  0x00007f6366e8ece6 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000b778e8 in my_write_core (sig=6) at stacktrace.c:309
#2  0x00000000006f4922 in handle_segfault (sig=6) at mysqld.cc:2765
#3  <signal handler called>
#4  0x00007f6365d8a5c5 in raise () from /lib64/libc.so.6
#5  0x00007f6365d8bbb3 in abort () from /lib64/libc.so.6
#6  0x00007f6365d831e9 in __assert_fail () from /lib64/libc.so.6
#7  0x0000000000b8c94b in thr_lock (data=0x173ae28, owner=0x16d1c30, lock_type=TL_WRITE) at thr_lock.c:718
#8  0x0000000000b8d7d4 in thr_multi_lock (data=0x16751b0, count=2, owner=0x16d1c30) at thr_lock.c:1059
#9  0x00000000006eac34 in mysql_lock_tables (thd=0x16d0eb8, tables=0x167d4d0, count=2, flags=0, need_reopen=0x402e8f7f) at lock.cc:321
#10 0x000000000075d23b in lock_tables (thd=0x16d0eb8, tables=0x167b700, count=2, flags=0, need_reopen=0x402e8f7f) at sql_base.cc:5082
#11 0x0000000000764a1a in open_and_lock_tables_derived (thd=0x16d0eb8, tables=0x167b700, derived=true, flags=0, prelocking_strategy=0x402e8fc0) at sql_base.cc:4771
#12 0x0000000000712ac2 in open_and_lock_tables_derived (thd=0x16d0eb8, tables=0x167b700, derived=true, flags=0) at ../mysql_priv.h:1518
#13 0x0000000000712afd in open_and_lock_tables (thd=0x16d0eb8, tables=0x167b700) at ../../sql/mysql_priv.h:1528
#14 0x00000000007bad36 in mysql_insert (thd=0x16d0eb8, table_list=0x167b700, fields=@0x16d33b8, values_list=@0x16d3400, update_fields=@0x16d33e8, update_values=@0x16d33d0, duplic=DUP_ERROR, ignore=false) at sql_insert.cc:638
#15 0x000000000070a1d1 in mysql_execute_command (thd=0x16d0eb8) at sql_parse.cc:3267
#16 0x000000000070f965 in mysql_parse (thd=0x16d0eb8, inBuf=0x167b620 "INSERT INTO t1 VALUES(0,0)", length=26, found_semicolon=0x402eaf20) at sql_parse.cc:5979
#17 0x00000000007105d1 in dispatch_command (command=COM_QUERY, thd=0x16d0eb8, packet=0x16300e9 "INSERT INTO t1 VALUES(0,0)", packet_length=26) at sql_parse.cc:1076
#18 0x0000000000711b18 in do_command (thd=0x16d0eb8) at sql_parse.cc:758
#19 0x00000000006feaf8 in handle_one_connection (arg=0x16d0eb8) at sql_connect.cc:1164
#20 0x00007f6366e8a040 in start_thread () from /lib64/libpthread.so.0
#21 0x00007f6365e2b08d in clone () from /lib64/libc.so.6
#22 0x0000000000000000 in ?? ()

When running RQG tests with WL5004_sql.yy I get this
assertion quite frequent.
Please fix this bug because this bug reduces the efficience
of RQG grammar simplification for other bugs significant.
[11 Nov 2009 11:39] Matthias Leich
This bug is not in mysql-5.0or5.1-bugteam where I get
query 'INSERT INTO t1 VALUES(0,0)' failed: 1442: Can't update table 't1' in stored function/trigger because it is already used by statement which invoked this stored function/trigger.
[11 Nov 2009 13:17] Jon Olav Hauglid
The bug is not present in 5.0 and 5.1 as the assert isn't there.
The bug is present in mysql-next-mr-bugfixing, however.

Slightly simplified MTR test case:

--disable_warnings
DROP TABLE IF EXISTS t1;
--enable_warnings

CREATE TABLE t1 (f1 INT, f2 INT) ENGINE = MEMORY;

delimiter |;
CREATE TRIGGER tr1 AFTER INSERT ON t1 
  FOR EACH ROW BEGIN 
    UPDATE LOW_PRIORITY t1 SET f2 = 7; 
  END|
delimiter ;|

--error ER_CANT_UPDATE_USED_TABLE_IN_SF_OR_TRG
INSERT INTO t1(f1) VALUES(0);

DROP TABLE t1;

The assert is triggered because the request TL_WRITE_CONCURRENT_INSERT is upgraded to TL_WRITE for the MEMORY engine (does not happen for MyISAM).
When the held lock is TL_WRITE_LOW_PRIORITY, the upgraded request triggers the assert.
[26 Nov 2009 11:44] 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/91784

2909 Dmitry Lenev	2009-11-26
      Fix for bug #48538 "Assertion in thr_lock() on LOAD DATA CONCURRENT
                          INFILE".
      
      Attempt to execute INSERT statement for MEMORY table which invoked
      trigger or called stored function which tried to perform LOW_PRIORITY
      update on table being inserted into resulted in debug server aborting
      due to assertion failure. On non-debug server such INSERT failed with
      error as it was expected.
      
      The problem was that in the above scenario TL_WRITE_CONCURRENT_INSERT
      is converted to TL_WRITE inside of thr_lock() function since MEMORY
      engine does not support concurrent inserts. This triggered failure of
      assertion which assumed that for the same table one thread always
      requests locks with higher thr_lock_type value first, since in this
      case TL_WRITE (converted from TL_WRITE_CONCURRENT_INSERT) is requested
      after acquiring TL_WRITE_LOW_PRIORITY lock on the table.
      
      This fix solves the problem by adjusting this assert to take this
      scenario into account.
      An alternative approach which suggested to change handler::store_locks()
      methods for all engines which do not support concurrent inserts in such
      way that TL_WRITE_CONCURRENT_INSERT is upgraded to TL_WRITE was
      considered too intrusive.
     @ mysql-test/r/lock.result
        Added simplified test for bug #48538 "Assertion in thr_lock() on LOAD
        DATA CONCURRENT INFILE".
     @ mysql-test/t/lock.test
        Added simplified test for bug #48538 "Assertion in thr_lock() on LOAD
        DATA CONCURRENT INFILE".
     @ mysys/thr_lock.c
        Adjusted assertion to account for situation when
        TL_WRITE_CONCURRENT_INSERT is converted to TL_WRITE inside of
        thr_lock() function because engine of table being locked does not
        support concurrent inserts.
        This scenario breaks assumption that for the same table one thread
        always requests locks with higher thr_lock_type value first, since
        thanks to it TL_WRITE on the table (converted from
        TL_WRITE_CONCURRENT_INSERT) can be requested after acquiring
        TL_WRITE_LOW_PRIORITY lock on the table.
        Note that it is still safe grant new lock without extra checks and
        waiting in such situation since TL_WRITE has the same compatibility
        rules as TL_WRITE_LOW_PRIORITY (their only difference is priority).
[8 Jan 2010 10:26] 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/96359

3048 Jon Olav Hauglid	2010-01-08
      Fix for bug #48538 "Assertion in thr_lock() on LOAD DATA CONCURRENT
                         INFILE".
      
      Attempts to execute an INSERT statement for a MEMORY table which invoked
      a trigger or called a stored function which tried to perform LOW_PRIORITY
      update on the table being inserted into, resulted in debug servers aborting
      due to an assertion failure. On non-debug servers such INSERTs failed with
      "Can't update table t1 in stored function/trigger because it is already used
      by statement which invoked this stored function/trigger" as expected.
      
      The problem was that in the above scenario TL_WRITE_CONCURRENT_INSERT
      is converted to TL_WRITE inside the thr_lock() function since the MEMORY
      engine does not support concurrent inserts. This triggered an assertion
      which assumed that for the same table, one thread always requests locks with
      higher thr_lock_type value first. When TL_WRITE_CONCURRENT_INSERT is
      upgraded to TL_WRITE after the locks have been sorted, this is no longer true.
      In this case, TL_WRITE was requested after acquiring a TL_WRITE_LOW_PRIORITY
      lock on the table, triggering the assert.
      
      This fix solves the problem by adjusting this assert to take this
      scenario into account.
      
      An alternative approach to change handler::store_locks() methods for all engines
      which do not support concurrent inserts in such way that
      TL_WRITE_CONCURRENT_INSERT is upgraded to TL_WRITE there instead, 
      was considered too intrusive.
      
      Commit on behalf of Dmitry Lenev.
     @ mysql-test/r/lock.result
        Added simplified test for bug #48538 "Assertion in thr_lock() on LOAD
        DATA CONCURRENT INFILE".
     @ mysql-test/t/lock.test
        Added simplified test for bug #48538 "Assertion in thr_lock() on LOAD
        DATA CONCURRENT INFILE".
     @ mysys/thr_lock.c
        Adjusted assertion to account for situation when
        TL_WRITE_CONCURRENT_INSERT is converted to TL_WRITE inside of the
        thr_lock() function because the engine of the table being locked 
        does not support concurrent inserts.
        This scenario breaks assumption that for the same table one thread
        always requests locks with higher thr_lock_type value first, since
        TL_WRITE on the table (converted from TL_WRITE_CONCURRENT_INSERT)
        can be requested after acquiring a TL_WRITE_LOW_PRIORITY lock on the table.
        Note that it is still safe to grant a new lock without extra checks and
        waiting in such situation since TL_WRITE has the same compatibility
        rules as TL_WRITE_LOW_PRIORITY (their only difference is priority).
[8 Jan 2010 13:28] 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/96385

3747 Jon Olav Hauglid	2010-01-08 [merge]
      Manual merge from mysql-next-4284 of fix for Bug #48538 
      "Assertion in thr_lock() on LOAD DATA CONCURRENT INFILE".
[8 Jan 2010 13:31] Jon Olav Hauglid
Pushed to mysql-next-4284 (5.6.0-beta) and merged to mysql-6.0-codebase-4284 (6.0.14-alpha).
[16 Feb 2010 16:48] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100216101445-2ofzkh48aq2e0e8o) (version source revid:jon.hauglid@sun.com-20100108132806-z7ffmatzgbgbf8zm) (merge vers: 6.0.14-alpha) (pib:16)
[16 Feb 2010 16:58] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100216101208-33qkfwdr0tep3pf2) (version source revid:jon.hauglid@sun.com-20100108102632-2uo6g34365yp5wf4) (pib:16)
[2 Mar 2010 0:56] Paul DuBois
Not present in any released version. No changelog entry.

Setting report to Need Merge pending push of Celosia into release tree.
[6 Mar 2010 11:07] 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:35] Paul DuBois
No changelog entry needed.