MySQL Bugs: #54583: InnoDB: Assertion failure in thread <..> in file sync/sync0sync.c line 1226

Bug #54583	InnoDB: Assertion failure in thread <..> in file sync/sync0sync.c line 1226
Submitted:	17 Jun 2010 12:14	Modified:	15 Oct 2010 13:22
Reporter:	Alexey Stroganov	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.5.5pre-debug	OS:	Any
Assigned to:	Sunny Bains	CPU Architecture:	Any

Description:
Server built with UNIV_DEBUG && UNIV_SYNC_DEBUG asserts at start  when datadir was created by InnoDB < 1.1.

InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3
100617 14:06:18  InnoDB: Using Linux native AIO
100617 14:06:18  InnoDB: highest supported file format is Barracuda.
InnoDB: sync levels should be > 350 but a level is 300
Mutex created at srv/srv0srv.c 972
InnoDB: Locked mutex: addr 0x29aff48 thread 139776012322560 file trx/trx0rseg.c line 306
100617 14:06:19  InnoDB: Assertion failure in thread 139776012322560 in file sync/sync0sync.c line 1226
InnoDB: Failing assertion: sync_thread_levels_g(array, SYNC_IBUF_BITMAP, TRUE)
InnoDB: We intentionally generate a memory trap.

...

backtrace:

(gdb) bt
#0  0x00000032e0e0c216 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000009e6928 in my_write_core (sig=6) at stacktrace.c:326
#2  0x00000000006315fb in handle_segfault (sig=6) at mysqld.cc:2791
#3  <signal handler called>
#4  0x00000032e0632f05 in raise () from /lib64/libc.so.6
#5  0x00000032e0634a73 in abort () from /lib64/libc.so.6
#6  0x00000000008c869d in sync_thread_add_level (latch=0x7f1fcd55b450, level=350) at sync/sync0sync.c:1225
#7  0x00000000008fbbf7 in buf_block_dbg_add_level (block=0x7f1fcd55b2f0, level=350) at ./include/buf0buf.ic:1146
#8  0x0000000000854fcf in ibuf_bitmap_get_map_page_func (space=0, page_no=45, zip_size=0, file=0xb5bc6a "ibuf/ibuf0ibuf.c",
    line=4218, mtr=0x7fff0590fce0) at ibuf/ibuf0ibuf.c:805
#9  0x000000000085a889 in ibuf_merge_or_delete_for_page (block=0x0, space=0, page_no=45, zip_size=0, update_ibuf_bitmap=1)
    at ibuf/ibuf0ibuf.c:4217
#10 0x000000000090420f in buf_page_create (space=0, offset=45, zip_size=0, mtr=0x7fff059107b0) at buf/buf0buf.c:3853
#11 0x0000000000936c27 in fsp_alloc_free_page (space=0, zip_size=0, hint=0, mtr=0x7fff059107b0) at fsp/fsp0fsp.c:1670
#12 0x00000000009390f8 in fseg_alloc_free_page_low (space=0, zip_size=0, seg_inode=0x7f1fd1114b72 "", hint=0,
    direction=111 'o', mtr=0x7fff059107b0) at fsp/fsp0fsp.c:2713
#13 0x00000000009381c7 in fseg_create_general (space=0, page=0, byte_offset=62, has_done_reservation=0, mtr=0x7fff059107b0)
    at fsp/fsp0fsp.c:2325
#14 0x0000000000938353 in fseg_create (space=0, page=0, byte_offset=62, mtr=0x7fff059107b0) at fsp/fsp0fsp.c:2376
#15 0x00000000008d3890 in trx_rseg_header_create (space=0, zip_size=0, max_size=18446744073709551614, rseg_slot_no=1,
    mtr=0x7fff059107b0) at trx/trx0rseg.c:89
#16 0x00000000008d4253 in trx_rseg_create () at trx/trx0rseg.c:316
#17 0x00000000008d67af in trx_sys_create_rsegs (n_rsegs=127) at trx/trx0sys.c:1333
#18 0x00000000008c2767 in innobase_start_or_create_for_mysql () at srv/srv0start.c:1732
#19 0x00000000008478f7 in innobase_init (p=0x29af090) at handler/ha_innodb.cc:2421
#20 0x0000000000763b9d in ha_initialize_handlerton (plugin=0x29ac820) at handler.cc:476
#21 0x000000000080c3c3 in plugin_initialize (plugin=0x29ac820) at sql_plugin.cc:1057
#22 0x000000000080f111 in plugin_init (argc=0x101a5e8, argv=0x29814d8, flags=0) at sql_plugin.cc:1343
#23 0x00000000006343e7 in init_server_components () at mysqld.cc:4155
#24 0x0000000000634f61 in mysqld_main (argc=34, argv=0x29814d8) at mysqld.cc:4756
#25 0x000000000062b9b7 in main (argc=6, argv=0x7fff059119d8) at main.cc:24

How to repeat:
Build the latest mysql-trunk-innodb with debug(UNIV_DEBUG && UNIV_SYNC_DEBUG) and start server with datatdir that was created with any other InnoDB < 1.1.

It will asserts immediately.

To reproduce isssue it is enough to use fresh datadir created by mysql_install_db with server/InnoDB <1.1.

happens in the extra rseg creation. Everything works fine
unless UNIV_SYNC_DEBUG is defined. The question is, if it's not some form
of overasserting, can it happen outside of this once-per-upgrade codepath?
My testing said no, so far.

I'm not sure this is actually a bug even. One of the requirements when upgrading is that the
database must have been shutdown cleanly. Implicit in this is that there should be no purge
and insert buffer operations pending. I think the documentation should explicitly state what
a clean shutdown means, at least in this context, if it doesn't do so already. 

The problem in this bug report is that when the page is accessed it triggers an insert buffer
merge operation and that cause the problem.

http://dev.mysql.com/doc/innodb-plugin/1.1/en/innodb-multiple-rollback-segments.html

Looks like the documentation already mentions "slow shutdown". The slow shutdown should
ensure that there are no purge or insert buffer merge operations at the next startup.

Secondly, the documentation says:

"Each transaction is assigned to one of the rollback segments using a hashing function, and remains tied to that rollback segment for the duration."  -- there is no hashing function, InnoDB uses a round
robin scheme.

The first perhaps needs some further elaboration and the second needs to be corrected.

It's still a bug because slow shutdown still ends up in an assert.
We need to execute insert buffer merge even if to find out there's nothing
to merge, and there we assert somewhere.
I'll reassign it to Marko to look at. 
The initial assesment of a serious bug was to get someone to look at a.s.a.p.
At this moment the bug does not look serious, so it needs to be retriaged.
Regarding why we didn't see it in our testing, I haven't run
the compatibility test suite which was supposed to catch it, with
UNIV_DEBUG or UNIV_SYNC_DEBUG, until lately. I found many complications
and some noise there. So far I've had about one run with UNIV*DEBUG
where I don't remember seeing this. However the expectation is that
UNIV_SYNC_DEBUG works always so we should fix this bug unless I'll never 
be able to run the compatibility tests with UNIV_SYNC_DEBUG.
I should retry it eventually to see if and why this bug isn't showing there
but for now the bug doesn't look too dangerous anyway so it may take time.

At the time of the assertion failure, following InnoDB latching orders are in use:

SYNC_NO_ORDER_CHECK (8 occurrences)
SYNC_FSP_PAGE (5 occurrences)
SYNC_FSP (3 occurrences)

These are OK, because they are above SYNC_IBUF_BITMAP. The following are not (1 occurrence each):

SYNC_KERNEL
SYNC_TRX_SYS_HEADER
SYNC_BUF_POOL
SYNC_BUF_BLOCK

Sunny is right that this assertion failure does not indicate a real problem, because InnoDB is running in a single-threaded mode. Michael is right that we should keep UNIV_SYNC_DEBUG clean of bogus failures. I will try to figure out an elegant fix for this.

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/112524

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/112525

Sunny, this occurs even without any pending insert buffer merges. I repeated this as follows, with an empty insert buffer bitmap:

(1) delete any data files
(2) start MySQL 5.1, let InnoDB create the system tablespace
(3) send SIGQUIT (ctrl-\) to mysqld
(4) start MySQL 5.5 compiled with -DUNIV_DEBUG -DUNIV_SYNC_DEBUG

I did not test what happens when an insert buffer merge (discarding buffered entries to a table that was dropped from the system tablespace) is needed. Testing that would require populating a large table with innodb_file_per_table=0, dropping it and doing a fast shutdown. (The upgrade advice of doing a slow shutdown would imply an insert buffer merge.)

Also, note that trx_sys_create_rsegs() does nothing if srv_force_recovery == TRUE or recv_needed_recovery == TRUE.

I would welcome a better fix that avoids relaxing the latching order checks. I believe that we should try to obey the latching order even during single-threaded
startup, because we might want to defer some tasks to a background thread, such as the rollback of incomplete transactions currently is.

You may want to reassign this to someone else while I am on vacation.

Pushed into 5.1.49 (revid:build@mysql.com-20100719143034-omcma40sblwmay3x) (version source revid:vasil.dimov@oracle.com-20100704071244-3lo4okzels3kvy1p) (merge vers: 5.1.49) (pib:16)

Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100723121820-jryu2fuw3pc53q9w) (version source revid:alik@sun.com-20100723121820-jryu2fuw3pc53q9w) (merge vers: 5.5.6-m3) (pib:18)

Pushed into mysql-next-mr (revid:alik@sun.com-20100723121929-90e9zemk3jkr2ocy) (version source revid:alik@sun.com-20100723121827-3bsh51m5sj6g4oma) (pib:18)

Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100731131027-1n61gseejyxsqk5d) (version source revid:alik@sun.com-20100731074942-o840woifuqioxxe4) (merge vers: 5.5.6-m3) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804080001-bny5271e65xo34ig) (version source revid:alik@sun.com-20100731075120-qz9z8c25zum2wgmm) (merge vers: 5.6.99-m4) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804081533-c1d3rbipo9e8rt1s) (version source revid:alik@sun.com-20100731075120-qz9z8c25zum2wgmm) (merge vers: 5.6.99-m4) (pib:18)

Pushed into mysql-next-mr (revid:alik@ibmvm-20100804081630-ntapn8bf9pko9vj3) (version source revid:alik@sun.com-20100731075120-qz9z8c25zum2wgmm) (pib:20)

Closing without adding anything to the doc changelog. I did correct the reference to the 'hashing function' for the transaction <=> rollback segment mapping.

Pushed into mysql-5.1-telco-7.0 5.1.51-ndb-7.0.20 (revid:martin.skold@mysql.com-20101014082627-jrmy9xbfbtrebw3c) (version source revid:martin.skold@mysql.com-20101014082627-jrmy9xbfbtrebw3c) (merge vers: 5.1.51-ndb-7.0.20) (pib:21)

Pushed into mysql-5.1-telco-6.3 5.1.51-ndb-6.3.39 (revid:martin.skold@mysql.com-20101014083757-5qo48b86d69zjvzj) (version source revid:martin.skold@mysql.com-20101014083757-5qo48b86d69zjvzj) (merge vers: 5.1.51-ndb-6.3.39) (pib:21)

Pushed into mysql-5.1-telco-6.2 5.1.51-ndb-6.2.19 (revid:martin.skold@mysql.com-20101014084420-y54ecj85j5we27oa) (version source revid:martin.skold@mysql.com-20101014084420-y54ecj85j5we27oa) (merge vers: 5.1.51-ndb-6.2.19) (pib:21)

Setting back to Closed -- see above.

This is a case of Bug #59733. When Bug #59733 is fixed, this "fix" of suppressing the check should be reverted.

It now looks like Bug#59733 is overasserting, and suppressing this assertion was OK after all.