This isn't a repeatable bug, but it is certainly a repeating one. We have issues on multiple machines running 4.0.20-Max-log with different data sets (in highly similar table structures) with InnoDB hanging and eventually crashing itself to get out of deadlock. Log is attached. There's only one InnoDB table in the database (rest are MyISAM). Its structure is:
CREATE TABLE session_data ( sid varchar(32) NOT NULL default '', session_data mediumtext NOT NULL, http_host varchar(255) NOT NULL default '', user varchar(32) NOT NULL default '', stamp datetime NOT NULL default '0000-00-00 00:00:00', PRIMARY KEY (sid), KEY http_host (http_host), KEY user (user) ) TYPE=InnoDB; -- Ian Gulliver Penguin Hosting "Failure is not an option; it comes bundled with your Microsoft products."
MySQL thread id 806227, query id 7467614 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='f697dfe1ccb2fddf0892d144a86d58bf'
---TRANSACTION 0 0, not started, process no 29469, OS thread id 1418817088 waiting in
InnoDB queue
mysql tables in use 1, locked 0
MySQL thread id 806226, query id 7467612 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='9200380a42dfd85e035865a845b61db2'
---TRANSACTION 0 0, not started, process no 29469, OS thread id 1422344512 waiting in
InnoDB queue
mysql tables in use 1, locked 0
MySQL thread id 806217, query id 7467599 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='4ee95161699670b944f62ff19a646270'
---TRANSACTION 0 0, not started, process no 29469, OS thread id 1420576192 waiting in
InnoDB queue
mysql tables in use 1, locked 0
MySQL thread id 806212, query id 7467587 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='1c60932c3eb0ef237397a295c6fd7b5d'
---TRANSACTION 0 0, not started, process no 29469, OS thread id 1413870528 waiting in
InnoDB queue
mysql tables in use 1, locked 0
MySQL thread id 806205, query id 7467575 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='a99ffb28fd5defe68eda15ab5bc9fb60'
---TRANSACTION 0 0, not started, process no 29469, OS thread id 1412495168 waiting in
InnoDB queue
mysql tables in use 1, locked 0
MySQL thread id 806201, query id 7467563 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='a5352dec66bfbcf1214a92f876661f6d'
---TRANSACTION 0 0, not started, process no 29469, OS thread id 1416821824 waiting in
InnoDB queue
mysql tables in use 1, locked 0
MySQL thread id 806193, query id 7467551 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='42129f31ba6456a9eb172948fb4ea3bd'
---TRANSACTION 0 0, not started, process no 29469, OS thread id 1439561920 waiting in
InnoDB queue
mysql tables in use 1, locked 0
MySQL thread id 806189, query id 7467539 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='cd924675587036968e63f7224f59e36f'
---TRANSACTION 0 6264628, ACTIVE 583 sec, process no 29469, OS thread id 1411119808
starting index read, thread declared inside InnoDB 500
mysql tables in use 1, locked 0
MySQL thread id 806164, query id 7467324 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='7e83e8ab037784d8193f7a0248b2990d'
---TRANSACTION 0 6264627, ACTIVE 586 sec, process no 29469, OS thread id 1414067008
starting index read, thread declared inside InnoDB 500
mysql tables in use 1, locked 0
MySQL thread id 806159, query id 7467312 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='37d046652a35c341c288dbc789f1d1c0'
---TRANSACTION 0 6264626, ACTIVE 590 sec, process no 29469, OS thread id 1416625344
starting index read, thread declared inside InnoDB 500
mysql tables in use 1, locked 0
MySQL thread id 806153, query id 7467300 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='7f511ae860c52a069fb457a8fb41b7fe'
---TRANSACTION 0 6264625, ACTIVE 590 sec, process no 29469, OS thread id 1401483712
starting index read, thread declared inside InnoDB 500
mysql tables in use 1, locked 0
MySQL thread id 806148, query id 7467288 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='3d548d965384247053f981e3cbad3323'
---TRANSACTION 0 6264624, ACTIVE 594 sec, process no 29469, OS thread id 1408770112
starting index read, thread declared inside InnoDB 500
mysql tables in use 1, locked 0
MySQL thread id 806144, query id 7467276 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='b044fd6bf5c596d76894df232b5df84a'
---TRANSACTION 0 6264623, ACTIVE 595 sec, process no 29469, OS thread id 1417214400
starting index read, thread declared inside InnoDB 500
mysql tables in use 1, locked 0
MySQL thread id 806140, query id 7467264 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='99999b291ae9fd1d351252dc6b9b94e6'
---TRANSACTION 0 6264622, ACTIVE 615 sec, process no 29469, OS thread id 1441723200
starting index read, thread declared inside InnoDB 500
mysql tables in use 1, locked 0
MySQL thread id 806136, query id 7467248 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid='4ee95161699670b944f62ff19a646270'
---TRANSACTION 0 6264621, ACTIVE 619 sec, process no 29469, OS thread id 1418226496
inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
1 lock struct(s), heap size 320, undo log entries 1
MySQL thread id 806132, query id 7467236 localhost downeast update
REPLACE INTO session_data (sid,session_data,http_host,user,stamp) VALUES
('88516d2e0c1859eae1c7b28816593398','real_order_num|N;real_temp_order_config_ids|N;temp_order_num|N;wishlist_order_num|N;temp_client_id|N;client_id|N;this_grand_total|N;first_name|N;last_name|N;is_guest|N;one_decline|N;order_ad
--------
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: 120,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
504 OS file reads, 167984 OS file writes, 116386 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 for space 0: size 1, free list len 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
Hash table size 138401, used cells 1902, node heap has 3 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 1 1766529219
Log flushed up to 1 1766519137
Last checkpoint at 1 1750951592
0 pending log writes, 0 pending chkp writes
99769 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 62133604; in additional pool allocated 1764864
Buffer pool size 2048
Free buffers 0
Database pages 2045
Modified db pages 1559
Pending reads 0
Pending writes: LRU 120, flush list 0, single page 0
Pages read 420, created 2434, written 83270
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
--------------
ROW OPERATIONS
--------------
8 queries inside InnoDB, 56 queries in queue
Main thread process no. 29469, id 1261676992, state: waiting for server activity
Number of rows inserted 5548, updated 85336, deleted 5570, read 368408
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: Warning: a long semaphore wait:
--Thread 1441723200 has waited at btr0cur.c line 346 for 625.00 seconds the semaphore:
S-lock on RW-latch at 0x4094f2bc created in file dict0dict.c line 3397
a writer (thread id 1418226496) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file btr0cur.c line 346
Last time write locked in file btr0cur.c line 339
InnoDB: Error: semaphore wait has lasted > 600 seconds
InnoDB: We intentionally crash the server, because it appears to be hung.
040927 9:39:49InnoDB: Assertion failure in thread 1253288512 in file sync0arr.c line
925
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.
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=134217728
read_buffer_size=131072
max_used_connections=201
max_connections=350
threads_connected=152
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 892669 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=0x4ab3a2ec, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x80da864
0x4003c618
(nil)
0x400372b6
0x420de407
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
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.
Number of processes running now: 0
040927 09:39:50 mysqld restarted
040927 9:39:51 InnoDB: Database was not shut down normally.
InnoDB: Starting recovery from log files...
InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 1 1750951592
InnoDB: Doing recovery: scanned up to log sequence number 1 1756194304
InnoDB: Doing recovery: scanned up to log sequence number 1 1761437184
InnoDB: Doing recovery: scanned up to log sequence number 1 1766519137
040927 9:39:51 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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
040927 9:39:59 InnoDB: Flushing modified pages from the buffer pool...
040927 9:40:00 InnoDB: Started
/usr/sbin/mysqld-max: ready for connections.
Version: '4.0.20-Max-log' socket: '/var/lib/mysql/mysql.sock' port: 3306
040927 9:40:00 Warning: Checking table: './apachelogs/namebrandoutlet_access_log'
040927 9:40:00 1 client is using or hasn't closed the table properly
040927 9:40:03 Warning: Checking table: './api/usage_log'
040927 9:40:03 1 client is using or hasn't closed the table properly
040927 9:41:13 Aborted connection 14 to db: 'downeast' user: 'downeast' host:
`localhost' (Got an error reading communication packets)
040927 9:41:13 Aborted connection 22 to db: 'downeast' user: 'downeast' host:
`localhost' (Got an error reading communication packets)
040927 9:41:13 Aborted connection 9 to db: 'downeast' user: 'downeast' host:
`localhost' (Got an error reading communication packets)
040927 9:41:13 Aborted connection 16 to db: 'downeast' user: 'downeast' host:
`localhost' (Got an error reading communication packets)
040927 9:41:13 Aborted connection 8 to db: 'downeast' user: 'downeast' host:
`localhost' (Got an error reading communication packets)
040927 9:41:13 Aborted connection 7 to db: 'downeast' user: 'downeast' host:
`localhost' (Got an error reading communication packets)
040927 9:42:42 Aborted connection 1 to db: 'api' user: 'api' host: `localhost' (Got
an error writing communication packets)
040927 9:42:42 Aborted connection 15 to db: 'api' user: 'api' host: `localhost' (Got
an error writing communication packets)
040927 9:42:42 Aborted connection 3 to db: 'api' user: 'api' host: `localhost' (Got
an error writing communication packets)
040927 9:42:42 Aborted connection 13 to db: 'api' user: 'api' host: `localhost' (Got
an error writing communication packets)
040927 9:42:42 Aborted connection 2 to db: 'api' user: 'api' host: `localhost' (Got
an error writing communication packets)
040927 9:42:42 Aborted connection 21 to db: 'api' user: 'api' host: `localhost' (Got
an error writing communication packets)
040927 9:43:47 Warning: Checking table: './apachelogs/misc_access_log'
040927 9:43:47 1 client is using or hasn't closed the table properly
signature.asc
Description: Digital signature
binaCttzkLoXk.bin
Description: application/postage-hashcash
