2013-04-16 119 views
3

我在Debian 6.0的MySQL(0.5GB數據庫)中使用InnoDB。簡單的MySQL查詢耗時太長

今天早上(完美運行時間120天后),突然服務器掛起(實際上服務器在過去兩天內第二次掛起),我不得不通過主機CP重新啓動服務器。

在kern.log,我有這樣的:

Apr 16 09:43:35 lhost kernel: [76680.208104] INFO: task mysqld:9755 blocked for more than 120 seconds. 
Apr 16 09:43:35 lhost kernel: [76680.233913] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 
Apr 16 09:43:35 lhost kernel: [76680.234249] mysqld  D ffff88007dc67170  0 9755 1241 0x00000000 
Apr 16 09:43:35 lhost kernel: [76680.234472] ffff88007dc67170 0000000000000086 0000000000000000 ffffffffa021c4c2 
Apr 16 09:43:35 lhost kernel: [76680.234815] ffff880009ff1ad8 ffff880009ff1ad8 000000000000f9e0 ffff880009ff1fd8 
Apr 16 09:43:35 lhost kernel: [76680.235181] 0000000000015780 0000000000015780 ffff88007d177170 ffff88007d177468 
Apr 16 09:43:35 lhost kernel: [76680.235549] Call Trace: 
Apr 16 09:43:35 lhost kernel: [76680.235732] [<ffffffffa021c4c2>] ? ext4_mark_iloc_dirty+0x46e/0x4f7 [ext4] 
Apr 16 09:43:35 lhost kernel: [76680.235963] [<ffffffffa021cd61>] ? ext4_mark_inode_dirty+0x18f/0x1c4 [ext4] 
Apr 16 09:43:35 lhost kernel: [76680.236212] [<ffffffff812fc2ab>] ? __mutex_lock_common+0x122/0x192 
Apr 16 09:43:35 lhost kernel: [76680.236422] [<ffffffff812fc3d3>] ? mutex_lock+0x1a/0x31 
Apr 16 09:43:35 lhost kernel: [76680.236626] [<ffffffff81113c8c>] ? __blockdev_direct_IO+0x1d3/0xa60 
Apr 16 09:43:35 lhost kernel: [76680.236852] [<ffffffff810b51c2>] ? generic_file_buffered_write+0x1f5/0x278 
Apr 16 09:43:35 lhost kernel: [76680.237097] [<ffffffffa021da26>] ? ext4_ind_direct_IO+0x10e/0x1be [ext4] 
Apr 16 09:43:35 lhost kernel: [76680.237320] [<ffffffffa02205c9>] ? ext4_get_block+0x0/0xe2 [ext4] 
Apr 16 09:43:35 lhost kernel: [76680.237528] [<ffffffff810b57bf>] ? generic_file_aio_read+0xf6/0x536 
Apr 16 09:43:35 lhost kernel: [76680.237794] [<ffffffff81071dbf>] ? wake_futex+0x31/0x4e 
Apr 16 09:43:35 lhost kernel: [76680.237984] [<ffffffff810ef061>] ? do_sync_read+0xce/0x113 
Apr 16 09:43:35 lhost kernel: [76680.238278] [<ffffffff8100f79c>] ? __switch_to+0x285/0x297 
Apr 16 09:43:35 lhost kernel: [76680.238471] [<ffffffff81065046>] ? autoremove_wake_function+0x0/0x2e 
Apr 16 09:43:35 lhost kernel: [76680.238687] [<ffffffff81048282>] ? finish_task_switch+0x3a/0xaf 
Apr 16 09:43:35 lhost kernel: [76680.238897] [<ffffffff810efa84>] ? vfs_read+0xa6/0xff 
Apr 16 09:43:35 lhost kernel: [76680.239090] [<ffffffff810efb34>] ? sys_pread64+0x57/0x77 
Apr 16 09:43:35 lhost kernel: [76680.239290] [<ffffffff81010b42>] ? system_call_fastpath+0x16/0x1b 

而剛剛完成停電前:

Apr 16 09:45:32 lhost kernel: [76800.253284] [<ffffffff81010b42>] ? system_call_fastpath+0x16/0x1b 
Apr 16 09:56:29 lhost kernel: [77453.643191] Clocksource tsc unstable (delta = -788398275 ns) 
Apr 16 10:01:01 lhost kernel: imklog 4.6.4, log source = /proc/kmsg started. 

所以我決定把慢查詢日誌上,這是什麼已記錄:

# Time: 130416 13:38:41 
# [email protected]: lhost[lhost] @ localhost [] 
# Query_time: 2.059521 Lock_time: 0.000026 Rows_sent: 0 Rows_examined: 1 
use lhost; 
SET timestamp=1366105121; 
UPDATE t_fuser SET DATE_UPDATE=now() WHERE ID = 992277; 
# Time: 130416 13:56:42 
# [email protected]: root[root] @ localhost [] 
# Query_time: 3.663760 Lock_time: 0.000037 Rows_sent: 230 Rows_examined: 230 
SET timestamp=1366106202; 
SHOW TABLE STATUS FROM `lhost`; 
# [email protected]: root[root] @ localhost [] 
# Query_time: 3.693291 Lock_time: 0.000031 Rows_sent: 230 Rows_examined: 230 
SET timestamp=1366106202; 
SHOW TABLE STATUS FROM `lhost`; 
# Time: 130416 14:00:19 
# [email protected]: lhost[lhost] @ localhost [] 
# Query_time: 7.139369 Lock_time: 0.000210 Rows_sent: 122 Rows_examined: 3027170 

這對我來說看起來很奇怪。我試着直接通過控制檯執行類似的查詢(日誌中有更復雜的查詢,但這不是重點),並且得到的結果要快得多,所以它不是索引。

我能做些什麼來解決這個問題?它是硬件嗎?

# free -m 
      total  used  free  shared buffers  cached 
Mem:   2012  1355  657   0   40  627 
-/+ buffers/cache:  687  1325 
Swap:   2047  129  1918 

在此先感謝您的建議。

附加信息:慢查詢的

CPU Usage - munin Memory Usage - munin

PROFILE:

mysql> show profile; 
+--------------------------------+----------+ 
| Status       | Duration | 
+--------------------------------+----------+ 
| starting      | 0.000020 | 
| checking query cache for query | 0.000111 | 
| checking permissions   | 0.000003 | 
| checking permissions   | 0.000001 | 
| checking permissions   | 0.000002 | 
| checking permissions   | 0.000001 | 
| checking permissions   | 0.000003 | 
| Opening tables     | 0.000032 | 
| System lock     | 0.000004 | 
| Table lock      | 0.000006 | 
| init       | 0.000074 | 
| optimizing      | 0.000020 | 
| statistics      | 0.000171 | 
| preparing      | 0.000027 | 
| Creating tmp table    | 0.000160 | 
| executing      | 0.000003 | 
| Copying to tmp table   | 4.572503 | 
| Creating sort index   | 0.009622 | 
| Copying to group table   | 0.029744 | 
| Removing duplicates   | 0.010745 | 
| Sorting result     | 0.000086 | 
| Sending data     | 0.004350 | 
| end       | 0.000008 | 
| removing tmp table    | 0.001207 | 
| end       | 0.000005 | 
| removing tmp table    | 0.000040 | 
| end       | 0.000004 | 
| query end      | 0.000003 | 
| freeing items     | 0.000018 | 
| removing tmp table    | 0.000005 | 
| freeing items     | 0.002768 | 
| logging slow query    | 0.000004 | 
| logging slow query    | 0.000029 | 
| cleaning up     | 0.000006 | 
+--------------------------------+----------+ 
34 rows in set (0.00 sec) 

回答

0

首先試圖執行的fsck然後檢查IO性能:DD如果= =的的/ dev /零/ var/lib/mysql/file1 bs = 512 count = 10000

+0

複製5120000字節(5.1 MB),0.0198583 s,258 MB/s \t命令正在計時:「dd if =/dev/zero of =/var/lib/mysql/file1 bs = 512 count = 10000」 \t用戶時間(秒):0.00 \t系統時間(秒):0.01 第一次和437MB/s的後續嘗試 –

+0

你可以做的是運行你的查詢與分析:SET profiling = 1;您的查詢 ; SHOW PROFILE; – user1209304

+0

你可能是對的。我更新了帖子。 '| |複製到tmp表| | 4.572503 |' –