MySQL Bugs: #23843: MySQL does not restart after crash

Bug #23843	MySQL does not restart after crash
Submitted:	1 Nov 2006 16:02	Modified:	23 Nov 2006 12:14
Reporter:	Oli Sennhauser	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.0.26	OS:	Linux (Linux 32-bit)
Assigned to:	Assigned Account	CPU Architecture:	Any

Description:
I did a bulk load in a mysql table with binary loging enabled. During bulk load I crashed instance and removed all the bin.0000x files.
Then I tried to restart the instance. It did not come up again and gave a dump:

061101 16:53:24 mysqld started
061101 16:53:24 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...
061101 16:53:24 InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 0 189019.
InnoDB: Doing recovery: scanned up to log sequence number 0 189019
InnoDB: Transaction 0 2653 was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 0 3072
InnoDB: Last MySQL binlog file position 0 15099, file name ./1.000001
061101 16:53:24 InnoDB: Started; log sequence number 0 189019
061101 16:53:24 InnoDB: Starting recovery for XA transactions...
061101 16:53:24 InnoDB: Transaction 0 2653 in prepared state after recovery
061101 16:53:24 InnoDB: Transaction contains changes to 1 rows
061101 16:53:24 InnoDB: 1 transactions in prepared state after recovery
061101 16:53:24 [Note] Found 1 prepared transaction(s) in InnoDB
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=0
read_buffer_size=131072
max_used_connections=0
max_connections=100
threads_connected=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 217599 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=(nil)
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...
Cannot determine thread, fp=0xbfffe8cc, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x81a3968
0x832c9c7
0x8327d8f
0x82d6766
0x82d5df1
0x83258aa
0x8327e64
0x824e7d0
0x8245915
0x81a5f75
0x81a3e75
0x400d3e80
0x812c4e1
New value of fp=(nil) failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/mysql/en/Using_stack_trace.html and follow instructions on how to resolve the stack trace. Resolved
stack trace is much more helpful in diagnosing the problem, so please do
resolve it
The manual page at http://www.mysql.com/doc/en/Crashing.html contains
information that should help you find out what is causing the crash.
061101 16:53:24 mysqld ended

How to repeat:
create table test (
id int not null auto_increment primary key
, data varchar(32)
) engine = innodb;

insert into test values (null, 'Hallo Otto!');
insert into test values (null, 'Hallo Otto!');
...
1000 times
...
drop table test;

Suggested fix:
No idea. Possible Workaround is to disable binary logging. then db comes up.

This is probably the same bug as http://bugs.mysql.com/bug.php?id=21468

I am able to repeat:

heikki@127:~/mysql-5.0/sql$ gdb mysqld
GNU gdb 6.3-debian
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "i386-linux"...Using host libthread_db library "/lib/tls/libthread_db.so.1".

(gdb) run
Starting program: /home/heikki/mysql-5.0/sql/mysqld
[Thread debugging using libthread_db enabled]
[New Thread 1075726944 (LWP 21712)]
061123 13:42:18 [Warning] Changed limits: max_open_files: 1024  max_connections: 1014  table_cache: 64
[New Thread 1129290672 (LWP 21715)]
[New Thread 1137679280 (LWP 21716)]
[New Thread 1146067888 (LWP 21717)]
[New Thread 1154456496 (LWP 21718)]
061123 13:42:19  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...
061123 13:42:19  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 0 189019.
InnoDB: Doing recovery: scanned up to log sequence number 0 189019
InnoDB: Transaction 0 2653 was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 0 3072
InnoDB: Last MySQL binlog file position 0 15099, file name ./1.000001
[New Thread 1167625136 (LWP 21719)]
[New Thread 1176013744 (LWP 21720)]
[New Thread 1184402352 (LWP 21721)]
[New Thread 1192790960 (LWP 21722)]
061123 13:42:21  InnoDB: Started; log sequence number 0 189019
InnoDB: Starting in background the rollback of uncommitted transactions
061123 13:42:21  InnoDB: Starting recovery for XA transactions...
061123 13:42:21  InnoDB: Transaction 0 2653 in prepared state after recovery
061123 13:42:21  InnoDB: Transaction contains changes to 1 rows
061123 13:42:21  InnoDB: 1 transactions in prepared state after recovery
061123 13:42:21 [Note] Found 1 prepared transaction(s) in InnoDB
061123 13:42:21 [Note] rollback xid 'MySQLXid\1\0\0\0]\0\0\0\0\0\0\0'

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 1075726944 (LWP 21712)]
0x084bc409 in trx_sig_send (trx=0x4224a468, type=1, sender=1,
    receiver_thr=0x4224f138, savept=0x0, next_thr=0x0) at trx0trx.c:1297
1297            if (trx->sess->state == SESS_ERROR) {
Current language:  auto; currently c
(gdb) bt
#0  0x084bc409 in trx_sig_send (trx=0x4224a468, type=1, sender=1,
    receiver_thr=0x4224f138, savept=0x0, next_thr=0x0) at trx0trx.c:1297
#1  0x084b7ec8 in trx_rollback_step (thr=0x4224f138) at trx0roll.c:1325
#2  0x0847f9a8 in que_thr_step (thr=0x4224f138) at que0que.c:1196
#3  0x0847fa55 in que_run_threads (thr=0x4224f138) at que0que.c:1248
#4  0x084b6120 in trx_general_rollback_for_mysql (trx=0x4224a468, partial=0,
    savept=0x0) at trx0roll.c:82
#5  0x084b6251 in trx_rollback_for_mysql (trx=0x4224a468) at trx0roll.c:133
#6  0x0830e7f5 in innobase_rollback_trx (trx=0x4224a468) at ha_innodb.cc:1892
#7  0x08316831 in innobase_rollback_by_xid (xid=0x8dfc2b8) at ha_innodb.cc:7259
#8  0x082f7eca in ha_recover (commit_list=0x0) at handler.cc:1050
#9  0x0821621c in init_server_components () at mysqld.cc:3134
#10 0x08216657 in main (argc=1, argv=0xbffffb34) at mysqld.cc:3427
(gdb)

The bug found: when InnoDB rolled back a prepared transaction in XA recovery, the transaction object did not have an InnoDB 'session' object. That caused a seg fault. Fix: use a dummy session object just like in trx_rollback_all_without_sess() in trx0roll.c.

I will post the patch to http://bugs.mysql.com/bug.php?id=21468