Bug #4159 Ciritical Innodb shutdown ( about ha_innodb.cc )
Submitted: 16 Jun 2004 4:17 Modified: 9 Sep 2004 16:44
Reporter: Lee HeeWon Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:4.0.20-max binary OS:Linux (Linux version 2.4.20-31.9smp)
Assigned to: Heikki Tuuri CPU Architecture:Any

[16 Jun 2004 4:17] Lee HeeWon
Description:
===== CASE 1 (host.err) ====================================================================================
InnoDB: Error: Mem area size is 0. Possibly a memory overrun of the
InnoDB: previous allocated area!
InnoDB: Apparent memory corruption: mem dump  len 500; hex bffebeeeb0adbbfdc0dbc7b0b0a8bbf33bc7cfb5e5bab9bff83bbbe7c1f8bab9b1b83bbbe7c1f8bab9bff83bb3ebc6aebacfbab9b1b83bbcadb9f6bab9b1b83bc4c4c7bbc5cdbcf6b8ae3b64617461bab9b1b83bc6f7b8e4bab9b1b83bc6c4c6bcbcc7bab9b1b83bbbe8c1a6bab9bff83b3bb8edc7b03be42e2e8100000000000000000000005c5d504e9268a520773073656c2e6300a308000000000000000000000000000000000000000000007000000000000000000000005000000040000000000000009766504e010000000000000001000000ceb3aab0a82031bdc3bfa120b5e9beeebfc2b4d9c7d42e0d0a0d0ab8deb8f0b3b2b1e82e800000000000000000000000b520c1d99268a520773073656c2e6300a308000000000000000000000000000000000000000000007000000000000000000000007000000040000000000000002920bec8c7d7b0f8b1c720bdbac6f9bcad35c0a720b3bbc0cfbacec5cd20b9ddbfb5bfe4c3bbb5e5b8b3b4cfb4d92e2ecfb4d92e000100000000000000000000a120b1a4b307952d30706375722e63001c0000000100000028c6134428c613440000000000000000a80000000000000000000000a80000004000000000000000fbbfebb568722b45581df54801000000806252450100000002000000010000000000000000000000070000000100; asc                 ;        ;        ;        ;          ;        ;          ;data    ;        ;          ;        ;;    ; ..            \]PN h  r0sea.c                         P           P   @        fPN                  1               .            .                 h  w0sel.c                         p           p   @       )                5                            ..   .                   -0pcur.c         (  D(  D                        @           hr+EX  H     bRE                          ;
InnoDB: Scanning backward trying to find previous allocated mem blocks
Freed mem block at - 112, file r0sea.c, line 496
Mem block at - 368, file w0sel.c, line 2211
Mem block at - 1392, file w0sel.c, line 2276
Freed mem block at - 3440, file 0vers.c, line 343
Mem block at - 5488, file mysql.c, line 348
Mem block at - 7536, file w0sel.c, line 2211
Mem block at - 9584, file w0ins.c, line 82
Mem block at - 13680, file w0sel.c, line 2558
Freed mem block at - 15728, file w0sel.c, line 2211
Mem block at - 17776, file w0sel.c, line 2558
InnoDB: Scanning forward trying to find next allocated mem blocks
Freed mem block at + 16, file w0sel.c, line 2211
Mem block at + 144, file 0pcur.c, line 28
Mem block at + 400, file w0sel.c, line 2211
Mem block at + 656, file w0sel.c, line 2276
Mem block at + 1168, file x0trx.c, line 80
Freed mem block at + 1680, file 0data.c, line 150
Mem block at + 2704, file mysql.c, line 348
Mem block at + 6800, file mysql.c, line 348
Freed mem block at + 8848, file 0vers.c, line 343
Freed mem block at + 10896, file 0vers.c, line 343
040615 12:05:21InnoDB: Assertion failure in thread 2058263344 in file mem0pool.c line 495
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. See section 6.1 of
InnoDB: http://www.innodb.com/ibman.php about forcing recovery.
InnoDB: Thread 2056657712 stopped in file ../../innobase/buf/../include/sync0sync.ic line 111
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=402653184
read_buffer_size=2093056
max_used_connections=76
max_connections=512
threads_connected=52
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 2488316 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=0x7a81b570
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=0x7aae8674, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x80d9110
0x4003f8f8
0x7aae8afc
0x821a22e
0x821e167
0x813a614
0x813a6f0
0x810750d
0x8106bd7
0x8106b81
0x8106861
0x80fded3
0x80fca46
0x80e3fca
0x80e798a
0x80e3063
0x80e2abd
0x80e22e8
InnoDB: Thread 2061699888 stopped in file ha_innodb.cc line 423
0x4003a484
0x420df147
New value of fp=(nil) failed sanity check, terminating stack trace!
Please read http://www.mysql.com/doc/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
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x8ae6b38 = SELECT ic.m_idx, ic.m_url, ic.m_category_idx, ic.m_service_type, ic.m_keyword,
						ic.m_company, ic.m_name, ic.m_phone, ic.m_email, ic.m_title, 
						ic.m_content, ic.m_result_content, ic.m_result_note, 
						ic.m_response_status, ic.m_client_status, 
						ic.m_price, ic.m_type, m.m_name m_tmr_name, ic.m_reg_time, c.m_record_file, ic.m_cti_id, ic.m_cti_phone,
						ic.m_response_member_idx, ic.m_response_time,
						ic.m_user_file, ic.m_user_file_url, ic.m_recall_parent_idx, ic.m_flag
					FROM m_inbound_call ic,
						m_call c, m_member m
					WHERE c.m_idx = ic.m_call_idx AND ic.m_member_idx = m.m_idx
					AND (ic.m_url = 'http://www.simbi.co.kr'; OR ic.m_url = 'http://www.simbi.co.kr/'; OR ic.m_url = 'www.simbi.co.kr' OR ic.m_url = 'www.simbi.co.kr/' OR ic.m_url = 'http://simbi.co.kr'; OR ic.m_url = 'http://simbi.co.kr/'; OR ic.m_url = InnoDB: Thread 1639316272 stopped in file ha_innodb.cc line 423
'simbi.co.kr' OR ic.m_url = 'simbi.co.kr/') ORDER BY m_idx DESC
thd->thread_id=27035
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.

===== CASE 1 (innodb.status) ====================================================================================
=====================================
040615 12:05:18 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 16 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 679813, signal count 446978
Mutex spin waits 430143881, rounds 250424704, OS waits 238641
RW-shared spins 1210417, OS waits 291839; RW-excl spins 1728266, OS waits 33594
------------
TRANSACTIONS
------------
Trx id counter 0 3177113
Purge done for trx's n:o < 0 3176627 undo n:o < 0 0
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 3177111, not started, process no 4605, OS thread id 1639316272
MySQL thread id 890, query id 1480452 Has read all relay log; waiting for the I/O slave thread to update it
---TRANSACTION 0 3177112, ACTIVE 0 sec, process no 4605, OS thread id 2057059120, thread declared inside InnoDB 361
mysql tables in use 2, locked 0
MySQL thread id 27009, query id 1480455 localhost root Sending data
SELECT  
		s.m_idx, u.m_url, s.m_status
		FROM m_sales s, m_url u
		WHERE s.m_url_idx = u.m_idx
		AND ( u.m_url like 'http://114pc%'; OR  u.m_url like 'http://www.114pc%'; )
Trx read view will not see trx with id >= 0 3177113, sees < 0 3177103
---TRANSACTION 0 3177103, ACTIVE 1 sec, process no 4605, OS thread id 2058664752 starting index read, thread declared inside InnoDB 342
mysql tables in use 4, locked 0
MySQL thread id 27022, query id 1480415 localhost root Sending data
select count(TradeItem_ID) from  Trade, TradeItem, User, Keyword  
				WHERE Trade_ID = TradeItem_TradeID 
                AND Trade_UserID = User_ID  AND Keyword_ID = TradeItem_KeywordID  AND keyword_kname like '%Áß°íÄÄÇ»ÅÍ%'  AND TradeItem_Type = 10
Trx read view will not see trx with id >= 0 3177104, sees < 0 3176892
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
131106 OS file reads, 165333 OS file writes, 89794 OS fsyncs
13.00 reads/s, 19771 avg bytes/read, 8.31 writes/s, 7.37 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf for space 0: size 1, free list len 20, seg size 22,
12683 inserts, 12598 merged recs, 9807 merges
Hash table size 1593833, used cells 1097772, node heap has 1824 buffer(s)
141719.08 hash searches/s, 6448.66 non-hash searches/s
---
LOG
---
Log sequence number 1 86008628
Log flushed up to   1 86008628
Last checkpoint at  1 85947784
0 pending log writes, 0 pending chkp writes
79586 log i/o's done, 7.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 462835256; in additional pool allocated 4281344
Buffer pool size   24576
Free buffers       0
Database pages     22752
Modified db pages  228
Pending reads 0 
Pending writes: LRU 0, flush list 0, single page 0
Pages read 437962, created 716, written 94942
15.69 reads/s, 0.12 creates/s, 1.25 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
2 queries inside InnoDB, 0 queries in queue
Main thread process no. 4605, id 1639115568, state: sleeping
Number of rows inserted 64167, updated 26987, deleted 20723, read 3570753961
6.12 inserts/s, 0.31 updates/s, 0.12 deletes/s, 181588.09 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

===== CASE 2 (host.err) ====================================================================================
InnoDB: Error: Removing element from mem pool free list 7 though the
InnoDB: element is not marked free!
InnoDB: Apparent memory corruption: mem dump  len 500; hex b7ce20bfacc0e5bec8b3bb0d0a687474703a2f2f676f6f6467756469652e636f2e6b7220bfc0c7c2bfb9c1a4c0ccb6f3b0ed20bdcec0ccc6aebecbb7c1c1d6bdc92e2eb4e3b4e7c7d8b4deb6f3b0edc7d483a2698483a3757d83200d0a3e200d0a3e203e203e20b8aec7cfbfb4bdc0b4cfb4d92ed92efd290a008000000000000000984e4845303031209268a520773073656c2e6300a30800000000000000000000000000000000000000000000700000000000000000000000700000004000000000000000a120a1a1b9dab5e6bcf620bbe7c0e5202f203031362d3331322d31363433200d0a0d0a2d3e2031bdc3c0ccc8c420c0e7c5ebc8ad810000000000000000000000c0d3202f20c7c1b7ceb7ce20c6d0c5b0c1f620c1a6bec8bfb9c1a4c0d3d9b0edc7d40000000000005000000000000000000000005000000040000000000000000abcbab0c0fcc8ad20bacec0e7c1dfc0d3d4bec8b3bbc7d4b1a4b0edc8bfb0fa20bab0b7ce20bef8c0bdcfbcbcbfe47eb3bbe47e0001000000000000187f5245e5b8b2c0b307952d6d7973716c2e63005c01000004000000284f484528f013440000000028dc5045c00000000000000000000000400000004000000000000000bb20bec8d7a5c7f2d8c74ef2d9c949f2da43c7f2db4d4ef2dc5fc1f2dd61c0f2de6bbbf2df65c2f2e047c5f2e149; asc              http://goodgudie.co.kr                              ..                i   u}    >   > > >             . . )           NHE001  h  w0sel.c                         p           p   @                       / 016-312-1643     -> 1                            /                                    P           P   @                                                      ~   ~          RE       -mysql.c \       (OHE(  D    ( PE            @   @                 N   I  C   MN  _   a   k   e   G   I;
InnoDB: Scanning backward trying to find previous allocated mem blocks
Freed mem block at - 112, file w0sel.c, line 2211
Freed mem block at - 624, file w0sel.c, line 2211
Mem block at - 1136, file x0trx.c, line 80
Mem block at - 1648, file w0sel.c, line 2211
Mem block at - 2160, file x0trx.c, line 141
Mem block at - 2416, file w0sel.c, line 2211
Mem block at - 2672, file w0sel.c, line 2211
Mem block at - 3696, file mysql.c, line 348
Mem block at - 4720, file w0ins.c, line 82
Mem block at - 5744, file w0sel.c, line 2211
InnoDB: Scanning forward trying to find next allocated mem blocks
Mem block at + 144, file mysql.c, line 348
Mem block at + 400, file t0mem.c, line 46
Freed mem block at + 2448, file r0sea.c, line 1137
Mem block at + 3472, file t0mem.c, line 189
Mem block at + 3728, file w0ins.c, line 82
Mem block at + 3984, file 0pcur.c, line 28
Mem block at + 4240, file w0upd.c, line 289
Mem block at + 4496, file w0ins.c, line 82
Mem block at + 6544, file x0trx.c, line 156
Mem block at + 7056, file 0undo.c, line 1289
InnoDB: Probably a race condition because now the area is marked free!
040615 16:54:49InnoDB: Assertion failure in thread 2052393776 in file mem0pool.c line 378
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. See section 6.1 of
InnoDB: http://www.innodb.com/ibman.php about forcing recovery.
InnoDB: Thread 1640721200 stopped in file ../../innobase/btr/../include/sync0sync.ic line 111
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=402653184
read_buffer_size=2093056
max_used_connections=76
max_connections=512
threads_connected=54
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 2488316 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=0x7a285bf8
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=0x7a54f4a4, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x80d9110
0x4003f8f8
(nil)
0x821a65d
0x821e167
0x813a614
0x813a86f
0x812bff6
0x812b9c7
Stack trace seems successful - bottom reached
Please read http://www.mysql.com/doc/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
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x7ae88e90  is invalid pointer
thd->thread_id=44149
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.

===== CASE 2 (innodb.status) ====================================================================================
=====================================
040615 16:54:37 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 16 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 1251443, signal count 790802
Mutex spin waits 751482969, rounds 457821724, OS waits 437180
RW-shared spins 2290492, OS waits 547072; RW-excl spins 3322395, OS waits 66662
------------
TRANSACTIONS
------------
Trx id counter 0 3410952
Purge done for trx's n:o < 0 3410906 undo n:o < 0 0
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 3410934, not started, process no 17479, OS thread id 1639516976
MySQL thread id 2, query id 1652096 Has read all relay log; waiting for the I/O slave thread to update it
---TRANSACTION 0 3410951, ACTIVE 0 sec, process no 17479, OS thread id 2052995888 fetching rows, thread declared inside InnoDB 243
mysql tables in use 1, locked 0
MySQL thread id 44106, query id 1652144 localhost root Copying to tmp table
SELECT m_service_type, count(ic.m_idx) count FROM m_inbound_call ic, m_inbound_call_type ict WHERE ic.m_category_idx = ict.m_idx AND m_reg_time >= 1087138800 AND m_reg_time <= 1087225200 AND (ict.m_parent = '-1-12' OR ict.m_parent LIKE '%-1-12-%') GROUP BY m_service_type
Trx read view will not see trx with id >= 0 3410952, sees < 0 3410930
---TRANSACTION 0 3410930, ACTIVE 2 sec, process no 17479, OS thread id 2064599856 starting index read, thread declared inside InnoDB 393
mysql tables in use 4, locked 0
, holds adaptive hash latch
MySQL thread id 44100, query id 1652043 localhost root Sending data
SELECT count(s.m_idx) count FROM m_sales s, m_url u, m_member m, m_buyer b
		WHERE s.m_url_idx = u.m_idx AND s.m_member_idx = m.m_idx AND s.m_buyer_idx = b.m_idx
		AND 1 AND ( u.m_url LIKE '%www.caraudiox.com%' OR u.m_url like '%www.www.caraudiox.com%') AND s.m_reg_time <= '1087311599'
Trx read view will not see trx with id >= 0 3410931, sees < 0 3410931
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
215666 OS file reads, 170891 OS file writes, 86849 OS fsyncs
15.12 reads/s, 31346 avg bytes/read, 10.94 writes/s, 4.94 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf for space 0: size 1, free list len 5, seg size 7,
20078 inserts, 20072 merged recs, 16600 merges
Hash table size 1593833, used cells 1084847, node heap has 1785 buffer(s)
75953.94 hash searches/s, 4135.49 non-hash searches/s
---
LOG
---
Log sequence number 1 104836325
Log flushed up to   1 104836315
Last checkpoint at  1 104810621
0 pending log writes, 0 pending chkp writes
79231 log i/o's done, 4.44 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 462835256; in additional pool allocated 4285824
Buffer pool size   24576
Free buffers       0
Database pages     22791
Modified db pages  103
Pending reads 0 
Pending writes: LRU 0, flush list 0, single page 0
Pages read 693967, created 802, written 100826
28.94 reads/s, 0.00 creates/s, 7.50 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
2 queries inside InnoDB, 0 queries in queue
Main thread process no. 17479, id 1639115568, state: sleeping
Number of rows inserted 68204, updated 8722, deleted 1793, read 2543066531
3.12 inserts/s, 0.69 updates/s, 0.00 deletes/s, 90312.29 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

How to repeat:
I don't know.

Suggested fix:
Realy ciritical, please fix them.
[16 Jun 2004 11:04] Marko Mäkelä
Not enough information was provided for us to be able
to handle this bug. Please re-read the instructions at
http://bugs.mysql.com/how-to-report.php

If you can provide more information, feel free to add it
to this bug and change the status back to 'Open'.

Thank you for your interest in MySQL.

Additional info:

We need a repeatable test case. Has a hardware fault been ruled out (try e.g., memtest86)? Does the crash always occur when trying to execute the same query (SELECT ic.m_idx, ic.m_url, ...)?
[17 Jun 2004 19:48] Heikki Tuuri
Hi!

This is probably the bug that has been fixed in upcoming 4.0.21. See the InnoDB change notes of 4.0.21 in the MySQL online manual.

Thank you,

Heikki
[18 Jun 2004 4:11] Lee HeeWon
Hi, thanks of your comment.

===== CASE 1 ======
I read about InnoDB-4.0.21/change history. So I can check below issue.
I checked about innodb_additional_mem_pool_size variable of my.cnf, but it was 20M(innodb_buffer_pool_size = 384M) and allocated memory size of CASE 1 Status of attached file was 4281344.
So It was too plenty.
I don't think about the problem of this error was just size issue of innodb_additional_mem_pool_size.

===== CASE 2 ======
I think.. Case 2 was another problem.
-----CASE 2----------------------------------------------------------
InnoDB: Error: Removing element from mem pool free list 7 though the
InnoDB: element is not marked free!
InnoDB: Apparent memory corruption: mem dump  len 500; hex
---------------------------------------------------------------------
So something are different from Case 1 (Case 1 was announced by InnoDB-4.0.21/change history)
-----CASE 1----------------------------------------------------------
InnoDB: Error: Mem area size is 0. Possibly a memory overrun of the
InnoDB: previous allocated area!
InnoDB: Apparent memory corruption: mem dump  len 500; hex
---------------------------------------------------------------------

and I want to know how to optimize memory pool.

"BUFFER POOL AND MEMORY" Informarion of "Show Innodb Status" is too small to optimize memory.
[9 Sep 2004 16:06] Heikki Tuuri
Hi!

I had overlooked your last comment.

Yes, the innodb.status files suggest that the '4 billion bug' (fixed in upcoming 4.0.21) cannot explain this corruption problem.

The next suspect is hardware/drivers/OS, or some unknown InnoDB bug.

You are not using InnoDB heavily, the log sequence number is less than 8 GB.

Regards,

Heikki
[9 Sep 2004 16:44] Heikki Tuuri
Hi!

I had overlooked your last comment.

Yes, the innodb.status files suggest that the '4 billion bug' (fixed in upcoming 4.0.21) cannot explain this corruption problem.

The next suspect is hardware/drivers/OS, or some unknown InnoDB bug.

You are not using InnoDB heavily, the log sequence number is less than 8 GB.

Regards,

Heikki