Toro, this might be a Linux kernel bug. What kernel are you using?
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]
