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

LNet: Service thread inactive for 300 causes client evictions

Details

    • Bug
    • Resolution: Unresolved
    • Major
    • None
    • Lustre 2.10.5, Lustre 2.12.1
    • None
    • 2
    • 9223372036854775807

    Description

      Update to 2.10.5 now we are seeing periods of mass evictions from servers. On the server we have the following stack trace

      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.033253] Pid: 11080, comm: ll_ost01_220 3.10.0-693.21.1.el7.20180508.x86_64.lustre2105 #1 SMP Mon Aug 27 23:04:41 UTC 2018
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.033260] Call Trace:
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.033274]  [<ffffffffa0c1d0e0>] ptlrpc_set_wait+0x4c0/0x920 [ptlrpc]
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.038258]  [<ffffffffa0bdae43>] ldlm_run_ast_work+0xd3/0x3a0 [ptlrpc]
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.038285]  [<ffffffffa0bfbabb>] ldlm_glimpse_locks+0x3b/0x100 [ptlrpc]
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.038294]  [<ffffffffa10e78a4>] ofd_intent_policy+0x444/0xa40 [ofd]
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.038318]  [<ffffffffa0bda2ba>] ldlm_lock_enqueue+0x38a/0x980 [ptlrpc]
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.038346]  [<ffffffffa0c03b53>] ldlm_handle_enqueue0+0x9d3/0x16a0 [ptlrpc]
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.038390]  [<ffffffffa0c89262>] tgt_enqueue+0x62/0x210 [ptlrpc]
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.038425]  [<ffffffffa0c8ceca>] tgt_request_handle+0x92a/0x1370 [ptlrpc]
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.038455]  [<ffffffffa0c354bb>] ptlrpc_server_handle_request+0x23b/0xaa0 [ptlrpc]
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.038484]  [<ffffffffa0c394a2>] ptlrpc_main+0xa92/0x1e40 [ptlrpc]
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.038489]  [<ffffffff810b1131>] kthread+0xd1/0xe0
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.038492]  [<ffffffff816a14f7>] ret_from_fork+0x77/0xb0
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.038512]  [<ffffffffffffffff>] 0xffffffffffffffff
      Nov  7 11:33:12 nbp8-oss7 kernel: [531465.038515] LustreError: dumping log to /tmp/lustre-log.1541619192.11080
      Nov  7 11:33:14 nbp8-oss7 kernel: [531467.254898] LNet: Service thread pid 9724 was inactive for 303.19s. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes:
      Nov  7 11:33:14 nbp8-oss7 kernel: [531467.310852] Pid: 9724, comm: ll_ost01_019 3.10.0-693.21.1.el7.20180508.x86_64.lustre2105 #1 SMP Mon Aug 27 23:04:41 UTC 2018
      Nov  7 11:33:14 nbp8-oss7 kernel: [531467.310854] Call Trace:
      Nov  7 11:33:14 nbp8-oss7 kernel: [531467.310866]  [<ffffffffa0c1d0e0>] ptlrpc_set_wait+0x4c0/0x920 [ptlrpc]
      Nov  7 11:33:14 nbp8-oss7 kernel: [531467.332869]  [<ffffffffa0bdae43>] ldlm_run_ast_work+0xd3/0x3a0 [ptlrpc]
      Nov  7 11:33:14 nbp8-oss7 kernel: [531467.332902]  [<ffffffffa0bfbabb>] ldlm_glimpse_locks+0x3b/0x100 [ptlrpc]
      Nov  7 11:33:14 nbp8-oss7 kernel: [531467.332912]  [<ffffffffa10e78a4>] ofd_intent_policy+0x444/0xa40 [ofd]
      Nov  7 11:33:14 nbp8-oss7 kernel: [531467.332936]  [<ffffffffa0bda2ba>] ldlm_lock_enqueue+0x38a/0x980 [ptlrpc]
      Nov  7 11:33:15 nbp8-oss7 kernel: [531467.332988]  [<ffffffffa0c03b53>] ldlm_handle_enqueue0+0x9d3/0x16a0 [ptlrpc]
      Nov  7 11:33:15 nbp8-oss7 kernel: [531467.333032]  [<ffffffffa0c89262>] tgt_enqueue+0x62/0x210 [ptlrpc]
      Nov  7 11:33:15 nbp8-oss7 kernel: [531467.333067]  [<ffffffffa0c8ceca>] tgt_request_handle+0x92a/0x1370 [ptlrpc]
      Nov  7 11:33:15 nbp8-oss7 kernel: [531467.333099]  [<ffffffffa0c354bb>] ptlrpc_server_handle_request+0x23b/0xaa0 [ptlrpc]
      Nov  7 11:33:15 nbp8-oss7 kernel: [531467.333128]  [<ffffffffa0c394a2>] ptlrpc_main+0xa92/0x1e40 [ptlrpc]
      Nov  7 11:33:15 nbp8-oss7 kernel: [531467.333134]  [<ffffffff810b1131>] kthread+0xd1/0xe0
      Nov  7 11:33:15 nbp8-oss7 kernel: [531467.333137]  [<ffffffff816a14f7>] ret_from_fork+0x77/0xb0
      Nov  7 11:33:15 nbp8-oss7 kernel: [531467.333158]  [<ffffffffffffffff>] 0xffffffffffffffff
      

      will upload to ftp:/uploads/LU11613/lustre-log.1541619192.11080

      we didn't have rpctrace or dlmtrace so may not be very useful.

      Could be related to https://jira.whamcloud.com/browse/LU-11613

       

       

      Attachments

        1. client_evictions_charts.pdf
          63 kB
        2. eviction_s611.06.05.19
          23 kB
        3. lnet_metrics_during_eviction.pdf
          398 kB
        4. nasa_lu11644.patch
          15 kB
        5. s214_bt.20200108.18.21.23
          990 kB
        6. s618.out
          37 kB
        7. zero.io.top.20210130.19.31.37
          480 kB

        Issue Links

          Activity

            [LU-11644] LNet: Service thread inactive for 300 causes client evictions

            Mahmoud, do you know what the client application is doing at this point in the run? Glimpse RPCs are generated when clients do "stat()" operations on files to get the size, that send the LDLM glimpse RPC for the OST object(s) in the file, which may in turn cause the OST to send RPCs to the client(s) holding the locks for the file if it is actively being written. So if there were a multiple clients doing parallel directory tree traversal in the same directory where other clients are writing it could generate a lot of glimpses, or if the application was malformed and calling stat() repeatedly on a shared file for some reason (e.g. to poll for updates/completion)?

            adilger Andreas Dilger added a comment - Mahmoud, do you know what the client application is doing at this point in the run? Glimpse RPCs are generated when clients do " stat() " operations on files to get the size, that send the LDLM glimpse RPC for the OST object(s) in the file, which may in turn cause the OST to send RPCs to the client(s) holding the locks for the file if it is actively being written. So if there were a multiple clients doing parallel directory tree traversal in the same directory where other clients are writing it could generate a lot of glimpses, or if the application was malformed and calling stat() repeatedly on a shared file for some reason (e.g. to poll for updates/completion)?

            I was able to get a backtrace of all threads during when the servers ping rpcs drop to zero. It show 508 outof 512 ll_ost threads in ldlm_run_ast_work. This must block receiving all other RPCS.

            What options do we have to slow down the rate of ldlm_glimpse_equeues?

            s214_bt.20200108.18.21.23

            mhanafi Mahmoud Hanafi added a comment - I was able to get a backtrace of all threads during when the servers ping rpcs drop to zero. It show 508 outof 512 ll_ost threads in ldlm_run_ast_work. This must block receiving all other RPCS. What options do we have to slow down the rate of ldlm_glimpse_equeues? s214_bt.20200108.18.21.23

            I am trying to create a reproducer for the case were a OSS get a large spike in ldlm_glimpse_equeue RPCS. What is the best way to recreate this RPC workload.

            mhanafi Mahmoud Hanafi added a comment - I am trying to create a reproducer for the case were a OSS get a large spike in ldlm_glimpse_equeue RPCS. What is the best way to recreate this RPC workload.

            I was able to capture some rpc rates before a client evictions. It showed that the server gets large spike in ldlm_glimpse_equeue rpcs that starves out the ping rpcs. I have two charts that show this. So some how when we enable +net debugging it slows down things and the pings rpcs doen't get blocked. client_evictions_charts.pdf
            What can cause just a large spike in ldlm_glimpse_equeue?

            mhanafi Mahmoud Hanafi added a comment - I was able to capture some rpc rates before a client evictions. It showed that the server gets large spike in ldlm_glimpse_equeue rpcs that starves out the ping rpcs. I have two charts that show this. So some how when we enable +net debugging it slows down things and the pings rpcs doen't get blocked. client_evictions_charts.pdf What can cause just a large spike in ldlm_glimpse_equeue?

            Because we had the crash with the larger peers.lndprs_num_peers we wanted to do more testing before installing on production filesystem. I haven't had time to get back to this yet... Since things are stable with +net debugging it's a bit lower on the priority.

            mhanafi Mahmoud Hanafi added a comment - Because we had the crash with the larger peers.lndprs_num_peers we wanted to do more testing before installing on production filesystem. I haven't had time to get back to this yet... Since things are stable with +net debugging it's a bit lower on the priority.
            pjones Peter Jones added a comment -

            Mahmoud

            Do you have the dedicated time scheduled to run this test yet?

            Peter

            pjones Peter Jones added a comment - Mahmoud Do you have the dedicated time scheduled to run this test yet? Peter

            Hi Mahmoud, I noted this limitation in my initial comment about the patch. I wanted to get the patch out and it would've taken longer to implement an iterative way of pulling up the peers in 4K chunks. But as long at the 16K works, it should be ok.

            ashehata Amir Shehata (Inactive) added a comment - Hi Mahmoud, I noted this limitation in my initial comment about the patch. I wanted to get the patch out and it would've taken longer to implement an iterative way of pulling up the peers in 4K chunks. But as long at the 16K works, it should be ok.
            mhanafi Mahmoud Hanafi added a comment - - edited

            Found an issue with the debug patch. It is only reporting the first 4097 peers.

            nbptest2-srv1 ~ # ls -l /proc/fs/lustre/mdt/nbptest2-MDT0000/exports/| wc -l
            14260
            nbptest2-srv1 ~ # lnetctl peer show --lnd --net o2ib |grep ' nid:' | wc -l
            4097

             We recompiled with larger value for peers.lndprs_num_peers = 16k.

            mhanafi Mahmoud Hanafi added a comment - - edited Found an issue with the debug patch. It is only reporting the first 4097 peers. nbptest2-srv1 ~ # ls -l /proc/fs/lustre/mdt/nbptest2-MDT0000/exports/| wc -l 14260 nbptest2-srv1 ~ # lnetctl peer show --lnd --net o2ib |grep ' nid:' | wc -l 4097  We recompiled with larger value for peers.lndprs_num_peers = 16k.

            I tested the patch with +8000 clients and no issues. It will take a few week to schedule dedicated time on our production filesystem. Will report back once I have more data.

             

            mhanafi Mahmoud Hanafi added a comment - I tested the patch with +8000 clients and no issues. It will take a few week to schedule dedicated time on our production filesystem. Will report back once I have more data.  

            Thanks, will test and report back results.

            mhanafi Mahmoud Hanafi added a comment - Thanks, will test and report back results.
            ashehata Amir Shehata (Inactive) added a comment - - edited

            took me a bit longer to get through.

            Here is a debug patch which can be used to monitor the internal iblnd queues and trigger an action when the queues get too large. I tested it locally, but I don't have a large cluster. So it'll be a good idea to test it on a larger cluster before deploying it on a live system.

            Patch is nasa_lu11644.patch.

            you can run:

            lnetctl peer show --lnd --net <net type: ex o2ib1> 

            This will dump output like

             [root@trevis-407 ~]# lnetctl peer show --lnd --net o2ib
            lnd_peer:
                - nid: 172.16.1.6@o2ib
                  ni_nid: 172.16.1.7@o2ib
                  num_conns: 1
                  tx_queue: 0
                  accepting: 0
                  connecting: 0
                  reconnecting: 0
                  conn_races: 0
                  reconnected: 0
                  refcount: 2
                  max_frags: 256
                  queue_depth: 8
                  conns:
                    - refcount: 0
                      credits: 20
                      outstanding_credits: 8
                      reserved_credits: 1
                      early_rxs: 8
                      tx_noops: 0
                      tx_active: 0
                      tx_queue_nocred: 0
                      tx_queue_rsrvd: 0
                      tx_queue: 0
                      conn_state: 0
                      sends_posted: 3
                      queue_depth: 0
                      max_frags: 0
                - nid: 172.16.1.7@o2ib
                  ni_nid: 172.16.1.7@o2ib
                  num_conns: 2
                  tx_queue: 0
                  accepting: 0
                  connecting: 0
                  reconnecting: 0
                  conn_races: 0
                  reconnected: 0
                  refcount: 3
                  max_frags: 256
                  queue_depth: 8
                  conns:
                    - refcount: 0
                      credits: 20
                      outstanding_credits: 7
                      reserved_credits: 0
                      early_rxs: 8
                      tx_noops: 0
                      tx_active: 0
                      tx_queue_nocred: 0
                      tx_queue_rsrvd: 0
                      tx_queue: 0
                      conn_state: 0
                      sends_posted: 3
                      queue_depth: 0
                      max_frags: 0
                    - refcount: 16777224
                      credits: 20
                      outstanding_credits: 8
                      reserved_credits: 1
                      early_rxs: 8
                      tx_noops: 0
                      tx_active: 0
                      tx_queue_nocred: 0
                      tx_queue_rsrvd: 0
                      tx_queue: 0
                      conn_state: 0
                      sends_posted: 3
                      queue_depth: 0
                      max_frags: 0
            

            Under the conns section you can monitor the different queue sizes: tx_active is the one of interest at the moment. This will require a bit of experimentation on a heavily loaded system, to see the average size of these queues. Then you can have a python script (or similar) to trigger an action whenever the queues grow beyond the expected average. The discussed action was to initiate some MLNX debugging to capture more data.

            Note the patch grabs the first 4096 peers only.

            An example python script is below. I used o2ib for the network and 300 for the expected average queue size. For the action, I simply print an output.

            import yaml
            import subprocess
            import time
            
            while True:
                output = subprocess.check_output(['lnetctl', 'peer', 'show', '--lnd', '--net', 'o2ib'])
                y = yaml.safe_load(output)
                for i in range (0, len(y['lnd_peer'])):
                    peer = y['lnd_peer'][i]
                    for j in range(0, len(peer['conns'])):
                       if peer['conns'][j]['tx_active'] > 300:
                          print("peer: ", peer['nid'], "active_tx is growing too large: ", peer['conns'][j]['tx_active'])
                time.sleep(10)
            
            
            ashehata Amir Shehata (Inactive) added a comment - - edited took me a bit longer to get through. Here is a debug patch which can be used to monitor the internal iblnd queues and trigger an action when the queues get too large. I tested it locally, but I don't have a large cluster. So it'll be a good idea to test it on a larger cluster before deploying it on a live system. Patch is nasa_lu11644.patch . you can run: lnetctl peer show --lnd --net <net type: ex o2ib1> This will dump output like [root@trevis-407 ~]# lnetctl peer show --lnd --net o2ib lnd_peer: - nid: 172.16.1.6@o2ib ni_nid: 172.16.1.7@o2ib num_conns: 1 tx_queue: 0 accepting: 0 connecting: 0 reconnecting: 0 conn_races: 0 reconnected: 0 refcount: 2 max_frags: 256 queue_depth: 8 conns: - refcount: 0 credits: 20 outstanding_credits: 8 reserved_credits: 1 early_rxs: 8 tx_noops: 0 tx_active: 0 tx_queue_nocred: 0 tx_queue_rsrvd: 0 tx_queue: 0 conn_state: 0 sends_posted: 3 queue_depth: 0 max_frags: 0 - nid: 172.16.1.7@o2ib ni_nid: 172.16.1.7@o2ib num_conns: 2 tx_queue: 0 accepting: 0 connecting: 0 reconnecting: 0 conn_races: 0 reconnected: 0 refcount: 3 max_frags: 256 queue_depth: 8 conns: - refcount: 0 credits: 20 outstanding_credits: 7 reserved_credits: 0 early_rxs: 8 tx_noops: 0 tx_active: 0 tx_queue_nocred: 0 tx_queue_rsrvd: 0 tx_queue: 0 conn_state: 0 sends_posted: 3 queue_depth: 0 max_frags: 0 - refcount: 16777224 credits: 20 outstanding_credits: 8 reserved_credits: 1 early_rxs: 8 tx_noops: 0 tx_active: 0 tx_queue_nocred: 0 tx_queue_rsrvd: 0 tx_queue: 0 conn_state: 0 sends_posted: 3 queue_depth: 0 max_frags: 0 Under the conns section you can monitor the different queue sizes: tx_active is the one of interest at the moment. This will require a bit of experimentation on a heavily loaded system, to see the average size of these queues. Then you can have a python script (or similar) to trigger an action whenever the queues grow beyond the expected average. The discussed action was to initiate some MLNX debugging to capture more data. Note the patch grabs the first 4096 peers only. An example python script is below. I used o2ib for the network and 300 for the expected average queue size. For the action, I simply print an output. import yaml import subprocess import time while True: output = subprocess.check_output([ 'lnetctl' , 'peer' , 'show' , '--lnd' , '--net' , 'o2ib' ]) y = yaml.safe_load(output) for i in range (0, len(y[ 'lnd_peer' ])): peer = y[ 'lnd_peer' ][i] for j in range(0, len(peer[ 'conns' ])): if peer[ 'conns' ][j][ 'tx_active' ] > 300: print( "peer: " , peer[ 'nid' ], "active_tx is growing too large: " , peer[ 'conns' ][j][ 'tx_active' ]) time.sleep(10)

            People

              ashehata Amir Shehata (Inactive)
              mhanafi Mahmoud Hanafi
              Votes:
              1 Vote for this issue
              Watchers:
              15 Start watching this issue

              Dates

                Created:
                Updated: