... InnoDB: Warning: a long semaphore wait: --Thread 139799274383104 has waited at trx0undo.ic line 156 for 241.00 seconds the semaphore: X-lock (wait_ex) on RW-latch at 0x7f259888c740 created in file buf0buf.c line 907 a writer (thread id 139799274383104) has reserved it in mode wait exclusive number of readers 1, waiters flag 0, lock_word: ffffffffffffffff Last time read locked in file buf0flu.c line 1294 Last time write locked in file /pb2/build/sb_0-4575859-1324066572.98/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/include/trx0undo.ic line 156 InnoDB: Warning: a long semaphore wait: --Thread 139799022716672 has waited at trx0undo.ic line 156 for 241.00 seconds the semaphore: X-lock (wait_ex) on RW-latch at 0x7f2598865a40 created in file buf0buf.c line 907 a writer (thread id 139799022716672) has reserved it in mode wait exclusive number of readers 1, waiters flag 0, lock_word: ffffffffffffffff Last time read locked in file buf0flu.c line 1294 Last time write locked in file /pb2/build/sb_0-4575859-1324066572.98/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/include/trx0undo.ic line 156 InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:01:21 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 13 seconds ----------------- BACKGROUND THREAD ----------------- srv_master_thread loops: 457748 1_second, 457741 sleeps, 44656 10_second, 13050 background, 13050 flush srv_master_thread log flush and writes: 459737 ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 3043415, signal count 2871178 --Thread 139799274383104 has waited at trx0undo.ic line 156 for 254.00 seconds the semaphore: X-lock (wait_ex) on RW-latch at 0x7f259888c740 created in file buf0buf.c line 907 a writer (thread id 139799274383104) has reserved it in mode wait exclusive number of readers 1, waiters flag 0, lock_word: ffffffffffffffff Last time read locked in file buf0flu.c line 1294 Last time write locked in file /pb2/build/sb_0-4575859-1324066572.98/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/include/trx0undo.ic line 156 --Thread 139799022716672 has waited at trx0undo.ic line 156 for 254.00 seconds the semaphore: X-lock (wait_ex) on RW-latch at 0x7f2598865a40 created in file buf0buf.c line 907 a writer (thread id 139799022716672) has reserved it in mode wait exclusive number of readers 1, waiters flag 0, lock_word: ffffffffffffffff Last time read locked in file buf0flu.c line 1294 Last time write locked in file /pb2/build/sb_0-4575859-1324066572.98/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/include/trx0undo.ic line 156 --Thread 139799246960384 has waited at trx0undo.ic line 156 for 244.00 seconds the semaphore: X-lock (wait_ex) on RW-latch at 0x7f259885c2c0 created in file buf0buf.c line 907 a writer (thread id 139799246960384) has reserved it in mode wait exclusive number of readers 1, waiters flag 0, lock_word: ffffffffffffffff Last time read locked in file buf0flu.c line 1294 Last time write locked in file /pb2/build/sb_0-4575859-1324066572.98/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/include/trx0undo.ic line 156 --Thread 139799247226624 has waited at trx0undo.ic line 156 for 224.00 seconds the semaphore: X-lock (wait_ex) on RW-latch at 0x7f259887ffc0 created in file buf0buf.c line 907 a writer (thread id 139799247226624) has reserved it in mode wait exclusive number of readers 1, waiters flag 0, lock_word: ffffffffffffffff Last time read locked in file buf0flu.c line 1294 Last time write locked in file /pb2/build/sb_0-4575859-1324066572.98/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/include/trx0undo.ic line 156 --Thread 139799024846592 has waited at trx0undo.ic line 156 for 185.00 seconds the semaphore: X-lock (wait_ex) on RW-latch at 0x7f2599f47fc0 created in file buf0buf.c line 907 a writer (thread id 139799024846592) has reserved it in mode wait exclusive number of readers 1, waiters flag 0, lock_word: ffffffffffffffff Last time read locked in file buf0flu.c line 1294 Last time write locked in file /pb2/build/sb_0-4575859-1324066572.98/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/include/trx0undo.ic line 156 --Thread 139799023515392 has waited at trx0undo.ic line 156 for 178.00 seconds the semaphore: X-lock (wait_ex) on RW-latch at 0x7f25988244c0 created in file buf0buf.c line 907 a writer (thread id 139799023515392) has reserved it in mode wait exclusive number of readers 1, waiters flag 0, lock_word: ffffffffffffffff Last time read locked in file buf0flu.c line 1294 Last time write locked in file /pb2/build/sb_0-4575859-1324066572.98/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/include/trx0undo.ic line 156 --Thread 139799026177792 has waited at trx0undo.ic line 156 for 131.00 seconds the semaphore: X-lock (wait_ex) on RW-latch at 0x7f2598823740 created in file buf0buf.c line 907 a writer (thread id 139799026177792) has reserved it in mode wait exclusive number of readers 1, waiters flag 0, lock_word: ffffffffffffffff Last time read locked in file buf0flu.c line 1294 Last time write locked in file /pb2/build/sb_0-4575859-1324066572.98/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/include/trx0undo.ic line 156 --Thread 139799267952384 has waited at trx0undo.ic line 156 for 114.00 seconds the semaphore: X-lock (wait_ex) on RW-latch at 0x7f2598831b40 created in file buf0buf.c line 907 a writer (thread id 139799267952384) has reserved it in mode wait exclusive number of readers 1, waiters flag 0, lock_word: ffffffffffffffff Last time read locked in file buf0flu.c line 1294 Last time write locked in file /pb2/build/sb_0-4575859-1324066572.98/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/include/trx0undo.ic line 156 --Thread 139799241635584 has waited at trx0undo.ic line 156 for 86.00 seconds the semaphore: X-lock (wait_ex) on RW-latch at 0x7f2598820740 created in file buf0buf.c line 907 a writer (thread id 139799241635584) has reserved it in mode wait exclusive number of readers 1, waiters flag 0, lock_word: ffffffffffffffff Last time read locked in file buf0flu.c line 1294 Last time write locked in file /pb2/build/sb_0-4575859-1324066572.98/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/include/trx0undo.ic line 156 --Thread 139799025379072 has waited at btr0pcur.c line 398 for 78.00 seconds the semaphore: S-lock on RW-latch at 0x7f25991271c0 created in file buf0buf.c line 907 a writer (thread id 139799024846592) has reserved it in mode exclusive number of readers 0, waiters flag 1, lock_word: 0 Last time read locked in file row0sel.c line 3090 Last time write locked in file /pb2/build/sb_0-4575859-1324066572.98/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/row/row0ins.c line 2008 Mutex spin waits 4195721, rounds 94179915, OS waits 2828938 RW-shared spins 161969, rounds 4377696, OS waits 136483 RW-excl spins 44486, rounds 2323846, OS waits 66610 Spin rounds per wait: 22.45 mutex, 27.03 RW-shared, 52.24 RW-excl ------------ TRANSACTIONS ------------ Trx id counter 138C8CE0 Purge done for trx's n:o < 138C82BC undo n:o < 0 History list length 2484 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 138C8CB3, not started MySQL thread id 1916417, OS thread handle 0x7f258c7c9700, query id 134180601 bermon02.be.ber.is24.loc 10.3.133.53 cactiber Waiting for table metadata lock truncate table poller_output ---TRANSACTION 138C8C84, not started MySQL thread id 1916391, OS thread handle 0x7f258c602700, query id 134179836 bermon02.be.ber.is24.loc 10.3.133.53 cactiber Waiting for table metadata lock truncate table poller_output ---TRANSACTION 138C8CD1, not started MySQL thread id 1729627, OS thread handle 0x7f258c4fe700, query id 134186655 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 138C8CD4, not started MySQL thread id 1726563, OS thread handle 0x7f258c706700, query id 134186927 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 138C8CD7, not started MySQL thread id 1701078, OS thread handle 0x7f258c47c700, query id 134186576 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 138C8CCB, not started MySQL thread id 1661397, OS thread handle 0x7f258d985700, query id 134185406 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 138C8CD6, not started MySQL thread id 1655987, OS thread handle 0x7f258c580700, query id 134186527 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 138C8CCE, not started MySQL thread id 1655983, OS thread handle 0x7f258c4bd700, query id 134185642 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 138C8CD0, not started MySQL thread id 1655955, OS thread handle 0x7f257f5bd700, query id 134186572 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 138C8CCA, not started MySQL thread id 1655944, OS thread handle 0x7f258c1b1700, query id 134185624 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 138C8CD5, not started MySQL thread id 1655940, OS thread handle 0x7f257f57c700, query id 134186847 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 138C8CD8, not started MySQL thread id 1655934, OS thread handle 0x7f257f478700, query id 134186671 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 138C8CCC, not started MySQL thread id 1655933, OS thread handle 0x7f258e0ec700, query id 134185593 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 138C8CCD, not started MySQL thread id 1655917, OS thread handle 0x7f258c684700, query id 134185709 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 138C8CD2, not started MySQL thread id 1655910, OS thread handle 0x7f258c06c700, query id 134186771 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 138C8CD3, not started MySQL thread id 1655909, OS thread handle 0x7f258c84b700, query id 134186953 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 138C8CCF, not started MySQL thread id 1655902, OS thread handle 0x7f257f1ad700, query id 134185871 bermon02.be.ber.is24.loc 10.3.133.53 cactiber ---TRANSACTION 13822890, not started MySQL thread id 1006, OS thread handle 0x7f257f4fa700, query id 133161434 berica01.be.ber.is24.loc 10.3.134.108 icinga_rw ---TRANSACTION 13822FFF, not started MySQL thread id 1005, OS thread handle 0x7f258c5c1700, query id 133164844 hamica01.be.ham.is24.loc 10.7.134.108 icinga_rw ---TRANSACTION 138C8CB4, ACTIVE 78 sec fetching rows mysql tables in use 3, locked 0 MySQL thread id 1916418, OS thread handle 0x7f257f3f6700, query id 134180603 bermon01.be.ber.is24.loc 10.3.133.52 cactiber Sorting result SELECT h.hostname host, dt.name service, date, result, ds.host_id host_id, ds.data_template_id data_template_id FROM is24_data_store ds LEFT OUTER JOIN host h ON ds.host_id = h.id left outer join data_template dt on ds.data_template_id = dt.id WHERE ds.date > '2013-04-01 16:00:03' and compute = 1 order by ds.date Trx read view will not see trx with id >= 138C8CB5, sees < 138C8C3B ---TRANSACTION 138C8CA1, ACTIVE 86 sec inserting mysql tables in use 3, locked 3 5 lock struct(s), heap size 1248, 2 row lock(s) MySQL thread id 1916414, OS thread handle 0x7f258c233700, query id 134180310 bermon01.be.ber.is24.loc 10.3.133.52 cactiber Sending data insert into is24_data_store ( host_id, data_template_id, date, result, compute) select h.id host_id, d.id data_template_id , '2013-04-01 17:59:55' , '127', 0 from host h, data_template d where h.hostname = 'berweb11' and d.name = 'WebProfiler-8182-fShowExposeDuration_ms' ---TRANSACTION 138C8C9A, ACTIVE 114 sec inserting mysql tables in use 3, locked 3 5 lock struct(s), heap size 1248, 2 row lock(s) MySQL thread id 1916407, OS thread handle 0x7f258db4c700, query id 134180290 bermon01.be.ber.is24.loc 10.3.133.52 cactiber Sending data insert into is24_data_store ( host_id, data_template_id, date, result, compute) select h.id host_id, d.id data_template_id , '2013-04-01 17:59:27' , '439', 0 from host h, data_template d where h.hostname = 'berweb03' and d.name = 'WebProfiler-8182-fShowExposeDuration_ms' ---TRANSACTION 138C8C97, ACTIVE 131 sec inserting mysql tables in use 3, locked 3 5 lock struct(s), heap size 1248, 2 row lock(s) MySQL thread id 1916404, OS thread handle 0x7f257f4b9700, query id 134180282 bermon01.be.ber.is24.loc 10.3.133.52 cactiber Sending data insert into is24_data_store ( host_id, data_template_id, date, result, compute) select h.id host_id, d.id data_template_id , '2013-04-01 17:59:10' , '287', 0 from host h, data_template d where h.hostname = 'berweb42' and d.name = 'WebProfiler-8182-fShowExposeDuration_ms' ---TRANSACTION 138C8C91, ACTIVE 178 sec inserting mysql tables in use 3, locked 3 5 lock struct(s), heap size 1248, 2 row lock(s) MySQL thread id 1916397, OS thread handle 0x7f257f22f700, query id 134179998 bermon01.be.ber.is24.loc 10.3.133.52 cactiber Sending data insert into is24_data_store ( host_id, data_template_id, date, result, compute) select h.id host_id, d.id data_template_id , '2013-04-01 17:58:23' , '346', 0 from host h, data_template d where h.hostname = 'berweb06' and d.name = 'WebProfiler-8182-fShowExposeDuration_ms' ---TRANSACTION 138C8C90, ACTIVE 185 sec inserting mysql tables in use 3, locked 3 5 lock struct(s), heap size 1248, 2 row lock(s) MySQL thread id 1916396, OS thread handle 0x7f257f374700, query id 134179996 bermon01.be.ber.is24.loc 10.3.133.52 cactiber Sending data insert into is24_data_store ( host_id, data_template_id, date, result, compute) select h.id host_id, d.id data_template_id , '2013-04-01 17:58:16' , '185', 0 from host h, data_template d where h.hostname = 'berweb01' and d.name = 'WebProfiler-8182-fShowExposeDuration_ms' ---TRANSACTION 138C8C69, ACTIVE 224 sec updating or deleting mysql tables in use 1, locked 1 3 lock struct(s), heap size 376, 2 row lock(s) MySQL thread id 26, OS thread handle 0x7f258c788700, query id 134179315 hamica01.be.ham.is24.loc 10.7.134.108 icinga_rw Updating UPDATE icinga_programstatus SET status_update_time=FROM_UNIXTIME(1364831857), program_start_time=FROM_UNIXTIME(1363181507), is_currently_running=1, process_id=16600, daemon_mode=1, last_command_check=FROM_UNIXTIME(1364831857), last_log_rotation=FROM_UNIXTIME(1364767200), notifications_enabled=1, active_service_checks_enabled=1, passive_service_checks_enabled=1, active_host_checks_enabled=1, passive_host_checks_enabled=1, event_handlers_enabled=1, flap_detection_enabled=1, failure_prediction_enabled=1, process_performance_data=0, obsess_over_hosts=0, obsess_over_services=0, modified_host_attrib ---TRANSACTION 138C8C49, ACTIVE 244 sec updating or deleting mysql tables in use 1, locked 1 3 lock struct(s), heap size 376, 2 row lock(s) MySQL thread id 28, OS thread handle 0x7f258c747700, query id 134178071 berica01.be.ber.is24.loc 10.3.134.108 icinga_rw Updating UPDATE icinga_servicestatus SET instance_id=1, service_object_id=197, status_update_time=FROM_UNIXTIME(1364831837), output='HTTP OK: HTTP/1\.1 200 OK - 55849 bytes in 0\.017 second response time', long_output='', perfdata='time=0\.017011s;;;0\.000000 size=55849B;;;0', current_state=0, has_been_checked=1, should_be_scheduled=1, current_check_attempt=1, max_check_attempts=5, last_check=FROM_UNIXTIME(1364831827), next_check=FROM_UNIXTIME(1364832127), check_type=0, last_state_change=FROM_UNIXTIME(1364830927), last_hard_state_change=FROM_UNIXTIME(1364365747), last_hard_state=0, last_time_ok=FROM_UN ---TRANSACTION 138C8C3C, ACTIVE 254 sec updating or deleting mysql tables in use 1, locked 1 2 lock struct(s), heap size 376, 1 row lock(s) MySQL thread id 1915909, OS thread handle 0x7f257f16c700, query id 134178057 bermon02.be.ber.is24.loc 10.3.133.53 cactiber updating delete from poller_output where local_data_id='9849' and rrd_name='load_1minute' and time='2013-04-01 17:56:18' ---TRANSACTION 138C8C3B, ACTIVE 254 sec inserting mysql tables in use 1, locked 1 1 lock struct(s), heap size 376, 0 row lock(s) MySQL thread id 2, OS thread handle 0x7f258e16e700, query id 134178056 update INSERT INTO poller_output (local_data_id, rrd_name, time, output) VALUES (11819,'cpu_rh_nice','2013-04-01 17:57:04','17986'),(11820,'cpu_rh_system','2013-04-01 17:57:04','2348491'),(11821,'cpu_rh_user','2013-04-01 17:57:04','18229902'),(11822,'load_1minute','2013-04-01 17:57:04','0.03'),(11823,'load_15minute','2013-04-01 17:57:04','0.01'),(11824,'load_5minute','2013-04-01 17:57:04','0.04'),(11825,'','2013-04-01 17:57:04','totalReal:8029748 availReal:3468900 totalSwap:1048568 availSwap:1048568 memBuffer:269464 memCached:2712432 usedReal:1578952 usedSwap:0'),(11826,'tcpActiveOpens','2013-04-01 1 -------- FILE I/O -------- I/O thread 0 state: waiting for completed aio requests (insert buffer thread) I/O thread 1 state: waiting for completed aio requests (log thread) I/O thread 2 state: waiting for completed aio requests (read thread) I/O thread 3 state: waiting for completed aio requests (read thread) I/O thread 4 state: waiting for completed aio requests (read thread) I/O thread 5 state: waiting for completed aio requests (read thread) I/O thread 6 state: waiting for completed aio requests (write thread) I/O thread 7 state: waiting for completed aio requests (write thread) I/O thread 8 state: waiting for completed aio requests (write thread) I/O thread 9 state: waiting for completed aio requests (write thread) Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] , ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0 Pending flushes (fsync) log: 0; buffer pool: 0 29180 OS file reads, 73642470 OS file writes, 67146069 OS fsyncs 0.00 reads/s, 0 avg bytes/read, 0.46 writes/s, 0.46 fsyncs/s ------------------------------------- INSERT BUFFER AND ADAPTIVE HASH INDEX ------------------------------------- Ibuf: size 1, free list len 36, seg size 38, 300 merges merged operations: insert 242, delete mark 4469, delete 66 discarded operations: insert 0, delete mark 0, delete 0 Hash table size 2212699, node heap has 166 buffer(s) 0.00 hash searches/s, 1.85 non-hash searches/s --- LOG --- Log sequence number 98073988698 Log flushed up to 98073988698 Last checkpoint at 98073356340 0 pending log writes, 0 pending chkp writes 66390694 log i/o's done, 0.46 log i/o's/second ---------------------- BUFFER POOL AND MEMORY ---------------------- Total memory allocated 1098907648; in additional pool allocated 0 Dictionary memory allocated 1301886 Buffer pool size 65536 Free buffers 0 Database pages 65370 Old database pages 24110 Modified db pages 342 Pending reads 0 Pending writes: LRU 0, flush list 28, single page 0 Pages made young 24409, not young 0 0.00 youngs/s, 0.00 non-youngs/s Pages read 28677, created 387991, written 6779208 0.00 reads/s, 0.00 creates/s, 0.00 writes/s Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s LRU len: 65370, unzip_LRU len: 0 I/O sum[0]:cur[0], unzip sum[0]:cur[0] -------------- ROW OPERATIONS -------------- 0 queries inside InnoDB, 0 queries in queue 2 read views open inside InnoDB Main thread process no. 15721, id 139799037998848, state: flushing buffer pool pages Number of rows inserted 39272289, updated 4446440, deleted 37175456, read 3149555581 0.23 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.46 reads/s ---------------------------- END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 4* "long semaphore wait" at trx0undo.ic line 156 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:01:41 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ ===================================== 130401 18:02:01 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 4* "long semaphore wait" at trx0undo.ic line 156 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:02:21 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 6* "long semaphore wait" at trx0undo.ic line 156 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:02:41 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ ===================================== 130401 18:03:01 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 7* "long semaphore wait" at trx0undo.ic line 156 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:03:21 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ ===================================== 130401 18:03:41 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 8* "long semaphore wait" at trx0undo.ic line 156 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:04:01 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 9* "long semaphore wait" at trx0undo.ic line 156 ... ]] InnoDB: Warning: a long semaphore wait: --Thread 139799025379072 has waited at btr0pcur.c line 398 for 251.00 seconds the semaphore: S-lock on RW-latch at 0x7f25991271c0 created in file buf0buf.c line 907 a writer (thread id 139799024846592) has reserved it in mode exclusive number of readers 0, waiters flag 1, lock_word: 0 Last time read locked in file row0sel.c line 3090 Last time write locked in file /pb2/build/sb_0-4575859-1324066572.98/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/row/row0ins.c line 2008 InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:04:21 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ ===================================== 130401 18:04:41 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 9* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:05:01 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 9* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:05:21 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ ===================================== 130401 18:05:41 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 9* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:06:01 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 9* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] InnoDB: Warning: a long semaphore wait: --Thread 139799240038144 has waited at trx0undo.c line 1759 for 271.00 seconds the semaphore: Mutex at 0x5be53b0 created file trx0rseg.c line 210, lock var 1 waiters flag 1 InnoDB: Warning: a long semaphore wait: --Thread 139799247759104 has waited at trx0undo.c line 1759 for 244.00 seconds the semaphore: Mutex at 0x5c35050 created file trx0rseg.c line 210, lock var 1 waiters flag 1 InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:06:21 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ ===================================== 130401 18:06:41 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 9* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] [[ ... 3* "long semaphore wait" at trx0undo.c line 1759 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:07:01 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 9* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] [[ ... 4* "long semaphore wait" at trx0undo.c line 1759 ... ]] InnoDB: Warning: a long semaphore wait: --Thread 139799265822464 has waited at row0ins.c line 2008 for 244.00 seconds the semaphore: X-lock on RW-latch at 0x7f25991271c0 created in file buf0buf.c line 907 a writer (thread id 139799024846592) has reserved it in mode exclusive number of readers 0, waiters flag 1, lock_word: 0 Last time read locked in file row0sel.c line 3090 Last time write locked in file /pb2/build/sb_0-4575859-1324066572.98/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/row/row0ins.c line 2008 InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:07:21 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ ===================================== 130401 18:07:41 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 9* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] [[ ... 4* "long semaphore wait" at trx0undo.c line 1759 ... ]] [[ ... 2* "long semaphore wait" at row0ins.c line 2008 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:08:01 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 10* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] [[ ... 4* "long semaphore wait" at trx0undo.c line 1759 ... ]] [[ ... 3* "long semaphore wait" at row0ins.c line 2008 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:08:41 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 11* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] [[ ... 4* "long semaphore wait" at trx0undo.c line 1759 ... ]] [[ ... 4* "long semaphore wait" at row0ins.c line 2008 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:09:01 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ ===================================== 130401 18:09:21 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 11* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] [[ ... 4* "long semaphore wait" at trx0undo.c line 1759 ... ]] [[ ... 5* "long semaphore wait" at row0ins.c line 2008 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:09:41 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 11* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] [[ ... 4* "long semaphore wait" at trx0undo.c line 1759 ... ]] [[ ... 5* "long semaphore wait" at row0ins.c line 2008 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:10:01 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ ===================================== 130401 18:10:21 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 12* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] [[ ... 4* "long semaphore wait" at trx0undo.c line 1759 ... ]] [[ ... 5* "long semaphore wait" at row0ins.c line 2008 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:10:41 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 12* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] [[ ... 4* "long semaphore wait" at trx0undo.c line 1759 ... ]] [[ ... 6* "long semaphore wait" at row0ins.c line 2008 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:11:01 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ ===================================== 130401 18:11:21 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 12* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] [[ ... 4* "long semaphore wait" at trx0undo.c line 1759 ... ]] [[ ... 7* "long semaphore wait" at row0ins.c line 2008 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:11:41 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 12* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] [[ ... 4* "long semaphore wait" at trx0undo.c line 1759 ... ]] [[ ... 8* "long semaphore wait" at row0ins.c line 2008 ... ]] InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:12:01 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ ===================================== 130401 18:12:21 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream [[ ... 12* "long semaphore wait" at trx0undo.ic line 156 ... ]] [[ ... 1* "long semaphore wait" at btr0pcur.c line 398 ... ]] [[ ... 5* "long semaphore wait" at trx0undo.c line 1759 ... ]] [[ ... 11* "long semaphore wait" at row0ins.c line 2008 ... ]] InnoDB: Warning: a long semaphore wait: --Thread 139799241369344 has waited at trx0roll.c line 944 for 270.00 seconds the semaphore: Mutex at 0x5c35050 created file trx0rseg.c line 210, lock var 1 waiters flag 1 InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 ===================================== 130401 18:12:41 INNODB MONITOR OUTPUT [[ ... monitor output deleted ... ]] END OF INNODB MONITOR OUTPUT ============================ InnoDB: ###### Diagnostic info printed to the standard error stream InnoDB: Error: semaphore wait has lasted > 600 seconds InnoDB: We intentionally crash the server, because it appears to be hung. 130401 18:13:01 InnoDB: Assertion failure in thread 139799284872960 in file srv0srv.c line 2454 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. Please refer to InnoDB: http://dev.mysql.com/doc/refman/5.5/en/forcing-innodb-recovery.html InnoDB: about forcing recovery. 16:13:01 UTC - mysqld got signal 6 ; 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=204800 read_buffer_size=262144 max_used_connections=77 max_threads=1000 thread_count=78 connection_count=77 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 331606 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 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... stack_bottom = 0 thread_stack 0x40000 /usr/sbin/mysqld(my_print_stacktrace+0x35)[0x79a725] /usr/sbin/mysqld(handle_fatal_signal+0x403)[0x669943] /lib64/libpthread.so.0[0x32dba0f520] /lib64/libc.so.6(gsignal+0x35)[0x32db232a45] /lib64/libc.so.6(abort+0x175)[0x32db234225] /usr/sbin/mysqld[0x7e854e] /lib64/libpthread.so.0[0x32dba077e1] /lib64/libc.so.6(clone+0x6d)[0x32db2e68ed] The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains information that should help you find out what is causing the crash. 130401 18:13:01 mysqld_safe Number of processes running now: 0 130401 18:13:01 mysqld_safe mysqld restarted 130401 18:13:01 InnoDB: The InnoDB memory heap is disabled 130401 18:13:01 InnoDB: Mutexes and rw_locks use GCC atomic builtins 130401 18:13:01 InnoDB: Compressed tables use zlib 1.2.3 130401 18:13:01 InnoDB: Using Linux native AIO 130401 18:13:01 InnoDB: Initializing buffer pool, size = 1.0G 130401 18:13:01 InnoDB: Completed initialization of buffer pool 130401 18:13:01 InnoDB: highest supported file format is Barracuda. InnoDB: Log scan progressed past the checkpoint lsn 98073356340 130401 18:13:01 InnoDB: Database was not shut down normally! InnoDB: Starting crash recovery. InnoDB: Reading tablespace information from the .ibd files... InnoDB: Restoring possible half-written data pages from the doublewrite InnoDB: buffer... InnoDB: Doing recovery: scanned up to log sequence number 98074023137 130401 18:13:02 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 InnoDB: Last MySQL binlog file position 0 171877329, file name /san/mysqlreplication/master/log-bin.000162 130401 18:13:03 InnoDB: Error: table 'cactiber/poller_time' InnoDB: in InnoDB data dictionary has tablespace id 56275, InnoDB: but a tablespace with that id does not exist. There is InnoDB: a tablespace of name ./cactiber/poller_time.ibd and id 56276, though. Have InnoDB: you deleted or moved .ibd files? InnoDB: Please refer to InnoDB: http://dev.mysql.com/doc/refman/5.5/en/innodb-troubleshooting-datadict.html InnoDB: for how to resolve the issue. 130401 18:13:03 InnoDB: Waiting for the background threads to start 130401 18:13:04 InnoDB: 1.1.8 started; log sequence number 98074023137 130401 18:13:04 [Note] Recovering after a crash using /san/mysqlreplication/master/log-bin 130401 18:13:04 [Note] Starting crash recovery... 130401 18:13:04 [Note] Crash recovery finished. 130401 18:13:04 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=bersql07-relay-bin' to avoid this problem. 130401 18:13:04 [ERROR] Native table 'performance_schema'.'events_waits_current' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'events_waits_history' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'events_waits_history_long' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'setup_consumers' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'setup_instruments' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'setup_timers' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'performance_timers' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'threads' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'events_waits_summary_by_thread_by_event_name' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'events_waits_summary_by_instance' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'events_waits_summary_global_by_event_name' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'file_summary_by_event_name' has the wrong structure 130401 18:13:04 [Note] Slave SQL thread initialized, starting replication in log 'log-bin.000145' at position 18969009, relay log './bersql07-relay-bin.000419' position: 18969153 130401 18:13:04 [ERROR] Native table 'performance_schema'.'file_summary_by_instance' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'mutex_instances' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'rwlock_instances' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'cond_instances' has the wrong structure 130401 18:13:04 [ERROR] Native table 'performance_schema'.'file_instances' has the wrong structure 130401 18:13:04 [Note] Event Scheduler: Loaded 1 event 130401 18:13:04 [Note] /usr/sbin/mysqld: ready for connections. Version: '5.5.20-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 MySQL Community Server (GPL) 130401 18:13:04 [Note] Event Scheduler: scheduler thread started with id 3 130401 18:13:04 [Note] Slave I/O thread: connected to master 'replication@10.7.150.49:3306',replication started in log 'log-bin.000145' at position 37407078 130401 18:14:01 InnoDB: error: space object of table 'cactiber/poller_time', InnoDB: space id 56275 did not exist in memory. Retrying an open. 130401 18:14:01 InnoDB: Error: tablespace id and flags in file './cactiber/poller_time.ibd' are 56276 and 0, but in the InnoDB InnoDB: data dictionary they are 56275 and 0. InnoDB: Have you moved InnoDB .ibd files around without using the InnoDB: commands DISCARD TABLESPACE and IMPORT TABLESPACE? InnoDB: Please refer to InnoDB: http://dev.mysql.com/doc/refman/5.5/en/innodb-troubleshooting-datadict.html InnoDB: for how to resolve the issue. 130401 18:14:01 InnoDB: cannot calculate statistics for table cactiber/poller_time InnoDB: because the .ibd file is missing. For help, please refer to InnoDB: http://dev.mysql.com/doc/refman/5.5/en/innodb-troubleshooting.html 130401 18:14:01 [ERROR] MySQL is trying to open a table handle but the .ibd file for table cactiber/poller_time does not exist. Have you deleted the .ibd file from the database directory under the MySQL datadir, or have you used DISCARD TABLESPACE? See http://dev.mysql.com/doc/refman/5.5/en/innodb-troubleshooting.html how you can resolve the problem. 130401 18:14:04 InnoDB: cannot calculate statistics for table cactiber/poller_time InnoDB: because the .ibd file is missing. For help, please refer to InnoDB: http://dev.mysql.com/doc/refman/5.5/en/innodb-troubleshooting.html ... [[ Message groups like that from 18:14:01 repeat for all accesses to that table ]]