Bug #33759 Falcon assertionFailed() in releaseDependency()
Submitted: 9 Jan 2008 8:42 Modified: 5 May 2008 17:27
Reporter: Philip Stoev Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S1 (Critical)
Version:6.0.4-p3 OS:Any
Assigned to: Jim Starkey CPU Architecture:Any

[9 Jan 2008 8:42] Philip Stoev
Description:
Running the iuds2 systems test against Falcon with falcon_debug_mask=65535 and logging to file resulted in the following crash:

0x824a181 handle_segfault + 441
0xffffe410 _end + -144808416
0x4 (?)
0x83fce71 Error::error(char const*, ...) + 73
0x83fcf7a Error::assertionFailed(char const*, int) + 22
0x83d42ce Transaction::releaseDependency() + 250
0x83d3366 Transaction::releaseDependencies() + 198
0x83d2259 Transaction::commitNoUpdates() + 161
0x83d1cea Transaction::commit() + 142
0x83e594e Connection::commit() + 82
0x83ba9df StorageConnection::commit() + 55
0x83badc5 StorageConnection::endImplicitTransaction() + 37
0x83b3a3a StorageInterface::external_lock(THD*, int) + 742
0x830e850 handler::ha_external_lock(THD*, int) + 24
0x8247801 unlock_external(THD*, st_table**, unsigned int) + 57
0x824631a mysql_unlock_tables(THD*, st_mysql_lock*) + 50
0x828152d close_thread_tables(THD*) + 429
0x82be9e5 Prepared_statement::cleanup_stmt() + 49
0x82befb8 Prepared_statement::execute(String*, bool) + 556
0x82bdcbb mysql_sql_stmt_execute(THD*) + 215
0x8259579 mysql_execute_command(THD*) + 17449
0x825b5ad mysql_parse(THD*, char const*, unsigned int, char const**) + 269
0x82540c5 dispatch_command(enum_server_command, THD*, char*, unsigned int) + 909
0x8253d08 do_command(THD*) + 176
0x8252557 handle_one_connection + 287

The falcon_debug_mask=65535 caused the following output to stderr:

Commit transaction 3187469
Commit transaction 3188058
18635: Cache flush: 169 pages, 152 writes in 0 seconds (169 pps)
dangling dependencies for tid 3188519 (0/11/1)
  0xe8d04904 Id 2665488, state 3, updates 1, wrtPend 1, states 43, dependencies 1, records 0
dependency from tid 2665488 still present
dependency from tid 2665488 still present
dependency from tid 2665488 still present
dependency from tid 2665488 still present
dependency from tid 2665488 still present
(followed by 6000 lines of identical output, referencing different tids and different dependency counts)

How to repeat:
Run iuds2 systems test as described in:

https://inside.mysql.com/wiki/SystemQATestPlan

No sysbench installation is needed. The run_systest script needs to be edited to pass those options to mysql-test-run.pl:

--mysqld="--falcon_record_memory_max=2GB"
--mysqld="--max_connections=500"
--mysqld="--falcon-lock-wait-timeout=1"
--mysqld=--skip-innodb
--mysqld=--log-output=FILE
--mysqld=--falcon_debug_mask=65535

The iuds2.tst file needs to be edited to remove all mention of innodb and myisam and replace those with Falcon.
[9 Jan 2008 8:45] Philip Stoev
The offending query was:

 SELECT ROUND(RAND() * MAX(i1)), MAX(i1), MIN(i1)
   INTO @next_val, @max_val, @min_val FROM systest1.tb1_eng1

which is identical to the query that caused the crash on bug #33496
[9 Jan 2008 9:17] Philip Stoev
Recovery failed with:

first recovery block is 141
last recovery block is 600259
recovery read block is 6528
Bugcheck: page 8138 wrong page type, expected 2 got 7

080109 10:00:43 - mysqld got signal 4;

0x83fce71 Error::error(char const*, ...) + 73
0x8472ea5 Cache::fetchPage(Dbb*, int, PageType, LockType) + 441
0x83f5d22 Dbb::handoffPage(Bdb*, int, PageType, LockType) + 34
0x844a9f2 Section::getSectionPage(Dbb*, int, int, LockType, unsigned int) + 554
0x844ce28 Section::getSectionPage(int, LockType, unsigned int) + 184
0x844b6c1 Section::fetchLocatorPage(int, int, LockType, unsigned int) + 65

vardir before recovery is available at:

dl360-g5-a:/data1/6.0.4/systest_vardir-bug33759-beforerecovery
[9 Jan 2008 9:25] Philip Stoev
Second recovery attempt crashes with:

0x824a181 handle_segfault + 441
0xffffe410 _end + -144808416

sizes of tablespace files before any recovery has been attempted:

-rw------- 1 qauser qauser 560783360 Jan  8 22:52 core.13138
-rw-rw---- 1 qauser qauser 460949504 Jan  8 22:52 falcon_master.fl1
-rw-rw---- 1 qauser qauser  18873856 Jan  8 17:42 falcon_master.fl2
-rw-rw---- 1 qauser qauser    458752 Jan  8 22:52 falcon_master.fts
-rw-rw---- 1 qauser qauser     16384 Jan  8 17:41 falcon_temporary.fts
-rw-rw---- 1 qauser qauser 105029632 Jan  8 22:52 falcon_user.fts

sizes after two recovery attempts:

-rw-rw---- 1 qauser qauser 460949504 Jan  9 09:47 falcon_master.fl1
-rw-rw---- 1 qauser qauser  18873856 Jan  9 09:47 falcon_master.fl2
-rw-rw---- 1 qauser qauser    458752 Jan  9 10:17 falcon_master.fts
-rw-rw---- 1 qauser qauser     16384 Jan  9 10:20 falcon_temporary.fts
-rw-rw---- 1 qauser qauser 118263808 Jan  9 10:21 falcon_user.fts
[10 Jan 2008 8:34] Philip Stoev
A (similar) crash happened again, here is the backtrace:

#0  0x00002ac6728c14c5 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000660113 in handle_segfault (sig=4) at mysqld.cc:2313
#2  <signal handler called>
#3  0x00002ac6728c3fed in raise () from /lib64/libpthread.so.0
#4  0x00000000008586bc in Error::error (string=<value optimized out>) at Error.cpp:92
#5  0x000000000082838f in Transaction::releaseDependency (this=0x2aaab554a440) at Transaction.cpp:1256
#6  0x00000000008285b7 in Transaction::releaseDependencies (this=0x2aaaae103888) at Transaction.cpp:743
#7  0x00000000008286f7 in Transaction::commitNoUpdates (this=0x2aaaae103888) at Transaction.cpp:337
#8  0x0000000000829717 in Transaction::commit (this=0x2aaaae103888) at Transaction.cpp:237
#9  0x0000000000840671 in Connection::commit (this=0x2aaabfdf6108) at Connection.cpp:269
#10 0x000000000080e6cb in StorageConnection::commit (this=0x2aaabfe390e8) at StorageConnection.cpp:146
#11 0x0000000000809dbe in StorageInterface::external_lock (this=0x2aaabcb808f0, thd=0x2aaabcbc3e40, lock_type=2) at ha_falcon.cpp:1767
#12 0x000000000074579a in handler::ha_external_lock (this=0x4ab1, thd=0x2c58, lock_type=4) at handler.cc:4568
#13 0x000000000065a451 in mysql_unlock_tables (thd=0x2aaabcbc3e40, sql_lock=0x2aaabcbea1e0) at lock.cc:814
#14 0x000000000064d4d2 in select_send::send_eof (this=0x1b82490) at sql_class.cc:1443
#15 0x00000000006cbc72 in do_select (join=0x2aaabcfdddf0, fields=0x2aaabcfdf840, table=0x0, procedure=0x0) at sql_select.cc:13060
#16 0x00000000006df336 in JOIN::exec (this=0x2aaabcfdddf0) at sql_select.cc:2713
#17 0x00000000006e0e90 in mysql_select (thd=0x2aaabcbc3e40, rref_pointer_array=0x17d06f8, tables=0x1b81900, wild_num=0, fields=@0x17d0618, conds=0x1b82310,
    og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2416200192, result=0x1b82490, unit=0x17d00d0, select_lex=0x17d0510)
    at sql_select.cc:2901
#18 0x00000000006e1863 in handle_select (thd=0x2aaabcbc3e40, lex=0x17d0030, result=0x1b82490, setup_tables_done_option=0) at sql_select.cc:282
#19 0x000000000066b199 in execute_sqlcom_select (thd=0x2aaabcbc3e40, all_tables=0x1b81900) at sql_parse.cc:4517
#20 0x000000000066f6a0 in mysql_execute_command (thd=0x2aaabcbc3e40) at sql_parse.cc:1845
#21 0x00000000006ea18a in Prepared_statement::execute (this=0x17cfd20, expanded_query=0x464ba080, open_cursor=false) at sql_prepare.cc:3100
#22 0x00000000006ea2c3 in mysql_sql_stmt_execute (thd=<value optimized out>) at sql_prepare.cc:2391
#23 0x000000000067098f in mysql_execute_command (thd=0x2aaabcbc3e40) at sql_parse.cc:1854
#24 0x0000000000675793 in mysql_parse (thd=0x2aaabcbc3e40, inBuf=0x1978120 "EXECUTE sel_single USING @next_val", length=34, found_semicolon=0x464bc110)
    at sql_parse.cc:5410
#25 0x0000000000675c83 in dispatch_command (command=COM_QUERY, thd=0x2aaabcbc3e40, packet=<value optimized out>, packet_length=34) at sql_parse.cc:921
#26 0x0000000000676c6e in do_command (thd=0x2aaabcbc3e40) at sql_parse.cc:697
#27 0x0000000000668843 in handle_one_connection (arg=0x2aaabcbc3e40) at sql_connect.cc:1146
#28 0x00002ac6728bd193 in start_thread () from /lib64/libpthread.so.0
#29 0x00002ac672ef045d in clone () from /lib64/libc.so.6
#30 0x0000000000000000 in ?? ()

The entire vardir + logs + core file has been preserved at:

dl360-g5-b:/data1/6.0.4/systest_vardir-bug33759-2
[10 Jan 2008 8:36] Philip Stoev
The second crash had this in mysql.err:

dependency from tid 0 still present (repeated hundreds of times)
  0x2aaab540ca80 Id 0, state 9, updates 0, wrtPend 0, states 0, dependencies 0, records 0
  0x2aaaad512298 Id 0, state 9, updates 0, wrtPend 0, states 0, dependencies 0, records 0
  0x2aaaaad00c20 Id 0, state 9, updates 0, wrtPend 0, states 0, dependencies 0, rec080110  6:22:37 - mysqld got signal 4;
[17 Jan 2008 11:38] Philip Stoev
Setting to verified so that it pops up in the relevant reports.

The corrupted tablespace is available to reproduce the second part of the bug even if the first one is non-deterministic.
[3 Feb 2008 21:30] Jim Starkey
The problem resulted from an initializing transaction creating a 
dependency on a commitNoUpdate transaction releasing transaction
dependencies.
[11 Feb 2008 20:50] Kevin Lewis
Patch is in mysql-6.0-falcon-team and mysql-6.0-release version 6.0.4
[5 May 2008 17:27] Paul DuBois
Noted in 6.0.4 changelog.

For Falcon, an initializing transaction created a dependency on a
commitNoUpdate transaction releasing transaction dependencies, which
caused an assertion failure.