MySQL Bugs: #48192: MySQL Crash (InnoDB: We intentionally generate a memory trap.)

Bug #48192	MySQL Crash (InnoDB: We intentionally generate a memory trap.)
Submitted:	20 Oct 2009 18:05	Modified:	17 Jul 2010 11:47
Reporter:	Tony Weber	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	5.0.86-enterprise-nt-log	OS:	Windows (XP Pro and 2003 Server)
Assigned to:		CPU Architecture:	Any

Description:
MySQL Crash.  Partial error log is shown below.  This happened in both MySQL 4.1.22 and 5.0.86 Enterprise.  It happened on several machines.  Windows XP Pro and Windows 2003 server.  It takes 1-2 days of running to reproduce it.  I will upload the initial database and the error log and the general query log.  

=====================================
091018 22:07:27 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 16 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 8459, signal count 8456
--Thread 5156 has waited at .\btr\btr0cur.c line 424 for 944.00 seconds the semaphore:
S-lock on RW-latch at 0B8BB4FC created in file .\buf\buf0buf.c line 497
a writer (thread id 5156) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1
Last time read locked in file .\buf\buf0flu.c line 585
Last time write locked in file .\btr\btr0sea.c line 792
Mutex spin waits 0, rounds 58875, OS waits 419
RW-shared spins 19573, OS waits 7785; RW-excl spins 256, OS waits 255
------------
TRANSACTIONS
------------
Trx id counter 0 376712
Purge done for trx's n:o < 0 376695 undo n:o < 0 0
History list length 42
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 376711, ACTIVE 944 sec, OS thread id 5156 inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
1 lock struct(s), heap size 320
MySQL thread id 2, query id 121862 localhost 127.0.0.1 root update
INSERT INTO `Event_Log` (`_MLogID`,`_MControlCode`,`_MNodeID`,`_MObjState`,`_MSupport`,`Test`,`_Mdate`,`_Mtime`,`_Mpath`) VALUES(387095,NULL,2928,1,NULL,0,"2009-10-18","21:51:43",NULL)
--------
FILE I/O
--------
I/O thread 0 state: wait Windows aio (insert buffer thread)
I/O thread 1 state: wait Windows aio (log thread)
I/O thread 2 state: wait Windows aio (read thread)
I/O thread 3 state: wait Windows aio (write thread)
Pending normal aio reads: 0, aio writes: 1,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
56522 OS file reads, 111700 OS file writes, 78321 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 266, seg size 268,
73 inserts, 73 merged recs, 70 merges
Hash table size 676649, used cells 42863, node heap has 45 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 1 3319786942
Log flushed up to   1 3319786942
Last checkpoint at  1 3319780010
0 pending log writes, 0 pending chkp writes
49575 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 189859432; in additional pool allocated 1800448
Buffer pool size   10432
Free buffers       0
Database pages     10387
Modified db pages  7
Pending reads 0
Pending writes: LRU 0, flush list 7, single page 0
Pages read 56475, created 1540, written 54889
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
--------------
ROW OPERATIONS
--------------
1 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread id 1460, state: flushing buffer pool pages
Number of rows inserted 25673, updated 18700, deleted 0, read 9950135
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Error: semaphore wait has lasted > 600 seconds
InnoDB: We intentionally crash the server, because it appears to be hung.
091018 22:07:37InnoDB: Assertion failure in thread 5008 in file .\srv\srv0srv.c line 2112
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.0/en/forcing-recovery.html
InnoDB: about forcing recovery.
091018 22:07:37 - mysqld got exception 0xc0000005 ;
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=88080384
read_buffer_size=65536
max_used_connections=7
max_connections=100
threads_connected=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 118016 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=00000000
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...
InnoDB: Thread 2008 stopped in file .\os\os0sync.c line 269
00653645    mysqld-nt.exe!srv_error_monitor_thread()[srv0srv.c:2112]
7C80B729    kernel32.dll!GetModuleFileNameA()
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

How to repeat:
Restore the initial databases (vfs and newsdd).  Run our Virtual Factory application for 1-2 days.

I uploaded the error log and general query log to
ftp://ftp.mysql.com/pub/mysql/upload/bug48192-logs.zip

I uploaded the initial databases to
ftp://ftp.mysql.com/pub/mysql/upload/bug48192-initial-databases.zip

The test case was clean: restore the initial databases (`vfs` and `newsdd`), run our Virtual Factory application for about 31 hours.  All queries after the restore are shown.

Thank you for the problem report. Please, send your my.ini file content, the resuslt of SHOW GLOBAL STATUS and describe your hardware.

Server was waiting too long for a buffer pool flush. So it was intentionally crashed. I'd say this is more a misconfiguration for your load than a bug.

I'd also recommend to upgrade to 5.0.86 at least.

Sorry, ignore my last suggestion. You are on 5.0.86 already it seems. Had you tried 5.1.x already?

my.ini and SHOW GLOBAL STATUS

Attachment: showglobalstatus.zip (application/x-zip-compressed, text), 6.28 KiB.

Machine name: VFS-SERVER
   Operating System: Windows XP Professional (5.1, Build 2600) Service Pack 3 (2600.xpsp_sp3_gdr.090206-1234)
           Language: Japanese (Regional Setting: Japanese)
System Manufacturer: NEC
       System Model: Express5800/51Lb [N8000-503]
               BIOS: Default System BIOS
          Processor: Intel(R) Pentium(R) 4 CPU 2.40GHz
             Memory: 1016MB RAM
          Page File: 617MB used, 1828MB available
        Windows Dir: C:\WINDOWS

See bug: http://bugs.mysql.com/bug.php?id=25506.

Can you, please, try to monitor IO writes using perfmon during high load periods before the crash? Had you checked that older bug report Miguel had found, for some workaround ideas/similarities?

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".

Others have reported this issue with InnoDB when innodb_file_per_table is on under Windows.  For example http://bugs.mysql.com/bug.php?id=25506. We also have BLOB data and at some point InnoDB starts heavy I/O thrashing, resulting in simple queries being blocked for over 10 minutes.  This results in InnoDB crashing itself.  Some others reported the issue happening when anti-virus or file indexing services are turned on (and therefore trying to read the tablespace file), but I verified that this is not our situation.  The situation does not occur when innodb_file_per_table is off.  This is our current work-around.

If you still have a chance, please, check if this still happens with a newer version, 5.0.91 or, even better, 5.1.48.

Bug #54720 could be a duplicate of this bug here.

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".