Bug #64050 MySql Crash
Submitted: 17 Jan 2012 13:39 Modified: 4 Mar 2012 8:05
Reporter: Christos Pavlides Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server Severity:S1 (Critical)
Version:5.5.20 OS:Windows (2008R2 x64)
Assigned to: CPU Architecture:Any
Tags: 5.5.20, crash, MySQL

[17 Jan 2012 13:39] Christos Pavlides
Description:
MySql Crashes unexpectetly on Windows 2008R2 x64 with MySql version 5.5.20.
The issue started occuring after an upgrade from 5.5.15 using the msi file.

This is the windows log:
Faulting application name: mysqld.exe, version: 5.5.20.0, time stamp: 0x4eebaeb7
Faulting module name: mysqld.exe, version: 5.5.20.0, time stamp: 0x4eebaeb7
Exception code: 0xc0000005
Fault offset: 0x000000000002bbb1
Faulting process id: 0x418
Faulting application start time: 0x01ccd4f86b5e31fa
Faulting application path: C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld.exe
Faulting module path: C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld.exe
Report Id: 81a16416-40f2-11e1-b3db-78e7d1df5f20

The error log:

120116 15:24:20 [Note] C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld: ready for connections.
Version: '5.5.20-log'  socket: ''  port: 3306  MySQL Community Server (GPL)
120116 15:24:36 [Note] Start binlog_dump to slave_server(1), pos(ibin.000122, 2336124)
120117  3:39:46 [Warning] Aborted connection 5 to db: 'pppp' user: 'host' host: '192.168.10.10' (Got timeout reading communication packets)
120117 11:13:28 [Note] Start binlog_dump to slave_server(0), pos(ibin.000123, 13459554)
120117 11:14:30 [Note] Plugin 'FEDERATED' is disabled.
120117 11:14:30 InnoDB: The InnoDB memory heap is disabled
120117 11:14:30 InnoDB: Mutexes and rw_locks use Windows interlocked functions
120117 11:14:30 InnoDB: Compressed tables use zlib 1.2.3
120117 11:14:30 InnoDB: Initializing buffer pool, size = 16.0G
120117 11:14:31 InnoDB: Completed initialization of buffer pool
120117 11:14:31 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 180587623058
120117 11:14:32  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 180587629412
120117 11:14:34  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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 55712333, file name .\ibin.000123
120117 11:14:37  InnoDB: Waiting for the background threads to start
120117 11:14:38 InnoDB: 1.1.8 started; log sequence number 180587629412
120117 11:14:38 [Note] Recovering after a crash using ibin
120117 11:14:38 [Note] Starting crash recovery...
120117 11:14:38 [Note] Crash recovery finished.
120117 11:14:38 [Note] Slave SQL thread initialized, starting replication in log '1bin.000119' at position 118357656, relay log '.\irelay.000354' position: 11571984
120117 11:14:38 [Note] Event Scheduler: Loaded 1 event
120117 11:14:38 [Note] Slave I/O thread: connected to master 'repl@192.168.10.21:3306',replication started in log 'ibin.000119' at position 118357656
120117 11:14:38 [Note] C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld: ready for connections.
Version: '5.5.20-log'  socket: ''  port: 3306  MySQL Community Server (GPL)
120117 11:14:51 [Note] Start binlog_dump to slave_server(1), pos(ibin.000123, 55712333)
120117 12:03:30 [Note] Start binlog_dump to slave_server(0), pos(ibin.000124, 13459554)
120117 12:04:31 [Note] Plugin 'FEDERATED' is disabled.
120117 12:04:31 InnoDB: The InnoDB memory heap is disabled
120117 12:04:31 InnoDB: Mutexes and rw_locks use Windows interlocked functions
120117 12:04:31 InnoDB: Compressed tables use zlib 1.2.3
120117 12:04:31 InnoDB: Initializing buffer pool, size = 16.0G
120117 12:04:32 InnoDB: Completed initialization of buffer pool
120117 12:04:32 InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
120117 12:04:33  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: Last MySQL binlog file position 0 1699946, file name .\ibin.000124
120117 12:04:34  InnoDB: Waiting for the background threads to start
120117 12:04:35 InnoDB: 1.1.8 started; log sequence number 180590093939
120117 12:04:35 [Note] Recovering after a crash using bin
120117 12:04:35 [Note] Starting crash recovery...
120117 12:04:35 [Note] Crash recovery finished.
120117 12:04:35 [Note] Slave SQL thread initialized, starting replication in log 'ibin.000119' at position 119987952, relay log '.\irelay.000356' position: 41642
120117 12:04:35 [Note] Slave I/O thread: connected to master 'repl@192.168.10.21:3306',replication started in log 'ibin.000119' at position 119987952
120117 12:04:35 [Note] Event Scheduler: Loaded 1 event
120117 12:04:35 [Note] C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld: ready for connections.
Version: '5.5.20-log'  socket: ''  port: 3306  MySQL Community Server (GPL)
120117 12:04:52 [Note] Start binlog_dump to slave_server(1), pos(ibin.000124, 1699946)

How to repeat:
Not sure
[17 Jan 2012 13:46] Christos Pavlides
The version before the upgrade was 5.5.11
[19 Jan 2012 7:02] Valeriy Kravchuk
When exactly this crash happened? I do not see any error messages explaining crash in that fragment of error log that you presented.
[19 Jan 2012 10:01] Christos Pavlides
Unfortunately the server crashes randomly. I have a feeling it might be data coruption since the other servers in the replication topology work fine up to now. Since check table is not very reliable with innodb how can I verify that the tables and indexes are not corrupted?
[19 Jan 2012 17:48] Sveta Smirnova
Thank you for the feedback.

CHECK TABLE works with InnoDB, it just shuts down the server if find error. But as server crashes every time anyway this probably would work for you. Otherwise you can SELECT or try to modify your tables, but this method is not 100% reliable.
[20 Jan 2012 16:33] Christos Pavlides
Ok I checked all tables and the results where ok, no errors found. What else can I do to troubleshoot the issue?
[23 Jan 2012 20:10] Sveta Smirnova
Thank you for the feedback.

Looks like crashes happen not in predictable order. Turn general query log to on and try to catch query issued prior the crash.
[24 Jan 2012 7:30] Christos Pavlides
Thank you Sveta for your comments. I will do that and let you know. I have one more question though. Does the check table alter anything during its checks or is it a read only operation for innodb? I am asking this since after I run the check table on all tables the server stopped crashing. Ofcourse I only have the replication traffic going to it and nothing else but before I did the check table, it was crashing with the same traffic. I will also try to use it a little more and see what happens.
[24 Jan 2012 18:18] Sveta Smirnova
Thank you for the feedback.

We will wait if you see crashes again.

Regarding to read-only or not, please, check error log file: CHECK TABLE not always crashes server, but you can have few records explaining if it found something wrong with the tables.
[1 Feb 2012 17:49] Christos Pavlides
Ok it crashed again today. I had a session connected to monitor the server through a third party tool for a few days. As soon as I closed that the server crashed. Therefore I assume that this issue might be related to connection closing.
The event log had this entry:
Faulting application name: mysqld.exe, version: 5.5.20.0, time stamp: 0x4eebaeb7
Faulting module name: mysqld.exe, version: 5.5.20.0, time stamp: 0x4eebaeb7
Exception code: 0xc0000005
Fault offset: 0x000000000002bbb1
Faulting process id: 0x2b4
Faulting application start time: 0x01ccd6290049e8a6
Faulting application path: C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld.exe
Faulting module path: C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld.exe
Report Id: 65ed4ad9-4cfa-11e1-b3db-78e7d1df5f20

The wer report file created for this has the following data:
Version=1
EventType=APPCRASH
EventTime=129725910147154527
ReportType=2
Consent=1
ReportIdentifier=65ed4ada-4cfa-11e1-b3db-78e7d1df5f20
IntegratorReportIdentifier=65ed4ad9-4cfa-11e1-b3db-78e7d1df5f20
Response.type=4
Sig[0].Name=Application Name
Sig[0].Value=mysqld.exe
Sig[1].Name=Application Version
Sig[1].Value=5.5.20.0
Sig[2].Name=Application Timestamp
Sig[2].Value=4eebaeb7
Sig[3].Name=Fault Module Name
Sig[3].Value=mysqld.exe
Sig[4].Name=Fault Module Version
Sig[4].Value=5.5.20.0
Sig[5].Name=Fault Module Timestamp
Sig[5].Value=4eebaeb7
Sig[6].Name=Exception Code
Sig[6].Value=c0000005
Sig[7].Name=Exception Offset
Sig[7].Value=000000000002bbb1
DynamicSig[1].Name=OS Version
DynamicSig[1].Value=6.1.7601.2.1.0.274.10
DynamicSig[2].Name=Locale ID
DynamicSig[2].Value=1033
DynamicSig[22].Name=Additional Information 1
DynamicSig[22].Value=ed4a
DynamicSig[23].Name=Additional Information 2
DynamicSig[23].Value=ed4a501691819ff5b828cdee7dc945fe
DynamicSig[24].Name=Additional Information 3
DynamicSig[24].Value=d23a
DynamicSig[25].Name=Additional Information 4
DynamicSig[25].Value=d23a32deb7121eacdb88c12139461400
UI[2]=C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld.exe
UI[5]=Check online for a solution (recommended)
UI[6]=Check for a solution later (recommended)
UI[7]=Close
UI[8]=mysqld.exe stopped working and was closed
UI[9]=A problem caused the application to stop working correctly. Windows will notify you if a solution is available.
UI[10]=&Close
LoadedModule[0]=C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld.exe
LoadedModule[1]=C:\Windows\SYSTEM32\ntdll.dll
LoadedModule[2]=C:\Windows\system32\kernel32.dll
LoadedModule[3]=C:\Windows\system32\KERNELBASE.dll
LoadedModule[4]=C:\Windows\system32\ADVAPI32.dll
LoadedModule[5]=C:\Windows\system32\msvcrt.dll
LoadedModule[6]=C:\Windows\SYSTEM32\sechost.dll
LoadedModule[7]=C:\Windows\system32\RPCRT4.dll
LoadedModule[8]=C:\Windows\system32\Secur32.dll
LoadedModule[9]=C:\Windows\system32\SSPICLI.DLL
LoadedModule[10]=C:\Windows\system32\dbghelp.dll
LoadedModule[11]=C:\Windows\system32\USER32.dll
LoadedModule[12]=C:\Windows\system32\GDI32.dll
LoadedModule[13]=C:\Windows\system32\LPK.dll
LoadedModule[14]=C:\Windows\system32\USP10.dll
LoadedModule[15]=C:\Windows\system32\WS2_32.dll
LoadedModule[16]=C:\Windows\system32\NSI.dll
LoadedModule[17]=C:\Windows\system32\IMM32.DLL
LoadedModule[18]=C:\Windows\system32\MSCTF.dll
LoadedModule[19]=C:\Windows\system32\NLAapi.dll
LoadedModule[20]=C:\Windows\system32\napinsp.dll
LoadedModule[21]=C:\Windows\System32\mswsock.dll
LoadedModule[22]=C:\Windows\system32\DNSAPI.dll
LoadedModule[23]=C:\Windows\System32\winrnr.dll
LoadedModule[24]=C:\Windows\System32\wship6.dll
LoadedModule[25]=C:\Windows\System32\wshtcpip.dll
FriendlyEventName=Stopped working
ConsentKey=APPCRASH
AppName=mysqld.exe
AppPath=C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld.exe

I am not sure if this is of any use to you but I would appreciate any comments.
[1 Feb 2012 20:39] Sveta Smirnova
Thank you for the feedback.

Have you turned general query log to on before crash? Can we get the query which crashes or full log compressed?

Please also check if you run mysql_upgrade after upgrade. If you did not run now.
[1 Feb 2012 23:08] Christos Pavlides
I have run the mysql_upgrade and everything was ok. It seems that the problem happens when an external process is doing auditing by reading the binlog. Everytime an important change happens on the server such as create index, create table, drop table etc we have an external process that automatically kicks in and reads the binlog of one of the slaves in order to find out what the change was.
It seems that everytime it tries to do that the server crashes. This process is working for well over a year now and I am not sure what could have caused the crash. In any case the server should not crash.
See below an extract of the general query log such before the server crashes.

"2012-02-02 00:40:35"	"[user] @  [x.x.x.x]"	"28"	"2"	"Connect"	"user@x.x.x.x on imsp_coredb"
"2012-02-02 00:40:35"	"user[user] @  [x.x.x.x]"	"28"	"2"	"Query"	"SHOW VARIABLES"
"2012-02-02 00:40:35"	"user[user] @  [x.x.x.x]"	"28"	"2"	"Query"	"SHOW COLLATION"
"2012-02-02 00:40:36"	"user[user] @  [x.x.x.x]"	"28"	"2"	"Query"	"SET NAMES utf8"
"2012-02-02 00:40:36"	"user[user] @  [x.x.x.x]"	"28"	"2"	"Query"	"SET character_set_results=NULL"
"2012-02-02 00:40:36"	"user[user] @  [x.x.x.x]"	"28"	"2"	"Init DB"	"imsp_coredb"
"2012-02-02 00:40:36"	"user[user] @  [x.x.x.x]"	"28"	"2"	"Query"	"SHOW MASTER STATUS"
"2012-02-02 00:40:36"	"[user] @  [x.x.x.x]"	"29"	"2"	"Connect"	"user@x.x.x.x on "
"2012-02-02 00:40:36"	"user[user] @  [x.x.x.x]"	"29"	"2"	"Query"	"SELECT VERSION()"
"2012-02-02 00:40:36"	"user[user] @  [x.x.x.x]"	"29"	"2"	"Binlog Dump"	"Log: 'xxxx_bin.000130'  Pos: 664553219"
[3 Feb 2012 18:06] Valeriy Kravchuk
Please, check if that position:

'xxxx_bin.000130'  Pos: 664553219"

exists in the binary log. See bug #64035.
[4 Mar 2012 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".
[4 Mar 2012 8:05] Christos Pavlides
Issue was related to #64035.
After upgrading to 5.5.21 the issue is now corrected