===================================== 080412 12:33:25 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 16 seconds ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 1898153642, signal count 1792171726 --Thread 1160853824 has waited at dict0dict.c line 298 for 807.00 seconds the semaphore: Mutex at 0x2aaab13128b8 created file dict0dict.c line 709, lock var 1 waiters flag 1 --Thread 1160055104 has waited at btr0sea.c line 1383 for 807.00 seconds the semaphore: X-lock on RW-latch at 0x2aaab130a0b8 created in file btr0sea.c line 139 a writer (thread id 1160055104) has reserved it in mode wait exclusive number of readers 1, waiters flag 1 Last time read locked in file btr0sea.c line 746 Last time write locked in file btr0sea.c line 1547 --Thread 1162451264 has waited at btr0sea.c line 1127 for 807.00 seconds the semaphore: S-lock on RW-latch at 0x2aaab130a0b8 created in file btr0sea.c line 139 a writer (thread id 1160055104) has reserved it in mode wait exclusive number of readers 1, waiters flag 1 Last time read locked in file btr0sea.c line 746 Last time write locked in file btr0sea.c line 1547 --Thread 1162185024 has waited at btr0sea.c line 1127 for 807.00 seconds the semaphore: S-lock on RW-latch at 0x2aaab130a0b8 created in file btr0sea.c line 139 a writer (thread id 1160055104) has reserved it in mode wait exclusive number of readers 1, waiters flag 1 Last time read locked in file btr0sea.c line 746 Last time write locked in file btr0sea.c line 1547 --Thread 1161386304 has waited at btr0sea.c line 1127 for 807.00 seconds the semaphore: S-lock on RW-latch at 0x2aaab130a0b8 created in file btr0sea.c line 139 a writer (thread id 1160055104) has reserved it in mode wait exclusive number of readers 1, waiters flag 1 Last time read locked in file btr0sea.c line 746 Last time write locked in file btr0sea.c line 1547 --Thread 1159788864 has waited at dict0dict.c line 298 for 807.00 seconds the semaphore: Mutex at 0x2aaab13128b8 created file dict0dict.c line 709, lock var 1 waiters flag 1 --Thread 1161652544 has waited at btr0sea.c line 1127 for 807.00 seconds the semaphore: S-lock on RW-latch at 0x2aaab130a0b8 created in file btr0sea.c line 139 a writer (thread id 1160055104) has reserved it in mode wait exclusive number of readers 1, waiters flag 1 Last time read locked in file btr0sea.c line 746 Last time write locked in file btr0sea.c line 1547 --Thread 1159256384 has waited at btr0sea.c line 1127 for 807.00 seconds the semaphore: S-lock on RW-latch at 0x2aaab130a0b8 created in file btr0sea.c line 139 a writer (thread id 1160055104) has reserved it in mode wait exclusive number of readers 1, waiters flag 1 Last time read locked in file btr0sea.c line 746 Last time write locked in file btr0sea.c line 1547 --Thread 1158457664 has waited at row0mysql.c line 1720 for 807.00 seconds the semaphore: S-lock on RW-latch at 0xbf0620 created in file dict0dict.c line 725 a writer (thread id 1160055104) has reserved it in mode exclusive number of readers 0, waiters flag 1 Last time read locked in file row0mysql.c line 1720 Last time write locked in file row0mysql.c line 1755 --Thread 1157658944 has waited at btr0sea.c line 916 for 806.00 seconds the semaphore: S-lock on RW-latch at 0x2aaab130a0b8 created in file btr0sea.c line 139 a writer (thread id 1160055104) has reserved it in mode wait exclusive number of readers 1, waiters flag 1 Last time read locked in file btr0sea.c line 746 Last time write locked in file btr0sea.c line 1547 --Thread 1160321344 has waited at btr0sea.c line 1127 for 612.00 seconds the semaphore: S-lock on RW-latch at 0x2aaab130a0b8 created in file btr0sea.c line 139 a writer (thread id 1160055104) has reserved it in mode wait exclusive number of readers 1, waiters flag 1 Last time read locked in file btr0sea.c line 746 Last time write locked in file btr0sea.c line 1547 Mutex spin waits 0, rounds 805079298239, OS waits 950609776 RW-shared spins 33399613, OS waits 5988067; RW-excl spins 57997867, OS waits 2106599 ------------ TRANSACTIONS ------------ Trx id counter 1 4216958589 Purge done for trx's n:o < 1 4216920753 undo n:o < 0 0 History list length 2 Total number of lock structs in row lock hash table 1 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 1 4216958487, not started, process no 556, OS thread id 1161386304 estimating records in index range mysql tables in use 1, locked 0 MySQL thread id 120378, query id 111521622 prod8.collectiveintellect.com 10.10.11.41 cidev statistics select msg.alg_ci_rank_rollup from dw_hist_message_fact msg where msg.dw_source_dim_id = '3259813' and msg.dw_date_dim_id between '20080405' and '20080411' and msg.valid = 'V' and msg.alg_ci_rank_rollup > 0 and msg.dw_topic_dim_id in (1,11599,11600,11601,11602,11603,11604,11605,11606,11607,11608,11610,11611,11612,11613,11614,11615,11616,11617,11618,11619,11620,11621,11622,11623,11624,11625,11626,11627,11628,11629,11630,11631,11632,11658,11661,11662,11663,11669,11683,11726,11753,11764,11765,11766,11767,11772,11777,117 ---TRANSACTION 1 4216958490, not started, process no 556, OS thread id 1161652544 estimating records in index range mysql tables in use 1, locked 0 MySQL thread id 120350, query id 111521630 prod8.collectiveintellect.com 10.10.11.41 cidev statistics select count(msg.dw_hist_message_fact_id) from dw_hist_message_fact msg where msg.dw_source_dim_id = '4611069' and msg.valid = 'V' and msg.dw_date_dim_id between '20080405' and '20080411' and msg.dw_topic_dim_id in (1,11599,11600,11601,11602,11603,11604,11605,11606,11607,11608,11610,11611,11612,11613,11614,11615,11616,11617,11618,11619,11620,11621,11622,11623,11624,11625,11626,11627,11628,11629,11630,11631,11632,11658,11661,11662,11663,11669,11683,11726,11753,11764,11765,11766,11767,11772,11777,11779,11780,11782,11 ---TRANSACTION 1 4216958495, not started, process no 556, OS thread id 1159256384 estimating records in index range mysql tables in use 1, locked 0 MySQL thread id 120322, query id 111521631 prod8.collectiveintellect.com 10.10.11.41 cidev statistics select msg.alg_ci_rank_rollup from dw_hist_message_fact msg where msg.dw_source_dim_id = '7562287' and msg.valid = 'V' and msg.dw_date_dim_id between '20080405' and '20080411' and msg.alg_ci_rank_rollup > 0 and msg.dw_topic_dim_id in (1,11599,11600,11601,11602,11603,11604,11605,11606,11607,11608,11610,11611,11612,11613,11614,11615,11616,11617,11618,11619,11620,11621,11622,11623,11624,11625,11626,11627,11628,11629,11630,11631,11632,11658,11661,11662,11663,11669,11683,11726,11753,11764,11765,11766,11767,11772,11777,117 ---TRANSACTION 1 4216958477, not started, process no 556, OS thread id 1162185024 estimating records in index range mysql tables in use 1, locked 0 MySQL thread id 120208, query id 111521619 prod8.collectiveintellect.com 10.10.11.41 cidev statistics select msg.alg_ci_rank_rollup from dw_hist_message_fact msg where msg.dw_source_dim_id = '1420788' and msg.valid = 'V' and msg.dw_date_dim_id between '20080405' and '20080411' and msg.alg_ci_rank_rollup > 0 and msg.dw_topic_dim_id in (1786,1787,1789,1790,1796,1797,1801,1802,1805,1806,1808,1809,1811,1812,1813,1817,1818,1819,1820,1825,1828,1830,1837,1838,1841,1842,1843,1847,1848,1849,1851,1852,1853,1854,1856,1858,1860,1862,1863,1866,1870,1874,1875,1876,1877,1878,1880,1881,1882,1883,1884,1887,1893,1895,1897,1898,1899,19 ---TRANSACTION 1 4216958488, not started, process no 556, OS thread id 1162451264 estimating records in index range mysql tables in use 1, locked 0 MySQL thread id 120095, query id 111521623 prod8.collectiveintellect.com 10.10.11.41 cidev statistics select count(msg.dw_hist_message_fact_id) from dw_hist_message_fact msg where msg.dw_source_dim_id = '7638555' and msg.dw_date_dim_id between '20080405' and '20080411' and msg.alg_ci_rank_rollup > 0 and msg.dw_topic_dim_id in (1786,1790,1802,1805,1806,1808,1809,1812,1813,1818,1819,1825,1828,1838,1841,1847,1848,1851,1852,1853,1854,1856,1858,1860,1862,1863,1870,1876,1877,1878,1880,1883,1884,1887,1893,1895,1897,1898,1899,1900,1902,1904,1905,1908,1911,1912,1915,1916,1918,1926,1927,1930,1931,1933,1934,1938,1939,1941,1942,1944,1947,1961,196 ---TRANSACTION 1 4216958588, ACTIVE 612 sec, process no 556, OS thread id 1160321344 starting index read, thread declared inside InnoDB 500 mysql tables in use 1, locked 0 MySQL thread id 120180, query id 111521841 prod8.collectiveintellect.com 10.10.11.41 cidev statistics SELECT * FROM ci_post_node WHERE (ci_post_node.`id` = '579651' ) LIMIT 1 ---TRANSACTION 1 4216958496, ACTIVE 807 sec, process no 556, OS thread id 1158457664 inserting, thread declared inside InnoDB 500 mysql tables in use 1, locked 1 2 lock struct(s), heap size 368, undo log entries 1 MySQL thread id 120265, query id 111521633 prod8.collectiveintellect.com 10.10.11.41 cidev update INSERT INTO ci_site_mavens (`name`, `score`, `feed`, `ci_maven_net_id`, `author`, `url`, `creation_date_id`, `maven_period_length`) VALUES('** that doesn\'t kill me can only make me stronger ll', 0.03423482674, 'http://soulnoire.livejournal.com/data/atom', 167, NULL, 'soulnoire.livejournal.com', 20080411, 7) ---TRANSACTION 1 4216958493, ACTIVE 807 sec, process no 556, OS thread id 1160055104 inserting, thread declared inside InnoDB 500 mysql tables in use 1, locked 1 ROLLING BACK 3 lock struct(s), heap size 368 MySQL thread id 120123, query id 111521628 prod8.collectiveintellect.com 10.10.11.41 cidev update INSERT INTO ci_post_link (`creation_day_id`, `creation_time_id`, `ci_maven_net_id`, `level`, `destination_id`, `source_id`) VALUES(20080411, '101010', 67, 3, 1383368, 1231366) ---TRANSACTION 1 4216958485, ACTIVE 807 sec, process no 556, OS thread id 1159788864, thread declared inside InnoDB 19 mysql tables in use 2, locked 0 MySQL thread id 120010, query id 111521620 prod8.collectiveintellect.com 10.10.11.41 cidev Sending data select site.score from ci_site_mavens site, authors author, sources source, rss_feeds feed where author.id = 2609699 and author.source_id = source.id and site.ci_maven_net_id = 9 and site.creation_date_id = 20080404 and source.rss_feed_id = feed.id and (site.url = feed.href or site.feed = feed.rss_url) Trx read view will not see trx with id >= 1 4216958486, sees < 1 4216958465 ---TRANSACTION 1 4216958465, ACTIVE 808 sec, process no 556, OS thread id 1160853824, thread declared inside InnoDB 497 mysql tables in use 6, locked 0 , holds adaptive hash latch MySQL thread id 120152, query id 111521591 prod8.collectiveintellect.com 10.10.11.41 cidev Copying to tmp table select distinct a.id, s.rss_feed_id, m.score from ci_site_mavens m straight_join rss_feeds r on (m.url = r.href or m.feed = r.rss_url) join sources s on s.rss_feed_id = r.id and s.source_type = 'BlogSite' and s.agent_id = 0 join authors a on a.source_id = s.id where m.ci_maven_net_id = 88 and m.creation_date_id = '20080411' Trx read view will not see trx with id >= 1 4216958466, sees < 1 4216958459 -------- 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 28108992 OS file reads, 47442700 OS file writes, 3719652 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: size 38, free list len 17259, seg size 17298, 35774218 inserts, 35769736 merged recs, 4559240 merges Hash table size 41503559, used cells 34735640, node heap has 111049 buffer(s) 0.00 hash searches/s, 0.00 non-hash searches/s --- LOG --- Log sequence number 1081 1311120613 Log flushed up to 1081 1311120613 Last checkpoint at 1081 1054482866 0 pending log writes, 0 pending chkp writes 1628359 log i/o's done, 0.00 log i/o's/second ---------------------- BUFFER POOL AND MEMORY ---------------------- Total memory allocated 23294339552; in additional pool allocated 18750464 Buffer pool size 1280000 Free buffers 0 Database pages 1168950 Modified db pages 109773 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages read 37527297, created 4814619, written 83118768 0.00 reads/s, 0.00 creates/s, 0.00 writes/s No buffer pool page gets since the last printout -------------- ROW OPERATIONS -------------- 5 queries inside InnoDB, 0 queries in queue 3 read views open inside InnoDB 1 tablespace extents now reserved for B-tree split operations Main thread process no. 556, id 1157658944, state: doing insert buffer merge Number of rows inserted 384365275, updated 1213051, deleted 72081301, read 295010973272 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s ---------------------------- 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. 080412 12:33:34InnoDB: Assertion failure in thread 1147169088 in file srv0srv.c line 2093 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.0/en/forcing-recovery.html InnoDB: about forcing recovery. 080412 12:33:34 - 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=8388600 read_buffer_size=2093056 max_used_connections=17 max_connections=200 threads_connected=11 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 2055390 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. thd=(nil) 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... frame pointer is NULL, did you compile with -fomit-frame-pointer? Aborting backtrace! 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 080412 12:33:36 mysqld restarted 080412 12:33:41 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... 080412 12:33:41 InnoDB: Starting log scan based on checkpoint at InnoDB: log sequence number 1081 1054482866. InnoDB: Doing recovery: scanned up to log sequence number 1081 1059725312 InnoDB: Doing recovery: scanned up to log sequence number 1081 1064968192 InnoDB: Doing recovery: scanned up to log sequence number 1081 1070211072 InnoDB: Doing recovery: scanned up to log sequence number 1081 1075453952 InnoDB: Doing recovery: scanned up to log sequence number 1081 1080696832 InnoDB: Doing recovery: scanned up to log sequence number 1081 1085939712 InnoDB: Doing recovery: scanned up to log sequence number 1081 1091182592 InnoDB: Doing recovery: scanned up to log sequence number 1081 1096425472 InnoDB: Doing recovery: scanned up to log sequence number 1081 1101668352 InnoDB: Doing recovery: scanned up to log sequence number 1081 1106911232 InnoDB: Doing recovery: scanned up to log sequence number 1081 1112154112 InnoDB: Doing recovery: scanned up to log sequence number 1081 1117396992 InnoDB: Doing recovery: scanned up to log sequence number 1081 1122639872 InnoDB: Doing recovery: scanned up to log sequence number 1081 1127882752 InnoDB: Doing recovery: scanned up to log sequence number 1081 1133125632 InnoDB: Doing recovery: scanned up to log sequence number 1081 1138368512 InnoDB: Doing recovery: scanned up to log sequence number 1081 1143611392 InnoDB: Doing recovery: scanned up to log sequence number 1081 1148854272 InnoDB: Doing recovery: scanned up to log sequence number 1081 1154097152 InnoDB: Doing recovery: scanned up to log sequence number 1081 1159340032 InnoDB: Doing recovery: scanned up to log sequence number 1081 1164582912 InnoDB: Doing recovery: scanned up to log sequence number 1081 1169825792 InnoDB: Doing recovery: scanned up to log sequence number 1081 1175068672 InnoDB: Doing recovery: scanned up to log sequence number 1081 1180311552 InnoDB: Doing recovery: scanned up to log sequence number 1081 1185554432 InnoDB: Doing recovery: scanned up to log sequence number 1081 1190797312 InnoDB: Doing recovery: scanned up to log sequence number 1081 1196040192 InnoDB: Doing recovery: scanned up to log sequence number 1081 1201283072 InnoDB: Doing recovery: scanned up to log sequence number 1081 1206525952 InnoDB: Doing recovery: scanned up to log sequence number 1081 1211768832 InnoDB: Doing recovery: scanned up to log sequence number 1081 1217011712 InnoDB: Doing recovery: scanned up to log sequence number 1081 1222254592 InnoDB: Doing recovery: scanned up to log sequence number 1081 1227497472 InnoDB: Doing recovery: scanned up to log sequence number 1081 1232740352 InnoDB: Doing recovery: scanned up to log sequence number 1081 1237983232 InnoDB: Doing recovery: scanned up to log sequence number 1081 1243226112 InnoDB: Doing recovery: scanned up to log sequence number 1081 1248468992 InnoDB: Doing recovery: scanned up to log sequence number 1081 1253711872 InnoDB: Doing recovery: scanned up to log sequence number 1081 1258954752 InnoDB: Doing recovery: scanned up to log sequence number 1081 1264197632 InnoDB: Doing recovery: scanned up to log sequence number 1081 1269440512 InnoDB: Doing recovery: scanned up to log sequence number 1081 1274683392 InnoDB: Doing recovery: scanned up to log sequence number 1081 1279926272 InnoDB: Doing recovery: scanned up to log sequence number 1081 1285169152 InnoDB: Doing recovery: scanned up to log sequence number 1081 1290412032 InnoDB: Doing recovery: scanned up to log sequence number 1081 1295654912 InnoDB: Doing recovery: scanned up to log sequence number 1081 1300897792 InnoDB: Doing recovery: scanned up to log sequence number 1081 1306140672 InnoDB: Doing recovery: scanned up to log sequence number 1081 1311120613 InnoDB: 2 transaction(s) which must be rolled back or cleaned up InnoDB: in total 2 row operations to undo InnoDB: Trx id counter is 1 4216958976 080412 12:34:18 InnoDB: Starting an apply batch of log records to the database... InnoDB: Progress in percents: 0 1 2 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: In a MySQL replication slave the last master binlog file InnoDB: position 0 1445, file name mysql-bin.000477 InnoDB: Last MySQL binlog file position 0 929354536, file name ./mysql-bin.000039 InnoDB: Starting in background the rollback of uncommitted transactions 080412 12:53:38 InnoDB: Rolling back trx with id 1 4216958496, 1 rows to undo 080412 12:53:38 InnoDB: Started; log sequence number 1081 1311120613 080412 12:53:38 [Note] Recovering after a crash using mysql-bin