[LU-12037] Possible DNE issue leading to hung filesystem

• Type: Bug
• Resolution: Fixed
• Priority: Critical
• Fix Version/s: Lustre 2.13.0, Lustre 2.12.1
• Affects Version/s: Lustre 2.12.0
• Environment: CentOS 7.6 - Servers: 2.12.0 Clients: 2.12.0 + patch LU-11964
• Severity: 2
• Assignee: Lai Siyao
• Reporter: Stephane Thiell

Description

A new issue with 2.12 started first with directories not accessible from a specific client (10.9.0.1@o2ib4) and ended up with a full filesystem deadlock. Restarting all MDTs resolved (temporarily) the issue...

This is the console of fir-md1-s1 (serves MDT0000 and MDT0002), when the directories started to become unaccessible:

[1378713.475739] LNet: Service thread pid 48757 was inactive for 212.00s. Watchdog stack traces are limited to 3 per 300 seconds, skipping this one.
[1378713.488774] LNet: Skipped 3 previous similar messages
[1378713.494012] LustreError: dumping log to /tmp/lustre-log.1551393702.48757
[1378716.547830] LustreError: dumping log to /tmp/lustre-log.1551393705.22268
[1378721.106914] Lustre: fir-MDT0000-osp-MDT0002: Connection to fir-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete
[1378721.108926] LustreError: 51417:0:(ldlm_request.c:129:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1551393409, 300s ago); not entering recovery in server code, just going back to sleep ns:
[1378721.161814] LustreError: 51459:0:(ldlm_request.c:147:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1551393409, 300s ago), entering recovery for fir-MDT0000_UUID@10.0.10.51@o2ib7 ns: fir-MD
[1378721.202150] Lustre: fir-MDT0000: Received new LWP connection from 0@lo, removing former export from same NID
[1378721.943952] LustreError: 22249:0:(ldlm_request.c:147:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1551393410, 300s ago), entering recovery for fir-MDT0000_UUID@10.0.10.51@o2ib7 ns: fir-MD
[1378721.984222] LustreError: 22249:0:(ldlm_request.c:147:ldlm_expired_completion_wait()) Skipped 2 previous similar messages
[1378724.392997] LustreError: 51445:0:(ldlm_request.c:147:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1551393413, 300s ago), entering recovery for fir-MDT0000_UUID@10.0.10.51@o2ib7 ns: fir-MD
[1378728.847103] LustreError: 22142:0:(ldlm_request.c:147:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1551393417, 300s ago), entering recovery for fir-MDT0000_UUID@10.0.10.51@o2ib7 ns: fir-MD
[1378729.910121] LustreError: 21796:0:(ldlm_request.c:129:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1551393418, 300s ago); not entering recovery in server code, just going back to sleep ns:
[1378729.949613] LustreError: 21796:0:(ldlm_request.c:129:ldlm_expired_completion_wait()) Skipped 4 previous similar messages
[1378736.197272] LustreError: 21546:0:(ldlm_request.c:147:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1551393424, 300s ago), entering recovery for fir-MDT0000_UUID@10.0.10.51@o2ib7 ns: fir-MD
[1378743.454431] LustreError: 21974:0:(ldlm_request.c:129:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1551393432, 300s ago); not entering recovery in server code, just going back to sleep ns:
[1378753.250665] LustreError: 22233:0:(ldlm_request.c:147:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1551393441, 300s ago), entering recovery for fir-MDT0000_UUID@10.0.10.51@o2ib7 ns: fir-MD
[1378753.290920] LustreError: 22233:0:(ldlm_request.c:147:ldlm_expired_completion_wait()) Skipped 2 previous similar messages
[1378771.845093] LNet: Service thread pid 22241 was inactive for 236.44s. Watchdog stack traces are limited to 3 per 300 seconds, skipping this one.
[1378771.858133] LNet: Skipped 1 previous similar message
[1378771.863282] LustreError: dumping log to /tmp/lustre-log.1551393760.22241
[1378774.917158] LustreError: dumping log to /tmp/lustre-log.1551393763.21826
[1378789.253489] LustreError: dumping log to /tmp/lustre-log.1551393777.51431
[1378796.422652] LustreError: dumping log to /tmp/lustre-log.1551393785.22159
[1378800.517748] LustreError: dumping log to /tmp/lustre-log.1551393789.47900
[1378801.468777] LustreError: 48757:0:(ldlm_request.c:147:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1551393490, 300s ago), entering recovery for fir-MDT0000_UUID@10.0.10.51@o2ib7 ns: fir-MD
[1378801.509027] LustreError: 48757:0:(ldlm_request.c:147:ldlm_expired_completion_wait()) Skipped 3 previous similar messages
[1378801.541773] LustreError: dumping log to /tmp/lustre-log.1551393790.21878
[1378833.603516] LustreError: 22159:0:(ldlm_request.c:147:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1551393522, 300s ago), entering recovery for fir-MDT0000_UUID@10.0.10.51@o2ib7 ns: fir-MD
[1378833.643766] LustreError: 22159:0:(ldlm_request.c:147:ldlm_expired_completion_wait()) Skipped 2 previous similar messages
[1378878.343542] LNet: Service thread pid 22157 was inactive for 313.10s. Watchdog stack traces are limited to 3 per 300 seconds, skipping this one.
[1378878.356579] LNet: Skipped 5 previous similar messages
[1378878.361831] LustreError: dumping log to /tmp/lustre-log.1551393867.22157
[1378938.760938] LNet: Service thread pid 21779 was inactive for 362.88s. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes:
[1378938.778069] LNet: Skipped 3 previous similar messages
[1378938.783305] Pid: 21779, comm: mdt01_015 3.10.0-957.1.3.el7_lustre.x86_64 #1 SMP Fri Dec 7 14:50:35 PST 2018
[1378938.793247] Call Trace:
[1378938.795883]  [<ffffffffc12340bd>] ldlm_completion_ast+0x63d/0x920 [ptlrpc]
[1378938.802998]  [<ffffffffc123612f>] ldlm_cli_enqueue_fini+0x96f/0xdf0 [ptlrpc]
[1378938.810278]  [<ffffffffc12389ee>] ldlm_cli_enqueue+0x40e/0x920 [ptlrpc]
[1378938.817141]  [<ffffffffc16507a2>] osp_md_object_lock+0x162/0x2d0 [osp]
[1378938.823899]  [<ffffffffc1a7be03>] lod_object_lock+0xf3/0x7b0 [lod]
[1378938.830299]  [<ffffffffc1afcd3e>] mdd_object_lock+0x3e/0xe0 [mdd]
[1378938.836613]  [<ffffffffc199b2e1>] mdt_remote_object_lock_try+0x1e1/0x750 [mdt]
[1378938.844053]  [<ffffffffc199b87a>] mdt_remote_object_lock+0x2a/0x30 [mdt]
[1378938.850995]  [<ffffffffc19bb022>] mdt_reint_rename_or_migrate.isra.51+0x362/0x860 [mdt]
[1378938.859211]  [<ffffffffc19bb553>] mdt_reint_rename+0x13/0x20 [mdt]
[1378938.865606]  [<ffffffffc19bb5e3>] mdt_reint_rec+0x83/0x210 [mdt]
[1378938.871828]  [<ffffffffc1998133>] mdt_reint_internal+0x6e3/0xaf0 [mdt]
[1378938.878586]  [<ffffffffc19a3497>] mdt_reint+0x67/0x140 [mdt]
[1378938.884456]  [<ffffffffc12d135a>] tgt_request_handle+0xaea/0x1580 [ptlrpc]
[1378938.891594]  [<ffffffffc127592b>] ptlrpc_server_handle_request+0x24b/0xab0 [ptlrpc]
[1378938.899485]  [<ffffffffc127925c>] ptlrpc_main+0xafc/0x1fc0 [ptlrpc]
[1378938.905998]  [<ffffffff8e8c1c31>] kthread+0xd1/0xe0
[1378938.911090]  [<ffffffff8ef74c24>] ret_from_fork_nospec_begin+0xe/0x21
[1378938.917767]  [<ffffffffffffffff>] 0xffffffffffffffff
[1378938.922966] LustreError: dumping log to /tmp/lustre-log.1551393927.21779

MDTs restarted occurred at ~15:47

I was able to gather some logs:

• a tar of the lustre-log files above (automatically generated) is available in the FTP (fir-md1-s1-lustre-log-20190228.tar.gz)
• I used the commands that Patrick provided in LU-11989, I did it two times, the results is available in fir-md1-s1-20190228-1.log.gz and fir-md1-s1-20190228-2.log.gz attached to this ticket
• fir-md1-s1 full kernel syslog dump in fir-md1-s1-kern-syslog-20190228.log

A bit more about our DNE configuration:
We use DNEv2 only to balance groups and users directories on different MDT (but only 1 each), but that's all. Basically:

$ lfs getdirstripe /fir
lmv_stripe_count: 0 lmv_stripe_offset: 0 lmv_hash_type: none
$ lfs getdirstripe /fir/users
lmv_stripe_count: 4 lmv_stripe_offset: 0 lmv_hash_type: fnv_1a_64
mdtidx           FID[seq:oid:ver]
     0           [0x200000400:0x5:0x0]  
     1           [0x240000402:0x5:0x0]  
     2           [0x2c0000400:0x5:0x0]  
     3           [0x280000401:0x5:0x0]  
$ lfs getdirstripe /fir/groups
lmv_stripe_count: 4 lmv_stripe_offset: 1 lmv_hash_type: fnv_1a_64
mdtidx           FID[seq:oid:ver]
     1           [0x240000400:0x8:0x0]  
     2           [0x2c0000401:0x6:0x0]  
     3           [0x280000403:0x2:0x0]  
     0           [0x200000401:0x6:0x0]  
$ lfs getdirstripe /fir/users/sthiell
lmv_stripe_count: 0 lmv_stripe_offset: 0 lmv_hash_type: none
$ lfs getdirstripe /fir/users/kilian
lmv_stripe_count: 0 lmv_stripe_offset: 1 lmv_hash_type: none

Thanks!

Issue Links

• is related to: LU-12834 MDT hung during failover
• is related to: LU-11989 Global filesystem hangs in 2.12
• is related to: LU-12125 Allow parallel rename of regular files
• is related to: LU-11964 Heavy load and soft lockups on MDS with DOM
• is related to: LU-11359 racer test 1 times out with client hung in dir_create.sh, ls, … and MDS in ldlm_completion_ast()
• is related to: LU-11285 don't stop on the first blocked lock in ldlm_reprocess_queue()