* Process is blocked for more than 120 seconds
@ 2015-11-02 11:43 Dmitry Katsubo
2015-11-07 12:22 ` Dmitry Katsubo
0 siblings, 1 reply; 5+ messages in thread
From: Dmitry Katsubo @ 2015-11-02 11:43 UTC (permalink / raw)
To: linux-btrfs
Hi everyone,
I have noticed the following in the log. The system continues to run,
but I am not sure for how long it will be stable.
# uname -a
Linux Debian 4.2.3-2~bpo8+1 (2015-10-20) i686 GNU/Linux
# mount | grep /var
/dev/sdd2 on /var type btrfs
(rw,noatime,compress=lzo,space_cache,subvolid=258,subvol=/var)
> [Mon Nov 2 06:35:57 2015] INFO: task nscd:859 blocked for more than 120 seconds.
> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Mon Nov 2 06:35:57 2015] nscd D f1c7dd20 0 859 1 0x00000000
> [Mon Nov 2 06:35:57 2015] f1c7dd40 00200082 f79de900 f1c7dd20 c10bc119 ffffffe0 f3aec740 00200246
> [Mon Nov 2 06:35:57 2015] f74ea800 f79e3f40 f77fb800 f1c7e000 f6b381dc f6b38000 f1c7dd4c c14f1fdb
> [Mon Nov 2 06:35:57 2015] d5553960 f1c7dd70 f867672f 00000000 f77fb800 c1099250 d0a4be08 d9755e68
> [Mon Nov 2 06:35:57 2015] Call Trace:
> [Mon Nov 2 06:35:57 2015] [<c10bc119>] ? del_timer_sync+0x49/0x50
> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
> [Mon Nov 2 06:35:57 2015] [<f867672f>] ? wait_current_trans.isra.21+0x8f/0xf0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c1099250>] ? wait_woken+0x80/0x80
> [Mon Nov 2 06:35:57 2015] [<f86782b0>] ? start_transaction+0x3d0/0x5d0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f866483d>] ? btrfs_delalloc_reserve_metadata+0x32d/0x580 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f867e480>] ? btrfs_dirty_inode+0xb0/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f8678533>] ? btrfs_join_transaction+0x23/0x30 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f867e409>] ? btrfs_dirty_inode+0x39/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f867e480>] ? btrfs_dirty_inode+0xb0/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c11aaa6e>] ? file_update_time+0x7e/0xc0
> [Mon Nov 2 06:35:57 2015] [<f8689aa0>] ? btrfs_page_mkwrite+0x80/0x3c0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c10bec89>] ? hrtimer_cancel+0x19/0x20
> [Mon Nov 2 06:35:57 2015] [<c10d0871>] ? futex_wait+0x1e1/0x270
> [Mon Nov 2 06:35:57 2015] [<c115d098>] ? do_page_mkwrite+0x38/0x90
> [Mon Nov 2 06:35:57 2015] [<c115ecd2>] ? do_wp_page+0x2e2/0x6d0
> [Mon Nov 2 06:35:57 2015] [<c10cf491>] ? futex_wake+0x71/0x140
> [Mon Nov 2 06:35:57 2015] [<c105c717>] ? kmap_atomic_prot+0xe7/0x110
> [Mon Nov 2 06:35:57 2015] [<c1160a89>] ? handle_mm_fault+0xd59/0x14d0
> [Mon Nov 2 06:35:57 2015] [<c1054bcc>] ? __do_page_fault+0x18c/0x480
> [Mon Nov 2 06:35:57 2015] [<c1054ec0>] ? __do_page_fault+0x480/0x480
> [Mon Nov 2 06:35:57 2015] [<c14f67cf>] ? error_code+0x67/0x6c
> [Mon Nov 2 06:35:57 2015] INFO: task nscd:864 blocked for more than 120 seconds.
> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Mon Nov 2 06:35:57 2015] nscd D f1c87f5c 0 864 1 0x00000000
> [Mon Nov 2 06:35:57 2015] f1c87ef4 00200082 f1c87f80 f1c87f5c 000003e7 f1c87ee4 f3aec740 ac76c560
> [Mon Nov 2 06:35:57 2015] f74ea800 f79e3f40 f3c7b040 f1c88000 f3c7b040 ffff0001 f1c87f00 c14f1fdb
> [Mon Nov 2 06:35:57 2015] f3aec77c f1c87f38 c14f4265 f1c87f1c f3aec780 f3aec788 00000000 00000125
> [Mon Nov 2 06:35:57 2015] Call Trace:
> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
> [Mon Nov 2 06:35:57 2015] [<c14f4265>] ? rwsem_down_write_failed+0x185/0x280
> [Mon Nov 2 06:35:57 2015] [<c12964d2>] ? call_rwsem_down_write_failed+0x6/0x8
> [Mon Nov 2 06:35:57 2015] [<c14f3b85>] ? down_write+0x25/0x40
> [Mon Nov 2 06:35:57 2015] [<c11505ba>] ? vm_mmap_pgoff+0x4a/0xa0
> [Mon Nov 2 06:35:57 2015] [<c1196d08>] ? SyS_fstat64+0x28/0x30
> [Mon Nov 2 06:35:57 2015] [<c1164e50>] ? SyS_mmap_pgoff+0x110/0x210
> [Mon Nov 2 06:35:57 2015] [<c14f559b>] ? sysenter_do_call+0x12/0x12
> [Mon Nov 2 06:35:57 2015] INFO: task nmbd:1330 blocked for more than 120 seconds.
> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Mon Nov 2 06:35:57 2015] nmbd D 00000000 0 1330 1 0x00000000
> [Mon Nov 2 06:35:57 2015] ef44bd74 00200086 00000000 00000000 00000000 00000000 f3984900 00000000
> [Mon Nov 2 06:35:57 2015] f69e1800 f79e3f40 f3a7a800 ef44c000 d17255a0 d17255a0 ef44bd80 c14f1fdb
> [Mon Nov 2 06:35:57 2015] d1725600 ef44bdc8 f86961b5 000d3fff 00000000 00001000 00000000 000d3000
> [Mon Nov 2 06:35:57 2015] Call Trace:
> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
> [Mon Nov 2 06:35:57 2015] [<f86961b5>] ? btrfs_start_ordered_extent+0xd5/0x100 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c1099250>] ? wait_woken+0x80/0x80
> [Mon Nov 2 06:35:57 2015] [<f868b254>] ? lock_and_cleanup_extent_if_need+0x134/0x260 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f868bb46>] ? prepare_pages+0xc6/0x150 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f868c76a>] ? __btrfs_buffered_write+0x17a/0x5e0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c113e663>] ? __alloc_pages_nodemask+0x133/0x880
> [Mon Nov 2 06:35:57 2015] [<f8690f85>] ? btrfs_file_write_iter+0x1e5/0x550 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c116980c>] ? page_add_new_anon_rmap+0x6c/0x90
> [Mon Nov 2 06:35:57 2015] [<c1191e29>] ? new_sync_write+0x79/0xb0
> [Mon Nov 2 06:35:57 2015] [<c1192433>] ? vfs_write+0x93/0x1a0
> [Mon Nov 2 06:35:57 2015] [<c1054be8>] ? __do_page_fault+0x1a8/0x480
> [Mon Nov 2 06:35:57 2015] [<c14f3030>] ? mutex_lock+0x10/0x30
> [Mon Nov 2 06:35:57 2015] [<c1192d96>] ? SyS_write+0x46/0x90
> [Mon Nov 2 06:35:57 2015] [<c14f559b>] ? sysenter_do_call+0x12/0x12
> [Mon Nov 2 06:35:57 2015] INFO: task master:2321 blocked for more than 120 seconds.
> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Mon Nov 2 06:35:57 2015] master D f79e3f40 0 2321 1 0x00000004
> [Mon Nov 2 06:35:57 2015] edcd9e18 00200082 cb7fd040 f79e3f40 cb7fd040 ffffffe0 f3903c80 00200246
> [Mon Nov 2 06:35:57 2015] c167cb00 f79d1f40 eef44800 edcda000 f6b381dc f6b38000 edcd9e24 c14f1fdb
> [Mon Nov 2 06:35:57 2015] d5553960 edcd9e48 f867672f 00000000 eef44800 c1099250 f3309e68 c7a17d64
> [Mon Nov 2 06:35:57 2015] Call Trace:
> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
> [Mon Nov 2 06:35:57 2015] [<f867672f>] ? wait_current_trans.isra.21+0x8f/0xf0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c1099250>] ? wait_woken+0x80/0x80
> [Mon Nov 2 06:35:57 2015] [<f86782b0>] ? start_transaction+0x3d0/0x5d0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f867e480>] ? btrfs_dirty_inode+0xb0/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f8678533>] ? btrfs_join_transaction+0x23/0x30 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f867e409>] ? btrfs_dirty_inode+0x39/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f867e480>] ? btrfs_dirty_inode+0xb0/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c11aaa6e>] ? file_update_time+0x7e/0xc0
> [Mon Nov 2 06:35:57 2015] [<c11998ea>] ? pipe_write+0x32a/0x400
> [Mon Nov 2 06:35:57 2015] [<c1191e29>] ? new_sync_write+0x79/0xb0
> [Mon Nov 2 06:35:57 2015] [<c1192433>] ? vfs_write+0x93/0x1a0
> [Mon Nov 2 06:35:57 2015] [<c11a4d88>] ? poll_select_set_timeout+0x68/0x80
> [Mon Nov 2 06:35:57 2015] [<c1192d96>] ? SyS_write+0x46/0x90
> [Mon Nov 2 06:35:57 2015] [<c14f559b>] ? sysenter_do_call+0x12/0x12
> [Mon Nov 2 06:35:57 2015] INFO: task xfce4-sensors-p:2611 blocked for more than 120 seconds.
> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Mon Nov 2 06:35:57 2015] xfce4-sensors-p D 00000000 0 2611 2560 0x00000000
> [Mon Nov 2 06:35:57 2015] e71f9e50 00200086 00000000 00000000 5ca90000 ffffffe0 eeec4ac0 00200246
> [Mon Nov 2 06:35:57 2015] c167cb00 f79d1f40 e7ea3040 e71fa000 f6f345dc f6f34400 e71f9e5c c14f1fdb
> [Mon Nov 2 06:35:57 2015] d5553960 e71f9e80 f867672f 00000000 e7ea3040 c1099250 c7a17d64 ea299e84
> [Mon Nov 2 06:35:57 2015] Call Trace:
> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
> [Mon Nov 2 06:35:57 2015] [<f867672f>] ? wait_current_trans.isra.21+0x8f/0xf0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c1099250>] ? wait_woken+0x80/0x80
> [Mon Nov 2 06:35:57 2015] [<f8678331>] ? start_transaction+0x451/0x5d0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f86784d4>] ? btrfs_start_transaction+0x24/0x30 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f86795a0>] ? __unlink_start_trans+0x20/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c11a6e02>] ? d_rehash+0x42/0x50
> [Mon Nov 2 06:35:57 2015] [<f86829c8>] ? btrfs_unlink+0x28/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c119e222>] ? vfs_unlink+0xf2/0x190
> [Mon Nov 2 06:35:57 2015] [<c11a0afb>] ? do_unlinkat+0x21b/0x280
> [Mon Nov 2 06:35:57 2015] [<c11a1505>] ? SyS_unlink+0x15/0x20
> [Mon Nov 2 06:35:57 2015] [<c14f559b>] ? sysenter_do_call+0x12/0x12
--
With best regards,
Dmitry
^ permalink raw reply [flat|nested] 5+ messages in thread
* Process is blocked for more than 120 seconds
2015-11-02 11:43 Process is blocked for more than 120 seconds Dmitry Katsubo
@ 2015-11-07 12:22 ` Dmitry Katsubo
2015-11-09 13:25 ` Austin S Hemmelgarn
0 siblings, 1 reply; 5+ messages in thread
From: Dmitry Katsubo @ 2015-11-07 12:22 UTC (permalink / raw)
To: linux-btrfs
Hi everyone,
I have noticed the following in the log. The system continues to run,
but I am not sure for how long it will be stable. Should I start
worrying? Thanks in advance for the opinion.
# uname -a
Linux Debian 4.2.3-2~bpo8+1 (2015-10-20) i686 GNU/Linux
# mount | grep /var
/dev/sdd2 on /var type btrfs
(rw,noatime,compress=lzo,space_cache,subvolid=258,subvol=/var)
> [Mon Nov 2 06:35:57 2015] INFO: task nscd:859 blocked for more than 120 seconds.
> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Mon Nov 2 06:35:57 2015] nscd D f1c7dd20 0 859 1 0x00000000
> [Mon Nov 2 06:35:57 2015] f1c7dd40 00200082 f79de900 f1c7dd20 c10bc119 ffffffe0 f3aec740 00200246
> [Mon Nov 2 06:35:57 2015] f74ea800 f79e3f40 f77fb800 f1c7e000 f6b381dc f6b38000 f1c7dd4c c14f1fdb
> [Mon Nov 2 06:35:57 2015] d5553960 f1c7dd70 f867672f 00000000 f77fb800 c1099250 d0a4be08 d9755e68
> [Mon Nov 2 06:35:57 2015] Call Trace:
> [Mon Nov 2 06:35:57 2015] [<c10bc119>] ? del_timer_sync+0x49/0x50
> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
> [Mon Nov 2 06:35:57 2015] [<f867672f>] ? wait_current_trans.isra.21+0x8f/0xf0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c1099250>] ? wait_woken+0x80/0x80
> [Mon Nov 2 06:35:57 2015] [<f86782b0>] ? start_transaction+0x3d0/0x5d0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f866483d>] ? btrfs_delalloc_reserve_metadata+0x32d/0x580 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f867e480>] ? btrfs_dirty_inode+0xb0/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f8678533>] ? btrfs_join_transaction+0x23/0x30 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f867e409>] ? btrfs_dirty_inode+0x39/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f867e480>] ? btrfs_dirty_inode+0xb0/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c11aaa6e>] ? file_update_time+0x7e/0xc0
> [Mon Nov 2 06:35:57 2015] [<f8689aa0>] ? btrfs_page_mkwrite+0x80/0x3c0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c10bec89>] ? hrtimer_cancel+0x19/0x20
> [Mon Nov 2 06:35:57 2015] [<c10d0871>] ? futex_wait+0x1e1/0x270
> [Mon Nov 2 06:35:57 2015] [<c115d098>] ? do_page_mkwrite+0x38/0x90
> [Mon Nov 2 06:35:57 2015] [<c115ecd2>] ? do_wp_page+0x2e2/0x6d0
> [Mon Nov 2 06:35:57 2015] [<c10cf491>] ? futex_wake+0x71/0x140
> [Mon Nov 2 06:35:57 2015] [<c105c717>] ? kmap_atomic_prot+0xe7/0x110
> [Mon Nov 2 06:35:57 2015] [<c1160a89>] ? handle_mm_fault+0xd59/0x14d0
> [Mon Nov 2 06:35:57 2015] [<c1054bcc>] ? __do_page_fault+0x18c/0x480
> [Mon Nov 2 06:35:57 2015] [<c1054ec0>] ? __do_page_fault+0x480/0x480
> [Mon Nov 2 06:35:57 2015] [<c14f67cf>] ? error_code+0x67/0x6c
> [Mon Nov 2 06:35:57 2015] INFO: task nscd:864 blocked for more than 120 seconds.
> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Mon Nov 2 06:35:57 2015] nscd D f1c87f5c 0 864 1 0x00000000
> [Mon Nov 2 06:35:57 2015] f1c87ef4 00200082 f1c87f80 f1c87f5c 000003e7 f1c87ee4 f3aec740 ac76c560
> [Mon Nov 2 06:35:57 2015] f74ea800 f79e3f40 f3c7b040 f1c88000 f3c7b040 ffff0001 f1c87f00 c14f1fdb
> [Mon Nov 2 06:35:57 2015] f3aec77c f1c87f38 c14f4265 f1c87f1c f3aec780 f3aec788 00000000 00000125
> [Mon Nov 2 06:35:57 2015] Call Trace:
> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
> [Mon Nov 2 06:35:57 2015] [<c14f4265>] ? rwsem_down_write_failed+0x185/0x280
> [Mon Nov 2 06:35:57 2015] [<c12964d2>] ? call_rwsem_down_write_failed+0x6/0x8
> [Mon Nov 2 06:35:57 2015] [<c14f3b85>] ? down_write+0x25/0x40
> [Mon Nov 2 06:35:57 2015] [<c11505ba>] ? vm_mmap_pgoff+0x4a/0xa0
> [Mon Nov 2 06:35:57 2015] [<c1196d08>] ? SyS_fstat64+0x28/0x30
> [Mon Nov 2 06:35:57 2015] [<c1164e50>] ? SyS_mmap_pgoff+0x110/0x210
> [Mon Nov 2 06:35:57 2015] [<c14f559b>] ? sysenter_do_call+0x12/0x12
> [Mon Nov 2 06:35:57 2015] INFO: task nmbd:1330 blocked for more than 120 seconds.
> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Mon Nov 2 06:35:57 2015] nmbd D 00000000 0 1330 1 0x00000000
> [Mon Nov 2 06:35:57 2015] ef44bd74 00200086 00000000 00000000 00000000 00000000 f3984900 00000000
> [Mon Nov 2 06:35:57 2015] f69e1800 f79e3f40 f3a7a800 ef44c000 d17255a0 d17255a0 ef44bd80 c14f1fdb
> [Mon Nov 2 06:35:57 2015] d1725600 ef44bdc8 f86961b5 000d3fff 00000000 00001000 00000000 000d3000
> [Mon Nov 2 06:35:57 2015] Call Trace:
> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
> [Mon Nov 2 06:35:57 2015] [<f86961b5>] ? btrfs_start_ordered_extent+0xd5/0x100 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c1099250>] ? wait_woken+0x80/0x80
> [Mon Nov 2 06:35:57 2015] [<f868b254>] ? lock_and_cleanup_extent_if_need+0x134/0x260 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f868bb46>] ? prepare_pages+0xc6/0x150 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f868c76a>] ? __btrfs_buffered_write+0x17a/0x5e0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c113e663>] ? __alloc_pages_nodemask+0x133/0x880
> [Mon Nov 2 06:35:57 2015] [<f8690f85>] ? btrfs_file_write_iter+0x1e5/0x550 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c116980c>] ? page_add_new_anon_rmap+0x6c/0x90
> [Mon Nov 2 06:35:57 2015] [<c1191e29>] ? new_sync_write+0x79/0xb0
> [Mon Nov 2 06:35:57 2015] [<c1192433>] ? vfs_write+0x93/0x1a0
> [Mon Nov 2 06:35:57 2015] [<c1054be8>] ? __do_page_fault+0x1a8/0x480
> [Mon Nov 2 06:35:57 2015] [<c14f3030>] ? mutex_lock+0x10/0x30
> [Mon Nov 2 06:35:57 2015] [<c1192d96>] ? SyS_write+0x46/0x90
> [Mon Nov 2 06:35:57 2015] [<c14f559b>] ? sysenter_do_call+0x12/0x12
> [Mon Nov 2 06:35:57 2015] INFO: task master:2321 blocked for more than 120 seconds.
> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Mon Nov 2 06:35:57 2015] master D f79e3f40 0 2321 1 0x00000004
> [Mon Nov 2 06:35:57 2015] edcd9e18 00200082 cb7fd040 f79e3f40 cb7fd040 ffffffe0 f3903c80 00200246
> [Mon Nov 2 06:35:57 2015] c167cb00 f79d1f40 eef44800 edcda000 f6b381dc f6b38000 edcd9e24 c14f1fdb
> [Mon Nov 2 06:35:57 2015] d5553960 edcd9e48 f867672f 00000000 eef44800 c1099250 f3309e68 c7a17d64
> [Mon Nov 2 06:35:57 2015] Call Trace:
> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
> [Mon Nov 2 06:35:57 2015] [<f867672f>] ? wait_current_trans.isra.21+0x8f/0xf0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c1099250>] ? wait_woken+0x80/0x80
> [Mon Nov 2 06:35:57 2015] [<f86782b0>] ? start_transaction+0x3d0/0x5d0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f867e480>] ? btrfs_dirty_inode+0xb0/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f8678533>] ? btrfs_join_transaction+0x23/0x30 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f867e409>] ? btrfs_dirty_inode+0x39/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f867e480>] ? btrfs_dirty_inode+0xb0/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c11aaa6e>] ? file_update_time+0x7e/0xc0
> [Mon Nov 2 06:35:57 2015] [<c11998ea>] ? pipe_write+0x32a/0x400
> [Mon Nov 2 06:35:57 2015] [<c1191e29>] ? new_sync_write+0x79/0xb0
> [Mon Nov 2 06:35:57 2015] [<c1192433>] ? vfs_write+0x93/0x1a0
> [Mon Nov 2 06:35:57 2015] [<c11a4d88>] ? poll_select_set_timeout+0x68/0x80
> [Mon Nov 2 06:35:57 2015] [<c1192d96>] ? SyS_write+0x46/0x90
> [Mon Nov 2 06:35:57 2015] [<c14f559b>] ? sysenter_do_call+0x12/0x12
> [Mon Nov 2 06:35:57 2015] INFO: task xfce4-sensors-p:2611 blocked for more than 120 seconds.
> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Mon Nov 2 06:35:57 2015] xfce4-sensors-p D 00000000 0 2611 2560 0x00000000
> [Mon Nov 2 06:35:57 2015] e71f9e50 00200086 00000000 00000000 5ca90000 ffffffe0 eeec4ac0 00200246
> [Mon Nov 2 06:35:57 2015] c167cb00 f79d1f40 e7ea3040 e71fa000 f6f345dc f6f34400 e71f9e5c c14f1fdb
> [Mon Nov 2 06:35:57 2015] d5553960 e71f9e80 f867672f 00000000 e7ea3040 c1099250 c7a17d64 ea299e84
> [Mon Nov 2 06:35:57 2015] Call Trace:
> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
> [Mon Nov 2 06:35:57 2015] [<f867672f>] ? wait_current_trans.isra.21+0x8f/0xf0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c1099250>] ? wait_woken+0x80/0x80
> [Mon Nov 2 06:35:57 2015] [<f8678331>] ? start_transaction+0x451/0x5d0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f86784d4>] ? btrfs_start_transaction+0x24/0x30 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<f86795a0>] ? __unlink_start_trans+0x20/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c11a6e02>] ? d_rehash+0x42/0x50
> [Mon Nov 2 06:35:57 2015] [<f86829c8>] ? btrfs_unlink+0x28/0xb0 [btrfs]
> [Mon Nov 2 06:35:57 2015] [<c119e222>] ? vfs_unlink+0xf2/0x190
> [Mon Nov 2 06:35:57 2015] [<c11a0afb>] ? do_unlinkat+0x21b/0x280
> [Mon Nov 2 06:35:57 2015] [<c11a1505>] ? SyS_unlink+0x15/0x20
> [Mon Nov 2 06:35:57 2015] [<c14f559b>] ? sysenter_do_call+0x12/0x12
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: Process is blocked for more than 120 seconds
2015-11-07 12:22 ` Dmitry Katsubo
@ 2015-11-09 13:25 ` Austin S Hemmelgarn
2015-11-11 11:38 ` Dmitry Katsubo
0 siblings, 1 reply; 5+ messages in thread
From: Austin S Hemmelgarn @ 2015-11-09 13:25 UTC (permalink / raw)
To: Dmitry Katsubo, linux-btrfs
[-- Attachment #1: Type: text/plain, Size: 10894 bytes --]
On 2015-11-07 07:22, Dmitry Katsubo wrote:
> Hi everyone,
>
> I have noticed the following in the log. The system continues to run,
> but I am not sure for how long it will be stable. Should I start
> worrying? Thanks in advance for the opinion.
>
This just means that a process was stuck in the D state (uninterruptible
I/O sleep) for more than 120 seconds. Depending on a number of factors,
this happening could mean:
1. Absolutely nothing (if you have low-powered or older hardware, for
example, I get these regularly on a first generation Raspberry Pi if I
don't increase the timeout significantly)
2. The program is doing a very large chunk of I/O (usually with the
O_DIRECT flag, although this probably isn't the case here)
3. There's a bug in the blocked program (this is rarely the case when
this type of thing happens)
4. There's a bug in the kernel (which is why this dumps a stack trace)
5. The filesystem itself is messed up somehow, and the kernel isn't
handling it properly (technically a bug, but a more specific case of it).
6. You're hardware is misbehaving, failing, or experienced a transient
error.
Assuming you can rule out possibilities 1 and 6, I think that 4 is the
most likely cause, as all of the listed programs (I'm assuming that
'master' is from postfix) are relatively well audited, and all of them
hit this at the same time.
For what it's worth, if you want you can do:
echo 0 > /proc/sys/kernel/hung_task_timeout_secs
like the message says to stop these from appearing in the future, or use
some arbitrary number to change the timeout before these messages appear
(I usually use at least 150 on production systems, and more often 300,
although on something like a Raspberry Pi I often use timeouts as high
as 1800 seconds).
>> [Mon Nov 2 06:35:57 2015] INFO: task nscd:859 blocked for more than 120 seconds.
>> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
>> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [Mon Nov 2 06:35:57 2015] nscd D f1c7dd20 0 859 1 0x00000000
>> [Mon Nov 2 06:35:57 2015] f1c7dd40 00200082 f79de900 f1c7dd20 c10bc119 ffffffe0 f3aec740 00200246
>> [Mon Nov 2 06:35:57 2015] f74ea800 f79e3f40 f77fb800 f1c7e000 f6b381dc f6b38000 f1c7dd4c c14f1fdb
>> [Mon Nov 2 06:35:57 2015] d5553960 f1c7dd70 f867672f 00000000 f77fb800 c1099250 d0a4be08 d9755e68
>> [Mon Nov 2 06:35:57 2015] Call Trace:
>> [Mon Nov 2 06:35:57 2015] [<c10bc119>] ? del_timer_sync+0x49/0x50
>> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
>> [Mon Nov 2 06:35:57 2015] [<f867672f>] ? wait_current_trans.isra.21+0x8f/0xf0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<c1099250>] ? wait_woken+0x80/0x80
>> [Mon Nov 2 06:35:57 2015] [<f86782b0>] ? start_transaction+0x3d0/0x5d0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<f866483d>] ? btrfs_delalloc_reserve_metadata+0x32d/0x580 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<f867e480>] ? btrfs_dirty_inode+0xb0/0xb0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<f8678533>] ? btrfs_join_transaction+0x23/0x30 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<f867e409>] ? btrfs_dirty_inode+0x39/0xb0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<f867e480>] ? btrfs_dirty_inode+0xb0/0xb0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<c11aaa6e>] ? file_update_time+0x7e/0xc0
>> [Mon Nov 2 06:35:57 2015] [<f8689aa0>] ? btrfs_page_mkwrite+0x80/0x3c0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<c10bec89>] ? hrtimer_cancel+0x19/0x20
>> [Mon Nov 2 06:35:57 2015] [<c10d0871>] ? futex_wait+0x1e1/0x270
>> [Mon Nov 2 06:35:57 2015] [<c115d098>] ? do_page_mkwrite+0x38/0x90
>> [Mon Nov 2 06:35:57 2015] [<c115ecd2>] ? do_wp_page+0x2e2/0x6d0
>> [Mon Nov 2 06:35:57 2015] [<c10cf491>] ? futex_wake+0x71/0x140
>> [Mon Nov 2 06:35:57 2015] [<c105c717>] ? kmap_atomic_prot+0xe7/0x110
>> [Mon Nov 2 06:35:57 2015] [<c1160a89>] ? handle_mm_fault+0xd59/0x14d0
>> [Mon Nov 2 06:35:57 2015] [<c1054bcc>] ? __do_page_fault+0x18c/0x480
>> [Mon Nov 2 06:35:57 2015] [<c1054ec0>] ? __do_page_fault+0x480/0x480
>> [Mon Nov 2 06:35:57 2015] [<c14f67cf>] ? error_code+0x67/0x6c
>> [Mon Nov 2 06:35:57 2015] INFO: task nscd:864 blocked for more than 120 seconds.
>> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
>> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [Mon Nov 2 06:35:57 2015] nscd D f1c87f5c 0 864 1 0x00000000
>> [Mon Nov 2 06:35:57 2015] f1c87ef4 00200082 f1c87f80 f1c87f5c 000003e7 f1c87ee4 f3aec740 ac76c560
>> [Mon Nov 2 06:35:57 2015] f74ea800 f79e3f40 f3c7b040 f1c88000 f3c7b040 ffff0001 f1c87f00 c14f1fdb
>> [Mon Nov 2 06:35:57 2015] f3aec77c f1c87f38 c14f4265 f1c87f1c f3aec780 f3aec788 00000000 00000125
>> [Mon Nov 2 06:35:57 2015] Call Trace:
>> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
>> [Mon Nov 2 06:35:57 2015] [<c14f4265>] ? rwsem_down_write_failed+0x185/0x280
>> [Mon Nov 2 06:35:57 2015] [<c12964d2>] ? call_rwsem_down_write_failed+0x6/0x8
>> [Mon Nov 2 06:35:57 2015] [<c14f3b85>] ? down_write+0x25/0x40
>> [Mon Nov 2 06:35:57 2015] [<c11505ba>] ? vm_mmap_pgoff+0x4a/0xa0
>> [Mon Nov 2 06:35:57 2015] [<c1196d08>] ? SyS_fstat64+0x28/0x30
>> [Mon Nov 2 06:35:57 2015] [<c1164e50>] ? SyS_mmap_pgoff+0x110/0x210
>> [Mon Nov 2 06:35:57 2015] [<c14f559b>] ? sysenter_do_call+0x12/0x12
>> [Mon Nov 2 06:35:57 2015] INFO: task nmbd:1330 blocked for more than 120 seconds.
>> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
>> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [Mon Nov 2 06:35:57 2015] nmbd D 00000000 0 1330 1 0x00000000
>> [Mon Nov 2 06:35:57 2015] ef44bd74 00200086 00000000 00000000 00000000 00000000 f3984900 00000000
>> [Mon Nov 2 06:35:57 2015] f69e1800 f79e3f40 f3a7a800 ef44c000 d17255a0 d17255a0 ef44bd80 c14f1fdb
>> [Mon Nov 2 06:35:57 2015] d1725600 ef44bdc8 f86961b5 000d3fff 00000000 00001000 00000000 000d3000
>> [Mon Nov 2 06:35:57 2015] Call Trace:
>> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
>> [Mon Nov 2 06:35:57 2015] [<f86961b5>] ? btrfs_start_ordered_extent+0xd5/0x100 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<c1099250>] ? wait_woken+0x80/0x80
>> [Mon Nov 2 06:35:57 2015] [<f868b254>] ? lock_and_cleanup_extent_if_need+0x134/0x260 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<f868bb46>] ? prepare_pages+0xc6/0x150 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<f868c76a>] ? __btrfs_buffered_write+0x17a/0x5e0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<c113e663>] ? __alloc_pages_nodemask+0x133/0x880
>> [Mon Nov 2 06:35:57 2015] [<f8690f85>] ? btrfs_file_write_iter+0x1e5/0x550 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<c116980c>] ? page_add_new_anon_rmap+0x6c/0x90
>> [Mon Nov 2 06:35:57 2015] [<c1191e29>] ? new_sync_write+0x79/0xb0
>> [Mon Nov 2 06:35:57 2015] [<c1192433>] ? vfs_write+0x93/0x1a0
>> [Mon Nov 2 06:35:57 2015] [<c1054be8>] ? __do_page_fault+0x1a8/0x480
>> [Mon Nov 2 06:35:57 2015] [<c14f3030>] ? mutex_lock+0x10/0x30
>> [Mon Nov 2 06:35:57 2015] [<c1192d96>] ? SyS_write+0x46/0x90
>> [Mon Nov 2 06:35:57 2015] [<c14f559b>] ? sysenter_do_call+0x12/0x12
>> [Mon Nov 2 06:35:57 2015] INFO: task master:2321 blocked for more than 120 seconds.
>> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
>> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [Mon Nov 2 06:35:57 2015] master D f79e3f40 0 2321 1 0x00000004
>> [Mon Nov 2 06:35:57 2015] edcd9e18 00200082 cb7fd040 f79e3f40 cb7fd040 ffffffe0 f3903c80 00200246
>> [Mon Nov 2 06:35:57 2015] c167cb00 f79d1f40 eef44800 edcda000 f6b381dc f6b38000 edcd9e24 c14f1fdb
>> [Mon Nov 2 06:35:57 2015] d5553960 edcd9e48 f867672f 00000000 eef44800 c1099250 f3309e68 c7a17d64
>> [Mon Nov 2 06:35:57 2015] Call Trace:
>> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
>> [Mon Nov 2 06:35:57 2015] [<f867672f>] ? wait_current_trans.isra.21+0x8f/0xf0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<c1099250>] ? wait_woken+0x80/0x80
>> [Mon Nov 2 06:35:57 2015] [<f86782b0>] ? start_transaction+0x3d0/0x5d0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<f867e480>] ? btrfs_dirty_inode+0xb0/0xb0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<f8678533>] ? btrfs_join_transaction+0x23/0x30 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<f867e409>] ? btrfs_dirty_inode+0x39/0xb0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<f867e480>] ? btrfs_dirty_inode+0xb0/0xb0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<c11aaa6e>] ? file_update_time+0x7e/0xc0
>> [Mon Nov 2 06:35:57 2015] [<c11998ea>] ? pipe_write+0x32a/0x400
>> [Mon Nov 2 06:35:57 2015] [<c1191e29>] ? new_sync_write+0x79/0xb0
>> [Mon Nov 2 06:35:57 2015] [<c1192433>] ? vfs_write+0x93/0x1a0
>> [Mon Nov 2 06:35:57 2015] [<c11a4d88>] ? poll_select_set_timeout+0x68/0x80
>> [Mon Nov 2 06:35:57 2015] [<c1192d96>] ? SyS_write+0x46/0x90
>> [Mon Nov 2 06:35:57 2015] [<c14f559b>] ? sysenter_do_call+0x12/0x12
>> [Mon Nov 2 06:35:57 2015] INFO: task xfce4-sensors-p:2611 blocked for more than 120 seconds.
>> [Mon Nov 2 06:35:57 2015] Not tainted 4.2.0-0.bpo.1-686-pae #1
>> [Mon Nov 2 06:35:57 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [Mon Nov 2 06:35:57 2015] xfce4-sensors-p D 00000000 0 2611 2560 0x00000000
>> [Mon Nov 2 06:35:57 2015] e71f9e50 00200086 00000000 00000000 5ca90000 ffffffe0 eeec4ac0 00200246
>> [Mon Nov 2 06:35:57 2015] c167cb00 f79d1f40 e7ea3040 e71fa000 f6f345dc f6f34400 e71f9e5c c14f1fdb
>> [Mon Nov 2 06:35:57 2015] d5553960 e71f9e80 f867672f 00000000 e7ea3040 c1099250 c7a17d64 ea299e84
>> [Mon Nov 2 06:35:57 2015] Call Trace:
>> [Mon Nov 2 06:35:57 2015] [<c14f1fdb>] ? schedule+0x2b/0x80
>> [Mon Nov 2 06:35:57 2015] [<f867672f>] ? wait_current_trans.isra.21+0x8f/0xf0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<c1099250>] ? wait_woken+0x80/0x80
>> [Mon Nov 2 06:35:57 2015] [<f8678331>] ? start_transaction+0x451/0x5d0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<f86784d4>] ? btrfs_start_transaction+0x24/0x30 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<f86795a0>] ? __unlink_start_trans+0x20/0xb0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<c11a6e02>] ? d_rehash+0x42/0x50
>> [Mon Nov 2 06:35:57 2015] [<f86829c8>] ? btrfs_unlink+0x28/0xb0 [btrfs]
>> [Mon Nov 2 06:35:57 2015] [<c119e222>] ? vfs_unlink+0xf2/0x190
>> [Mon Nov 2 06:35:57 2015] [<c11a0afb>] ? do_unlinkat+0x21b/0x280
>> [Mon Nov 2 06:35:57 2015] [<c11a1505>] ? SyS_unlink+0x15/0x20
>> [Mon Nov 2 06:35:57 2015] [<c14f559b>] ? sysenter_do_call+0x12/0x12
[-- Attachment #2: S/MIME Cryptographic Signature --]
[-- Type: application/pkcs7-signature, Size: 3019 bytes --]
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: Process is blocked for more than 120 seconds
2015-11-09 13:25 ` Austin S Hemmelgarn
@ 2015-11-11 11:38 ` Dmitry Katsubo
2016-06-16 1:05 ` Dmitry Katsubo
0 siblings, 1 reply; 5+ messages in thread
From: Dmitry Katsubo @ 2015-11-11 11:38 UTC (permalink / raw)
To: linux-btrfs
On 2015-11-09 14:25, Austin S Hemmelgarn wrote:
> On 2015-11-07 07:22, Dmitry Katsubo wrote:
>> Hi everyone,
>>
>> I have noticed the following in the log. The system continues to run,
>> but I am not sure for how long it will be stable. Should I start
>> worrying? Thanks in advance for the opinion.
>>
> This just means that a process was stuck in the D state (uninterruptible
> I/O sleep) for more than 120 seconds. Depending on a number of factors,
> this happening could mean:
> 1. Absolutely nothing (if you have low-powered or older hardware, for
> example, I get these regularly on a first generation Raspberry Pi if I
> don't increase the timeout significantly)
> 2. The program is doing a very large chunk of I/O (usually with the
> O_DIRECT flag, although this probably isn't the case here)
> 3. There's a bug in the blocked program (this is rarely the case when
> this type of thing happens)
> 4. There's a bug in the kernel (which is why this dumps a stack trace)
> 5. The filesystem itself is messed up somehow, and the kernel isn't
> handling it properly (technically a bug, but a more specific case of it).
> 6. You're hardware is misbehaving, failing, or experienced a transient
> error.
>
> Assuming you can rule out possibilities 1 and 6, I think that 4 is the
> most likely cause, as all of the listed programs (I'm assuming that
> 'master' is from postfix) are relatively well audited, and all of them
> hit this at the same time.
>
> For what it's worth, if you want you can do:
> echo 0 > /proc/sys/kernel/hung_task_timeout_secs
> like the message says to stop these from appearing in the future, or use
> some arbitrary number to change the timeout before these messages appear
> (I usually use at least 150 on production systems, and more often 300,
> although on something like a Raspberry Pi I often use timeouts as high
> as 1800 seconds).
Thanks for comments, Austin.
The system is "normal" PC, running Intel Core 2 Duo Mobile @1.66GHz.
"master" is indeed a postfix process.
I haven't seen anything like that when I was on 3.16 kernel, but after I
have upgraded to 4.2.3, I caught that message. I/O and CPU load are
usually low, but it could be (6) from your list, as the system is
generally very old (5+ years).
As the problem appeared only once for passed 15 days, I think it is just
a transient error. Thanks for clarifying the possible reasons.
--
With best regards,
Dmitry
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: Process is blocked for more than 120 seconds
2015-11-11 11:38 ` Dmitry Katsubo
@ 2016-06-16 1:05 ` Dmitry Katsubo
0 siblings, 0 replies; 5+ messages in thread
From: Dmitry Katsubo @ 2016-06-16 1:05 UTC (permalink / raw)
To: linux-btrfs
On 2015-11-11 12:38, Dmitry Katsubo wrote:
> On 2015-11-09 14:25, Austin S Hemmelgarn wrote:
>> On 2015-11-07 07:22, Dmitry Katsubo wrote:
>>> Hi everyone,
>>>
>>> I have noticed the following in the log. The system continues to run,
>>> but I am not sure for how long it will be stable. Should I start
>>> worrying? Thanks in advance for the opinion.
>>>
>> This just means that a process was stuck in the D state (uninterruptible
>> I/O sleep) for more than 120 seconds. Depending on a number of factors,
>> this happening could mean:
>> 1. Absolutely nothing (if you have low-powered or older hardware, for
>> example, I get these regularly on a first generation Raspberry Pi if I
>> don't increase the timeout significantly)
>> 2. The program is doing a very large chunk of I/O (usually with the
>> O_DIRECT flag, although this probably isn't the case here)
>> 3. There's a bug in the blocked program (this is rarely the case when
>> this type of thing happens)
>> 4. There's a bug in the kernel (which is why this dumps a stack trace)
>> 5. The filesystem itself is messed up somehow, and the kernel isn't
>> handling it properly (technically a bug, but a more specific case of it).
>> 6. You're hardware is misbehaving, failing, or experienced a transient
>> error.
>>
>> Assuming you can rule out possibilities 1 and 6, I think that 4 is the
>> most likely cause, as all of the listed programs (I'm assuming that
>> 'master' is from postfix) are relatively well audited, and all of them
>> hit this at the same time.
>>
>> For what it's worth, if you want you can do:
>> echo 0 > /proc/sys/kernel/hung_task_timeout_secs
>> like the message says to stop these from appearing in the future, or use
>> some arbitrary number to change the timeout before these messages appear
>> (I usually use at least 150 on production systems, and more often 300,
>> although on something like a Raspberry Pi I often use timeouts as high
>> as 1800 seconds).
>
> Thanks for comments, Austin.
>
> The system is "normal" PC, running Intel Core 2 Duo Mobile @1.66GHz.
> "master" is indeed a postfix process.
>
> I haven't seen anything like that when I was on 3.16 kernel, but after I
> have upgraded to 4.2.3, I caught that message. I/O and CPU load are
> usually low, but it could be (6) from your list, as the system is
> generally very old (5+ years).
>
> As the problem appeared only once for passed 15 days, I think it is just
> a transient error. Thanks for clarifying the possible reasons.
The problem (rarely) re-occurs. It does not happen on XFS filesystem (root)
but only on btrfs. I will increase timeout up to 300 and see what happens.
=== cut dmesg ===
INFO: task fail2ban-server:1747 blocked for more than 120 seconds.
Tainted: G W 4.4.0-1-rt-686-pae #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
fail2ban-server D 0000001f 0 1747 1 0x00000000
f1ca1bc0 00200086 f2d24190 0000001f 00000000 f79ca4c0 f3d21bc0 00000000
c1168726 f1ca1bc0 e9152000 00000000 e9151d8c c156075f c0d25a90 f1ca1bc0
e9151db4 c1561ed4 00000000 00000000 f1ca1bc0 00000002 eab98940 c0d25a90
Call Trace:
[<c1168726>] ? __filemap_fdatawrite_range+0xb6/0xf0
[<c156075f>] ? schedule+0x3f/0xd0
[<c1561ed4>] ? __rt_mutex_slowlock+0x74/0x140
[<c1562373>] ? rt_mutex_slowlock+0xf3/0x250
[<f8c2bb8e>] ? btrfs_write_marked_extents+0xae/0x190 [btrfs]
[<c1562575>] ? rt_mutex_lock+0x45/0x50
[<f8c78515>] ? btrfs_sync_log+0x1d5/0x9a0 [btrfs]
[<c106ec71>] ? pin_current_cpu+0x71/0x1a0
[<c1091cda>] ? preempt_count_add+0x8a/0xb0
[<c106edb3>] ? unpin_current_cpu+0x13/0x70
[<f8c474ee>] ? btrfs_sync_file+0x3ce/0x410 [btrfs]
[<f8c47120>] ? start_ordered_ops+0x40/0x40 [btrfs]
[<c11f9767>] ? vfs_fsync_range+0x47/0xb0
[<c11f983c>] ? do_fsync+0x3c/0x60
[<c11f9ab5>] ? SyS_fdatasync+0x15/0x20
[<c100393d>] ? do_fast_syscall_32+0x8d/0x150
[<c1563e28>] ? sysenter_past_esp+0x3d/0x61
[<c1560000>] ? pci_mmcfg_check_reserved+0x90/0xb0
INFO: task cleanup:2093 blocked for more than 120 seconds.
Tainted: G W 4.4.0-1-rt-686-pae #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
cleanup D d0f5de0c 0 2093 28135 0x00000000
eab99bc0 00200086 c1836760 d0f5de0c 00000002 f79ca4c0 f3d21bc0 00000000
00000001 eab99bc0 d0f5e000 f325d2c4 d0f5ddfc c156075f f325d000 00000088
d0f5de30 f8c72f36 00000310 f325d290 00000000 eab99bc0 c10afd70 f325d2dc
Call Trace:
[<c156075f>] ? schedule+0x3f/0xd0
[<f8c72f36>] ? wait_log_commit+0xc6/0xf0 [btrfs]
[<c10afd70>] ? wake_atomic_t_function+0x70/0x70
[<f8c786aa>] ? btrfs_sync_log+0x36a/0x9a0 [btrfs]
[<c106ec71>] ? pin_current_cpu+0x71/0x1a0
[<c1091cda>] ? preempt_count_add+0x8a/0xb0
[<c106edb3>] ? unpin_current_cpu+0x13/0x70
[<f8c792d4>] ? btrfs_log_dentry_safe+0x64/0x70 [btrfs]
[<f8c474ee>] ? btrfs_sync_file+0x3ce/0x410 [btrfs]
[<c11c6100>] ? do_sys_truncate+0xb0/0xb0
[<f8c47120>] ? start_ordered_ops+0x40/0x40 [btrfs]
[<c11f9767>] ? vfs_fsync_range+0x47/0xb0
[<c11f983c>] ? do_fsync+0x3c/0x60
[<c11f9a92>] ? SyS_fsync+0x12/0x20
[<c100393d>] ? do_fast_syscall_32+0x8d/0x150
[<c1563e28>] ? sysenter_past_esp+0x3d/0x61
INFO: task lmtpd:2101 blocked for more than 120 seconds.
Tainted: G W 4.4.0-1-rt-686-pae #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
lmtpd D db0c7e0c 0 2101 7894 0x00000000
cd540940 00200086 c1836760 db0c7e0c 00000002 f79674c0 c1706dc0 00000000
00000001 cd540940 db0c8000 f325d2e4 db0c7dfc c156075f f325d000 00000087
db0c7e30 f8c72f36 00000314 f325d290 00000000 cd540940 c10afd70 f325d2fc
Call Trace:
[<c156075f>] ? schedule+0x3f/0xd0
[<f8c72f36>] ? wait_log_commit+0xc6/0xf0 [btrfs]
[<c10afd70>] ? wake_atomic_t_function+0x70/0x70
[<f8c783e5>] ? btrfs_sync_log+0xa5/0x9a0 [btrfs]
[<c106ec71>] ? pin_current_cpu+0x71/0x1a0
[<c1091cda>] ? preempt_count_add+0x8a/0xb0
[<c106edb3>] ? unpin_current_cpu+0x13/0x70
[<f8c792d4>] ? btrfs_log_dentry_safe+0x64/0x70 [btrfs]
[<f8c474ee>] ? btrfs_sync_file+0x3ce/0x410 [btrfs]
[<f8c47120>] ? start_ordered_ops+0x40/0x40 [btrfs]
[<c11f9767>] ? vfs_fsync_range+0x47/0xb0
[<c11f983c>] ? do_fsync+0x3c/0x60
[<c11f9ab5>] ? SyS_fdatasync+0x15/0x20
[<c100393d>] ? do_fast_syscall_32+0x8d/0x150
[<c1563e28>] ? sysenter_past_esp+0x3d/0x61
INFO: task nmbd:2104 blocked for more than 120 seconds.
Tainted: G W 4.4.0-1-rt-686-pae #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
nmbd D f6a652d4 0 2104 1702 0x00000000
eab9ca00 00200086 c1836760 f6a652d4 00000002 f79ca4c0 f3d21bc0 00000000
c10929fb eab9ca00 ca910000 f2fe2ea0 ca90fd20 c156075f f2023900 f325d1dc
ca90fd48 f8c2b70f 00000000 eab9ca00 c10afd70 f6a652ec dfd2bdb4 98141c71
Call Trace:
[<c10929fb>] ? migrate_enable+0x8b/0x150
[<c156075f>] ? schedule+0x3f/0xd0
[<f8c2b70f>] ? wait_current_trans.isra.21+0xaf/0xf0 [btrfs]
[<c10afd70>] ? wake_atomic_t_function+0x70/0x70
[<f8c2d09a>] ? start_transaction+0x29a/0x500 [btrfs]
[<c106edb3>] ? unpin_current_cpu+0x13/0x70
[<f8c2d31c>] ? btrfs_start_transaction+0x1c/0x20 [btrfs]
[<f8c3e5d0>] ? btrfs_create+0x40/0x240 [btrfs]
[<c106ec71>] ? pin_current_cpu+0x71/0x1a0
[<c1563445>] ? _raw_spin_lock+0x15/0x40
[<c1091cda>] ? preempt_count_add+0x8a/0xb0
[<c11d3bab>] ? vfs_create+0xcb/0x140
[<c11d626c>] ? path_openat+0x103c/0x1130
[<c119ec91>] ? page_add_file_rmap+0x11/0x50
[<c11d7ce8>] ? do_filp_open+0x68/0xe0
[<c106edb3>] ? unpin_current_cpu+0x13/0x70
[<c10929fb>] ? migrate_enable+0x8b/0x150
[<c11e5375>] ? __alloc_fd+0xa5/0x160
[<c11c7af6>] ? do_sys_open+0x116/0x220
[<c11c7c22>] ? SyS_open+0x22/0x30
[<c100393d>] ? do_fast_syscall_32+0x8d/0x150
[<c1563e28>] ? sysenter_past_esp+0x3d/0x61
=== end ===
--
With best regards,
Dmitry
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2016-06-16 1:05 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2015-11-02 11:43 Process is blocked for more than 120 seconds Dmitry Katsubo
2015-11-07 12:22 ` Dmitry Katsubo
2015-11-09 13:25 ` Austin S Hemmelgarn
2015-11-11 11:38 ` Dmitry Katsubo
2016-06-16 1:05 ` Dmitry Katsubo
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.