We're experiencing occasional client evictions on our Lustre 2.1 filesystem which are causing some compute jobs to fail to write their output. This seems to be traceable to some issue with an expiring "lock callback timer".
We've experienced at least five instances where compute nodes are evicted by the MDT toward the end of a long job:
Jan 23 09:06:57 nh0258 kernel: LustreError: 167-0: This client was
evicted by sbm-MDT0000; in progress operations using this service will
fail.
Jan 24 16:39:36 nh0130 kernel: LustreError: 167-0: This client was
evicted by sbm-MDT0000; in progress operations using this service will
fail.
Jan 25 17:50:12 nh0127 kernel: LustreError: 167-0: This client was
evicted by sbm-MDT0000; in progress operations using this service will
fail.
Jan 25 22:09:57 nh0140 kernel: LustreError: 167-0: This client was
evicted by sbm-MDT0000; in progress operations using this service will
fail.
Jan 26 01:30:25 nh0025 kernel: LustreError: 167-0: This client was
evicted by sbm-MDT0000; in progress operations using this service will
fail.
Using the most recent instance as an example: On the failing compute node nh0025 we see the client being evicted, a number of errors, and then finally the connection is restored.
Jan 26 01:30:25 nh0025 kernel: LustreError: 11-0: an error occurred
while communicating with 10.66.17.1@o2ib. The mds_reint operation
failed with -107
Jan 26 01:30:25 nh0025 kernel: Lustre:
sbm-MDT0000-mdc-ffff8105f6d5e400: Connection to service sbm-MDT0000
via nid 10.66.17.1@o2ib was lost; in progress operations using this
service will wait for recovery to complete.
Jan 26 01:30:25 nh0025 kernel: LustreError: 167-0: This client was
evicted by sbm-MDT0000; in progress operations using this service will
fail.
Jan 26 01:30:25 nh0025 kernel: LustreError:
7127:0:(client.c:1060:ptlrpc_import_delay_req()) @@@ IMP_INVALID
req@ffff810144ec0c00 x1391200321417798/t0(0)
o-1->sbm-MDT0000_UUID@10.66.17.1@o2ib:12/10 lens 560/1400 e 0 to 0 dl
0 ref 2 fl Rpc:/ffffffff/ffffffff rc 0/-1
Jan 26 01:30:25 nh0025 kernel: LustreError:
7127:0:(mdc_locks.c:722:mdc_enqueue()) ldlm_cli_enqueue: -108
Jan 26 01:30:25 nh0025 kernel: LustreError:
7127:0:(mdc_locks.c:722:mdc_enqueue()) Skipped 1 previous similar
message
Jan 26 01:30:25 nh0025 kernel: LustreError:
7127:0:(file.c:158:ll_close_inode_openhandle()) inode
144115244246036471 mdc close failed: rc = -108
Jan 26 01:30:25 nh0025 kernel: LustreError:
7128:0:(client.c:1060:ptlrpc_import_delay_req()) @@@ IMP_INVALID
req@ffff81029612f000 x1391200321417803/t0(0)
o-1->sbm-MDT0000_UUID@10.66.17.1@o2ib:12/10 lens 568/1400 e 0 to 0 dl
0 ref 2 fl Rpc:/ffffffff/ffffffff rc 0/-1
Jan 26 01:30:25 nh0025 kernel: LustreError:
7128:0:(client.c:1060:ptlrpc_import_delay_req()) Skipped 7 previous
similar messages
Jan 26 01:30:25 nh0025 kernel: LustreError:
7128:0:(mdc_locks.c:722:mdc_enqueue()) ldlm_cli_enqueue: -108
Jan 26 01:30:25 nh0025 kernel: LustreError:
7128:0:(mdc_locks.c:722:mdc_enqueue()) Skipped 2 previous similar
messages
Jan 26 01:30:25 nh0025 kernel: LustreError:
22478:0:(file.c:158:ll_close_inode_openhandle()) inode
144115205524192864 mdc close failed: rc = -108
Jan 26 01:30:25 nh0025 kernel: LustreError:
22478:0:(file.c:158:ll_close_inode_openhandle()) Skipped 2 previous
similar messages
Jan 26 01:30:25 nh0025 kernel: Lustre:
sbm-MDT0000-mdc-ffff8105f6d5e400: Connection restored to service
sbm-MDT0000 using nid 10.66.17.1@o2ib.
By the time service is restored, however, the compute process in progress has experienced an I/O error and failed to write its output. At the same time on the MDT server (sbmmds1), we see corresponding messages: (the messages before 01:30:25 may not be related, but are included just in case)
Jan 26 01:26:21 sbmmds1 kernel: LustreError:
10258:0:(ldlm_lib.c:2129:target_send_reply_msg()) @@@ processing error
(-95) req@ffff810f624d9400 x1390880832379849/t0(0) o-1->847a5c9e-2e39
-68ef-399a-405f39029d01@NET_0x500000a42006f_UUID:0/0 lens 448/328 e 0
to 0 dl 1327562787 ref 1 fl Interpret:/ffffffff/ffffffff rc -95/-1
Jan 26 01:26:49 sbmmds1 kernel: LustreError:
7880:0:(ldlm_lib.c:2129:target_send_reply_msg()) @@@ processing error
(-95) req@ffff81026bdb3400 x1390880832412002/t0(0)
o-1->847a5c9e-2e39-
68ef-399a-405f39029d01@NET_0x500000a42006f_UUID:0/0 lens 448/328 e 0
to 0 dl 1327562815 ref 1 fl Interpret:/ffffffff/ffffffff rc -95/-1
Jan 26 01:26:49 sbmmds1 kernel: LustreError:
7880:0:(ldlm_lib.c:2129:target_send_reply_msg()) Skipped 15 previous
similar messages
Jan 26 01:30:25 sbmmds1 kernel: LustreError:
0:0:(ldlm_lockd.c:356:waiting_locks_callback()) ### lock callback
timer expired after 6500s: evicting client at 10.66.1.25@o2ib ns:
mdt-ffff
8109092d9000 lock: ffff81013a477d80/0xeff37306d1dd260c lrc: 3/0,0
mode: PR/PR res: 8589937940/61621 bits 0x3 rrc: 2 type: IBT flags:
0x4000020 remote: 0x56444e051623e259 expref: 8123 pid
: 6132 timeout: 5449792637
Jan 26 01:30:25 sbmmds1 kernel: LustreError:
7870:0:(mdt_handler.c:2785:mdt_recovery()) operation 36 on unconnected
MDS from 12345-10.66.1.25@o2ib
Jan 26 01:30:25 sbmmds1 kernel: LustreError:
7870:0:(ldlm_lib.c:2129:target_send_reply_msg()) @@@ processing error
(-107) req@ffff810aca523000 x1391200321417503/t0(0) o-1-><?>@<?>:0/0
l
ens 472/0 e 0 to 0 dl 1327563031 ref 1 fl Interpret:/ffffffff/ffffffff
rc -107/-1
Jan 26 01:30:25 sbmmds1 kernel: LustreError:
7870:0:(ldlm_lib.c:2129:target_send_reply_msg()) Skipped 1 previous
similar message
Jan 26 01:30:25 sbmmds1 kernel: Lustre:
7870:0:(ldlm_lib.c:877:target_handle_connect()) sbm-MDT0000:
connection from 3cb0b468-917d-9596-fe06-57506f30d0f9@10.66.1.25@o2ib
t8800065711 exp
0000000000000000 cur 1327563025 last 0
Jan 26 01:30:25 sbmmds1 kernel: Lustre:
7870:0:(sec.c:1474:sptlrpc_import_sec_adapt()) import
sbm-MDT0000->NET_0x500000a420119_UUID netid 50000: select flavor null
Similar messages are observed on the MDT for each of the five evictions which have resulted in job problems. The number of seconds in the message "lock callback timer expired after XXXXs" varies, between 4440s and 6500s.
So to sum up: the MDT evicts the client due to a "lock callback timer expired" message, and the compute process running on the client node fails to write its data. The client is restored to service, but not before the compute process has given up.
Has anyone seen this before? How did you fix it? Any advice that helps us resolve this is appreciated.
