Hello all.
We're having a few problems with mysql, innodb seems to be stalling and then causing a restarts at random times. I've looked through some of the old posts and seen stuff similar to this with causes ranging from incorrect memory setting to kernel problems.
So I was hoping that someone with more knowledge than me would be able to take a look at the details and see if they can point me in the right direction.
Below is our setup, my.cnf and the error log.
I've included the start and end of the error log below because the full thing is quite long. The full log can be seen at http://equillia.net/mysql/mysql.error.txt as I've seen this asked for in several of the previous posts about this sort of problem.
Thanks in advance. Toro
select version(); 4.0.20-standard-log
/proc/version
Linux version 2.4.26-ow1 ([EMAIL PROTECTED]) (gcc version 3.2.2 20030222 (Red Hat Linux 3.2.2-5)) #3 Wed Apr 28 13:39:23 NZST 2004
------- resolve_stack_dump -s /tmp/mysqld.sym -n mysql.stack 0x80720d4 handle_connections_sockets + 476 0x8250d48 inflate_blocks + 2920 0x81ed044 ha_insert_for_fold + 124 0x80f9148 innobase_shutdown_for_mysql + 104 0x824e4fc send_all_trees + 204 0x828452a _dl_signal_error + 250
------- /etc/my.cnf [mysqld] datadir=/var/lib/mysql socket=/var/lib/mysql/mysql.sock innodb_data_file_path = ibdata1:10M:autoextend:max:1900M innodb_flush_log_at_trx_commit=1 innodb_lock_wait_timeout=50 innodb_buffer_pool_size=200M innodb_additional_mem_pool_size=50M
skip-locking
max_user_connections=20 max_connections=100 interactive_timeout=100 wait_timeout=100 connect_timeout=10 thread_cache_size=8 key_buffer=64M max_allowed_packet=16M table_cache=1024 sort_buffer=2M record_buffer=2M thread_cache=8 thread_concurrency=8 myisam_sort_buffer_size=64M server-id = 1
query_cache_size=1000000 query_cache_type=1
log-slow-queries=mysql-slow-query.log long_query_time=5
[mysql.server] user=mysql basedir=/var/lib
[safe_mysqld] err-log=/var/lib/mysql/mysql.error pid-file=/var/lib/mysql/mysql.pid open_files_limit=8192
[mysqldump] quick max_allowed_packet=16M
[mysql] no-auto-rehash
[isamchk] key_buffer=256M sort_buffer=256M read_buffer=2M write_buffer=2M
[myisamchk] key_buffer=256M sort_buffer=256M read_buffer=2M write_buffer=2M
[mysqlhotcopy] interactive-timeout
--------
/var/lib/mysql/mysql.error
040906 10:38:00 mysqld started
040906 10:38:01 Warning: Asked for 196608 thread stack, but got 126976
040906 10:38:01 InnoDB: Started
/usr/sbin/mysqld: ready for connections.
Version: '4.0.20-standard-log' socket: '/var/lib/mysql/mysql.sock' port: 3306
InnoDB: Warning: a long semaphore wait:
--Thread 565262 has waited at btr0cur.c line 401 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x44b394 created in file buf0buf.c line 438
number of readers 0, waiters flag 0
Last time read locked in file btr0sea.c line 767
Last time write locked in file buf0buf.c line 1401
wait is ending
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
=====================================
040906 11:44:09 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 16 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 408, signal count 406
--Thread 565262 has waited at btr0cur.c line 401 for 245.00 seconds the semaphore:
S-lock on RW-latch at 0x44b394 created in file buf0buf.c line 438
number of readers 0, waiters flag 0
Last time read locked in file btr0sea.c line 767
Last time write locked in file buf0buf.c line 1401
wait is ending
--Thread 614421 has waited at btr0cur.c line 401 for 181.00 seconds the semaphore:
S-lock on RW-latch at 0x4708ac created in file buf0buf.c line 438
number of readers 0, waiters flag 0
Last time read locked in file btr0pcur.c line 228
Last time write locked in file buf0buf.c line 1401
wait is ending
Mutex spin waits 287, rounds 3190, OS waits 12
RW-shared spins 705, OS waits 349; RW-excl spins 47, OS waits 47
------------
TRANSACTIONS
------------
Trx id counter 0 1599098
Purge done for trx's n:o < 0 1599020 undo n:o < 0 0
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 1599004, ACTIVE 182 sec, process no 25262, OS thread id 614421 fetching rows, thread declared inside InnoDB 27
mysql tables in use 2, locked 0
MySQL thread id 1347, query id 11895 localhost outreach Sorting result
SELECT logparams_s2.value as host, UNIX_TIMESTAMP(log.dt) as datetime FROM log INNER JOIN logparams_s2 ON (log.param2key=logparams_s2.param2key) WHERE (((log.user='1735' AND log.type='S'))) AND (log.user='1735') ORDER BY datetime desc LIMIT 0,2
Trx read view will not see trx with id >= 0 1599005, sees < 0 1598963
---TRANSACTION 0 1598963, ACTIVE 245 sec, process no 25134, OS thread id 565262 fetching rows, thread declared inside InnoDB 70
mysql tables in use 2, locked 0
MySQL thread id 1318, query id 11735 localhost outreach Sorting result
SELECT logparams_s2.value as host, UNIX_TIMESTAMP(log.dt) as datetime FROM log INNER JOIN logparams_s2 ON (log.param2key=logparams_s2.param2key) WHERE (((log.user='1735' AND log.type='S'))) AND (log.user='1735') ORDER BY datetime desc LIMIT 0,2
Trx read view will not see trx with id >= 0 1598964, sees < 0 1598964
--------
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
10033 OS file reads, 1124 OS file writes, 581 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,
24 inserts, 24 merged recs, 24 merges
Hash table size 830173, used cells 158922, node heap has 174 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 0 397035997
Log flushed up to 0 397035997
Last checkpoint at 0 397035997
0 pending log writes, 0 pending chkp writes
352 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 281238172; in additional pool allocated 12288128
Buffer pool size 12800
Free buffers 1
Database pages 12625
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 21254, created 3, written 711
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
2 queries inside InnoDB, 0 queries in queue
Main thread process no. 22631, id 28680, state: sleeping
Number of rows inserted 274, updated 31, deleted 30, read 4371210
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 41.12 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
.
.
.
=====================================
040906 11:50:17 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 16 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 429, signal count 425
--Thread 565262 has waited at btr0cur.c line 401 for 613.00 seconds the semaphore:
S-lock on RW-latch at 0x44b394 created in file buf0buf.c line 438
number of readers 0, waiters flag 0
Last time read locked in file btr0sea.c line 767
Last time write locked in file buf0buf.c line 1401
wait is ending
--Thread 614421 has waited at btr0cur.c line 401 for 549.00 seconds the semaphore:
S-lock on RW-latch at 0x4708ac created in file buf0buf.c line 438
number of readers 0, waiters flag 0
Last time read locked in file btr0cur.c line 401
Last time write locked in file buf0buf.c line 1401
wait is ending
--Thread 663579 has waited at btr0cur.c line 401 for 242.00 seconds the semaphore:
S-lock on RW-latch at 0x48dbd4 created in file buf0buf.c line 438
a writer (thread id 663579) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file btr0pcur.c line 228
Last time write locked in file buf0buf.c line 1401
--Thread 671773 has waited at btr0cur.c line 401 for 186.00 seconds the semaphore:
S-lock on RW-latch at 0x49bdac created in file buf0buf.c line 438
a writer (thread id 671773) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file btr0cur.c line 3529
Last time write locked in file buf0buf.c line 1401
Mutex spin waits 292, rounds 3270, OS waits 13
RW-shared spins 760, OS waits 369; RW-excl spins 47, OS waits 47
------------
TRANSACTIONS
------------
Trx id counter 0 1599373
Purge done for trx's n:o < 0 1599020 undo n:o < 0 0
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 1599236, ACTIVE 186 sec, process no 25468, OS thread id 671773 fetching rows, thread declared inside InnoDB 404
mysql tables in use 2, locked 0
MySQL thread id 1478, query id 12664 localhost outreach Sorting result
SELECT logparams_s2.value as host, UNIX_TIMESTAMP(log.dt) as datetime FROM log INNER JOIN logparams_s2 ON (log.param2key=logparams_s2.param2key) WHERE (((log.user='4009' AND log.type='S'))) AND (log.user='4009') ORDER BY datetime desc LIMIT 0,2
Trx read view will not see trx with id >= 0 1599237, sees < 0 1598963
---TRANSACTION 0 1599181, ACTIVE 242 sec, process no 25428, OS thread id 663579 fetching rows, thread declared inside InnoDB 202
mysql tables in use 2, locked 0
MySQL thread id 1464, query id 12555 localhost outreach Sorting result
SELECT logparams_s2.value as host, UNIX_TIMESTAMP(log.dt) as datetime FROM log INNER JOIN logparams_s2 ON (log.param2key=logparams_s2.param2key) WHERE (((log.user='1735' AND log.type='S'))) AND (log.user='1735') ORDER BY datetime desc LIMIT 0,2
Trx read view will not see trx with id >= 0 1599182, sees < 0 1598963
---TRANSACTION 0 1599004, ACTIVE 550 sec, process no 25262, OS thread id 614421 fetching rows, thread declared inside InnoDB 27
mysql tables in use 2, locked 0
MySQL thread id 1347, query id 11895 localhost outreach Sorting result
SELECT logparams_s2.value as host, UNIX_TIMESTAMP(log.dt) as datetime FROM log INNER JOIN logparams_s2 ON (log.param2key=logparams_s2.param2key) WHERE (((log.user='1735' AND log.type='S'))) AND (log.user='1735') ORDER BY datetime desc LIMIT 0,2
Trx read view will not see trx with id >= 0 1599005, sees < 0 1598963
---TRANSACTION 0 1598963, ACTIVE 613 sec, process no 25134, OS thread id 565262 fetching rows, thread declared inside InnoDB 70
mysql tables in use 2, locked 0
MySQL thread id 1318, query id 11735 localhost outreach Sorting result
SELECT logparams_s2.value as host, UNIX_TIMESTAMP(log.dt) as datetime FROM log INNER JOIN logparams_s2 ON (log.param2key=logparams_s2.param2key) WHERE (((log.user='1735' AND log.type='S'))) AND (log.user='1735') ORDER BY datetime desc LIMIT 0,2
Trx read view will not see trx with id >= 0 1598964, sees < 0 1598964
--------
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: 74, 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
10112 OS file reads, 1264 OS file writes, 662 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,
25 inserts, 25 merged recs, 25 merges
Hash table size 830173, used cells 185863, node heap has 207 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 0 397043057
Log flushed up to 0 397043057
Last checkpoint at 0 397043057
0 pending log writes, 0 pending chkp writes
399 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 281238172; in additional pool allocated 12410240
Buffer pool size 12800
Free buffers 0
Database pages 12593
Modified db pages 0
Pending reads 74
Pending writes: LRU 0, flush list 0, single page 0
Pages read 21380, created 3, written 798
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
4 queries inside InnoDB, 0 queries in queue
Main thread process no. 22631, id 28680, state: sleeping
Number of rows inserted 306, updated 35, deleted 30, read 4675166
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 2045.87 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
--Thread 565262 has waited at btr0cur.c line 401 for 625.00 seconds the semaphore:
S-lock on RW-latch at 0x44b394 created in file buf0buf.c line 438
number of readers 0, waiters flag 0
Last time read locked in file btr0sea.c line 767
Last time write locked in file buf0buf.c line 1401
wait is ending
InnoDB: Error: semaphore wait has lasted > 600 seconds
InnoDB: We intentionally crash the server, because it appears to be hung.
040906 11:50:29InnoDB: Assertion failure in thread 24583 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=67108864
read_buffer_size=2093056
max_used_connections=14
max_connections=100
threads_connected=5
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 474735 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
thd=(nil)
InnoDB: Thread 712743 stopped in file ha_innodb.cc line 423
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=0xbfedf758, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x80720d4
0x8250d48
0x81ed044
0x80f9148
0x824e4fc
0x828452a
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
040906 11:50:31 mysqld restarted
040906 11:50:31 Warning: Asked for 196608 thread stack, but got 126976
040906 11:50:31 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 0 397043057
InnoDB: Doing recovery: scanned up to log sequence number 0 397044970
040906 11:50:31 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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
040906 11:50:31 InnoDB: Flushing modified pages from the buffer pool...
040906 11:50:32 InnoDB: Started
/usr/sbin/mysqld: ready for connections.
Version: '4.0.20-standard-log' socket: '/var/lib/mysql/mysql.sock' port: 3306
-- MySQL General Mailing List For list archives: http://lists.mysql.com/mysql To unsubscribe: http://lists.mysql.com/[EMAIL PROTECTED]
