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

OSS Servers stuck in connecting/disconnect loop

Details

    • Bug
    • Resolution: Duplicate
    • Minor
    • None
    • None
    • None
    • 1
    • 9223372036854775807

    Description

      We have had several OSS started to get into a state of disconnect and reconnect with clients. Sometimes they clear-up and then re-enter the same state later. Even with reboot the will enter into the same state.

      Attaching Lustre Debug dump. Please advice on what additional info is need for debugging.

      Attachments

        Issue Links

          is related to

          Bug - A problem which impairs or prevents the functions of the product. LU-7054 ib_cm scalling issue when lustre clients connect to OSS

          • Critical - Crashes, loss of data, severe memory leak.
          • Resolved

          Bug - A problem which impairs or prevents the functions of the product. LU-7569 IB leaf switch caused LNet routers to crash

          • Major - Major loss of function.
          • Resolved

          Activity

            [LU-7676] OSS Servers stuck in connecting/disconnect loop
            jaylan Jay Lan (Inactive) added a comment -

            It looks like http://review.whamcloud.com/#/c/18025/ is a backport of patch LU-7569 http://review.whamcloud.com/#/c/17892/ that I have been asking for. Thanks.

            jaylan Jay Lan (Inactive) added a comment - It looks like http://review.whamcloud.com/#/c/18025/ is a backport of patch LU-7569 http://review.whamcloud.com/#/c/17892/ that I have been asking for. Thanks.
            jaylan Jay Lan (Inactive) added a comment -

            Patch 18026 missed a newline at line 1909.

            jaylan Jay Lan (Inactive) added a comment - Patch 18026 missed a newline at line 1909.
            doug Doug Oucharek (Inactive) added a comment -

            NASA: Please apply both patches being discussed here: http://review.whamcloud.com/#/c/18025/ and http://review.whamcloud.com/18026.

            doug Doug Oucharek (Inactive) added a comment - NASA: Please apply both patches being discussed here: http://review.whamcloud.com/#/c/18025/ and http://review.whamcloud.com/18026 .
            doug Doug Oucharek (Inactive) added a comment -

            Liang: is your patch in addition to the one Amir ported or is it a replacement for it?

            doug Doug Oucharek (Inactive) added a comment - Liang: is your patch in addition to the one Amir ported or is it a replacement for it?
            liang Liang Zhen (Inactive) added a comment - - edited

            I checked my original patch, seems I forgot to call set_current_state() before schedule_timeout(), which can't really help because current thread wouldn't sleep. I have updated the patch uploaded by Amir (http://review.whamcloud.com/#/c/16470/), I also ported it to 2_5_fe (http://review.whamcloud.com/18026)

            liang Liang Zhen (Inactive) added a comment - - edited I checked my original patch, seems I forgot to call set_current_state() before schedule_timeout(), which can't really help because current thread wouldn't sleep. I have updated the patch uploaded by Amir ( http://review.whamcloud.com/#/c/16470/ ), I also ported it to 2_5_fe ( http://review.whamcloud.com/18026 )
            ashehata Amir Shehata (Inactive) added a comment -

            Ported the patch here:
            http://review.whamcloud.com/#/c/18025/

            ashehata Amir Shehata (Inactive) added a comment - Ported the patch here: http://review.whamcloud.com/#/c/18025/
            ashehata Amir Shehata (Inactive) added a comment -

            I looked through the log file attached and I see 442 instances of connection races, which occurs when two nodes are attempting to reconnect. This could result in a flurry of reconnects, which could consume memory. There is a prototype patch that has been done to address the same issue on another site. I'm in the process of porting it to NASA's branch and I'll push it in later today for you to try.

            ashehata Amir Shehata (Inactive) added a comment - I looked through the log file attached and I see 442 instances of connection races, which occurs when two nodes are attempting to reconnect. This could result in a flurry of reconnects, which could consume memory. There is a prototype patch that has been done to address the same issue on another site. I'm in the process of porting it to NASA's branch and I'll push it in later today for you to try.
            Bob.C Bob Ciotti (Inactive) added a comment -

            We still have two production filesystems down. This is a critical problem.

            We are going to try to run jobs on the remaining filesystems, but there were issues doing this earlier. So risky.

            We are going to investigate network issues. We have found no HW problems.

            Assuming that its not a network problem, do you have any suggestions as to where we should look? Debug settings? Other information we can provide to you? Mahmoud said that the traces uploaded show from boot to encountering the issue.

            Bob.C Bob Ciotti (Inactive) added a comment - We still have two production filesystems down. This is a critical problem. We are going to try to run jobs on the remaining filesystems, but there were issues doing this earlier. So risky. We are going to investigate network issues. We have found no HW problems. Assuming that its not a network problem, do you have any suggestions as to where we should look? Debug settings? Other information we can provide to you? Mahmoud said that the traces uploaded show from boot to encountering the issue.
            Bob.C Bob Ciotti (Inactive) added a comment - - edited

            We also see many messages like this:
            out.nbp2-oss18.1452913951.gz.denum:
            00000800:00000200:15.0:1452913946.993806:0:21340:0:(o2iblnd.c:1898:kiblnd_pool_alloc_node()) Another thread is allocating new TX pool, waiting 1024 HZs for her to complete.trips = 83498830

            This was part of a patch generated in https://jira.hpdd.intel.com/browse/LU-7054
            http://review.whamcloud.com/#/c/16470/2/lnet/klnds/o2iblnd/o2iblnd.c
            but we still see that there are a large number of "complete.trips" through. I has assumed that the "waiting HZs" of 1024 would slow this down, or does it simply schedule other threads if one waiting and not sleep (unclear to me), but in the traces I've looked at, I dont see any new pools being successfully created (and the indication of how long pool creation took to complete).

            You must forgive me, grasping a little from memory... I seem to recall that there were some competition between the freeing (unregister) and pool allocation, is it possible that a something slow in the deallocation prevents new pools from being created?

            Also, since I'm not familiar with this code (and I'm looking at this on my apple watch)
            the "schedule_timeout(interval)", mapped to an inline null function. So I couldn't decipher yet.

            Bob.C Bob Ciotti (Inactive) added a comment - - edited We also see many messages like this: out.nbp2-oss18.1452913951.gz.denum: 00000800:00000200:15.0:1452913946.993806:0:21340:0:(o2iblnd.c:1898:kiblnd_pool_alloc_node()) Another thread is allocating new TX pool, waiting 1024 HZs for her to complete.trips = 83498830 This was part of a patch generated in https://jira.hpdd.intel.com/browse/LU-7054 http://review.whamcloud.com/#/c/16470/2/lnet/klnds/o2iblnd/o2iblnd.c but we still see that there are a large number of "complete.trips" through. I has assumed that the "waiting HZs" of 1024 would slow this down, or does it simply schedule other threads if one waiting and not sleep (unclear to me), but in the traces I've looked at, I dont see any new pools being successfully created (and the indication of how long pool creation took to complete). You must forgive me, grasping a little from memory... I seem to recall that there were some competition between the freeing (unregister) and pool allocation, is it possible that a something slow in the deallocation prevents new pools from being created? Also, since I'm not familiar with this code (and I'm looking at this on my apple watch) the "schedule_timeout(interval)", mapped to an inline null function. So I couldn't decipher yet.
            green Oleg Drokin added a comment -

            That unexpectedly long timeout is more of the same.
            Network/network driver/network card is slow in trying to unregister buffers we are trying to unregister. Slow as in it takes over 300 seconds to unregister such buffers )this is what triggers the message).

            I think this is another sign of unhealthy network/card/driver. It's not normal for connection to a peer to fail with ETIMEOUT (-110)/UNREACHABLE as seen in the last snippet in my previous comment.

            green Oleg Drokin added a comment - That unexpectedly long timeout is more of the same. Network/network driver/network card is slow in trying to unregister buffers we are trying to unregister. Slow as in it takes over 300 seconds to unregister such buffers )this is what triggers the message). I think this is another sign of unhealthy network/card/driver. It's not normal for connection to a peer to fail with ETIMEOUT (-110)/UNREACHABLE as seen in the last snippet in my previous comment.
            mhanafi Mahmoud Hanafi added a comment - - edited

            We haven't been able to identify any network issues. As far as we can tell the network is find.

            what do you make of these messages. The downward slide of the servers is pre-seeded by these

            Jan 15 19:10:09 nbp2-oss20 kernel: Lustre: 22081:0niobuf.c:285tlrpc_abort_bulk()) Unexpectedly long timeout: desc ffff880494ed2000
            Jan 15 19:10:09 nbp2-oss20 kernel: Lustre: 22081:0niobuf.c:285tlrpc_abort_bulk()) Skipped 5 previous similar messages
            Jan 15 19:10:22 nbp2-oss18 kernel: Lustre: 21874:0niobuf.c:285tlrpc_abort_bulk()) Unexpectedly long timeout: desc ffff881b124e4000
            Jan 15 19:10:22 nbp2-oss18 kernel: Lustre: 21874:0niobuf.c:285tlrpc_abort_bulk()) Skipped 9 previous similar messages

            mhanafi Mahmoud Hanafi added a comment - - edited We haven't been able to identify any network issues. As far as we can tell the network is find. what do you make of these messages. The downward slide of the servers is pre-seeded by these Jan 15 19:10:09 nbp2-oss20 kernel: Lustre: 22081:0niobuf.c:285tlrpc_abort_bulk()) Unexpectedly long timeout: desc ffff880494ed2000 Jan 15 19:10:09 nbp2-oss20 kernel: Lustre: 22081:0niobuf.c:285tlrpc_abort_bulk()) Skipped 5 previous similar messages Jan 15 19:10:22 nbp2-oss18 kernel: Lustre: 21874:0niobuf.c:285tlrpc_abort_bulk()) Unexpectedly long timeout: desc ffff881b124e4000 Jan 15 19:10:22 nbp2-oss18 kernel: Lustre: 21874:0niobuf.c:285tlrpc_abort_bulk()) Skipped 9 previous similar messages

            People

              green Oleg Drokin
              mhanafi Mahmoud Hanafi
              Votes:
              0 Vote for this issue
              Watchers:
              11 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: