Bug #52590 Assertion heap_no == ULINT_UNDEFINED in lock/lock0lock.c line 3695
Submitted: 5 Apr 2010 5:10 Modified: 14 May 2010 16:37
Reporter: Elena Stepanova Email Updates:
Status: Closed Impact on me:
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:5.5.4-m3 OS:Any
Assigned to: Sunny Bains CPU Architecture:Any

[5 Apr 2010 5:10] Elena Stepanova
With a concurrent DML flow performed in several threads, server crashes with 

Version: '5.5.4-m3-log'  socket: '/var/tmp/mysqld.1.sock'  port: 13100  MySQL Community Server (GPL)
100405  7:58:15  InnoDB: Assertion failure in thread 1183963456 in file lock/lock0lock.c line 3695
InnoDB: Failing assertion: heap_no == ULINT_UNDEFINED
InnoDB: We intentionally generate a memory trap.

0  0x0000003ba880b132 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000005df58e in handle_segfault (sig=6) at mysqld.cc:2751
#2  <signal handler called>
#3  0x0000003ba8030055 in raise () from /lib64/libc.so.6
#4  0x0000003ba8031af0 in abort () from /lib64/libc.so.6
#5  0x00000000007d6d0c in lock_deadlock_recursive (start=0x59ffb38, trx=0x644ca08, wait_lock=0x5a7d8f0, cost=0x4691a750, depth=1, heap_no=0)
    at lock/lock0lock.c:3695
#6  0x00000000007d646a in lock_deadlock_recursive (start=0x59ffb38, trx=0x59ffb38, wait_lock=0x6132f48, cost=0x4691a750, depth=0, 
    heap_no=18446744073709551615) at lock/lock0lock.c:3830
#7  0x00000000007d6e73 in lock_deadlock_occurs (lock=0x6132f48, heap_no=18446744073709551615, trx=0x59ffb38) at lock/lock0lock.c:3515
#8  0x00000000007d82eb in lock_table (flags=<value optimized out>, table=0x59a2228, mode=<value optimized out>, thr=0x602d3a8)
    at lock/lock0lock.c:4016
#9  0x0000000000812614 in row_lock_table_autoinc_for_mysql (prebuilt=0x5ccc0d8) at row/row0mysql.c:942
#10 0x00000000007b4e1a in ha_innobase::innobase_lock_autoinc (this=0x5f8fa30) at handler/ha_innodb.cc:4677
#11 0x00000000007b4f1e in ha_innobase::innobase_set_max_autoinc (this=0xf30, auto_inc=10898) at handler/ha_innodb.cc:4728
#12 0x00000000007beff0 in ha_innobase::write_row (this=0x5f8fa30, record=0x5f8fc30 "�86\001") at handler/ha_innodb.cc:4967
#13 0x00000000006ebd8f in handler::ha_write_row (this=0x5f8fa30, buf=0x5f8fc30 "�86\001") at handler.cc:4670
#14 0x0000000000667d2d in write_record (thd=0x2aaab00b1110, table=0x59ea530, info=0x5a83188) at sql_insert.cc:1658
#15 0x0000000000668646 in select_insert::send_data (this=0x5a83150, values=<value optimized out>) at sql_insert.cc:3266
#16 0x000000000064cc8b in end_send (join=0x6197460, join_tab=<value optimized out>, end_of_records=6) at sql_select.cc:12385
#17 0x000000000064d622 in do_select (join=0x6197460, fields=0x2aaab00b3090, table=0x0, procedure=0x0) at sql_select.cc:11187
#18 0x00000000006633e7 in JOIN::exec (this=0x6197460) at sql_select.cc:2311
#19 0x000000000065f2da in mysql_select (thd=0x2aaab00b1110, rref_pointer_array=<value optimized out>, tables=<value optimized out>, wild_num=0, 
    fields=<value optimized out>, conds=<value optimized out>, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=0, 
    result=0x5a83150, unit=0x2aaab00b2988, select_lex=0x2aaab00b2f88) at sql_select.cc:2506
#20 0x0000000000664e44 in handle_select (thd=0x2aaab00b1110, lex=0x2aaab00b28e8, result=0x5a83150, setup_tables_done_option=1073741824)
    at sql_select.cc:271
#21 0x00000000005f8fdb in mysql_execute_command (thd=0x2aaab00b1110) at sql_parse.cc:3291
#22 0x00000000005f9c45 in mysql_parse (thd=0x2aaab00b1110, 
    inBuf=0x5a81840 "INSERT INTO systest1.tb1_eng1 (i1, f1, f2, f3, f4)\nSELECT i1, f1, f2, f3, f4\nFROM systest1.t1_tmp WHERE pk = 11", 
    length=111, found_semicolon=0x4691d060) at sql_parse.cc:5871
#23 0x00000000005fa6b4 in dispatch_command (command=COM_QUERY, thd=0x2aaab00b1110, 
    packet=0x2aaab00b3d01 "INSERT INTO systest1.tb1_eng1 (i1, f1, f2, f3, f4)\nSELECT i1, f1, f2, f3, f4\nFROM systest1.t1_tmp WHERE pk = 11", 
    packet_length=<value optimized out>) at sql_parse.cc:1023
#24 0x00000000005ed9b8 in do_handle_one_connection (thd_arg=<value optimized out>) at sql_connect.cc:1173
#25 0x00000000005eddba in handle_one_connection (arg=<value optimized out>) at sql_connect.cc:1112
#26 0x000000000090eb17 in pfs_spawn_thread (arg=<value optimized out>) at pfs.cc:1011
#27 0x0000003ba88062f7 in start_thread () from /lib64/libpthread.so.0
#28 0x0000003ba80ce85d in clone () from /lib64/libc.so.6

How to repeat:
- unpack the attached archive in <mysql-basedir>/mysql-test. It should create
'stress_test_basedir' folder;
- on Linux/Solaris, run as  
perl ./stress_test_basedir/run.pl

run.pl is a wrapper for MTR to start server, and mysql-stress-test to run a multi-thread stress test. 
For mysql-stress-test you need to have perl with threads on the top of your path 
(or please modify run.pl to call mysql-stress-test.pl with the right perl).

The screen output should say 'Waiting for server(s) to exit...' for a few seconds 
(sleep time for the server to start), and then start rapidly producing lines like

test_loop[0:0 0:26]: TID 2 test: 'stress2'  Errors: No Errors. Test Passed OK
test_loop[0:0 0:27]: TID 1 test: 'stress1'  Errors: No Errors. Test Passed OK

When/if the problem is hit, the output changes to 

test_loop[0:0 0:870]: TID 4 test: 'stress2'  Errors: Severity S1: 1 (thread aborting)

and soon stops. 
If the server does not start fast enough, the test might report something like 

test_loop[0:0 0:2]: TID 2 test: 'stress1'  Errors: Severity S1: 15 (thread aborting)

In this case please increase sleep time in run.pl.

A path to MySQL client is hard-coded inside run.pl as ../bin/mysqltest. 
If it's different from yours, please modify it accordingly.

It might take several minutes before the problem is hit.
[5 Apr 2010 5:15] Elena Stepanova
mysql-stress-test-based test

Attachment: bug52590_stress_test.tar.gz (application/x-gzip, text), 21.26 KiB.

[15 Nov 2010 6:36] Roel Van de Paar
Note bug #58191