Hi,
I'm looking for two things - help understanding why InnoDB crashed on our server this morning, and help speeding up recovery from that crash. We are running 4.0.21 binaries on Fedora Core 2 (Tettnang) Linux, 2.6.5-1.358smp. I'll explain what happened ....
We spent the weekend importing all our data into InnoDB. The last step was to create an index on a table with 28mil rows (ALTER TABLE master_dna_list ADD PRIMARY KEY (email(55)). Since this table isn't critical to other areas of our website, we turned the site back on while the alter table was still running. Things seemed ok for several hours, but this morning, lots of threads started locking. Looking in the log showed "InnoDB: Warning: difficult to find free blocks from the buffer pool", and vmstat showed that the CPU and disks were completely idle. "SHOW INNODB STATUS" would just hang indefinitely. Seeing no other recourse, I restarted mysqld, which of course caused a rollback of the alter table. The roll back is progressing at about 1% every 12 minutes, which equates to about 20hrs before the server can be back up - not a good thing. Reading through the mysql documentation, we found this...
http://dev.mysql.com/doc/mysql/en/forcing-recovery.html
Starting from MySQL 3.23.53 and 4.0.4, you are allowed to |DROP| or
|CREATE| a table even if forced recovery is used. If you know that a
certain table is causing a crash in rollback, you can drop it. You can
use
this also to stop a runaway rollback caused by a failing mass import or
|ALTER TABLE|. You can kill the *mysqld* process and set
|innodb_force_recovery| to |3| to bring your database up without
the rollback. Then |DROP| the table that is causing the runaway
rollback.
So we tried it - stopped the server (kill -9 at this point since a proper shutdown just hangs), edit my.cnf and added "innodb_force_recovery=3" and "skip-networking", start up, "drop table master_dna_list", "show tables" and it's not there - good, stop the server again. waiting .... the mysqld process would not terminate, after waiting 10 minutes with the system totally idle, kill -9 again. start mysqld normally, and the rollback is STILL going. Is there something else I must do to abort this rollback? Any help would be appreciated :)
My other question is just why did InnoDB crash to begin with? At 3:40am this message began to show up in the log file.
050207 3:40:04 InnoDB: WARNING: over 4 / 5 of the buffer pool is occupied by InnoDB: lock heaps or the adaptive hash index! Check that your InnoDB: transactions do not set too many row locks. InnoDB: Your buffer pool size is 8 MB. Maybe you should make InnoDB: the buffer pool bigger? InnoDB: Starting the InnoDB Monitor to print diagnostics, including InnoDB: lock heap and hash index sizes.
In the documentation, there is this
# The size of the buffer InnoDB uses for buffering log data. As soon as # it is full, InnoDB will have to flush it to disk. As it is flushed # once per second anyway, it does not make sense to have it very large # (even with long transactions). innodb_log_buffer_size = 8M
It explicitly states that it "does not make sense to have it very large", so I had left it at 8M on our server. Later in the morning, this message begins appearing in the log file... this is about the time when I woke up and saw that the server was completely idle - no disk i/o and no cpu activity. Could anyone please try to explain what happened? Thanks very much for any help or advice.
050207 7:42:33 InnoDB: Warning: difficult to find free blocks from InnoDB: the buffer pool (1342 search iterations)! Consider InnoDB: increasing the buffer pool size. InnoDB: It is also possible that in your Unix version InnoDB: fsync is very slow, or completely frozen inside InnoDB: the OS kernel. Then upgrading to a newer version InnoDB: of your operating system may help. Look at the InnoDB: number of fsyncs in diagnostic info below. InnoDB: Pending flushes (fsync) log: 0; buffer pool: 0 InnoDB: 59958419 OS file reads, 46937102 OS file writes, 3223373 OS fsyncs InnoDB: Starting InnoDB Monitor to print further InnoDB: diagnostics to the standard output.
This is the last complete INNODB MONITOR output in the log file, from 5:46. There is one a few seconds after this, but the monitor's output is truncated :(
=====================================
050207 5:46:22 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 16 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 48037914, signal count 46488800
Mutex spin waits 1167745252, rounds 3021712380, OS waits 24059258
RW-shared spins 3802825, OS waits 1886668; RW-excl spins 5144033, OS waits 2480352
------------
TRANSACTIONS
------------
Trx id counter 0 1396082
Purge done for trx's n:o < 0 1396054 undo n:o < 0 0
Total number of lock structs in row lock hash table 88587
LIST OF TRANSACTIONS FOR EACH SESSION:
~~~~~~~~~~~~~~~ 8 INSERTs omitted b/c they contain client data
---TRANSACTION 0 546539, ACTIVE 30114 sec, process no 2892, OS thread id 368651 inserting, thread declared inside InnoDB 168
mysql tables in use 2, locked 2
85327 lock struct(s), heap size 6860096, undo log entries 22004587
MySQL thread id 27631, query id 1227994 192.168.1.2 deva copy to tmp table
alter table master_dna_list add primary key (email(55))
--------
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: 1
59946807 OS file reads, 46930662 OS file writes, 3222579 OS fsyncs
1 pending preads, 0 pending pwrites
1416.04 reads/s, 19239 avg bytes/read, 808.51 writes/s, 97.43 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf for space 0: size 264, free list len 139, seg size 404,
278215563 inserts, 278148922 merged recs, 9104700 merges
Hash table size 34679, used cells 8, node heap has 1 buffer(s)
412.54 hash searches/s, 6956.19 non-hash searches/s
---
LOG
---
Log sequence number 37 2367585903
Log flushed up to 37 2367585903
Last checkpoint at 37 2367525098
0 pending log writes, 0 pending chkp writes
1681395 log i/o's done, 40.37 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 60169174; in additional pool allocated 1048576
Buffer pool size 512
Free buffers 0
Database pages 76
Modified db pages 43
Pending reads 1 Pending writes: LRU 41, flush list 0, single page 0
Pages read 66933579, created 5898321, written 57859562
1662.77 reads/s, 5.87 creates/s, 812.26 writes/s
Buffer pool hit rate 966 / 1000
--------------
ROW OPERATIONS
--------------
2 queries inside InnoDB, 0 queries in queue
Main thread process no. 24079, id 28680, state: sleeping
Number of rows inserted 760368359, updated 278958, deleted 9585, read 991879310
768.08 inserts/s, 5.00 updates/s, 0.00 deletes/s, 21583.28 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
-- Devananda van der Veen Systems Developer http://hydragroup.com
-- MySQL General Mailing List For list archives: http://lists.mysql.com/mysql To unsubscribe: http://lists.mysql.com/[EMAIL PROTECTED]
