[LU-4497] tgt_recov hung task timeout OSSes when caching is on Created: 16/Jan/14  Updated: 24/Jan/14  Resolved: 24/Jan/14

Status: Resolved
Project: Lustre
Component/s: None
Affects Version/s: Lustre 2.5.0
Fix Version/s: None

Type: Bug Priority: Major
Reporter: Erich Focht Assignee: John Fuchs-Chesney (Inactive)
Resolution: Not a Bug Votes: 0
Labels: None
Environment:

HA environment, 2 * 2 OSS pairs. ~500 Client nodes, all over QDR InfiniBand.

Severity: 3
Rank (Obsolete): 12302

 Description   

After updating a very stable Lustre 1.8.4 environment to 2.5.0 we regularly were getting hung task messages on OSSes often leading to unexpected failovers (which triggered some other bugs). We tried various clients (2.5.0, patched 2.5.0, 1.8.9, ...) and the most stable configuration seemed to be the one with 1.8.9 clients.

The symptoms disappeared after we turned off read and write caching!

lctl set_param obdfilter.*.read_cache_enable=0
lctl set_param obdfilter.*.writethrough_cache_enable=0

We do have quota turned on, and somehow the bug reminded of LU-952, but the hangs are different. The server hardware is not very powerful, and they get quite some load. We're using 63 concurrent_sends. Anyway, I'd expect that caching ... eases the load and helps, and can't really imagine that server side caching is broken in 2.5.0. But maybe I'm wrong?

Regards,
Erich

Lustre: Lustre: Build Version: 2.5.0-RC1--PRISTINE-2.6.32-358.18.1.el6_lustre.x86_64
LNet: Added LNI 10.188.20.43@o2ib [63/2016/0/180]
LNet: Added LNI 10.188.8.43@tcp [8/256/0/180]
LNet: Accept all, port 988
RPC: Registered named UNIX socket transport module.
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
RPC: Registered tcp NFSv4.1 backchannel transport module.
802.1Q VLAN Support v1.8 Ben Greear <greearb@candelatech.com>
All bugs added by David S. Miller <davem@redhat.com>
8021q: adding VLAN 0 to HW filter on device eth0
8021q: adding VLAN 0 to HW filter on device eth1
8021q: adding VLAN 0 to HW filter on device eth2
ipmi device interface
zunicode: module license 'CDDL' taints kernel.
Disabling lock debugging due to kernel taint
SPL: Loaded module v0.6.1-1
ZFS: Loaded module v0.6.1-1, ZFS pool version 5000, ZFS filesystem version 5
LDISKFS-fs (sdf): mounted filesystem with ordered data mode. quota=on. Opts: 
LDISKFS-fs (sdd): mounted filesystem with ordered data mode. quota=on. Opts: 
LDISKFS-fs (sdj): mounted filesystem with ordered data mode. quota=on. Opts: 
LDISKFS-fs (sdc): mounted filesystem with ordered data mode. quota=on. Opts: 
LDISKFS-fs (sdh): mounted filesystem with ordered data mode. quota=on. Opts: 
LDISKFS-fs (sdi): 
LDISKFS-fs (sde): mounted filesystem with ordered data mode. quota=on. Opts: 
mounted filesystem with ordered data mode. quota=on. Opts: 
LDISKFS-fs (sdg): mounted filesystem with ordered data mode. quota=on. Opts: 

Lustre: 2419:0:(client.c:1897:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1389200837/real 1389200837]  req@ffff8805ff93ec00 x1456682189193224/t0(0) o250->MGC10.188
.20.32@o2ib@10.188.8.32@tcp:26/25 lens 400/544 e 0 to 1 dl 1389200842 ref 1 fl Rpc:XN/0/ffffffff rc 0/-1
LustreError: 4392:0:(obd_mount_server.c:1123:server_register_target()) lnec-OST000b: error registering with the MGS: rc = -5 (not fatal)
Lustre: 5801:0:(ofd_dev.c:222:ofd_process_config()) For interoperability, skip this ost.quota_type. It is obsolete.
Lustre: 2419:0:(client.c:1897:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1389200842/real 1389200842]  req@ffff8805ff93e000 x1456682189193240/t0(0) o250->MGC10.188
.20.32@o2ib@10.188.20.31@o2ib:26/25 lens 400/544 e 0 to 1 dl 1389200847 ref 1 fl Rpc:XN/0/ffffffff rc 0/-1
LustreError: 13a-8: Failed to get MGS log params and no local copy.
Lustre: 2419:0:(client.c:1897:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1389200847/real 1389200847]  req@ffff8802f0eb8c00 x1456682189193252/t0(0) o250->MGC10.188
.20.32@o2ib@10.188.8.31@tcp:26/25 lens 400/544 e 0 to 1 dl 1389200852 ref 1 fl Rpc:XN/0/ffffffff rc 0/-1
LustreError: 13a-8: Failed to get MGS log params and no local copy.
LustreError: 11-0: lnec-MDT0000-lwp-OST000b: Communicating with 10.188.20.31@o2ib, operation mds_connect failed with -19.
LustreError: 4749:0:(client.c:1080:ptlrpc_import_delay_req()) @@@ send limit expired   req@ffff8805ffa31800 x1456682189193268/t0(0) o101->MGC10.188.20.32@o2ib@10.188.20.32@o2ib:26/25 lens 328/344 e 0 t
o 0 dl 0 ref 2 fl Rpc:W/0/ffffffff rc 0/-1
LustreError: 4392:0:(client.c:1080:ptlrpc_import_delay_req()) @@@ send limit expired   req@ffff8802f0eb8800 x1456682189193276/t0(0) o101->MGC10.188.20.32@o2ib@10.188.20.32@o2ib:26/25 lens 328/344 e 0 t
o 0 dl 0 ref 2 fl Rpc:W/0/ffffffff rc 0/-1
LustreError: 13a-8: Failed to get MGS log params and no local copy.
LustreError: 137-5: lnec-OST0008_UUID: not available for connect from 10.188.20.31@o2ib (no target). If you are running an HA pair check that the target is mounted on the other server.
LustreError: 137-5: lnec-OST0009_UUID: not available for connect from 10.188.20.31@o2ib (no target). If you are running an HA pair check that the target is mounted on the other server.
Lustre: 2419:0:(client.c:1897:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1389200852/real 1389200852]  req@ffff8802f0eb8000 x1456682189193264/t0(0) o250->MGC10.188.20.32@o2ib@10.188.20.32@o2ib:26/25 lens 400/544 e 0 to 1 dl 1389200862 ref 1 fl Rpc:XN/0/ffffffff rc 0/-1
LustreError: 4749:0:(client.c:1080:ptlrpc_import_delay_req()) @@@ send limit expired   req@ffff8805ffa31800 x1456682189193292/t0(0) o101->MGC10.188.20.32@o2ib@10.188.8.32@tcp:26/25 lens 328/344 e 0 to 0 dl 0 ref 2 fl Rpc:W/0/ffffffff rc 0/-1
Lustre: 2419:0:(client.c:1897:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1389200862/real 1389200862]  req@ffff8802f0eb8400 x1456682189193284/t0(0) o250->MGC10.188.20.32@o2ib@10.188.8.32@tcp:26/25 lens 400/544 e 0 to 1 dl 1389200872 ref 1 fl Rpc:XN/0/ffffffff rc 0/-1
LustreError: 4395:0:(obd_mount_server.c:1123:server_register_target()) lnec-OST000c: error registering with the MGS: rc = -5 (not fatal)
Lustre: 5872:0:(ofd_dev.c:222:ofd_process_config()) For interoperability, skip this ost.quota_type. It is obsolete.
LustreError: 4395:0:(client.c:1080:ptlrpc_import_delay_req()) @@@ send limit expired   req@ffff8805ffa31000 x1456682189193320/t0(0) o101->MGC10.188.20.32@o2ib@10.188.20.31@o2ib:26/25 lens 328/344 e 0 to 0 dl 0 ref 2 fl Rpc:W/0/ffffffff rc 0/-1
LustreError: 13a-8: Failed to get MGS log params and no local copy.
Lustre: 2419:0:(client.c:1897:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1389200872/real 1389200872]  req@ffff8802f0eb8800 x1456682189193316/t0(0) o250->MGC10.188.20.32@o2ib@10.188.20.31@o2ib:26/25 lens 400/544 e 0 to 1 dl 1389200882 ref 1 fl Rpc:XN/0/ffffffff rc 0/-1
LustreError: 4749:0:(client.c:1080:ptlrpc_import_delay_req()) @@@ send limit expired   req@ffff880339cf1c00 x1456682189193340/t0(0) o101->MGC10.188.20.32@o2ib@10.188.8.31@tcp:26/25 lens 328/344 e 0 to 0 dl 0 ref 2 fl Rpc:W/0/ffffffff rc 0/-1
LustreError: 13a-8: Failed to get MGS log params and no local copy.
Lustre: 2419:0:(client.c:1897:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1389200882/real 1389200882]  req@ffff8802f0eb8000 x1456682189193336/t0(0) o250->MGC10.188.20.32@o2ib@10.188.8.31@tcp:26/25 lens 400/544 e 0 to 1 dl 1389200892 ref 1 fl Rpc:XN/0/ffffffff rc 0/-1
Lustre: 2419:0:(client.c:1897:ptlrpc_expire_one_request()) Skipped 1 previous similar message
LustreError: 4749:0:(client.c:1080:ptlrpc_import_delay_req()) @@@ send limit expired   req@ffff880339cf1c00 x1456682189193352/t0(0) o101->MGC10.188.20.32@o2ib@10.188.8.31@tcp:26/25 lens 328/344 e 0 to 0 dl 0 ref 2 fl Rpc:W/0/ffffffff rc 0/-1
LustreError: 4749:0:(client.c:1080:ptlrpc_import_delay_req()) Skipped 1 previous similar message
Lustre: lnec-OST000c: Will be in recovery for at least 5:00, or until 2 clients reconnect
Lustre: lnec-OST000b: Denying connection for new client lnec-MDT0000-mdtlov_UUID (at 10.188.20.31@o2ib), waiting for all 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 5:00
LustreError: 137-5: lnec-OST000e_UUID: not available for connect from 10.188.20.31@o2ib (no target). If you are running an HA pair check that the target is mounted on the other server.
LustreError: Skipped 1 previous similar message
Lustre: Skipped 1 previous similar message
Lustre: lnec-OST000c: Denying connection for new client lnec-MDT0000-mdtlov_UUID (at 10.188.20.31@o2ib), waiting for all 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 4:59
LustreError: 4749:0:(client.c:1080:ptlrpc_import_delay_req()) @@@ send limit expired   req@ffff880339cf1c00 x1456682189193368/t0(0) o101->MGC10.188.20.32@o2ib@10.188.8.31@tcp:26/25 lens 328/344 e 0 to 0 dl 0 ref 2 fl Rpc:W/0/ffffffff rc 0/-1
LustreError: 4749:0:(client.c:1080:ptlrpc_import_delay_req()) Skipped 2 previous similar messages
Lustre: 5953:0:(ofd_dev.c:222:ofd_process_config()) For interoperability, skip this ost.quota_type. It is obsolete.
LustreError: 13a-8: Failed to get MGS log params and no local copy.
LustreError: Skipped 1 previous similar message
Lustre: lnec-OST000f: Will be in recovery for at least 5:00, or until 3 clients reconnect
Lustre: lnec-OST0009: Will be in recovery for at least 5:00, or until 3 clients reconnect
Lustre: 6030:0:(ofd_dev.c:222:ofd_process_config()) For interoperability, skip this ost.quota_type. It is obsolete.
Lustre: 6030:0:(ofd_dev.c:222:ofd_process_config()) Skipped 1 previous similar message
LustreError: 13a-8: Failed to get MGS log params and no local copy.
LustreError: Skipped 7 previous similar messages
Lustre: lnec-OST000d: Will be in recovery for at least 5:00, or until 3 clients reconnect
Lustre: lnec-OST000e: Will be in recovery for at least 5:00, or until 3 clients reconnect
Lustre: Skipped 2 previous similar messages
Lustre: lnec-OST000c: Denying connection for new client lnec-MDT0000-mdtlov_UUID (at 10.188.20.31@o2ib), waiting for all 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 4:35
Lustre: Skipped 1 previous similar message
Lustre: lnec-OST000b: Denying connection for new client lnec-MDT0000-mdtlov_UUID (at 10.188.20.31@o2ib), waiting for all 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 4:10
Lustre: lnec-OST000c: Denying connection for new client lnec-MDT0000-mdtlov_UUID (at 10.188.20.31@o2ib), waiting for all 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 4:10
Lustre: lnec-OST000c: Denying connection for new client lnec-MDT0000-mdtlov_UUID (at 10.188.20.31@o2ib), waiting for all 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 3:45
Lustre: lnec-OST000b: Denying connection for new client lnec-MDT0000-mdtlov_UUID (at 10.188.20.31@o2ib), waiting for all 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 3:45
Lustre: lnec-OST000c: Denying connection for new client lnec-MDT0000-mdtlov_UUID (at 10.188.20.31@o2ib), waiting for all 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 3:20
Lustre: Skipped 1 previous similar message
Lustre: lnec-OST000b: Denying connection for new client lnec-MDT0000-mdtlov_UUID (at 10.188.20.31@o2ib), waiting for all 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 2:55
Lustre: lnec-OST000c: Denying connection for new client lnec-MDT0000-mdtlov_UUID (at 10.188.20.31@o2ib), waiting for all 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 2:55
INFO: task tgt_recov:5864 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
tgt_recov     D 000000000000000d     0  5864      2 0x00000000
 ffff88031d269da0 0000000000000046 0000000000000000 0000000000000003
 ffff88031d269d30 ffffffff81055f96 ffff88031d269d40 ffff880338ade080
 ffff8803390cbaf8 ffff88031d269fd8 000000000000fb88 ffff8803390cbaf8
Call Trace:
 [<ffffffff81055f96>] ? enqueue_task+0x66/0x80
 [<ffffffffa064e210>] ? check_for_clients+0x0/0x70 [ptlrpc]
 [<ffffffffa064f87d>] target_recovery_overseer+0x9d/0x230 [ptlrpc]
 [<ffffffffa064df00>] ? exp_connect_healthy+0x0/0x20 [ptlrpc]
 [<ffffffff81096da0>] ? autoremove_wake_function+0x0/0x40
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffffa0656680>] target_recovery_thread+0x540/0x1920 [ptlrpc]
 [<ffffffff81063422>] ? default_wake_function+0x12/0x20
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffff81096a36>] kthread+0x96/0xa0
 [<ffffffff8100c0ca>] child_rip+0xa/0x20
 [<ffffffff810969a0>] ? kthread+0x0/0xa0
 [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
INFO: task tgt_recov:5944 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
tgt_recov     D 000000000000000d     0  5944      2 0x00000000
 ffff8803280cbda0 0000000000000046 0000000000000000 0000000000000003
 ffff8803280cbd30 ffffffff81055f96 ffff8803280cbd40 ffff8806298dcae0
 ffff8802f0ef85f8 ffff8803280cbfd8 000000000000fb88 ffff8802f0ef85f8
Call Trace:
 [<ffffffff81055f96>] ? enqueue_task+0x66/0x80
 [<ffffffffa064e210>] ? check_for_clients+0x0/0x70 [ptlrpc]
 [<ffffffffa064f87d>] target_recovery_overseer+0x9d/0x230 [ptlrpc]
 [<ffffffffa064df00>] ? exp_connect_healthy+0x0/0x20 [ptlrpc]
 [<ffffffff81096da0>] ? autoremove_wake_function+0x0/0x40
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffffa0656680>] target_recovery_thread+0x540/0x1920 [ptlrpc]
 [<ffffffff81063422>] ? default_wake_function+0x12/0x20
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffff81096a36>] kthread+0x96/0xa0
 [<ffffffff8100c0ca>] child_rip+0xa/0x20
 [<ffffffff810969a0>] ? kthread+0x0/0xa0
 [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
INFO: task tgt_recov:5956 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
tgt_recov     D 000000000000000d     0  5956      2 0x00000000
 ffff88033959dda0 0000000000000046 ffff88033959dd68 ffff88033959dd64
 ffff88033959dd30 ffff88033fc25d00 ffff88034ac36740 0000000000000400
 ffff880330f6dab8 ffff88033959dfd8 000000000000fb88 ffff880330f6dab8
Call Trace:
 [<ffffffffa064e210>] ? check_for_clients+0x0/0x70 [ptlrpc]
 [<ffffffffa064f87d>] target_recovery_overseer+0x9d/0x230 [ptlrpc]
 [<ffffffffa064df00>] ? exp_connect_healthy+0x0/0x20 [ptlrpc]
 [<ffffffff81096da0>] ? autoremove_wake_function+0x0/0x40
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffffa0656680>] target_recovery_thread+0x540/0x1920 [ptlrpc]
 [<ffffffff81063422>] ? default_wake_function+0x12/0x20
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffff81096a36>] kthread+0x96/0xa0
 [<ffffffff8100c0ca>] child_rip+0xa/0x20
 [<ffffffff810969a0>] ? kthread+0x0/0xa0
 [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
INFO: task tgt_recov:5961 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
tgt_recov     D 000000000000000d     0  5961      2 0x00000000
 ffff88033969bda0 0000000000000046 0000000000000000 0000000000000003
 ffff88033969bd30 ffffffff81055f96 ffff88033969bd40 ffff8803391fd540
 ffff88032c0da5f8 ffff88033969bfd8 000000000000fb88 ffff88032c0da5f8
Call Trace:
 [<ffffffff81055f96>] ? enqueue_task+0x66/0x80
 [<ffffffffa064e210>] ? check_for_clients+0x0/0x70 [ptlrpc]
 [<ffffffffa064f87d>] target_recovery_overseer+0x9d/0x230 [ptlrpc]
 [<ffffffffa064df00>] ? exp_connect_healthy+0x0/0x20 [ptlrpc]
 [<ffffffff81096da0>] ? autoremove_wake_function+0x0/0x40
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffffa0656680>] target_recovery_thread+0x540/0x1920 [ptlrpc]
 [<ffffffff81063422>] ? default_wake_function+0x12/0x20
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffff81096a36>] kthread+0x96/0xa0
 [<ffffffff8100c0ca>] child_rip+0xa/0x20
 [<ffffffff810969a0>] ? kthread+0x0/0xa0
 [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
INFO: task tgt_recov:6033 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
tgt_recov     D 000000000000000d     0  6033      2 0x00000000
 ffff8802ef76fda0 0000000000000046 0000000000000000 0000000000000003
 ffff8802ef76fd30 ffffffff81055f96 ffff8802ef76fd40 ffff880338129500
 ffff8802ef69daf8 ffff8802ef76ffd8 000000000000fb88 ffff8802ef69daf8
Call Trace:
 [<ffffffff81055f96>] ? enqueue_task+0x66/0x80
 [<ffffffffa064e210>] ? check_for_clients+0x0/0x70 [ptlrpc]
 [<ffffffffa064f87d>] target_recovery_overseer+0x9d/0x230 [ptlrpc]
 [<ffffffffa064df00>] ? exp_connect_healthy+0x0/0x20 [ptlrpc]
 [<ffffffff81096da0>] ? autoremove_wake_function+0x0/0x40
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffffa0656680>] target_recovery_thread+0x540/0x1920 [ptlrpc]
 [<ffffffff81063422>] ? default_wake_function+0x12/0x20
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffff81096a36>] kthread+0x96/0xa0
 [<ffffffff8100c0ca>] child_rip+0xa/0x20
 [<ffffffff810969a0>] ? kthread+0x0/0xa0
 [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
INFO: task tgt_recov:6044 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
tgt_recov     D 000000000000000d     0  6044      2 0x00000000
 ffff8802eac99da0 0000000000000046 ffff8802eac99d68 ffff8802eac99d64
 ffff8802eac99d30 ffff88033fc25d00 ffff88034ac36740 0000000000000400
 ffff8803382de5f8 ffff8802eac99fd8 000000000000fb88 ffff8803382de5f8
Call Trace:
 [<ffffffffa064e210>] ? check_for_clients+0x0/0x70 [ptlrpc]
 [<ffffffffa064f87d>] target_recovery_overseer+0x9d/0x230 [ptlrpc]
 [<ffffffffa064df00>] ? exp_connect_healthy+0x0/0x20 [ptlrpc]
 [<ffffffff81096da0>] ? autoremove_wake_function+0x0/0x40
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffffa0656680>] target_recovery_thread+0x540/0x1920 [ptlrpc]
 [<ffffffff81063422>] ? default_wake_function+0x12/0x20
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffff81096a36>] kthread+0x96/0xa0
 [<ffffffff8100c0ca>] child_rip+0xa/0x20
 [<ffffffff810969a0>] ? kthread+0x0/0xa0
 [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
INFO: task tgt_recov:6049 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
tgt_recov     D 0000000000000006     0  6049      2 0x00000000
 ffff8802eaeb1da0 0000000000000046 0000000000000000 ffff8802eaeb1d64
 ffff880200000000 ffff88033fc24f00 ffff88034ac36740 0000000000000400
 ffff88033a2e4638 ffff8802eaeb1fd8 000000000000fb88 ffff88033a2e4638
Call Trace:
 [<ffffffffa064e210>] ? check_for_clients+0x0/0x70 [ptlrpc]
 [<ffffffffa064f87d>] target_recovery_overseer+0x9d/0x230 [ptlrpc]
 [<ffffffffa064df00>] ? exp_connect_healthy+0x0/0x20 [ptlrpc]
 [<ffffffff81096da0>] ? autoremove_wake_function+0x0/0x40
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffffa0656680>] target_recovery_thread+0x540/0x1920 [ptlrpc]
 [<ffffffff81063422>] ? default_wake_function+0x12/0x20
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffff81096a36>] kthread+0x96/0xa0
 [<ffffffff8100c0ca>] child_rip+0xa/0x20
 [<ffffffff810969a0>] ? kthread+0x0/0xa0
 [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
INFO: task tgt_recov:6054 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
tgt_recov     D 0000000000000006     0  6054      2 0x00000000
 ffff8802eaf2bda0 0000000000000046 ffff880028276740 0000000000000003
 ffff8802eaf2bd30 ffffffff81055f96 ffff8802eaf2bd40 ffff880338aaeaa0
 ffff880330ff65f8 ffff8802eaf2bfd8 000000000000fb88 ffff880330ff65f8
Call Trace:
 [<ffffffff81055f96>] ? enqueue_task+0x66/0x80
 [<ffffffff8109708e>] ? prepare_to_wait+0x4e/0x80
 [<ffffffffa064e210>] ? check_for_clients+0x0/0x70 [ptlrpc]
 [<ffffffffa064f87d>] target_recovery_overseer+0x9d/0x230 [ptlrpc]
 [<ffffffffa064df00>] ? exp_connect_healthy+0x0/0x20 [ptlrpc]
 [<ffffffff81096da0>] ? autoremove_wake_function+0x0/0x40
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffffa0656680>] target_recovery_thread+0x540/0x1920 [ptlrpc]
 [<ffffffff81063422>] ? default_wake_function+0x12/0x20
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffff81096a36>] kthread+0x96/0xa0
 [<ffffffff8100c0ca>] child_rip+0xa/0x20
 [<ffffffff810969a0>] ? kthread+0x0/0xa0
 [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
Lustre: lnec-OST000b: Denying connection for new client lnec-MDT0000-mdtlov_UUID (at 10.188.20.31@o2ib), waiting for all 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 2:30
Lustre: Skipped 1 previous similar message
Lustre: lnec-OST000b: Denying connection for new client lnec-MDT0000-mdtlov_UUID (at 10.188.20.31@o2ib), waiting for all 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:40
Lustre: lnec-OST000c: Denying connection for new client lnec-MDT0000-mdtlov_UUID (at 10.188.20.31@o2ib), waiting for all 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:40
Lustre: Skipped 2 previous similar messages
Lustre: Skipped 2 previous similar messages
INFO: task tgt_recov:5864 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
tgt_recov     D 000000000000000d     0  5864      2 0x00000000
 ffff88031d269da0 0000000000000046 0000000000000000 0000000000000003
 ffff88031d269d30 ffffffff81055f96 ffff88031d269d40 ffff880338ade080
 ffff8803390cbaf8 ffff88031d269fd8 000000000000fb88 ffff8803390cbaf8
Call Trace:
 [<ffffffff81055f96>] ? enqueue_task+0x66/0x80
 [<ffffffffa064e210>] ? check_for_clients+0x0/0x70 [ptlrpc]
 [<ffffffffa064f87d>] target_recovery_overseer+0x9d/0x230 [ptlrpc]
 [<ffffffffa064df00>] ? exp_connect_healthy+0x0/0x20 [ptlrpc]
 [<ffffffff81096da0>] ? autoremove_wake_function+0x0/0x40
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffffa0656680>] target_recovery_thread+0x540/0x1920 [ptlrpc]
 [<ffffffff81063422>] ? default_wake_function+0x12/0x20
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffff81096a36>] kthread+0x96/0xa0
 [<ffffffff8100c0ca>] child_rip+0xa/0x20
 [<ffffffff810969a0>] ? kthread+0x0/0xa0
 [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
INFO: task tgt_recov:5944 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
tgt_recov     D 000000000000000d     0  5944      2 0x00000000
 ffff8803280cbda0 0000000000000046 0000000000000000 0000000000000003
 ffff8803280cbd30 ffffffff81055f96 ffff8803280cbd40 ffff8806298dcae0
 ffff8802f0ef85f8 ffff8803280cbfd8 000000000000fb88 ffff8802f0ef85f8
Call Trace:
 [<ffffffff81055f96>] ? enqueue_task+0x66/0x80
 [<ffffffffa064e210>] ? check_for_clients+0x0/0x70 [ptlrpc]
 [<ffffffffa064f87d>] target_recovery_overseer+0x9d/0x230 [ptlrpc]
 [<ffffffffa064df00>] ? exp_connect_healthy+0x0/0x20 [ptlrpc]
 [<ffffffff81096da0>] ? autoremove_wake_function+0x0/0x40
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffffa0656680>] target_recovery_thread+0x540/0x1920 [ptlrpc]
 [<ffffffff81063422>] ? default_wake_function+0x12/0x20
 [<ffffffffa0656140>] ? target_recovery_thread+0x0/0x1920 [ptlrpc]
 [<ffffffff81096a36>] kthread+0x96/0xa0
 [<ffffffff8100c0ca>] child_rip+0xa/0x20
 [<ffffffff810969a0>] ? kthread+0x0/0xa0
 [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
Lustre: lnec-OST000c: recovery is timed out, evict stale exports
Lustre: lnec-OST000b: disconnecting 2 stale clients
Lustre: lnec-OST000b: Recovery over after 5:00, of 2 clients 0 recovered and 2 were evicted.
Lustre: Skipped 1 previous similar message
Lustre: lnec-OST000c: disconnecting 2 stale clients
Lustre: lnec-OST000c: Recovery over after 5:00, of 2 clients 0 recovered and 2 were evicted.
Lustre: lnec-OST000f: recovery is timed out, evict stale exports
Lustre: lnec-OST0009: recovery is timed out, evict stale exports
Lustre: lnec-OST0009: disconnecting 2 stale clients
Lustre: lnec-OST0009: Recovery over after 5:00, of 3 clients 1 recovered and 2 were evicted.
Lustre: lnec-OST0009: deleting orphan objects from 0x0:9393083 to 0x0:9394465
Lustre: lnec-OST000f: deleting orphan objects from 0x0:9374587 to 0x0:9375201
Lustre: lnec-OST000a: recovery is timed out, evict stale exports
Lustre: lnec-OST000e: disconnecting 2 stale clients
Lustre: Skipped 3 previous similar messages
Lustre: lnec-OST0008: Recovery over after 5:00, of 3 clients 1 recovered and 2 were evicted.
Lustre: Skipped 1 previous similar message
Lustre: lnec-OST0008: deleting orphan objects from 0x0:9365659 to 0x0:9366273
Lustre: lnec-OST000d: deleting orphan objects from 0x0:9397403 to 0x0:9398145
Lustre: lnec-OST000e: deleting orphan objects from 0x0:9377403 to 0x0:9378017
Lustre: Skipped 3 previous similar messages
Lustre: lnec-OST000a: deleting orphan objects from 0x0:9370459 to 0x0:9371201
Lustre: lnec-OST000b: deleting orphan objects from 0x0:9366091 to 0x0:9366705
Lustre: lnec-OST000c: deleting orphan objects from 0x0:9381147 to 0x0:9382657
Lustre: Failing over lnec-OST000c
Lustre: Failing over lnec-OST000d
Lustre: Failing over lnec-OST000f
Lustre: Skipped 1 previous similar message
LustreError: 137-5: lnec-OST000d_UUID: not available for connect from 10.188.23.12@o2ib (no target). If you are running an HA pair check that the target is mounted on the other server.
LustreError: 137-5: lnec-OST000c_UUID: not available for connect from 10.188.23.12@o2ib (no target). If you are running an HA pair check that the target is mounted on the other server.
LustreError: Skipped 2 previous similar messages
LustreError: Skipped 2 previous similar messages
Lustre: server umount lnec-OST000d complete

Sorry for adding so much of the dmesg output, maybe there is some hint there...

 Comments   
Comment by Erich Focht [ 17/Jan/14 ]

Some clarifications in addition (after questions): this is a production, academic site. But if the issue is generic for Lustre 2.5.0 then this doesn't matter

The OS is CentOS 6.4.

The Filesystem was formatted freshly under 2.5.0 and is ldiskfs.

Comment by Oleg Drokin [ 22/Jan/14 ]

The traces you uploaded just show recovery threads waiting for the clients to reconnect and is normal.

Now can you actually show some logs of unexpected failovers and events preceding those please?

Comment by Erich Focht [ 22/Jan/14 ]

Hi Oleg, this was a clean shutdown of all Lustre servers before, but without unmounting the clients. What you see is what happened after boot, loading the Lustre modules and trying to mount the OSTs. The other machine looks quiet. This happened later again when trying to failover OSTs (for rebalancing them across OSSes). Looks exactly the same. I'll dig into the logs to find one of the spontaneous events (tomorrow, it's late here, today). The problem is that these lockups were leading to corosync not being scheduled and the failover partner STONITHing the machine with the lockups. Since we disabled caching all is fine, no "blocked for more than 120 seconds" any more.

Comment by Oleg Drokin [ 22/Jan/14 ]

I still don;t quite see the connection between blocking (and it's not blocking on io or anything even remotely related) during recovery, waiting for clients to connect and caching. We see clearly in the logs provided that once the stale clients are evicted, the operations continue.

So unless you have some great evidence the stale clients actually did connect and got stuck somewhere in io before being reported (need some stack traces of that happening) or better logs that demonstrate problems, I am not even sure how is the cache affecting your operations during recovery.

Also the standard workaround if you think the cche affects your osts too much is to limit the cached object size:
/proc/fs/lustre/osd-ldiskfs/*/readcache_max_filesize - change that from -1 to something where you thing the cache hits would still happen like 4G, or whatever you feel (note this is not really a file size contrary to the name, but individual object size).

Comment by Erich Focht [ 24/Jan/14 ]

Thanks and sorry, obviously I picked a wrong piece of logs :-/ And I understand your argument with cache not being involved in the recovery. I am still wondering why tgt_recov was regularly getting in that blocked state and now not any more.

For the sake of completeness, we have seen also the thing below, but that is not matching the subject line of this report, and has disappeared also.

2013-12-20T18:59:28.489440+01:00 loss3 kernel: Lustre: 5873:0:(client.c:1897:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1387562361/real 1387562361]  req@ffff8803bf40bc00 x1454871704773124/t0(0) o106->lnec-OST000b@10.188.23.40@o2ib
:15/16 lens 296/280 e 0 to 1 dl 1387562368 ref 1 fl Rpc:X/0/ffffffff rc 0/-1
2013-12-20T18:59:28.489461+01:00 loss3 kernel: Lustre: 5873:0:(client.c:1897:ptlrpc_expire_one_request()) Skipped 2 previous similar messages
2013-12-20T18:59:42.490972+01:00 loss3 kernel: Lustre: 5877:0:(client.c:1897:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1387562375/real 1387562375]  req@ffff8804589db400 x1454871704773112/t0(0) o106->lnec-OST0009@10.188.23.40@o2ib
:15/16 lens 296/280 e 0 to 1 dl 1387562382 ref 1 fl Rpc:X/2/ffffffff rc 0/-1
2013-12-20T18:59:42.491010+01:00 loss3 kernel: Lustre: 5877:0:(client.c:1897:ptlrpc_expire_one_request()) Skipped 9 previous similar messages
2013-12-20T19:00:03.505100+01:00 loss3 kernel: Lustre: 5907:0:(client.c:1897:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1387562396/real 1387562396]  req@ffff88038c9a7c00 x1454871704773120/t0(0) o106->lnec-OST000a@10.188.23.40@o2ib
:15/16 lens 296/280 e 0 to 1 dl 1387562403 ref 1 fl Rpc:X/2/ffffffff rc 0/-1
2013-12-20T19:00:03.505115+01:00 loss3 kernel: Lustre: 5907:0:(client.c:1897:ptlrpc_expire_one_request()) Skipped 13 previous similar messages
2013-12-20T19:00:12.276007+01:00 loss3 kernel: LNetError: 2642:0:(o2iblnd_cb.c:3012:kiblnd_check_txs_locked()) Timed out tx: active_txs, 10 seconds
2013-12-20T19:00:12.276027+01:00 loss3 kernel: LNetError: 2642:0:(o2iblnd_cb.c:3075:kiblnd_check_conns()) Timed out RDMA with 10.188.22.166@o2ib (23): c: 57, oc: 0, rc: 62
2013-12-20T19:00:12.297737+01:00 loss3 kernel: LustreError: 2642:0:(events.c:450:server_bulk_callback()) event type 5, status -103, desc ffff88026261c380
2013-12-20T19:00:38.554032+01:00 loss3 kernel: Lustre: 5873:0:(client.c:1897:ptlrpc_expire_one_request()) @@@ Request sent has timed out for sent delay: [sent 1387562431/real 1387562417]  req@ffff8803bf40bc00 x1454871704773124/t0(0) o106->lnec-OST000b@10.188.23.40@o2ib:15/16 lens 296/280 e 0 to 1 dl 1387562438 ref 3 fl Rpc:X/2/ffffffff rc 0/-1
2013-12-20T19:00:38.554053+01:00 loss3 kernel: Lustre: 5873:0:(client.c:1897:ptlrpc_expire_one_request()) Skipped 27 previous similar messages

2013-12-20T19:01:19.288921+01:00 loss3 kernel: LNetError: 2642:0:(o2iblnd_cb.c:3012:kiblnd_check_txs_locked()) Timed out tx: tx_queue, 4 seconds
2013-12-20T19:01:19.288941+01:00 loss3 kernel: LNetError: 2642:0:(o2iblnd_cb.c:3075:kiblnd_check_conns()) Timed out RDMA with 10.188.23.40@o2ib (61): c: 0, oc: 0, rc: 63
2013-12-20T19:01:46.798338+01:00 loss3 kernel: INFO: task ll_ost_io00_065:6171 blocked for more than 120 seconds.
2013-12-20T19:01:46.798351+01:00 loss3 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
2013-12-20T19:01:46.828517+01:00 loss3 kernel: ll_ost_io00_0 D 0000000000000008     0  6171      2 0x00000000
2013-12-20T19:01:46.828876+01:00 loss3 kernel: ffff880313519720 0000000000000046 ffff8803135196e8 ffff8803135196e4
2013-12-20T19:01:46.858008+01:00 loss3 kernel: ffff880313519690 ffff88033fc25300 ffff880028236740 0000000000000400
2013-12-20T19:01:46.872589+01:00 loss3 kernel: ffff8803134ed058 ffff880313519fd8 000000000000fb88 ffff8803134ed058
2013-12-20T19:01:46.872597+01:00 loss3 kernel: Call Trace:
2013-12-20T19:01:46.886663+01:00 loss3 kernel: [<ffffffff81119e10>] ? sync_page+0x0/0x50
2013-12-20T19:01:46.900515+01:00 loss3 kernel: [<ffffffff8150ed03>] io_schedule+0x73/0xc0
2013-12-20T19:01:46.913935+01:00 loss3 kernel: [<ffffffff81119e4d>] sync_page+0x3d/0x50
2013-12-20T19:01:46.939621+01:00 loss3 kernel: [<ffffffff8150f56a>] __wait_on_bit_lock+0x5a/0xc0
2013-12-20T19:01:46.939630+01:00 loss3 kernel: [<ffffffff81119de7>] __lock_page+0x67/0x70
2013-12-20T19:01:46.952042+01:00 loss3 kernel: [<ffffffff81096de0>] ? wake_bit_function+0x0/0x50
2013-12-20T19:01:46.964091+01:00 loss3 kernel: [<ffffffff81119c1e>] ? find_get_page+0x1e/0xa0
2013-12-20T19:01:46.976894+01:00 loss3 kernel: [<ffffffff8111ae90>] find_lock_page+0x50/0x80
2013-12-20T19:01:46.989161+01:00 loss3 kernel: [<ffffffff8111afbf>] find_or_create_page+0x3f/0xb0
2013-12-20T19:01:47.001039+01:00 loss3 kernel: [<ffffffffa0de195a>] osd_get_page+0x11a/0x180 [osd_ldiskfs]
2013-12-20T19:01:47.024749+01:00 loss3 kernel: [<ffffffffa0de1bb6>] osd_bufs_get+0x1f6/0x370 [osd_ldiskfs]
2013-12-20T19:01:47.036409+01:00 loss3 kernel: [<ffffffffa0e6da5b>] ofd_preprw_read+0x14b/0x7f0 [ofd]
2013-12-20T19:01:47.036418+01:00 loss3 kernel: [<ffffffffa046ce9a>] ? LNetPut+0x31a/0x860 [lnet]
2013-12-20T19:01:47.047692+01:00 loss3 kernel: [<ffffffffa0e6e87a>] ofd_preprw+0x77a/0x1480 [ofd]
2013-12-20T19:01:47.058147+01:00 loss3 kernel: [<ffffffffa0692e51>] ? lustre_pack_reply_v2+0x1e1/0x280 [ptlrpc]
2013-12-20T19:01:47.068527+01:00 loss3 kernel: [<ffffffffa0e2fe11>] obd_preprw+0x121/0x390 [ost]
2013-12-20T19:01:47.078892+01:00 loss3 kernel: [<ffffffffa0e37569>] ost_brw_read+0xd29/0x1350 [ost]
2013-12-20T19:01:47.089398+01:00 loss3 kernel: [<ffffffff81277ab9>] ? cpumask_next_and+0x29/0x50
2013-12-20T19:01:47.099759+01:00 loss3 kernel: [<ffffffff81059e67>] ? find_busiest_group+0x907/0x9f0
2013-12-20T19:01:47.120309+01:00 loss3 kernel: [<ffffffffa06939ec>] ? lustre_msg_get_version+0x8c/0x100 [ptlrpc]
2013-12-20T19:01:47.120317+01:00 loss3 kernel: [<ffffffffa0693b48>] ? lustre_msg_check_version+0xe8/0x100 [ptlrpc]
2013-12-20T19:01:47.130446+01:00 loss3 kernel: [<ffffffffa0e3e6d8>] ost_handle+0x24a8/0x44d0 [ost]
2013-12-20T19:01:47.150695+01:00 loss3 kernel: [<ffffffffa069a9cb>] ? ptlrpc_update_export_timer+0x4b/0x560 [ptlrpc]
2013-12-20T19:01:47.150703+01:00 loss3 kernel: [<ffffffffa06a2e25>] ptlrpc_server_handle_request+0x385/0xc00 [ptlrpc]
2013-12-20T19:01:47.170693+01:00 loss3 kernel: [<ffffffffa03ac4ce>] ? cfs_timer_arm+0xe/0x10 [libcfs]
2013-12-20T19:01:47.170701+01:00 loss3 kernel: [<ffffffffa03bd27f>] ? lc_watchdog_touch+0x6f/0x170 [libcfs]
2013-12-20T19:01:47.190137+01:00 loss3 kernel: [<ffffffffa069a4c9>] ? ptlrpc_wait_event+0xa9/0x2d0 [ptlrpc]
2013-12-20T19:01:47.190144+01:00 loss3 kernel: [<ffffffff81051439>] ? __wake_up_common+0x59/0x90
2013-12-20T19:01:47.208938+01:00 loss3 kernel: [<ffffffffa06a418d>] ptlrpc_main+0xaed/0x1740 [ptlrpc]
2013-12-20T19:01:47.208946+01:00 loss3 kernel: [<ffffffffa06a36a0>] ? ptlrpc_main+0x0/0x1740 [ptlrpc]
2013-12-20T19:01:47.218144+01:00 loss3 kernel: [<ffffffff81096a36>] kthread+0x96/0xa0
2013-12-20T19:01:47.227034+01:00 loss3 kernel: [<ffffffff8100c0ca>] child_rip+0xa/0x20
2013-12-20T19:01:47.235714+01:00 loss3 kernel: [<ffffffff810969a0>] ? kthread+0x0/0xa0
2013-12-20T19:01:47.252419+01:00 loss3 kernel: [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
2013-12-20T19:01:47.252428+01:00 loss3 kernel: INFO: task ll_ost_io01_005:6239 blocked for more than 120 seconds.
2013-12-20T19:01:47.260764+01:00 loss3 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
2013-12-20T19:01:47.277413+01:00 loss3 kernel: ll_ost_io01_0 D 0000000000000003     0  6239      2 0x00000000
2013-12-20T19:01:47.285496+01:00 loss3 kernel: ffff880312d1f720 0000000000000046 0000000000000000 0000000000000001
2013-12-20T19:01:47.285902+01:00 loss3 kernel: ffff880312d1f6e0 ffffffffa085b877 0000000000016740 0000000000000282
2013-12-20T19:01:47.320939+01:00 loss3 kernel: Lustre: 6028:0:(client.c:1897:ptlrpc_expire_one_request()) @@@ Request sent has timed out for sent delay: [sent 1387562500/real 1387562479]  req@ffff880495f1e800 x1454871704792124/t0(0) o106->lnec-OST000b@10.188.23.40@o2ib:15/16 lens 296/280 e 0 to 1 dl 1387562507 ref 7 fl Rpc:X/2/ffffffff rc 0/-1
2013-12-20T19:01:47.320948+01:00 loss3 kernel: Lustre: 6028:0:(client.c:1897:ptlrpc_expire_one_request()) Skipped 122 previous similar messages
2013-12-20T19:01:47.330352+01:00 loss3 kernel: ffff880315e4faf8 ffff880312d1ffd8 000000000000fb88 ffff880315e4faf8
2013-12-20T19:01:47.330361+01:00 loss3 kernel: Call Trace:
2013-12-20T19:01:47.339458+01:00 loss3 kernel: [<ffffffffa085b877>] ? kiblnd_post_tx_locked+0x487/0x930 [ko2iblnd]
2013-12-20T19:01:47.348904+01:00 loss3 kernel: [<ffffffff81119e10>] ? sync_page+0x0/0x50
2013-12-20T19:01:47.367200+01:00 loss3 kernel: [<ffffffff8150ed03>] io_schedule+0x73/0xc0
2013-12-20T19:01:47.367208+01:00 loss3 kernel: [<ffffffff81119e4d>] sync_page+0x3d/0x50
2013-12-20T19:01:47.375924+01:00 loss3 kernel: [<ffffffff8150f56a>] __wait_on_bit_lock+0x5a/0xc0
2013-12-20T19:01:47.384484+01:00 loss3 kernel: [<ffffffff81119de7>] __lock_page+0x67/0x70
2013-12-20T19:01:47.392933+01:00 loss3 kernel: [<ffffffff81096de0>] ? wake_bit_function+0x0/0x50
2013-12-20T19:01:47.401341+01:00 loss3 kernel: [<ffffffff81119c1e>] ? find_get_page+0x1e/0xa0
2013-12-20T19:01:47.409136+01:00 loss3 kernel: [<ffffffff8111ae90>] find_lock_page+0x50/0x80
2013-12-20T19:01:47.416318+01:00 loss3 kernel: [<ffffffff8111afbf>] find_or_create_page+0x3f/0xb0
2013-12-20T19:01:47.429442+01:00 loss3 kernel: [<ffffffffa0de195a>] osd_get_page+0x11a/0x180 [osd_ldiskfs]
2013-12-20T19:01:47.435733+01:00 loss3 kernel: [<ffffffffa0de1bb6>] osd_bufs_get+0x1f6/0x370 [osd_ldiskfs]
2013-12-20T19:01:47.435742+01:00 loss3 kernel: [<ffffffffa0e6da5b>] ofd_preprw_read+0x14b/0x7f0 [ofd]
2013-12-20T19:01:47.447887+01:00 loss3 kernel: [<ffffffffa0e6e87a>] ofd_preprw+0x77a/0x1480 [ofd]
2013-12-20T19:01:47.447896+01:00 loss3 kernel: [<ffffffffa0692e51>] ? lustre_pack_reply_v2+0x1e1/0x280 [ptlrpc]
2013-12-20T19:01:47.453899+01:00 loss3 kernel: [<ffffffffa0e2fe11>] obd_preprw+0x121/0x390 [ost]
2013-12-20T19:01:47.459902+01:00 loss3 kernel: [<ffffffffa0e37569>] ost_brw_read+0xd29/0x1350 [ost]
2013-12-20T19:01:47.465961+01:00 loss3 kernel: [<ffffffff81277ab9>] ? cpumask_next_and+0x29/0x50
2013-12-20T19:01:47.471928+01:00 loss3 kernel: [<ffffffff810597a4>] ? find_busiest_group+0x244/0x9f0
2013-12-20T19:01:47.477924+01:00 loss3 kernel: [<ffffffffa06939ec>] ? lustre_msg_get_version+0x8c/0x100 [ptlrpc]
2013-12-20T19:01:47.490292+01:00 loss3 kernel: [<ffffffffa0693b48>] ? lustre_msg_check_version+0xe8/0x100 [ptlrpc]
2013-12-20T19:01:47.490301+01:00 loss3 kernel: [<ffffffffa0e3e6d8>] ost_handle+0x24a8/0x44d0 [ost]
2013-12-20T19:01:47.502949+01:00 loss3 kernel: [<ffffffffa069a9cb>] ? ptlrpc_update_export_timer+0x4b/0x560 [ptlrpc]
2013-12-20T19:01:47.502957+01:00 loss3 kernel: [<ffffffffa06a2e25>] ptlrpc_server_handle_request+0x385/0xc00 [ptlrpc]
2013-12-20T19:01:47.509588+01:00 loss3 kernel: [<ffffffffa03ac4ce>] ? cfs_timer_arm+0xe/0x10 [libcfs]
2013-12-20T19:01:47.516164+01:00 loss3 kernel: [<ffffffffa03bd27f>] ? lc_watchdog_touch+0x6f/0x170 [libcfs]
2013-12-20T19:01:47.529409+01:00 loss3 kernel: [<ffffffffa069a4c9>] ? ptlrpc_wait_event+0xa9/0x2d0 [ptlrpc]
2013-12-20T19:01:47.529418+01:00 loss3 kernel: [<ffffffff81051439>] ? __wake_up_common+0x59/0x90
2013-12-20T19:01:47.535955+01:00 loss3 kernel: [<ffffffffa06a418d>] ptlrpc_main+0xaed/0x1740 [ptlrpc]
2013-12-20T19:01:47.549135+01:00 loss3 kernel: [<ffffffffa06a36a0>] ? ptlrpc_main+0x0/0x1740 [ptlrpc]
2013-12-20T19:01:47.549143+01:00 loss3 kernel: [<ffffffff81096a36>] kthread+0x96/0xa0
2013-12-20T19:01:47.555478+01:00 loss3 kernel: [<ffffffff8100c0ca>] child_rip+0xa/0x20
2013-12-20T19:01:47.561770+01:00 loss3 kernel: [<ffffffff810969a0>] ? kthread+0x0/0xa0
2013-12-20T19:01:47.568126+01:00 loss3 kernel: [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
[... many of these, all pretty similar ...]

2013-12-20T19:02:31.612842+01:00 loss3 kernel: LNet: Service thread pid 6324 was inactive for 200.00s. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes:
2013-12-20T19:02:31.612863+01:00 loss3 kernel: Pid: 6324, comm: ll_ost_io01_089
2013-12-20T19:02:31.619178+01:00 loss3 kernel: 
2013-12-20T19:02:31.619187+01:00 loss3 kernel: Call Trace:
2013-12-20T19:02:31.631284+01:00 loss3 kernel: [<ffffffff810810cc>] ? lock_timer_base+0x3c/0x70
2013-12-20T19:02:31.637633+01:00 loss3 kernel: [<ffffffff8150f362>] schedule_timeout+0x192/0x2e0
2013-12-20T19:02:31.643873+01:00 loss3 kernel: [<ffffffff810811e0>] ? process_timeout+0x0/0x10
2013-12-20T19:02:31.656587+01:00 loss3 kernel: [<ffffffffa065d700>] target_bulk_io+0x3a0/0x8d0 [ptlrpc]
2013-12-20T19:02:31.656596+01:00 loss3 kernel: [<ffffffff81063410>] ? default_wake_function+0x0/0x20
2013-12-20T19:02:31.669657+01:00 loss3 kernel: [<ffffffffa0681b88>] ? __ptlrpc_prep_bulk_page+0x68/0x170 [ptlrpc]
2013-12-20T19:02:31.669666+01:00 loss3 kernel: [<ffffffffa0e3787c>] ost_brw_read+0x103c/0x1350 [ost]
2013-12-20T19:02:31.682418+01:00 loss3 kernel: [<ffffffffa0653340>] ? target_bulk_timeout+0x0/0xc0 [ptlrpc]
2013-12-20T19:02:31.688483+01:00 loss3 kernel: [<ffffffffa0691f85>] ? lustre_msg_buf+0x55/0x60 [ptlrpc]
2013-12-20T19:02:31.694600+01:00 loss3 kernel: [<ffffffffa06939ec>] ? lustre_msg_get_version+0x8c/0x100 [ptlrpc]
2013-12-20T19:02:31.700701+01:00 loss3 kernel: [<ffffffffa0693b48>] ? lustre_msg_check_version+0xe8/0x100 [ptlrpc]
2013-12-20T19:02:31.706902+01:00 loss3 kernel: [<ffffffffa0e3e6d8>] ost_handle+0x24a8/0x44d0 [ost]
2013-12-20T19:02:31.713206+01:00 loss3 kernel: [<ffffffffa069a9cb>] ? ptlrpc_update_export_timer+0x4b/0x560 [ptlrpc]
2013-12-20T19:02:31.719745+01:00 loss3 kernel: [<ffffffffa06a2e25>] ptlrpc_server_handle_request+0x385/0xc00 [ptlrpc]
2013-12-20T19:02:31.719759+01:00 loss3 kernel: [<ffffffffa03ac4ce>] ? cfs_timer_arm+0xe/0x10 [libcfs]
2013-12-20T19:02:31.732621+01:00 loss3 kernel: [<ffffffffa03bd27f>] ? lc_watchdog_touch+0x6f/0x170 [libcfs]
2013-12-20T19:02:31.739263+01:00 loss3 kernel: [<ffffffffa069a4c9>] ? ptlrpc_wait_event+0xa9/0x2d0 [ptlrpc]
2013-12-20T19:02:31.745570+01:00 loss3 kernel: [<ffffffff81051439>] ? __wake_up_common+0x59/0x90
2013-12-20T19:02:31.751837+01:00 loss3 kernel: [<ffffffffa06a418d>] ptlrpc_main+0xaed/0x1740 [ptlrpc]
2013-12-20T19:02:31.758155+01:00 loss3 kernel: [<ffffffffa06a36a0>] ? ptlrpc_main+0x0/0x1740 [ptlrpc]
2013-12-20T19:02:31.758164+01:00 loss3 kernel: [<ffffffff81096a36>] kthread+0x96/0xa0
2013-12-20T19:02:31.764198+01:00 loss3 kernel: [<ffffffff8100c0ca>] child_rip+0xa/0x20
2013-12-20T19:02:31.770221+01:00 loss3 kernel: [<ffffffff810969a0>] ? kthread+0x0/0xa0
2013-12-20T19:02:31.781787+01:00 loss3 kernel: [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
[...]
2013-12-20T19:02:32.866524+01:00 loss3 kernel: LNet: Service thread pid 6347 was inactive for 201.26s. Watchdog stack traces are limited to 3 per 300 seconds, skipping this one.
2013-12-20T19:02:32.872898+01:00 loss3 kernel: LNet: Skipped 67 previous similar messages
2013-12-20T19:02:41.456894+01:00 loss3 kernel: LNet: Service thread pid 5873 was inactive for 200.00s. Watchdog stack traces are limited to 3 per 300 seconds, skipping this one.
2013-12-20T19:02:41.456924+01:00 loss3 kernel: LNet: Skipped 5 previous similar messages
2013-12-20T19:02:41.477049+01:00 loss3 kernel: LustreError: dumping log to /tmp/lustre-log.1387562561.5873
2013-12-20T19:02:41.833779+01:00 loss3 kernel: LustreError: dumping log to /tmp/lustre-log.1387562561.5698
2013-12-20T19:02:57.038254+01:00 loss3 kernel: Lustre: lnec-OST000a: haven't heard from client 09dfb705-7d7e-7380-64a8-31791efe2078 (at 10.188.22.166@o2ib) in 227 seconds. I think it's dead, and I am evicting it. exp ffff88060384a400, cur 1387562577 expire 1387562427 last 1387562350
2013-12-20T19:02:57.130512+01:00 loss3 kernel: LustreError: 5907:0:(ldlm_lockd.c:662:ldlm_handle_ast_error()) ### client (nid 10.188.23.40@o2ib) returned 0 from glimpse AST ns: filter-lnec-OST000a_UUID lock: ffff88035db94900/0x735a341dfc56203f lrc: 4/0,0 mode: PW/PW res: [0x2ab7b1:0x0:0x0].0 rrc: 2 type: EXT [0->18446744073709551615] (req 0->18446744073709551615) flags: 0x40000000000000 nid: 10.188.23.40@o2ib remote: 0xa8f716fa8e29d84c expref: 25 pid: 5986 timeout: 0 lvb_type: 0
2013-12-20T19:02:57.130529+01:00 loss3 kernel: LNet: Service thread pid 5671 completed after 215.21s. This indicates the system was overloaded (too many service threads, or there were not enough hardware resources).
2013-12-20T19:02:57.130532+01:00 loss3 kernel: LNet: Skipped 54 previous similar messages
2013-12-20T19:02:57.130533+01:00 loss3 kernel: LustreError: 5907:0:(ldlm_lockd.c:662:ldlm_handle_ast_error()) Skipped 14 previous similar messages
2013-12-20T19:02:57.180170+01:00 loss3 kernel: LNet: Service thread pid 5907 completed after 215.69s. This indicates the system was overloaded (too many service threads, or there were not enough hardware resources).
2013-12-20T19:02:57.180181+01:00 loss3 kernel: LNet: Skipped 5 previous similar messages
2013-12-20T19:02:57.625402+01:00 loss3 kernel: LustreError: 6324:0:(ldlm_lib.c:2698:target_bulk_io()) @@@ Eviction on bulk PUT  req@ffff8803053d0800 x1454760633405268/t0(0) o3->09dfb705-7d7e-7380-64a8-31791efe2078@10.188.22.166@o2ib:0/0 lens 488/432 e 2 to 0 dl 1387562583 ref 1 fl Interpret:/0/0 rc 0/0
2013-12-20T19:02:57.625415+01:00 loss3 kernel: Lustre: lnec-OST000a: Bulk IO read error with 09dfb705-7d7e-7380-64a8-31791efe2078 (at 10.188.22.166@o2ib), client will retry: rc -107
2013-12-20T19:02:57.662876+01:00 loss3 kernel: LustreError: 6347:0:(ldlm_lib.c:2722:target_bulk_io()) @@@ bulk PUT failed: rc -107  req@ffff88011e780000 x1454759876310416/t0(0) o3->71bc3d74-04b5-26bf-f18d-4c7786c94180@10.188.21.205@o2ib:0/0 lens 488/432 e 2 to 0 dl 1387562583 ref 1 fl Interpret:/0/0 rc 0/0
2013-12-20T19:02:57.712335+01:00 loss3 kernel: Lustre: lnec-OST000a: Bulk IO read error with 71bc3d74-04b5-26bf-f18d-4c7786c94180 (at 10.188.21.205@o2ib), client will retry: rc -107
2013-12-20T19:02:57.712344+01:00 loss3 kernel: LNet: Service thread pid 6337 completed after 226.06s. This indicates the system was overloaded (too many service threads, or there were not enough hardware resources).
2013-12-20T19:02:57.712345+01:00 loss3 kernel: LNet: Skipped 6 previous similar messages

If that is of any interest, please email me. Otherwise I'll follow the advice on readcache_max_filesize and this ticket can be closed.

Comment by John Fuchs-Chesney (Inactive) [ 24/Jan/14 ]

Thanks Erich – sounds like you have received some satisfaction here, which is good. I'll mark this as resolved. Have a good week-end! ~ jfc.

Comment by John Fuchs-Chesney (Inactive) [ 24/Jan/14 ]

We provided advice to Erich on readcache_max_filesize.

Generated at Sat Feb 10 01:43:14 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.