Bug #45067 Assertion `stmt_da->is_error()' in Delayed_insert::open_and_lock_table
Submitted: 25 May 2009 13:35 Modified: 6 Mar 2010 23:42
Reporter: Philip Stoev Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Locking Severity:S3 (Non-critical)
Version:6.0, 5.4 OS:Any
Assigned to: Jon Olav Hauglid CPU Architecture:Any

[25 May 2009 13:35] Philip Stoev
Description:
When executing a random workload involving tables that act on table locking, the server asserted as follows:

mysqld: sql_class.h:2112: void THD::fatal_error(): Assertion `stmt_da->is_error()' failed.

# 16:10:41 #2  0x00000000006c9350 in handle_segfault (sig=6) at mysqld.cc:2711
# 16:10:41 #3  <signal handler called>
# 16:10:41 #4  0x000000315a432ed5 in raise () from /lib64/libc.so.6
# 16:10:41 #5  0x000000315a434a43 in abort () from /lib64/libc.so.6
# 16:10:41 #6  0x000000315a42bec9 in __assert_fail () from /lib64/libc.so.6
# 16:10:41 #7  0x00000000006e5f36 in THD::fatal_error (this=0x23e47f8) at sql_class.h:2112
# 16:10:41 #8  0x0000000000783874 in Delayed_insert::open_and_lock_table (this=0x23e47d8) at sql_insert.cc:2303
# 16:10:41 #9  0x00000000007869b1 in handle_delayed_insert (arg=0x23e47d8) at sql_insert.cc:2387
# 16:10:41 #10 0x000000315b0073da in start_thread () from /lib64/libpthread.so.0
# 16:10:41 #11 0x000000315a4e627d in clone () from /lib64/libc.so.6

This was in the log before the crash, may or may not be relevant:

Warning at 'read lock with old write lock': Found lock of type 6 that is write and read locked
Warning at 'start of release lock': Found lock of type 6 that is write and read locked
Warning at 'read lock with old write lock': Found lock of type 6 that is write and read locked
Warning at 'start of release lock': Found lock of type 6 that is write and read locked
Warning at 'read lock with old write lock': Found lock of type 6 that is write and read locked
Warning at 'got wait_for_lock': Found lock of type 6 that is write and read locked
Warning at 'enter read_lock': Found lock of type 6 that is write and read locked
Warning at 'read lock with old write lock': Found lock of type 6 that is write and read locked
Warning at 'start of release lock': Found lock of type 6 that is write and read locked
Warning at 'after releasing lock': Found lock of type 6 that is write and read locked

How to repeat:
If this is repeatable, a test case will be provided.
[5 Jun 2009 11:24] Philip Stoev
Grammar for bug 45067

Attachment: bug45067.yy (application/octet-stream, text), 2.19 KiB.

[5 Jun 2009 11:24] Philip Stoev
A grammar file has been uploaded for this bug. To reproduce, please run:

perl runall.pl --basedir=/build/bzr/azalea/ --grammar=conf/bug45067.yy  --mysqld=--innodb-lock-wait-timeout=1 --mysqld=--table-lock-wait-timeout=1

against a debug build.
[25 Jun 2009 20:49] Matthias Leich
Switch to 'Analyzing' + assign to me, because I will
come up with a testcase for MTR and results for MySQL 5.1 soon.
Preliminar results:
- 5.1 has the same bug
- only ALTER/ANALYZE/... + INSERT DELAYED + MyISAM +
  two concurrent sessions are needed
- partitioning, auto_increment, indexes are irrelevant
[26 Jun 2009 10:03] Matthias Leich
Test script

Attachment: bug45067.test (text/plain), 1.29 KiB.

[26 Jun 2009 10:03] Matthias Leich
File with expected results

Attachment: bug45067.result (text/plain), 44 bytes.

[26 Jun 2009 11:05] Matthias Leich
Results when applying bug45067.test:
=====================================
- MySQL releases compiled from source
  ./BUILD/compile-pentium64-debug-max
- Linux OpenSuSE 11.0 (64 Bit)
- Intel Core2Duo
- ./mtr --mem --force --max-test-fail=0 \
  --retry=0 --repeat=100 --do-test=bug45067

Azalea last modification 2009-06-23
-----------------------------------
- Failed 100/100 tests, 0.00% were successful.
  MTR analyzes 6 times a crashed server per 100 runs.
  This is a bit surprising but I guess MTR does not
  work 100 % perfect. Maybe in some cases MTR does not
  detect that we are short before completion of a
  server crash or somehow other important information
  gets lost and/or ignored.
  In a single run the likelihood that MTR analyzes a
  core file is significant higher.
  The frequent MTR messages
  Failed to read from '/.../mysql-test/var/log/bug45067.log'
      , errno: 22
  are suspicious.
- Typical output:
  mysqltest: At line 41: query 'reap' failed:
  2013: Lost connection to MySQL server during query
  or
  1053: Server shutdown in progress

mysal-5.1-bugteam last modification 2009-06-25
----------------------------------------------
- Failed 81/100 tests, 19.00% were successful.
MTR reports never about a core but I do not trust
MTR 100 %. Please see the effects mentioned above.
- typical output
  mysqltest: At line 41: query 'reap' failed:
  1053: Server shutdown in progres

Some comments about the importance of this bug
and the script bug45067.test:
----------------------------------------------
1. The goal of bug45067.test is to replay the
   problem with the
   - smallest number of statements
   - most simple statements
   for easy bug fixing and testing.
   bug45067.test like any test does not need to
   simulate the behavior of a typical customer
   application. So please do not focus on the
   100 loop rounds containing the ALTER TABLE.
2. My impression is that we could suffer from
   the current bug whenever we have some specific
   timing between the INSERT DELAYED and the ALTER.
   The 100 loops in bug45067.test are simply
   100 attempts to get by luck the specific
   timing needed.

Setting to "Needs Triage" because MySQL 5.1 is
also affected.
Please do not forget to decide if the fix should
start in 5.1.
[4 Jul 2009 19:38] Philip Stoev
See similar backtrace in bug#45949 .
[4 Jul 2009 19:39] Philip Stoev
See similar backtrace in bug#45949 .
[30 Jul 2009 9:17] 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/79609

2834 Jon Olav Hauglid	2009-07-30
      Bug #45067 Assertion `stmt_da->is_error()' in 
                 Delayed_insert::open_and_lock_table
      
      The assert was triggered when delayed insert was killed by another 
      connection using mysql_notify_thread_having_shared_lock().
      During handling of thd->killed, thd.fatal_error() was called without
      a previous call to my_error() which triggered the assert.
      This patch allows the assert to pass if thd->killed has been set.
      
      Test case will be added as a part of the patch for the closely 
      related bug #45949.
[30 Jul 2009 10:39] Jon Olav Hauglid
Pushed to azalea-bugfixing
[4 Aug 2009 19:52] Bugs System
Pushed into 5.4.4-alpha (revid:alik@sun.com-20090804194615-h40sa098mx4z49qg) (version source revid:iggy@mysql.com-20090731204544-7nio1afvg0dmzs7g) (merge vers: 5.4.4-alpha) (pib:11)
[7 Aug 2009 20:35] Paul DuBois
Noted in 5.4.4 changelog.

Killing a delayed-insert thread could cause a server crash.
[12 Aug 2009 22:24] Paul DuBois
Noted in 5.4.2 changelog because next 5.4 version will be 5.4.2 and not 5.4.4.
[14 Aug 2009 23:10] Paul DuBois
Ignore previous comment about 5.4.2.
[8 Dec 2009 14:40] Jon Olav Hauglid
Pushed to mysql-next-4284 (5.6.0-beta).
[8 Jan 2010 13:34] Jon Olav Hauglid
Bug#49974 marked as a duplicate of this bug.
[16 Feb 2010 16:50] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100216101445-2ofzkh48aq2e0e8o) (version source revid:kostja@sun.com-20091211154405-c9yhiewr9o5d20rq) (merge vers: 6.0.14-alpha) (pib:16)
[16 Feb 2010 17:00] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100216101208-33qkfwdr0tep3pf2) (version source revid:jon.hauglid@sun.com-20091208143858-mjvvybtbhzg93j3t) (pib:16)
[17 Feb 2010 0:40] Paul DuBois
Noted in 6.0.14 changelog.

Setting report to Need Merge pending push of Celosia into release tree.
[6 Mar 2010 11:04] 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)
[6 Mar 2010 23:42] Paul DuBois
Noted in 5.5.3 changelog.