Ian,
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
-------------------------------------
hmm... InnoDB has posted 120 pages to be written to the ibdata files. That
is because it wants to get replaceable blocks in the buffer pool, InnoDB
uses mostly the LRU replacement policy.
The question is why the write thread has not waken up to process these
writes.
I added the following patch to 4.0.22 to trace this problem:
------------------------------------------------
D 1.76 04/09/11 09:37:03+03:00 [EMAIL PROTECTED] 95 94 16/1/3132
P innobase/os/os0file.c
C Add more precise diagnostics about the state of the I/O threads of InnoDB;
pri
nt in SHOW INNODB STATUS if the event wait semaphore of each I/O thread is
set
------------------------------------------------
It will print whether the 'event' is set to wake up the thread.
for (i = 0; i < srv_n_file_io_threads; i++) {
fprintf(file, "I/O thread %lu state: %s (%s)", i,
srv_io_thread_op_info[i],
srv_io_thread_function[i]);
#ifndef __WIN__
if (os_aio_segment_wait_events[i]->is_set) {
fprintf(file, " ev set");
}
#endif
fprintf(file, "\n");
}
There are a few similar reports lately. It might even be that some recent
Linux kernel or glibc version has a bug in threads and condition variables.
Events use condition variables. But we will know more when this problem is
repeated with 4.0.22.
Best regards,
Heikki
Innobase Oy
InnoDB - transactions, row level locking, and foreign keys for MySQL
InnoDB Hot Backup - a hot backup tool for InnoDB which also backs up MyISAM
tables
http://www.innodb.com/order.php
Order MySQL support from http://www.mysql.com/support/index.html
...............................
From: Ian Gulliver ([EMAIL PROTECTED])
Subject: InnoDB crash issue
This is the only article in this thread
View: Original Format
Newsgroups: mailing.database.myodbc
Date: 2004-09-29 07:21:24 PST
--54328a363d28c325cc36d4d54176940d
Content-Type: multipart/signed; micalg=pgp-sha1;
protocol="application/pgp-signature"; boundary="kORqDWCi7qDJ0mEj"
--kORqDWCi7qDJ0mEj
Content-Type: multipart/mixed; boundary="PNTmBPCT7hxwcZjr"
Content-Disposition: inline
--PNTmBPCT7hxwcZjr
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable
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=3DInnoDB;
--=20
Ian Gulliver
Penguin Hosting
"Failure is not an option; it comes bundled with your Microsoft products."
--PNTmBPCT7hxwcZjr
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment; filename="downeast_innodb_crash.txt"
Content-Transfer-Encoding: quoted-printable
MySQL thread id 806227, query id 7467614 localhost downeast statistics
SELECT session_data FROM session_data WHERE sid=3D'f697dfe1ccb2fddf0892d144=
a86d58bf'
---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=3D'9200380a42dfd85e035865a8=
45b61db2'
---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=3D'4ee95161699670b944f62ff1=
9a646270'
---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=3D'1c60932c3eb0ef237397a295=
c6fd7b5d'
---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=3D'a99ffb28fd5defe68eda15ab=
5bc9fb60'
---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=3D'a5352dec66bfbcf1214a92f8=
76661f6d'
---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=3D'42129f31ba6456a9eb172948=
fb4ea3bd'
---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=3D'cd924675587036968e63f722=
4f59e36f'
---TRANSACTION 0 6264628, ACTIVE 583 sec, process no 29469, OS thread id 14=
11119808 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=3D'7e83e8ab037784d8193f7a02=
48b2990d'
---TRANSACTION 0 6264627, ACTIVE 586 sec, process no 29469, OS thread id 14=
14067008 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=3D'37d046652a35c341c288dbc7=
89f1d1c0'
---TRANSACTION 0 6264626, ACTIVE 590 sec, process no 29469, OS thread id 14=
16625344 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=3D'7f511ae860c52a069fb457a8=
fb41b7fe'
---TRANSACTION 0 6264625, ACTIVE 590 sec, process no 29469, OS thread id 14=
01483712 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=3D'3d548d965384247053f981e3=
cbad3323'
---TRANSACTION 0 6264624, ACTIVE 594 sec, process no 29469, OS thread id 14=
08770112 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=3D'b044fd6bf5c596d76894df23=
2b5df84a'
---TRANSACTION 0 6264623, ACTIVE 595 sec, process no 29469, OS thread id 14=
17214400 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=3D'99999b291ae9fd1d351252dc=
6b9b94e6'
---TRANSACTION 0 6264622, ACTIVE 615 sec, process no 29469, OS thread id 14=
41723200 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=3D'4ee95161699670b944f62ff1=
9a646270'
---TRANSACTION 0 6264621, ACTIVE 619 sec, process no 29469, OS thread id 14=
18226496 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;th=
is_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=20
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 act=
ivity
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
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D
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 sync0=
arr.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 diagno=
se
the problem, but since we have already crashed, something is definitely wro=
ng
and this may fail.
key_buffer_size=3D134217728
read_buffer_size=3D131072
max_used_connections=3D201
max_connections=3D350
threads_connected=3D152
It is possible that mysqld could use up to=20
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections =3D=
892669 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
thd=3D(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=3D0x4ab3a2ec, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x80da864
0x4003c618
(nil)
0x400372b6
0x420de407
New value of fp=3D(nil) failed sanity check, terminating stack trace!
Please read http://www.mysql.com/doc/en/Using_stack_trace.html and follow i=
nstructions on how to resolve the stack trace. Resolved
stack trace is much more helpful in diagnosing the problem, so please do=20
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 data=
base...
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=20
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_a=
ccess_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' h=
ost: `localhost' (Got an error reading communication packets)
040927 9:41:13 Aborted connection 22 to db: 'downeast' user: 'downeast' h=
ost: `localhost' (Got an error reading communication packets)
040927 9:41:13 Aborted connection 9 to db: 'downeast' user: 'downeast' ho=
st: `localhost' (Got an error reading communication packets)
040927 9:41:13 Aborted connection 16 to db: 'downeast' user: 'downeast' h=
ost: `localhost' (Got an error reading communication packets)
040927 9:41:13 Aborted connection 8 to db: 'downeast' user: 'downeast' ho=
st: `localhost' (Got an error reading communication packets)
040927 9:41:13 Aborted connection 7 to db: 'downeast' user: 'downeast' ho=
st: `localhost' (Got an error reading communication packets)
040927 9:42:42 Aborted connection 1 to db: 'api' user: 'api' host: `local=
host' (Got an error writing communication packets)
040927 9:42:42 Aborted connection 15 to db: 'api' user: 'api' host: `loca=
lhost' (Got an error writing communication packets)
040927 9:42:42 Aborted connection 3 to db: 'api' user: 'api' host: `local=
host' (Got an error writing communication packets)
040927 9:42:42 Aborted connection 13 to db: 'api' user: 'api' host: `loca=
lhost' (Got an error writing communication packets)
040927 9:42:42 Aborted connection 2 to db: 'api' user: 'api' host: `local=
host' (Got an error writing communication packets)
040927 9:42:42 Aborted connection 21 to db: 'api' user: 'api' host: `loca=
lhost' (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
--
MySQL General Mailing List
For list archives: http://lists.mysql.com/mysql
To unsubscribe: http://lists.mysql.com/[EMAIL PROTECTED]
