Thanks for the reply, much appreciated.
> this might be a Linux kernel bug. What kernel are you using? /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
The problem had been happening approximately once a day. But two days ago I dumped all the databases, then created a completely new mysql data directory and then recreated all the databases from the scratch. I did this just in case there was some obscure corruption in the some of the data, (nothing had showed with check table however, although I do recall a table being corrupted about a week ago, but it had seemed to have fixed itself as it didn't show up in subsequent check table queries).
Nothing has happened in the last two days, so I'm waiting to see if any thing does.
I also had a look through the old error files and and the error seems to have always occured when the log sequence number was close to 400M, eg. 414M, 418M, 423M, 390M, 396M, 397M etc.
Currently the log sequence number for is only up to 261M (and this makes sense as I moved a few databases to another machine a couple of days ago as well, so now it should take longer than a day to reach 400M). So I'll keep an eye on the sequence number and see what happens when it gets to 400M.
Thanks for the help. Toro
Heikki Tuuri wrote:
Toro,
You have done very little processing, the log sequence number is only 400 MB.
Looks like a thread has been waiting for a disk read. The output shows that the InnoDB 'event' it has waited for is already signaled. In Unix, an InnoDB 'event' is a condition variable. But the thread is not progressing. It has not called sync_array_free_cell().
--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
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
/*********************************************************************** Puts the cell event in set state. */ static void sync_cell_event_set( /*================*/ sync_cell_t* cell) /* in: array cell */ { os_event_set(cell->event); cell->event_set = TRUE; }
/********************************************************************** This function should be called when a thread starts to wait on a wait array cell. In the debug version this function checks if the wait for a semaphore will result in a deadlock, in which case prints info and asserts. */
void sync_array_wait_event( /*==================*/ sync_array_t* arr, /* in: wait array */ ulint index) /* in: index of the reserved cell */ { sync_cell_t* cell; os_event_t event;
ut_a(arr);
sync_array_enter(arr);
cell = sync_array_get_nth_cell(arr, index);
ut_a(cell->wait_object); ut_a(!cell->waiting); ut_ad(os_thread_get_curr_id() == cell->thread);
event = cell->event; cell->waiting = TRUE;
#ifdef UNIV_SYNC_DEBUG
/* We use simple enter to the mutex below, because if we cannot acquire it at once, mutex_enter would call recursively sync_array routines, leading to trouble. rw_lock_debug_mutex freezes the debug lists. */
rw_lock_debug_mutex_enter();
if (TRUE == sync_array_detect_deadlock(arr, cell, cell, 0)) {
fputs("########################################\n", stderr); ut_error; }
rw_lock_debug_mutex_exit(); #endif sync_array_exit(arr);
os_event_wait(event);
sync_array_free_cell(arr, index); }
..........
if (!cell->waiting) { fputs("wait has ended\n", file); }
if (cell->event_set) { fputs("wait is ending\n", file); } }
----- Original Message ----- From: "Toro Hill" <[EMAIL PROTECTED]>
Newsgroups: mailing.database.myodbc
Sent: Tuesday, September 07, 2004 8:46 AM
Subject: innodb long sempahore wait
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]
-- MySQL General Mailing List For list archives: http://lists.mysql.com/mysql To unsubscribe: http://lists.mysql.com/[EMAIL PROTECTED]
