Bug #63537 on delete cascade on parent table + optimize child cause MySQL crash
Submitted: 2 Dec 2011 8:43 Modified: 21 Jan 2012 16:00
Reporter: Antoine Bonamour Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.5.17 OS:Linux (CentOS 5 64 Kernel 2.6.18-194.26.1.el5)
Assigned to: CPU Architecture:Any
Tags: foreign key on delete cascade optimize table crash

[2 Dec 2011 8:43] Antoine Bonamour
Description:
Hello,

innodb_file_per_table is activated.

First table : table repository_us PRIMARY KEY (`id`)

Second table : queue_exporter_us with : CONSTRAINT `queue_exporter_us_ibfk_1` FOREIGN KEY (`id`) REFERENCES `repository_us` (`id`) ON DELETE CASCADE ON UPDATE CASCADE

When an optimize table is running on the child table queue_exporter_us,
And, during this optimize, a delete is applied on the parent table repository_us,
And some rows from the child table ( queue_exporter_us ) are concerned by this delete,
Then I reach a MySQL crash

111129 18:45:03 - mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=998
max_threads=2000
thread_count=578
connection_count=578
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1310910 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x2aaeec0fc260
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x506380b8 thread_stack 0x40000
/usr/libexec/mysqld(my_print_stacktrace+0x33)[0x7abe93]
/usr/libexec/mysqld(handle_segfault+0x381)[0x5012f1]
/lib64/libpthread.so.0[0x3d5760eb10]
/usr/libexec/mysqld[0x839b86]
/usr/libexec/mysqld[0x83afdb]
/usr/libexec/mysqld[0x827851]
/usr/libexec/mysqld[0x815138]
/usr/libexec/mysqld(_ZN7handler13ha_delete_rowEPKh+0x8f)[0x67daef]
/usr/libexec/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyy+0x8f8)[0x76c758]
/usr/libexec/mysqld(_Z21mysql_execute_commandP3THD+0x37e5)[0x5760f5]
/usr/libexec/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x193)[0x578ab3]
/usr/libexec/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x13a4)[0x579eb4]
/usr/libexec/mysqld(_Z10do_commandP3THD+0xc2)[0x57a532]
/usr/libexec/mysqld(_Z24do_handle_one_connectionP3THD+0xf2)[0x60c432]
/usr/libexec/mysqld(handle_one_connection+0x53)[0x60c523]
/lib64/libpthread.so.0[0x3d5760673d]
/lib64/libc.so.6(clone+0x6d)[0x3d56ed3f6d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x1d570ec0): DELETE FROM repository_us WHERE id IN (739340)
Connection ID (thread ID): 155986
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
pure virtual method called
terminate called without an active exception
Fatal signal 6 while backtracing
111129 18:45:04 mysqld_safe Number of processes running now: 0
111129 18:45:04 mysqld_safe mysqld restarted
111129 18:45:04 [Warning] option 'group_concat_max_len': unsigned value 0 adjusted to 4
111129 18:45:04 [Note] Plugin 'FEDERATED' is disabled.
111129 18:45:04 InnoDB: The InnoDB memory heap is disabled
111129 18:45:04 InnoDB: Mutexes and rw_locks use GCC atomic builtins
111129 18:45:04 InnoDB: Compressed tables use zlib 1.2.3
111129 18:45:04 InnoDB: Using Linux native AIO
111129 18:45:04 InnoDB: Initializing buffer pool, size = 16.0G
111129 18:45:05 InnoDB: Completed initialization of buffer pool
111129 18:45:05 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 310986086735
111129 18:45:05  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 310991329280
......
InnoDB: Doing recovery: scanned up to log sequence number 311457237477
InnoDB: 7 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 415 row operations to undo
InnoDB: Trx id counter is 3E4100
111129 18:45:11  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Starting in background the rollback of uncommitted transactions
111129 18:45:16  InnoDB: Rolling back trx with id 3E3EF9, 100 rows to undo
111129 18:45:16  InnoDB: Waiting for the background threads to start

InnoDB: Rolling back of trx id 3E3EF9 completed
111129 18:45:16  InnoDB: Rolling back trx with id 3E3EE2, 2 rows to undo

InnoDB: Rolling back of trx id 3E3EE2 completed
111129 18:45:16  InnoDB: Rolling back trx with id 3E3EE0, 100 rows to undo

InnoDB: Rolling back of trx id 3E3EE0 completed
111129 18:45:16  InnoDB: Rolling back trx with id 3E3EDE, 12 rows to undo

InnoDB: Rolling back of trx id 3E3EDE completed
111129 18:45:16  InnoDB: Rolling back trx with id 3E3EDC, 1 rows to undo

InnoDB: Rolling back of trx id 3E3EDC completed
111129 18:45:16  InnoDB: Rolling back trx with id 3E3ECF, 100 rows to undo

InnoDB: Rolling back of trx id 3E3ECF completed
111129 18:45:16  InnoDB: Rolling back trx with id 3E3EBD, 100 rows to undo

InnoDB: Rolling back of trx id 3E3EBD completed
111129 18:45:16  InnoDB: Rollback of non-prepared transactions completed
111129 18:45:17 InnoDB: 1.1.8 started; log sequence number 311457237477
111129 18:45:17 [Note] Event Scheduler: Loaded 0 events
111129 18:45:17 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.5.17'  socket: '/opt/mysql/instances/default/mysql-3306.sock'  port: 3306  Distributed by The IUS Community Project
111129 18:45:17 [ERROR] Cannot find or open table queues_us/queue_exporter_us from
the internal data dictionary of InnoDB though the .frm file for the
table exists. Maybe you have deleted and recreated InnoDB data
files but have forgotten to delete the corresponding .frm files
of InnoDB tables, or you have moved .frm files to another database?
or, the table contains indexes that this version of the engine
doesn't support.
See http://dev.mysql.com/doc/refman/5.5/en/innodb-troubleshooting.html
how you can resolve the problem.

After this crash, files queue_exporter_us.frm and queue_exporter_us.ibd are missing. Instead I've some temporary file ( like #sql-5722_24cad.frm and #sql2-5722-24cad.ibd ) probably generated by the optimize table.

I've introduced foreign key in production this week, and I reach 3 crash like this one.
I didn't reach any crach with the same DB/apps before ( without foreign key ).
I've a script that check InnoDB tables fragmentation and automatically launch an "optimize table" if needed.

How to repeat:
Should be repeatable by generating a big child table ( big volume => optimize table take time ) with constraint ON DELETE CASCADE
Then launch the optimize table on the child, and immediately after launch a "delete from parent_table".

Suggested fix:
Perhaps "optimize table" on a child table should acquire a write lock on parent table, so the delete is delayed after the end on the optimize?
[12 Dec 2011 19:24] Sveta Smirnova
Thank you for the report.

I can not repeat described behavior. Please try with current version 5.5.19 and if problem still exists send us exact output of SHOW CREATE TABLE for both tables, your configuration file and MySQL package name you use (file name you downloaded).
[14 Dec 2011 8:25] Antoine Bonamour
Hello,

Thanks for your answer.
I will upgrade to 5.5.19 when this version will be available in the IUS repo we use in production.

I've updated my script in production to skip "optimize table" for "queue_exporter_us"
This is the only change I made, about 10 days ago.
I don't reach any crash in production since I made this change, whereas I reach ~1 crash per day with the last configuration ( same DB usage, about 2000 queries per seconds )

The exact table description are:

CREATE TABLE `repository_us` (
  `id` int(10) unsigned NOT NULL AUTO_INCREMENT COMMENT 'private id',
  `offerId` varchar(255) CHARACTER SET utf8 COLLATE utf8_bin NOT NULL COMMENT 'offer id',
  `status` tinyint(3) unsigned NOT NULL,
  `batchId` varchar(255) DEFAULT NULL,
  `comId` int(10) unsigned DEFAULT NULL,
  `catId` int(10) unsigned DEFAULT NULL,
  `pid` int(10) unsigned DEFAULT NULL,
  `title` varchar(255) DEFAULT NULL,
  `features` text,
  `metas` text,
  `creationTime` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
  `lastUpdateTime` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`),
  UNIQUE KEY `idx_offerId` (`offerId`)
) ENGINE=InnoDB AUTO_INCREMENT=1660 DEFAULT CHARSET=utf8 MAX_ROWS=100000000 AVG_ROW_LENGTH=4096

CREATE TABLE `queue_exporter_us` (
  `id` int(10) unsigned NOT NULL,
  `process` smallint(5) unsigned DEFAULT NULL,
  `processTime` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
  `priority` tinyint(3) unsigned DEFAULT NULL,
  `catId` int(10) unsigned DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `idx_order` (`process`,`catId`),
  CONSTRAINT `queue_exporter_us_ibfk_1` FOREIGN KEY (`id`) REFERENCES `repository_us` (`id`) ON DELETE CASCADE ON UPDATE CASCADE
) ENGINE=InnoDB DEFAULT CHARSET=utf8 MAX_ROWS=1000000 AVG_ROW_LENGTH=20

The my.cnf I use is:

[mysqld]
datadir="/opt/mysql/instances/default/data"
socket="/opt/mysql/instances/default/mysql-3306.sock"
log-error="/opt/mysql/instances/default/logs/mysqld.log"
pid-file="/opt/mysql/instances/default/mysqld-3306.pid"
port=3306
server-id=1
user=mysql
group=mysql
# Default to using old password format for compatibility with mysql 3.x
# clients (those using the mysqlclient10 compatibility package).
old_passwords=1

# Default configuration

# Specific configuration for this instance of mysql 
character_set_server=utf8
collation_server=utf8_general_ci
innodb_adaptive_flushing=1
innodb_additional_mem_pool_size=1G
innodb_autoinc_lock_mode=2
innodb_buffer_pool_size=16G
innodb_change_buffering=all
innodb_checksums=1
innodb_commit_concurrency=0
innodb_data_file_path=oq_data01:10M;oq_data02:1M:autoextend:max:50G
innodb_doublewrite=1
innodb_file_format=Barracuda
innodb_file_per_table=1
innodb_flush_log_at_trx_commit=2
innodb_flush_method=O_DIRECT
innodb_io_capacity=1200
innodb_lock_wait_timeout=10
innodb_locks_unsafe_for_binlog=0
innodb_log_buffer_size=16M
innodb_log_file_size=200M
innodb_log_files_in_group=3
innodb_max_dirty_pages_pct=16
innodb_max_purge_lag=4294967295
innodb_open_files=1000
innodb_purge_batch_size=5
innodb_purge_threads=1
innodb_support_xa=0
innodb_thread_concurrency=0
innodb_thread_sleep_delay=0
interactive_timeout=600
max_allowed_packet=16M
max_connect_errors=20000
max_connections=2000
max_heap_table_size=100M
query_cache_size=16M
query_cache_type=2
sort_buffer_size=512K
table_cache=2048
thread_cache_size=0
wait_timeout=300

When the 5.5.19 will be available in the IUS repo, I'll use it in production.
Then, I'll try to reproduce the problem under control.

Regards,

Antoine.
[19 Dec 2011 12:34] Valeriy Kravchuk
5.5.19 should be available already...
[19 Dec 2011 12:50] Antoine Bonamour
Hello,

Yes, available in the official IUS repo, but not in our IUS mirror repo ( the one we should use in production )
I'll check with the Infra team to update our mirror repo.

I'll keep you inform about this problem.

Regards
[20 Dec 2011 9:19] Antoine Bonamour
Hello,

Just one update : our private production yum repo is a mirror of the public http://mirrors.ircam.fr/pub/ius/stable/Redhat/6/x86_64/
This one is a mirror of http://dl.iuscommunity.org/pub/ius/stable/Redhat/6/x86_64/
I'll upgrade MySQL in production when 5.5.19 will be available in those repo.

Then I'll try to reproduce the behavior described above.

Regards,

Antoine.
[22 Jan 2012 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".