Bug #48339 Delayed inserts into archive table lead to warnings in error log on debug server
Submitted: 27 Oct 2009 7:17 Modified: 27 Oct 2009 10:38
Reporter: Dmitry Lenev Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Archive storage engine Severity:S3 (Non-critical)
Version:5.1.41-bzr, 5.5.0-bzr, 6.0.14-bzr OS:Any
Assigned to: CPU Architecture:Any

[27 Oct 2009 7:17] Dmitry Lenev
Description:
Attempt to concurrently perform delayed and normal inserts into table which uses Archive engine on debug build of server sometimes leads to "Warning: Found locks from different threads in write: start of release lock" warnings in server error log. This happens rarely and typically under heavy load. Occasionally this leads to archive.test failure on debug build of server (due to presence of these warnings in error log).

IMO this warnings might indicate bigger problem with locking for Archive engine.

How to repeat:
Apply the below patch to 5.1 server sources: 

=== modified file 'mysys/thr_lock.c'
--- mysys/thr_lock.c    2009-09-29 15:38:40 +0000
+++ mysys/thr_lock.c    2009-10-27 05:46:47 +0000
@@ -153,6 +153,7 @@ static int check_lock(struct st_lock_lis
        fprintf(stderr,
                "Warning: Found locks from different threads in %s: %s\n",
                lock_type,where);
+        DBUG_ASSERT(0);
        return 1;
       }
       if (no_cond && data->cond)

=== modified file 'sql/sql_insert.cc'
--- sql/sql_insert.cc   2009-09-10 07:40:57 +0000
+++ sql/sql_insert.cc   2009-10-27 05:46:47 +0000
@@ -2418,6 +2418,7 @@ static void handle_delayed_insert_impl(T
       }
       pthread_cond_broadcast(&di->cond_client);
     }
+    my_sleep(3000000);
     if (di->stacked_inserts)
     {
       if (di->handle_inserts())
---

This patch:
 - modifies server to simulate unfortunate scheduling which could also happen
   under natural conditions.
 - converts warning in a error log to assertion failure to make problem more
   noticeable.

Run the following test case against debug build of server:

---
CREATE TABLE t2 (
  auto int,
  fld1 int(6) unsigned zerofill DEFAULT '000000' NOT NULL,
  companynr tinyint(2) unsigned zerofill DEFAULT '00' NOT NULL,
  fld3 char(30) DEFAULT '' NOT NULL,
  fld4 char(35) DEFAULT '' NOT NULL,
  fld5 char(35) DEFAULT '' NOT NULL,
  fld6 char(4) DEFAULT '' NOT NULL
) ENGINE=archive;

INSERT DELAYED INTO t2 VALUES (99999,011403,37,'the','delayed','insert','');

INSERT INTO t2 VALUES (100000,sleep(10),00,'after','delayed','insert','');
---

Observe server crash due to assertion failure and warnings in error log.

Suggested fix:
AFAICS Archive engine "downgrades" TL_WRITE_DELAYED locks to TL_WRITE_ALLOW_WRITE locks which somewhat breaks locking logic in delayed inserts handling (e.g. we try to upgrade TL_WRITE_ALLOW_WRITE to TL_WRITE lock which is not supported).
[27 Oct 2009 10:38] MySQL Verification Team
Thank you for the bug report. Verified as described:

miguel@laras:~/dbs/5.1$ bin/mysql -uroot test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1                            
Server version: 5.1.41-debug Source distribution         

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> CREATE TABLE t2 (
    ->   auto int,
    ->   fld1 int(6) unsigned zerofill DEFAULT '000000' NOT NULL,
    ->   companynr tinyint(2) unsigned zerofill DEFAULT '00' NOT NULL,
    ->   fld3 char(30) DEFAULT '' NOT NULL,
    ->   fld4 char(35) DEFAULT '' NOT NULL,
    ->   fld5 char(35) DEFAULT '' NOT NULL,
    ->   fld6 char(4) DEFAULT '' NOT NULL
    -> ) ENGINE=archive;
Query OK, 0 rows affected (0.04 sec)

mysql>
mysql> INSERT DELAYED INTO t2 VALUES (99999,011403,37,'the','delayed','insert','');
Query OK, 1 row affected (0.00 sec)

mysql>
mysql> INSERT INTO t2 VALUES (100000,sleep(10),00,'after','delayed','insert','');
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql>