Uploaded image for project: 'Lustre'
  1. Lustre
  2. LU-12037

Possible DNE issue leading to hung filesystem

    XMLWordPrintable

Details

    • Bug
    • Resolution: Fixed
    • Critical
    • Lustre 2.13.0, Lustre 2.12.1
    • Lustre 2.12.0
    • None
    • CentOS 7.6 - Servers: 2.12.0 Clients: 2.12.0 + patch LU-11964
    • 2
    • 9223372036854775807

    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!

      Attachments

        1. dk.fir-md1-s1.gz
          13.62 MB
        2. dk-full.fir-md1-s1.gz
          17.88 MB
        3. fir-md1-s1_20190304-dk.log.gz
          7.55 MB
        4. fir-md1-s1_20190403-dk.log.gz
          3.00 MB
        5. fir-md1-s1_20190412.log
          4.70 MB
        6. fir-md1-s1_console_full_20190309.log.gz
          424 kB
        7. fir-md1-s1_dkdlmtrace_20190314.log.gz
          46 kB
        8. fir-md1-s1_dkdlmtrace_20190327.log.gz
          562 kB
        9. fir-md1-s1_dkdlmtrace_20190327.log.gz
          562 kB
        10. fir-md1-s1_kern_20190314.log.gz
          155 kB
        11. fir-md1-s1_sysrq-t_20190308.log.gz
          343 kB
        12. fir-md1-s1-20190228-1.log.gz
          6.10 MB
        13. fir-md1-s1-20190228-2.log.gz
          747 kB
        14. fir-md1-s1-console-20190403.gz
          375 kB
        15. fir-md1-s1-kern_20190327.log.gz
          172 kB
        16. fir-md1-s1-kern_20190327.log.gz
          172 kB
        17. fir-md1-s1-kern-syslog-20190228.log
          598 kB
        18. fir-md1-s2_20190304-dk.log.gz
          1.75 MB
        19. fir-md1-s2_20190403-dk.log.gz
          1.76 MB
        20. fir-md1-s2_console_full_20190309.log.gz
          516 kB
        21. fir-md1-s2_dkdlmtrace_20190314.log.gz
          2.51 MB
        22. fir-md1-s2_dkdlmtrace_20190327.log.gz
          9.69 MB
        23. fir-md1-s2_dkdlmtrace_20190327.log.gz
          9.69 MB
        24. fir-md1-s2_kern_20190314.log.gz
          179 kB
        25. fir-md1-s2_sysrq-t_20190308.log.gz
          358 kB
        26. fir-md1-s2-console-20190403.gz
          362 kB
        27. fir-md1-s2-dlmtrace_20190311.log.gz
          4.26 MB
        28. fir-md1-s2-kern_20190327.log.gz
          133 kB
        29. fir-md1-s2-kern_20190327.log.gz
          133 kB

        Issue Links

          Activity

            People

              laisiyao Lai Siyao
              sthiell Stephane Thiell
              Votes:
              0 Vote for this issue
              Watchers:
              12 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: