MySQL Bugs: #55028: assertion: trx->dict_operation_lock_mode == 0 in srv_suspend_mysql

Bug #55028	assertion: trx->dict_operation_lock_mode == 0 in srv_suspend_mysql_thread()
Submitted:	6 Jul 2010 15:22	Modified:	19 Aug 2010 7:53
Reporter:	Mikhail Izioumtchenko	Email Updates:
Status:	Won't fix	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.1	OS:	Any
Assigned to:	Marko Mäkelä	CPU Architecture:	Any

Description:
builtin only bug, fixed in the plugin in 2007.

100706  6:11:40  InnoDB: Assertion failure in thread 47541628600992 in file srv/srv0srv.c line 1504
InnoDB: Failing assertion: trx->dict_operation_lock_mode == 0

 #5  0x0000003acbc31d10 in abort () from /lib64/libc.so.6
 #6  0x000000000088156a in srv_suspend_mysql_thread (thr=0x2aaaac093bb0)
     at srv/srv0srv.c:1504
 #7  0x000000000085d976 in que_run_threads (thr=0x2aaaac093bb0)
     at que/que0que.c:1375
 #8  0x000000000085daea in que_eval_sql (info=0x2aaaac0958b8,
     sql=0xa53fa8 "PROCEDURE DROP_TABLE_PROC () IS\nsys_foreign_id CHAR;\ntable_id CHAR;\nindex_id CHAR;\nforeign_id CHAR;\nfound INT;\nBEGIN\nSELECT ID INTO table_id\nFROM SYS_TABLES\nWHERE NAME = :table_name\nLOCK IN SHARE MODE"...,
     reserve_dict_mutex=0, trx=0x2aaaac08b0b8) at que/que0que.c:1438
 #9  0x000000000086ed42 in row_drop_table_for_mysql (
     name=0x7fff3df2c350 "c51/#sql9bd_85_0", trx=0x2aaaac08b0b8, drop_db=0)
     at row/row0mysql.c:3178
 #10 0x00000000007ee9a0 in ha_innobase::delete_table (this=0x165e1320,
     name=0x7fff3df2cb50 "/spare2/mizioumt/ctc/data/c51/#sql9bd_85_0")
     at handler/ha_innodb.cc:5908
 #11 0x000000000072405f in handler::ha_delete_table (this=0x165e1320,
     name=0x7fff3df2cb50 "/spare2/mizioumt/ctc/data/c51/#sql9bd_85_0")
     at handler.cc:3373
 #12 0x000000000065871b in mysql_rm_tmp_tables () at sql_base.cc:8425

How to repeat:
popped up in my stress testing. The code is obviously wrong.

Suggested fix:
backport the simple low risk plugin fix, see the related code in the plugin.

    revno: 0.3.824
    committer: marko
    timestamp: Fri 2007-10-19 10:30:34 +0000
    message:
      branches/zip: srv_suspend_mysql_thread(): Allow the transaction to
      hold an X-latch to the data dictionary, to avoid an assertion failure
      when a lock wait occurs in row_merge_lock_table().

Issue addressed in 5.5 and will not be fixed in 5.1

Sorry, I believe that the suggested fix is wrong. 

When I implemented fast index creation aka smart ALTER TABLE (fast DROP INDEX, CREATE INDEX) in the InnoDB Plugin, I initially failed to understand that record or table lock waits (and related deadlocks) are not allowed when accessing the InnoDB data dictionary. This is guaranteed by bracketing all InnoDB dictionary operations with row_mysql_freeze_data_dictionary/row_mysql_unfreeze_data_dictionary or row_mysql_lock_data_dictionary/row_mysql_unlock_data_dictionary, and by creating a separate transaction for DDL operations.

Initially, I failed to create a separate DDL transaction for CREATE INDEX in ha_innobase::add_index(), and I tried to acquire a lock on the user table in the same transaction that accessed the InnoDB data dictionary tables.

We should find out what is causing the lock wait in the built-in InnoDB of MySQL 5.1, and see if a dictionary lock/freeze is missing somewhere. And we should consider reverting my "fix" in later InnoDB versions.

let's keep the bug open until the end of this discussion.

Marko, do I understand you correctly:
1. you are interested in finding out, in 5.1 builtin, what is the cause
for the fact that we arrive at thread suspension while holding
the latch in X mode? This should be possible to determine from the coredump
I saved, see a previous note.
2. When you say, 
we should consider reverting my
"fix" in later InnoDB versions.

Do you mean that in 5.1 plugin, 5.5 etc we should restore the original
code which now exists in the 5.1 builtin only? If not, what should we revert?
If yes, I could consider it to be too dangerous for 5.1 plugin
but I could test it for 5.5.

I think Marko's point is that all data dictionary operations are sync-ed up by dict_operation_lock, so there would be no lock wait when we query system tables. In this case, there could be another thread that did not acquire (or acquire sufficient) dict_operation_lock, and causing this drop table operation wait on system table access. So we will need to figure out what this other thread is doing (and this is not available in the core dump). Probably require code examination.

bug#54113 could be related

I studied Michael’s core dump. I see that one thread is spinning for dict_operation_lock in S mode, in row_mysql_freeze_data_dictionary() called by row_purge_parse_undo_rec(). The dict_operation_lock is x-latched by some thread, likely Thread 1 (3720), where the lock wait occurred.

The purge thread is apparently trying to access table_id={0,3}, that is, SYS_FIELDS. However, it is not holding any locks (trx->trx_locks={0,0,0}) and it would not attempt to access the table until after acquiring the dict_operation_lock.

The failing thread is holding 16 locks:

IS-lock on SYS_TABLES, record S-locks,
IS-lock on SYS_FOREIGN, record S-locks,
IS-lock on SYS_INDEXES, record S-locks,
IX-lock on SYS_FIELDS, record X-locks,
IX-lock on SYS_INDEXES, record X-locks,
IX-lock on SYS_COLUMNS, record X-locks,
IX-lock on SYS_TABLES, record X-locks,
record X-locks,
waiting record X-lock on (space=0,page_no=9,heap_no=61)

Next, I will try to extract the page and the record from the core dump. Judging from the page number, it probably is a index B-tree root page of some system table.

The block of (space=0,page=9) is block = (buf_block_t*) 0x2aabad456d80. The block and the page frame look sensible. The PAGE_INDEX_ID contains DICT_TABLE_IDS_ID (CREATE INDEX ID_IND ON SYS_TABLES(ID)), and PAGE_LEVEL is 0, meaning the leaf page level (probably the root page).

The record with heap_no=61 starts at block->frame[0x75c]:

ID=70
NAME=c51/#sql9bd_9_0

The table name differs from the stack trace of the failing assertion, but it seems to belong to a temporary table nevertheless:

#6  0x000000000088156a in srv_suspend_mysql_thread (thr=0x2aaaac093bb0)
    at srv/srv0srv.c:1504
#7  0x000000000085d976 in que_run_threads (thr=0x2aaaac093bb0)
    at que/que0que.c:1375
#8  0x000000000085daea in que_eval_sql (info=0x2aaaac0958b8, 
    sql=0xa53fa8 "PROCEDURE DROP_TABLE_PROC () IS\nsys_foreign_id CHAR;\ntable_id CHAR;\nindex_id CHAR;\nforeign_id CHAR;\nfound INT;\nBEGIN\nSELECT ID INTO table_id\nFROM SYS_TABLES\nWHERE NAME = :table_name\nLOCK IN SHARE MODE"..., 
    reserve_dict_mutex=0, trx=0x2aaaac08b0b8) at que/que0que.c:1438
#9  0x000000000086ed42 in row_drop_table_for_mysql (
    name=0x7fff3df2c350 "c51/#sql9bd_85_0", trx=0x2aaaac08b0b8, drop_db=0)
    at row/row0mysql.c:3178
#10 0x00000000007ee9a0 in ha_innobase::delete_table (this=0x165e1320, 
    name=0x7fff3df2cb50 "/spare2/mizioumt/ctc/data/c51/#sql9bd_85_0")
    at handler/ha_innodb.cc:5908
#11 0x000000000072405f in handler::ha_delete_table (this=0x165e1320, 
    name=0x7fff3df2cb50 "/spare2/mizioumt/ctc/data/c51/#sql9bd_85_0")
    at handler.cc:3373
#12 0x000000000065871b in mysql_rm_tmp_tables () at sql_base.cc:8425
#13 0x0000000000607f32 in main (argc=18, argv=0x7fff3df2d0d8) at mysqld.cc:4450

The next step could be to dump trx_list and see which transactions are in the system. It looks like this bug could be caused by forgetting to commit and free a transaction object.

As far as I can tell, there is not much InnoDB activity going on yet. Only the master thread doing purge, and one thread serving the MySQL initialization. No threads appear to be serving client connections yet.

The tables most likely were created by CREATE TEMPORARY TABLE. According to Michael, tmpdir=…/c51 and the database always is "test". Any tables created by ALTER TABLE would have been named test/#sql….

Thread 7 (Thread 3726) is still executing trx_rollback_or_clean_all_without_sess(), rolling back transactions that were active at the time when the server crashed.

There are 20 transactions in trx_sys->trx_list and 2 in trx_sys->mysql_trx_list.

My current hypothesis is that one of the 18 old transactions is a dictionary transaction that is locking the SYS_TABLES record. In InnoDB Plugin 1.0, dictionary transactions are rolled back synchronously, before dropping any incomplete indexes from ha_innobase::add_index() and before accepting MySQL client connections.

In the built-in InnoDB in MySQL 5.1 and earlier, there is a bug in the background rollback of incomplete transactions. If a DDL transaction is started right after starting the MySQL server, before InnoDB has rolled back any incomplete dictionary transactions, then a lock wait can occur.

Workaround: do not start DDL operations (CREATE TABLE, CREATE INDEX, DROP INDEX, DROP TABLE, ALTER TABLE) before InnoDB has completed the background rollback of incomplete transactions, if the server crashed while performing a DDL operation.

I have to confirm this hypothesis by examining the 20 transactions in the core dump.

I confirmed my hypothesis.

In the core dump, (trx_t *) 0x2aaaac07d8b8 is a recovered transaction that has trx->dict_operation=1 and table_id=70. The new transaction trx_sys->mysql_trx_list.start = (trx_t *) 0x2aaaac08b0b8 has table_id=69.

The new transaction (operating on table_id=69) is trying to lock the secondary index record in SYS_TABLES for ID=70, and fails, because the to-be-rolled-back transaction is holding a lock on it.

Bug #56114 was filed against the bogus error handling that was initially supposed to be the fix of this bug.