Bug #69312 InnoDB: Assertion failure in thread 47585491499328 in file btr0pcur.c line 250
Submitted: 24 May 2013 13:40 Modified: 28 Apr 2015 12:10
Reporter: Ignacio Coterillo Coz Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:5.5.30 OS:Linux (RHEL 5.9)
Assigned to: CPU Architecture:Any
Tags: innodb

[24 May 2013 13:40] Ignacio Coterillo Coz
Description:
Spontaneously happened during a shutdown operation. The following error message was logged at the tail of the binlog.index file, causing an error when trying to re-start the server afterwards:

--------------------- Appended at the tail of binlog.index -----------------
09:46:42 UTC - mysqld got signal 6 ;
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=268435456
read_buffer_size=131072
max_used_connections=215
max_threads=1000
thread_count=58
---------------------------------------------------------------------

This was recorded in the error log:
------------------------- Error output ------------------------------
130524 11:46:42  InnoDB: Assertion failure in thread 47585491499328 in file btr0pcur.c line 250
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.5/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
130524 11:46:47 mysqld_safe Number of processes running now: 0
130524 11:46:47 mysqld_safe mysqld restarted
130524 11:46:48 [Warning] Changed limits: max_open_files: 1024  max_connections: 214  table_cache: 400
130524 11:46:48 [ERROR] An old style --language value with language specific part detected: /usr/local/mysql/mysql-5.5.30/share/english/
130524 11:46:48 [ERROR] Use --lc-messages-dir without language specific part instead.
130524 11:46:48 [Note] Plugin 'FEDERATED' is disabled.
130524 11:46:48 InnoDB: The InnoDB memory heap is disabled
130524 11:46:48 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130524 11:46:48 InnoDB: Compressed tables use zlib 1.2.3
130524 11:46:48 InnoDB: Using Linux native AIO
130524 11:46:48 InnoDB: Initializing buffer pool, size = 40.0G
130524 11:46:51 InnoDB: Completed initialization of buffer pool
130524 11:46:51 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 6015042515350
130524 11:46:52  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...
InnoDB: Doing recovery: scanned up to log sequence number 6015047757824
InnoDB: Doing recovery: scanned up to log sequence number 6015053000704
InnoDB: Doing recovery: scanned up to log sequence number 6015058243584
InnoDB: Doing recovery: scanned up to log sequence number 6015063486464
InnoDB: Doing recovery: scanned up to log sequence number 6015065521503
130524 11:47:11  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 920383611, file name /ORA/dbs02/HC_ATLAS/mysql/binlog.007299
130524 11:47:18  InnoDB: Waiting for the background threads to start
130524 11:47:19 InnoDB: 5.5.30 started; log sequence number 6015065521503
^G/usr/local/mysql/mysql-5.5.30/bin/mysqld: File '/ORA/dbs02/HC_ATLAS/mysql/something is definitely wrong and this may fail.' not found (Errcode: 2)
130524 11:47:19 [ERROR] Failed to open log (file '/ORA/dbs02/HC_ATLAS/mysql/something is definitely wrong and this may fail.', errno 2)
130524 11:47:19 [ERROR] Could not open log file
130524 11:47:19 [ERROR] Can't init tc log
130524 11:47:19 [ERROR] Aborting
-------------------------------------------------------------------------

How to repeat:
Not sure. It's the first time we have found this behavior.

Suggested fix:
Removing the error message output from the binlog.index file allows the server to boot.
[24 May 2013 14:42] MySQL Verification Team
Thank you for the bug report. If that happens again please try version 5.5.31. Thanks.
[26 May 2013 5:36] MySQL Verification Team
the reason for asking to test 5.5.31 is we believe this is the same problem reported in http://bugs.mysql.com/bug.php?id=68051
[25 Jun 2013 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".
[28 Apr 2015 11:19] Robert Roth
I can confirm Shane Bester's hunch on this one being a duplicate of http://bugs.mysql.com/bug.php?id=68051.
We've also had this on 5.5.30, on FreeBSD, with most of our tables being InnoDB, , and the crash was caused by killing a slow query started from the mysql console, which makes 68051 even more suspect.

Relevant log:

 len 224; hex 78de2b6d18000000aab2f4591700000000bb29500b00000000000000000000000000000000000000000000000000000003000000000000000300000000000000010000000000000000000000000000000000000000000000000000000000000000000000000000000100000000000000b88b15102d0100000000000000000000010000000000000083445107000000007ed74472180000000200000000000000010000000000000000bb29500b000000020000000000000060e11177000000000200000000000000787ecf7d1800000078d74472180000001800000000000000; asc x +m       Y      )P                                                                                                -                    DQ     ~ Dr                      )P            `  w            x~ }    x Dr            ;
TRANSACTION 5E6F9BF97, ACTIVE 8 sec fetching rows, thread declared inside InnoDB 255
mysql tables in use 2, locked 0
MySQL thread id 4195463, OS thread handle 0x186fa5c800, query id 3598715788 localhost root preparing
select 'POWEROFF', event_timestamp, resource_id, resourcepos_id, 1, meter_counter from resourcepos where resource_id=10745 and event_type='powerOnEvent' and resourcepos_id not in (select position_id from event_backlog where resource_id=10745)
150428 12:40:48  InnoDB: Assertion failure in thread 104952350720 in file btr0pcur.c line 250
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.5/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
10:40:48 UTC - mysqld got signal 6 ;
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=12884901888
read_buffer_size=4194304
max_used_connections=303
max_threads=800
thread_count=38
connection_count=38
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 17507012 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.