Bug #28901 MySQL insert delayed + triggers crash
Submitted: 5 Jun 2007 16:32 Modified: 5 Jun 2007 17:46
Reporter: Evert Pot Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: MyISAM storage engine Severity:S2 (Serious)
Version:5.0.32-Debian_7etch1-log OS:Linux (debian etch)
Assigned to: CPU Architecture:Any
Tags: crash, insert delayed, trigger

[5 Jun 2007 16:32] Evert Pot
Description:
MySQL crashes about 50% of the times when using insert delayed that have on insert triggers.

Please excuse me and ignore this bug if this was already found and fixed ( i couldn't find a bug that wasn't supposed to be fixed already related to this issue)

The problem doesn't occur when I delete the trigger.

My log:
Jun  5 12:23:34 dev2 mysqld[15265]: 070605 12:23:34 [Note] Recovering after a crash using /var/log/mysql/mysql-bin
Jun  5 12:23:34 dev2 mysqld[15265]: 070605 12:23:34 [Note] Starting crash recovery...
Jun  5 12:23:34 dev2 mysqld[15265]: 070605 12:23:34 [Note] Crash recovery finished.
Jun  5 12:23:34 dev2 mysqld[15265]: 070605 12:23:34 [Note] /usr/sbin/mysqld: ready for connections.
Jun  5 12:23:34 dev2 mysqld[15265]: Version: '5.0.32-Debian_7etch1-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Debian etch distribution
Jun  5 12:30:15 dev2 mysqld[15265]: mysqld got signal 11;
Jun  5 12:30:15 dev2 mysqld[15265]: This could be because you hit a bug. It is also possible that this binary
Jun  5 12:30:15 dev2 mysqld[15265]: or one of the libraries it was linked against is corrupt, improperly built,
Jun  5 12:30:15 dev2 mysqld[15265]: or misconfigured. This error can also be caused by malfunctioning hardware.
Jun  5 12:30:15 dev2 mysqld[15265]: We will try our best to scrape up some info that will hopefully help diagnose
Jun  5 12:30:15 dev2 mysqld[15265]: the problem, but since we have already crashed, something is definitely wrong
Jun  5 12:30:15 dev2 mysqld[15265]: and this may fail.
Jun  5 12:30:15 dev2 mysqld[15265]: 
Jun  5 12:30:15 dev2 mysqld[15265]: key_buffer_size=16777216
Jun  5 12:30:15 dev2 mysqld[15265]: read_buffer_size=131072
Jun  5 12:30:15 dev2 mysqld[15265]: max_used_connections=5
Jun  5 12:30:15 dev2 mysqld[15265]: max_connections=400
Jun  5 12:30:15 dev2 mysqld[15265]: threads_connected=3
Jun  5 12:30:15 dev2 mysqld[15265]: It is possible that mysqld could use up to 
Jun  5 12:30:15 dev2 mysqld[15265]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 886780 K
Jun  5 12:30:15 dev2 mysqld[15265]: bytes of memory
Jun  5 12:30:15 dev2 mysqld[15265]: Hope that's ok; if not, decrease some variables in the equation.
Jun  5 12:30:15 dev2 mysqld[15265]: 
Jun  5 12:30:15 dev2 mysqld[15265]: thd=0x8b5e310
Jun  5 12:30:15 dev2 mysqld[15265]: Attempting backtrace. You can use the following information to find out
Jun  5 12:30:15 dev2 mysqld[15265]: where mysqld died. If you see no messages after this, something went
Jun  5 12:30:15 dev2 mysqld[15265]: terribly wrong...
Jun  5 12:30:15 dev2 mysqld[15265]: Cannot determine thread, fp=0xb0e82f68, backtrace may not be correct.
Jun  5 12:30:15 dev2 mysqld[15265]: Stack range sanity check OK, backtrace follows:
Jun  5 12:30:15 dev2 mysqld[15265]: 0x81c0659
Jun  5 12:30:15 dev2 mysqld[15265]: 0x8272878
Jun  5 12:30:15 dev2 mysqld[15265]: 0x82244d5
Jun  5 12:30:15 dev2 mysqld[15265]: 0x8226380
Jun  5 12:30:15 dev2 mysqld[15265]: 0x8226d99
Jun  5 12:30:15 dev2 mysqld[15265]: 0xb7f0e0bd
Jun  5 12:30:15 dev2 mysqld[15265]: 0xb7d489ee
Jun  5 12:30:15 dev2 mysqld[15265]: New value of fp=(nil) failed sanity check, terminating stack trace!
Jun  5 12:30:15 dev2 mysqld[15265]: Please read http://dev.mysql.com/doc/mysql/en/using-stack-trace.html and follow instructions on how to resolve the stack trace. Resolved
Jun  5 12:30:15 dev2 mysqld[15265]: stack trace is much more helpful in diagnosing the problem, so please do 
Jun  5 12:30:15 dev2 mysqld[15265]: resolve it
Jun  5 12:30:15 dev2 mysqld[15265]: Trying to get some variables.
Jun  5 12:30:15 dev2 mysqld[15265]: Some pointers may be invalid and cause the dump to abort...
Jun  5 12:30:15 dev2 mysqld[15265]: thd->query at 0x8b43ac8 = data_hits
Jun  5 12:30:15 dev2 mysqld[15265]: thd->thread_id=63
Jun  5 12:30:15 dev2 mysqld[15265]: The manual page at http://www.mysql.com/doc/en/Crashing.html contains
Jun  5 12:30:15 dev2 mysqld[15265]: information that should help you find out what is causing the crash.
Jun  5 12:30:15 dev2 mysqld_safe[15346]: Number of processes running now: 0
Jun  5 12:30:15 dev2 mysqld_safe[15348]: restarted
Jun  5 12:30:15 dev2 mysqld[15351]: 070605 12:30:15  InnoDB: Database was not shut down normally!
Jun  5 12:30:15 dev2 mysqld[15351]: InnoDB: Starting crash recovery.
Jun  5 12:30:15 dev2 mysqld[15351]: InnoDB: Reading tablespace information from the .ibd files...
Jun  5 12:30:15 dev2 mysqld[15351]: InnoDB: Restoring possible half-written data pages from the doublewrite
Jun  5 12:30:15 dev2 mysqld[15351]: InnoDB: buffer...
Jun  5 12:30:15 dev2 mysqld[15351]: 070605 12:30:15  InnoDB: Starting log scan based on checkpoint at
Jun  5 12:30:15 dev2 mysqld[15351]: InnoDB: log sequence number 0 1430934823.
Jun  5 12:30:15 dev2 mysqld[15351]: InnoDB: Doing recovery: scanned up to log sequence number 0 1430934823
Jun  5 12:30:15 dev2 mysqld[15351]: InnoDB: Last MySQL binlog file position 0 34313670, file name /var/log/mysql/mysql-bin.000634
Jun  5 12:30:15 dev2 mysqld[15351]: 070605 12:30:15  InnoDB: Started; log sequence number 0 1430934823
Jun  5 12:30:15 dev2 mysqld[15351]: 070605 12:30:15 [Note] Recovering after a crash using /var/log/mysql/mysql-bin
Jun  5 12:30:15 dev2 mysqld[15351]: 070605 12:30:15 [Note] Starting crash recovery...
Jun  5 12:30:15 dev2 mysqld[15351]: 070605 12:30:15 [Note] Crash recovery finished.
Jun  5 12:30:15 dev2 mysqld[15351]: 070605 12:30:15 [Note] /usr/sbin/mysqld: ready for connections.
Jun  5 12:30:15 dev2 mysqld[15351]: Version: '5.0.32-Debian_7etch1-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Debian etch distribution

How to repeat:
CREATE TABLE data_files (
  `id` INT(11) PRIMARY KEY NOT NULL AUTO_INCREMENT,
  `name` VARCHAR(200),
  `hits` INT(11) NOT NULL DEFAULT '0'
);

CREATE TABLE data_hits ( 
  `id` INT(11) PRIMARY KEY NOT NULL AUTO_INCREMENT,
  `time` TIMESTAMP DEFAULT CURRENT_TIMESTAMP,
  `mid` INT(11) NOT NULL,
  `size` INT(11),
  `type` INT(11)
);

DELIMITER |

CREATE TRIGGER `hitsupdater` AFTER INSERT ON `data_hits`
  FOR EACH ROW BEGIN

  IF (NEW.type > 14 OR NEW.type=0) THEN
  UPDATE data_files SET hits = hits + 1 WHERE id = NEW.mid;
  END IF;
  END;
|

DELIMITER ;

INSERT INTO data_files (name) values ('testfile');
INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
[5 Jun 2007 16:42] MySQL Verification Team
Thank you for the bug report. I was not able to repeat with current source
server, could you please try with the latest released version 5.0.41? Thanks
in advance.

[miguel@light 5.0]$ bin/mysql -uroot test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.0.44-debug Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> CREATE TABLE data_files (
    ->   `id` INT(11) PRIMARY KEY NOT NULL AUTO_INCREMENT,
    ->   `name` VARCHAR(200),
    ->   `hits` INT(11) NOT NULL DEFAULT '0'
    -> );
Query OK, 0 rows affected (0.01 sec)

mysql> 
mysql> CREATE TABLE data_hits ( 
    ->   `id` INT(11) PRIMARY KEY NOT NULL AUTO_INCREMENT,
    ->   `time` TIMESTAMP DEFAULT CURRENT_TIMESTAMP,
    ->   `mid` INT(11) NOT NULL,
    ->   `size` INT(11),
    ->   `type` INT(11)
    -> );
Query OK, 0 rows affected (0.03 sec)

mysql> 
mysql> DELIMITER |
mysql> 
mysql> CREATE TRIGGER `hitsupdater` AFTER INSERT ON `data_hits`
    ->   FOR EACH ROW BEGIN
    -> 
    ->   IF (NEW.type > 14 OR NEW.type=0) THEN
    ->   UPDATE data_files SET hits = hits + 1 WHERE id = NEW.mid;
    ->   END IF;
    ->   END;
    -> |
Query OK, 0 rows affected (0.01 sec)

mysql> 
mysql> DELIMITER ;
mysql> 
mysql> INSERT INTO data_files (name) values ('testfile');
Query OK, 1 row affected (0.00 sec)

mysql> INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
Query OK, 1 row affected (0.02 sec)

mysql> INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
Query OK, 1 row affected (0.01 sec)

mysql> INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
Query OK, 1 row affected (0.06 sec)

mysql> INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
Query OK, 1 row affected (0.01 sec)

mysql> INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
Query OK, 1 row affected (0.00 sec)

mysql> INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
Query OK, 1 row affected (0.01 sec)

mysql> INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
Query OK, 1 row affected (0.00 sec)

mysql> select version();
+--------------+
| version()    |
+--------------+
| 5.0.44-debug | 
+--------------+
1 row in set (0.01 sec)

mysql>
[5 Jun 2007 17:46] Evert Pot
I just updated mysql to the latest stable version (5.0.41), and I'm getting the same errors.

Are there any settings that could be relevant to this bug?

mysql> CREATE TABLE data_files (
    ->   `id` INT(11) PRIMARY KEY NOT NULL AUTO_INCREMENT,
    ->   `name` VARCHAR(200),
    ->   `hits` INT(11) NOT NULL DEFAULT '0'
    -> );
Query OK, 0 rows affected (0.00 sec)

mysql> 
mysql> CREATE TABLE data_hits ( 
    ->   `id` INT(11) PRIMARY KEY NOT NULL AUTO_INCREMENT,
    ->   `time` TIMESTAMP DEFAULT CURRENT_TIMESTAMP,
    ->   `mid` INT(11) NOT NULL,
    ->   `size` INT(11),
    ->   `type` INT(11)
    -> );
Query OK, 0 rows affected (0.00 sec)

mysql> 
mysql> DELIMITER |
mysql> 
mysql> CREATE TRIGGER `hitsupdater` AFTER INSERT ON `data_hits`
    ->   FOR EACH ROW BEGIN
    -> 
    ->   IF (NEW.type > 14 OR NEW.type=0) THEN
    ->   UPDATE data_files SET hits = hits + 1 WHERE id = NEW.mid;
    ->   END IF;
    ->   END;
    -> |
Query OK, 0 rows affected (0.00 sec)

mysql> 
mysql> DELIMITER ;
mysql> 
mysql> INSERT INTO data_files (name) values ('testfile');
Query OK, 1 row affected (0.00 sec)

mysql> INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
Query OK, 1 row affected (0.00 sec)

mysql> INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
Query OK, 1 row affected (0.00 sec)

mysql> INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
Query OK, 1 row affected (0.00 sec)

mysql> INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql> INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (111)
ERROR: 
Can't connect to the server

mysql> INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
No connection. Trying to reconnect...
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (111)
ERROR: 
Can't connect to the server

mysql> INSERT DELAYED INTO data_hits (mid,size,type) VALUES (1,100,1);
No connection. Trying to reconnect...
Connection id:    1
Current database: bugdb

Query OK, 1 row affected (0.00 sec)

mysql> select VERSION();
+------------------------------+
| VERSION()                    |
+------------------------------+
| 5.0.41-Dotdeb_1.dotdeb.2-log | 
+------------------------------+
1 row in set (0.00 sec)