郵件告警發現海外工廠一Linux伺服器連接不上，DPA（Database Performance Analyzer）系統也發現其出現問題，ping這台伺服器發現網路不通，聯繫不到當地系統管理員，郵件咨詢後，這個系統管理員也發現有問題，直接重啟了，事後檢查發現日誌message裡面，從10:10分開始... ...
郵件告警發現海外工廠一Linux伺服器連接不上，DPA（Database Performance Analyzer）系統也發現其出現問題，ping這台伺服器發現網路不通，聯繫不到當地系統管理員，郵件咨詢後，這個系統管理員也發現有問題，直接重啟了，事後檢查發現日誌message裡面，從10:10分開始出現下麵錯誤信息（敏感信息處理了）
Jul 7 10:10:27 localhost kernel: ata2.00: qc timeout (cmd 0xa0)
Jul 7 10:11:00 localhost kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
Jul 7 10:11:00 localhost kernel: sr 2:0:0:0: CDB: Test Unit Ready: 00 00 00 00 00 00
Jul 7 10:11:00 localhost kernel: ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
Jul 7 10:11:00 localhost kernel: res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x5 (timeout)
Jul 7 10:11:00 localhost kernel: ata2.00: status: { DRDY ERR }Jul 7 10:11:00 localhost kernel: ata2: soft resetting link
Jul 7 10:11:00 localhost kernel: INFO: task hald-addon-stor:3728 blocked for more than 120 seconds.Jul 7 10:11:00 localhost kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Jul 7 10:11:00 localhost kernel: hald-addon-st D ffff8801989b6080 0 3728 3690 0x00000080
Jul 7 10:11:00 localhost kernel: ffff880428dd76a8 0000000000000082 ffff880428dd7668 ffff88042c6300d0
Jul 7 10:11:00 localhost kernel: ffff8804294ac0c0 ffff88040d730700 ffff8804294ac490 ffffffff812ef88e
Jul 7 10:11:00 localhost kernel: ffff880428dd76a8 ffffffff81311442 ffff88042c630000 7fffffffffffffff
Jul 7 10:12:06 localhost kernel: Call Trace:
Jul 7 10:12:06 localhost kernel: [<ffffffff812ef88e>] ? scsi_done+0x0/0x17
Jul 7 10:12:06 localhost kernel: [<ffffffff81311442>] ? __ata_scsi_queuecmd+0x1a6/0x200
Jul 7 10:12:06 localhost kernel: [<ffffffff814527e9>] schedule_timeout+0x36/0xe7
Jul 7 10:12:06 localhost kernel: [<ffffffff812331b6>] ? kobject_put+0x47/0x4c
Jul 7 10:12:06 localhost kernel: [<ffffffff8104367e>] ? need_resched+0x23/0x2d
Jul 7 10:12:06 localhost kernel: [<ffffffff8145265b>] wait_for_common+0xb7/0x12c
Jul 7 10:12:06 localhost kernel: [<ffffffff8104cf2f>] ? default_wake_function+0x0/0x19
Jul 7 10:12:06 localhost kernel: [<ffffffff8121e449>] ? __generic_unplug_device+0x32/0x37
Jul 7 10:12:06 localhost kernel: [<ffffffff81452773>] wait_for_completion+0x1d/0x1f
Jul 7 10:12:06 localhost kernel: [<ffffffff8122540b>] blk_execute_rq+0xcb/0x104
Jul 7 10:12:06 localhost kernel: [<ffffffff8121d88c>] ? freed_request+0x34/0x55
Jul 7 10:12:06 localhost kernel: [<ffffffff812f60af>] scsi_execute+0xde/0x12e
Jul 7 10:12:06 localhost kernel: [<ffffffff812f61cc>] scsi_execute_req+0xcd/0xf2
Jul 7 10:12:06 localhost kernel: [<ffffffff81302a9a>] sr_test_unit_ready+0x5c/0xb5
Jul 7 10:12:06 localhost kernel: [<ffffffff81302d0f>] sr_media_change+0x5d/0x28a
Jul 7 10:12:06 localhost kernel: [<ffffffff810448c9>] ? task_rq_unlock+0x11/0x13
Jul 7 10:12:06 localhost kernel: [<ffffffff8104cf08>] ? try_to_wake_up+0x3aa/0x3d1
Jul 7 10:12:06 localhost kernel: [<ffffffff8131f73f>] media_changed+0x53/0x88
Jul 7 10:12:06 localhost kernel: [<ffffffff8131f7a5>] cdrom_media_changed+0x31/0x37
Jul 7 10:12:06 localhost kernel: [<ffffffff81303072>] sr_block_media_changed+0x19/0x1b
Jul 7 10:12:06 localhost kernel: [<ffffffff8114407d>] check_disk_change+0x29/0x5b
Jul 7 10:12:06 localhost kernel: [<ffffffff81322f9b>] cdrom_open+0x919/0x9b9
Jul 7 10:12:06 localhost kernel: [<ffffffff810447f2>] ? __wake_up_sync_key+0x53/0x5f
Jul 7 10:12:06 localhost kernel: [<ffffffff8142ebec>] ? unix_stream_recvmsg+0x40f/0x4d3
Jul 7 10:12:06 localhost kernel: [<ffffffff813b63b5>] ? skb_release_data+0xaa/0xaf
Jul 7 10:12:06 localhost kernel: [<ffffffff8142ebec>] ? unix_stream_recvmsg+0x40f/0x4d3
Jul 7 10:12:06 localhost kernel: [<ffffffff8104367e>] ? need_resched+0x23/0x2d
系統版本為Oracle Linux Server release 5.7， VMware虛擬機，剛開始檢查的時候，註意力集中在“ kernel: INFO: task hald-addon-stor:3728 blocked for more than 120 seconds”等相關信息上，關於hald-addon-store,這個是掛載媒體設備讀寫操作的進程，它是一個硬體守護進程，不停的檢測有沒有設備接入接出。
[root@localhost log]# grep 'Jul 7' messages | grep -E 'more than 120 seconds|hung_task_timeout_secs'Jul 7 10:11:00 localhost kernel: INFO: task hald-addon-stor:3728 blocked for more than 120 seconds.Jul 7 10:11:00 localhost kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Jul 7 10:12:06 localhost kernel: INFO: task hald-addon-stor:3728 blocked for more than 120 seconds.Jul 7 10:12:06 localhost kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Jul 7 10:17:39 localhost kernel: INFO: task hald-addon-stor:3728 blocked for more than 120 seconds.Jul 7 10:17:39 localhost kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.[root@localhost log]#
而關於“task blocked for more than 120 seconds”，網上很多資料都千篇一律的說，修改參數 vm.dirty_ratio 和 vm.dirty_backgroud_ratio 可以避免這個問題。但是我對這個還是有點疑慮，理由如下一些：
1：這台伺服器的vm.dirty_background_ratio 參數為10，vm.dirty_ratio為20。這個我查了一下，Redhat的官方文檔介紹這是預設值。
[root@localhost log]# sysctl -a | grep 'vm.dirty'vm.dirty_background_ratio = 10
vm.dirty_background_bytes = 0
vm.dirty_ratio = 20
vm.dirty_bytes = 0
vm.dirty_writeback_centisecs = 500
vm.dirty_expire_centisecs = 3000
2： 這台伺服器已經運行好多年了，如果這個參數有問題，理應經常出現這個問題，但是到目前為止只出現了一次這個問題。
3： 我們還有多台伺服器都是這個操作系統版本，內核參數同樣是官方的預設值，也沒有見到其出現過這樣的問題。
當然也不排除某些操作觸發了某些臨界值導致了這個錯誤。那麼我們還是繼續分析一下錯誤信息吧，看能否挖掘出一些信息。
sar -r 查看發現這一段時間的記憶體使用情況，已使用記憶體的百分數（%memused）非常高，已使用交換空間的百分數（%swapused）比例也在個位數到40%直接，伺服器在10:31重啟，10:00 到10:30之間的數據沒有，不清楚什麼原因導致。從這些數據也可以看出記憶體資源非常緊張。
另外也用sar -u查看了CPU，CPU使用率不高。基本正常，當時忘記查看I/O和傳送速率的統計信息（現在去查看，已經看不到昨天的數據了），另外在message日誌裡面看到有"ata2.00: status: { DRDY ERR }"， "ata2.00: qc timeout(cmd 0xa0)"; 之類的錯誤信息
關於這個錯誤，很多資料都說是硬碟故障或硬碟讀寫錯誤等等。也有說是內核bug的
當然我們系統的內核版本為2.6.32-200.13.1.el5uek ，這個https://lists.linuxfoundation.org/pipermail/bugme-new/2009-July/022389.html 鏈接也說了不止出現在2.6.31這個內核版本：
I have seen this messages not only on 2.6.31... also on many other 2.6 kernels.
但是自己的知識和經驗也無法判斷、定位問題，只能有個模糊的判斷，要麼是硬碟故障或讀寫錯誤，要麼是內核錯誤。讓那邊系統管理員去檢查存儲設備是否有什麼告警，暫時沒有回饋，檢查磁碟分區是否存在壞塊，發現沒有壞塊情況
[root@localhost ~]# /sbin/badblocks -v /dev/sdaChecking blocks 0 to 104857600
Checking for bad blocks (read-only test): done Pass completed, 0 bad blocks found.
[root@localhost ~]# /sbin/badblocks -v /dev/sdbChecking blocks 0 to 157286400
Checking for bad blocks (read-only test): done Pass completed, 0 bad blocks found.
[root@localhost ~]# /sbin/badblocks -v /dev/sdcChecking blocks 0 to 41943040
Checking for bad blocks (read-only test): done Pass completed, 0 bad blocks found.
[root@localhost ~]# /sbin/badblocks -v /dev/sddChecking blocks 0 to 104857600
Checking for bad blocks (read-only test): done Pass completed, 0 bad blocks found.
[root@localhost ~]# /sbin/badblocks -v /dev/sdeChecking blocks 0 to 188743680
Checking for bad blocks (read-only test): done Pass completed, 0 bad blocks found.
另外在message裡面發現系統啟動時，有大量BAR 13: can't allocate I/O resource [0x10000-0xffff]信息。
Jul 7 10:32:02 egvlnx03 kernel: ACPI: ACPI bus type pnp unregistered
Jul 7 10:32:02 egvlnx03 kernel: system 00:01: ioport range 0x1000-0x103f has been reserved
Jul 7 10:32:02 egvlnx03 kernel: system 00:01: ioport range 0x1040-0x104f has been reserved
Jul 7 10:32:02 egvlnx03 kernel: system 00:01: ioport range 0xcf0-0xcf1 has been reserved
Jul 7 10:32:02 egvlnx03 kernel: system 00:08: iomem range 0xfed00000-0xfed003ff has been reserved
Jul 7 10:32:02 egvlnx03 kernel: system 00:0d: ioport range 0xfce0-0xfcff has been reserved
Jul 7 10:32:02 egvlnx03 kernel: system 00:0d: iomem range 0xf0000000-0xf7ffffff has been reserved
Jul 7 10:32:02 egvlnx03 kernel: system 00:0d: iomem range 0xfe800000-0xfe9fffff has been reserved
Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:15.3: BAR 13: can't allocate I/O resource [0x10000-0xffff]Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:15.4: BAR 13: can't allocate I/O resource [0x10000-0xffff]
Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:15.5: BAR 13: can't allocate I/O resource [0x10000-0xffff]Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:15.6: BAR 13: can't allocate I/O resource [0x10000-0xffff]
Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:15.7: BAR 13: can't allocate I/O resource [0x10000-0xffff]Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:16.3: BAR 13: can't allocate I/O resource [0x10000-0xffff]
Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:16.4: BAR 13: can't allocate I/O resource [0x10000-0xffff]Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:16.5: BAR 13: can't allocate I/O resource [0x10000-0xffff]
Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:16.6: BAR 13: can't allocate I/O resource [0x10000-0xffff]Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:16.7: BAR 13: can't allocate I/O resource [0x10000-0xffff]
Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:17.3: BAR 13: can't allocate I/O resource [0x10000-0xffff]Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:17.4: BAR 13: can't allocate I/O resource [0x10000-0xffff]
Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:17.5: BAR 13: can't allocate I/O resource [0x10000-0xffff]Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:17.6: BAR 13: can't allocate I/O resource [0x10000-0xffff]
Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:17.7: BAR 13: can't allocate I/O resource [0x10000-0xffff]Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:18.2: BAR 13: can't allocate I/O resource [0x10000-0xffff]
Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:18.3: BAR 13: can't allocate I/O resource [0x10000-0xffff]Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:18.4: BAR 13: can't allocate I/O resource [0x10000-0xffff]
Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:18.5: BAR 13: can't allocate I/O resource [0x10000-0xffff]Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:18.6: BAR 13: can't allocate I/O resource [0x10000-0xffff]
Jul 7 10:32:02 egvlnx03 kernel: pci 0000:00:18.7: BAR 13: can't allocate I/O resource [0x10000-0xffff]
經過查證，有篇文章解釋了這個消息出現的原因，並表示可以忽略這個問題。
該消息表明內核無法分配預取記憶體插槽。
預取記憶體插槽的編號是 13(PCI_BRIDGE_RESOURCES)。
