Take the 2-minute tour ×
Server Fault is a question and answer site for professional system and network administrators. It's 100% free, no registration required.

I have a postgres server running since years and the load have been more or less constant (load average around 0.5-5). Yesterday it reached an average of 110!

It is a virtual server running Debian 5.0.4 (2.6.26-2-686 #1 SMP) and Postgres 8.3. The database and transaction logs are on separate filesystems (ext3). No other vm:s impose any load on this server and the vm has dedicated disks, so the vm is some how causing this on its own.

The system spent 99% of its time in iowait. When I stopped the postgres server the load returned to 0 at once.

The kernel seems to have issues with blocking/hanging io tasks. Could this be initial signs of hardware problems? Or are there other possible causes?

Here are the log statements:

Apr 25 08:32:32 mdb kernel: [2566091.564038] INFO: task postgres:9365 blocked for more than 120 seconds.
Apr 25 08:32:32 mdb kernel: [2566091.564152] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr 25 08:32:32 mdb kernel: [2566091.564319] postgres      D 605d234e     0  9365   4548
Apr 25 08:32:32 mdb kernel: [2566091.564322]        f78d49c0 00000082 c319a000 605d234e 00091dba f78d4b4c c2011fc0 00000000
Apr 25 08:32:32 mdb kernel: [2566091.564325]        00000000 f740ec40 006c40b6 00000000 c0131a24 f2761f24 00000101 00000001
Apr 25 08:32:32 mdb kernel: [2566091.564328]        ef23b8fc ef23b904 ef23b900 f78d49c0 c02b9146 f4141f44 ef71bf44 f78d49c0
Apr 25 08:32:32 mdb kernel: [2566091.564330] Call Trace:
Apr 25 08:32:32 mdb kernel: [2566091.564352]  [<c0131a24>] autoremove_wake_function+0x0/0x2d
Apr 25 08:32:32 mdb kernel: [2566091.564364]  [<c02b9146>] __mutex_lock_slowpath+0x50/0x7b
Apr 25 08:32:32 mdb kernel: [2566091.564374]  [<c02b8fdc>] mutex_lock+0xa/0xb
Apr 25 08:32:32 mdb kernel: [2566091.564376]  [<c0174efb>] generic_file_llseek+0x26/0xa1
Apr 25 08:32:32 mdb kernel: [2566091.564382]  [<c0174ed5>] generic_file_llseek+0x0/0xa1
Apr 25 08:32:32 mdb kernel: [2566091.564386]  [<c01741f5>] vfs_llseek+0x30/0x34
Apr 25 08:32:32 mdb kernel: [2566091.564390]  [<c017516a>] sys_llseek+0x41/0x82
Apr 25 08:32:32 mdb kernel: [2566091.564399]  [<c0103857>] sysenter_past_esp+0x78/0xb1
Apr 25 08:32:32 mdb kernel: [2566091.564417]  =======================

Apr 25 08:32:57 mdb kernel: [2566116.260420] INFO: task postgres:10444 blocked for more than 120 seconds.
Apr 25 08:32:57 mdb kernel: [2566116.260526] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr 25 08:32:57 mdb kernel: [2566116.260693] postgres      D 9ebc8733     0 10444   4548
Apr 25 08:32:57 mdb kernel: [2566116.260694]        f26d2f20 00000086 c319a000 9ebc8733 00091dba f26d30ac c2011fc0 00000000
Apr 25 08:32:57 mdb kernel: [2566116.260697]        00000000 f740ec40 00048e95 00000000 ee8e1e48 f28b7ac0 00000101 00000001
Apr 25 08:32:57 mdb kernel: [2566116.260700]        ef23b8fc ef23b904 ef23b900 f26d2f20 c02b9146 ee9edf44 f2761f44 f26d2f20
Apr 25 08:32:57 mdb kernel: [2566116.260702] Call Trace:
Apr 25 08:32:57 mdb kernel: [2566116.260721]  [<c02b9146>] __mutex_lock_slowpath+0x50/0x7b
Apr 25 08:32:57 mdb kernel: [2566116.260729]  [<c02b8fdc>] mutex_lock+0xa/0xb
Apr 25 08:32:57 mdb kernel: [2566116.260731]  [<c0174efb>] generic_file_llseek+0x26/0xa1
Apr 25 08:32:57 mdb kernel: [2566116.260736]  [<c0174ed5>] generic_file_llseek+0x0/0xa1
Apr 25 08:32:57 mdb kernel: [2566116.260740]  [<c01741f5>] vfs_llseek+0x30/0x34
Apr 25 08:32:57 mdb kernel: [2566116.260745]  [<c017516a>] sys_llseek+0x41/0x82
Apr 25 08:32:57 mdb kernel: [2566116.260753]  [<c0103857>] sysenter_past_esp+0x78/0xb1
Apr 25 08:32:57 mdb kernel: [2566116.260762]  [<c02b0000>] quirk_vt8235_acpi+0x10/0x7a
Apr 25 08:32:57 mdb kernel: [2566116.260771]  =======================

Apr 25 08:34:45 mdb kernel: [2566224.708037] INFO: task updatedb.mlocat:10645 blocked for more than 120 seconds.
Apr 25 08:34:45 mdb kernel: [2566224.708208] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr 25 08:34:45 mdb kernel: [2566224.708375] updatedb.mloc D 503a8c62     0 10645  10642
Apr 25 08:34:45 mdb kernel: [2566224.708378]        c240c9c0 00000086 00003057 503a8c62 00091dd7 c240cb4c c2011fc0 00000000
Apr 25 08:34:45 mdb kernel: [2566224.708381]        f259f1ec 7070f7b0 004394a5 00000000 7070f7b0 f259f1ec 7070f7b0 eebebd3c
Apr 25 08:34:45 mdb kernel: [2566224.708384]        c2011fc0 01c57000 eebebd3c c20024c8 c02b8d58 eebebd34 00000000 c0190bb6
Apr 25 08:34:45 mdb kernel: [2566224.708386] Call Trace:
Apr 25 08:34:45 mdb kernel: [2566224.708415]  [<c02b8d58>] io_schedule+0x49/0x80
Apr 25 08:34:45 mdb kernel: [2566224.708422]  [<c0190bb6>] sync_buffer+0x30/0x33
Apr 25 08:34:45 mdb kernel: [2566224.708425]  [<c02b8f46>] __wait_on_bit+0x33/0x58
Apr 25 08:34:45 mdb kernel: [2566224.708427]  [<c0190b86>] sync_buffer+0x0/0x33
Apr 25 08:34:45 mdb kernel: [2566224.708432]  [<c0190b86>] sync_buffer+0x0/0x33
Apr 25 08:34:45 mdb kernel: [2566224.708434]  [<c02b8fca>] out_of_line_wait_on_bit+0x5f/0x67
Apr 25 08:34:45 mdb kernel: [2566224.708442]  [<c0131a51>] wake_bit_function+0x0/0x3c
Apr 25 08:34:45 mdb kernel: [2566224.708450]  [<c0190b52>] __wait_on_buffer+0x16/0x18
Apr 25 08:34:45 mdb kernel: [2566224.708454]  [<f899853d>] ext3_find_entry+0x37a/0x515 [ext3]
Apr 25 08:34:45 mdb kernel: [2566224.708475]  [<c0117d1b>] kunmap_atomic+0x55/0x8a
Apr 25 08:34:45 mdb kernel: [2566224.708482]  [<c0117d2d>] kunmap_atomic+0x67/0x8a
Apr 25 08:34:45 mdb kernel: [2566224.708491]  [<c015b0c1>] get_page_from_freelist+0x34f/0x3e9
Apr 25 08:34:45 mdb kernel: [2566224.708512]  [<f8999bea>] ext3_lookup+0x21/0x9b [ext3]
Apr 25 08:34:45 mdb kernel: [2566224.708523]  [<c017a95f>] do_lookup+0xb6/0x153
Apr 25 08:34:45 mdb kernel: [2566224.708532]  [<c017c560>] __link_path_walk+0x726/0xb26
Apr 25 08:34:45 mdb kernel: [2566224.708539]  [<c01829d2>] dput+0x15/0xbb
Apr 25 08:34:45 mdb kernel: [2566224.708542]  [<c017a7a7>] __follow_mount+0x1e/0x60
Apr 25 08:34:45 mdb kernel: [2566224.708551]  [<c0186de8>] mntput_no_expire+0x13/0xd9
Apr 25 08:34:45 mdb kernel: [2566224.708557]  [<c017c997>] path_walk+0x37/0x70
Apr 25 08:34:45 mdb kernel: [2566224.708563]  [<c017cc46>] do_path_lookup+0x122/0x184
Apr 25 08:34:45 mdb kernel: [2566224.708570]  [<c017d4a3>] __user_walk_fd+0x29/0x3a
Apr 25 08:34:45 mdb kernel: [2566224.708576]  [<c0177551>] vfs_lstat_fd+0x12/0x39
Apr 25 08:34:45 mdb kernel: [2566224.708598]  [<c01775e5>] sys_lstat64+0xf/0x23
Apr 25 08:34:45 mdb kernel: [2566224.708615]  [<c0103857>] sysenter_past_esp+0x78/0xb1
Apr 25 08:34:45 mdb kernel: [2566224.708631]  =======================

I found this article that describes something similar, but it seemed related to SSD drives (which I dont use here).

The referenced article also suggests that it could be file system corruption. I did check all filesystems with fsck without finding any errors.

The drives are locally attached to an ESXi server. I have not been able to run any S.M.A.R.T tests since it is a remote server I dont have easy access to.

After a reboot things seems to be back to normal again. No more kernel log messages and IO load is normal. Is there something I could do to diagnose the error and how do I prevent it from happening again?

share|improve this question
add comment

1 Answer 1

Do you have a battery backed raid controller? If the battery is re-learning, or discharging below a set threshold, controllers will default from write back to write through causing higher IO wait times (most pronounced on DB servers).

I had almost identical behavior ('fine after reboot', high IO wait 'all of a sudden')

share|improve this answer
    
Thanks for your suggestion. No, I have no raid controller. It is a fairly low end database. –  mhson Apr 25 '12 at 13:59
add comment

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.