<div dir="auto">Have you been able to replicate the issue with a simple test?<div dir="auto"><br></div><div dir="auto"><br></div><div dir="auto">find /mnt/lustre -exec lfs path2fid {} \; </div><div dir="auto"><br></div><div dir="auto">?</div></div><div class="gmail_extra"><br><div class="gmail_quote">On May 17, 2017 12:04 PM, "Jessica Otey" <<a href="mailto:jotey@nrao.edu">jotey@nrao.edu</a>> wrote:<br type="attribution"><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
  

    
  
  <div bgcolor="#FFFFFF" text="#000000">
    <p>All,</p>
    <p>We have observed an unfortunate interaction between Robinhood and
      two Lustre 2.5.5 file systems (both of which originated as 1.8.9
      file systems).</p>
    <p> Robinhood was used successfully against these file systems when
      they were both 1.8.9, 2.4.3, and then 2.5.3 (a total time span of
      about 11 months). <br>
    </p>
    <p>We also have a third Lustre file system that originated as 2.4.3,
      and has since been upgraded to 2.5.5, against which Robinhood is
      currently operating as expected. This leads me to suppose that the
      issue may have to do the interaction between Robinhood and a
      legacy-1.8.x-now-lustre-2.5.5 system. But I don't know. <br>
    </p>
    <p>The problem manifests itself as follows: Either a Robinhood file
      scan or the initiation of the consumption of changelogs results in
      the consumption all the available RPC resources on the MDT. This
      in turn leads to the MDT not being able to satisfy any other
      requests from clients, which in turn leads to client
      disconnections (the MDT thinks they are dead and evicts them).
      Meanwhile, Robinhood itself is unable to traverse the file system
      to gather the information it seeks, and so its scans either hang
      (due to the client disconnect) or run at a rate such that they
      would never complete (less than 1 file per second).<br>
    </p>
    <p>If we don't run robinhood at all, the file system performs (after
      a remount of the MDT) as expected. <br>
    </p>
    <p>Initially, we thought that the difficulty might be that we
      neglected to activate the FID-in-direct feature when we upgraded
      to 2.4.3. We did so on one of these systems, and ran an lfsck
      oi_scrub, but that did not ameliorate the problem.</p>
    <p>Any thoughts on this matter would be appreciated. (We miss using
      Robinhood!)<br>
    </p>
    <p>Thanks,</p>
    <p>Jessica<br>
    </p>
    <p>******************************<wbr>******************************<br>
    </p>
    <p>More data for those who cannot help themselves:<br>
    </p>
    April 2016 - Robinhood comes into production use against both our
    1.8.9 file systems.<br>
    <p>July 2016 - Upgrade to 2.4.3 (on both production lustre file
      systems) -- Robinhood rebuilt against 2.4.3 client; changelog
      consumption now included.</p>
    <p>        Lustre "reconnects" (from /var/log/messages on one of the
      MDTs): <br>
    </p>
    <p>        July 2016: 4<br>
    </p>
    <p>        Aug 2016: 20<br>
    </p>
    <p>        Sept 2016: 8<br>
    </p>
    <p>        Oct 2016: 8<br>
    </p>
    <p>Nov 4-6, 2016 - Upgrade to 2.5.3 (on both production lustre file
      systems) -- Robinhood rebuilt against 2.5.3 client.</p>
    <p>        Lustre "reconnects":   <br>
    </p>
    <p>Nov. 2016: 180</p>
    <p>Dec. 2016: 62 <br>
    </p>
    <p>Jan. 2017: 96 <br>
    </p>
    <p>Feb 1-24, 2017: 2</p>
    <p> Feb 24, 2017 - Upgrade to 2.5.5 (on both production lustre file
      systems)    <br>
    </p>
    <p><tt>**** NAASC-Lustre MDT coming back ****</tt><br>
    </p>
    <tt>Feb 24 20:46:44 10.7.7.8 kernel: Lustre: Lustre: Build Version:
      2.5.5-g22a210f-CHANGED-2.6.32-<wbr>642.6.2.el6_lustre.2.5.5.x86_<wbr>64</tt><tt><br>
    </tt><tt>Feb 24 20:46:44 10.7.7.8 kernel: Lustre: Lustre: Build
      Version:
      2.5.5-g22a210f-CHANGED-2.6.32-<wbr>642.6.2.el6_lustre.2.5.5.x86_<wbr>64</tt><tt><br>
    </tt><tt>Feb 24 20:46:44 10.7.7.8 kernel: LNet: Added LNI
      10.7.17.8@o2ib [8/256/0/180]</tt><tt><br>
    </tt><tt>Feb 24 20:46:44 10.7.7.8 kernel: LNet: Added LNI
      10.7.17.8@o2ib [8/256/0/180]</tt><tt><br>
    </tt><tt>Feb 24 20:46:45 10.7.7.8 kernel: LDISKFS-fs (md127):
      mounted filesystem with ordered data mode. quota=off. Opts: </tt><tt><br>
    </tt><tt>Feb 24 20:46:45 10.7.7.8 kernel: LDISKFS-fs (md127):
      mounted filesystem with ordered data mode. quota=off. Opts: </tt><tt><br>
    </tt><tt>Feb 24 20:46:46 10.7.7.8 kernel: Lustre: MGC10.7.17.8@o2ib:
      Connection restored to MGS (at 0@lo)</tt><tt><br>
    </tt><tt>Feb 24 20:46:46 10.7.7.8 kernel: Lustre: MGC10.7.17.8@o2ib:
      Connection restored to MGS (at 0@lo)</tt><tt><br>
    </tt><tt>Feb 24 20:46:47 10.7.7.8 kernel: Lustre: naaschpc-MDT0000:
      used disk, loading</tt><tt><br>
    </tt><tt>Feb 24 20:46:47 10.7.7.8 kernel: Lustre: naaschpc-MDT0000:
      used disk, loading</tt><br>
    <br>
    The night after this upgrade, a regular rsync to the backup Lustre
    system provokes a failure/client disconnect. (Unfortunately, I don't
    have the logs to look at Robinhood activity from this time, but I
    believe I restarted the service after the system came back.)<br>
    <tt><br>
    </tt><tt>Feb 25 02:14:24 10.7.7.8 kernel: LustreError:
      25103:0:(service.c:2020:<wbr>ptlrpc_server_handle_request()<wbr>) @@@
      Dropping timed-out request from 12345-10.7.17.123@o2ib: deadline
      6:11s ago</tt><tt><br>
    </tt><tt>Feb 25 02:14:24 10.7.7.8 kernel: LustreError:
      25103:0:(service.c:2020:<wbr>ptlrpc_server_handle_request()<wbr>) @@@
      Dropping timed-out request from 12345-10.7.17.123@o2ib: deadline
      6:11s ago</tt><tt><br>
    </tt><tt>Feb 25 02:14:24 10.7.7.8 kernel:  req@ffff88045b3a2050
      x1560271381909936/t0(0) o103-><a class="m_5614911303794612623moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0" target="_blank">bb228923-4216-cc59-d847-<wbr>38b543af1ae2@10.7.17.123@o2ib:<wbr>0/0</a>
      lens 3584/0 e 0 to 0 dl 1488006853 ref 1 fl Interpret:/0/ffffffff
      rc 0/-1</tt><tt><br>
    </tt><tt>Feb 25 02:14:24 10.7.7.8 kernel:  req@ffff88045b3a2050
      x1560271381909936/t0(0) o103-><a class="m_5614911303794612623moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0" target="_blank">bb228923-4216-cc59-d847-<wbr>38b543af1ae2@10.7.17.123@o2ib:<wbr>0/0</a>
      lens 3584/0 e 0 to 0 dl 1488006853 ref 1 fl Interpret:/0/ffffffff
      rc 0/-1</tt><tt><br>
    </tt><tt>Feb 25 02:14:24 10.7.7.8 kernel: Lustre:
      25111:0:(service.c:2052:<wbr>ptlrpc_server_handle_request()<wbr>) @@@
      Request took longer than estimated (6:11s); client may timeout. 
      req@ffff88045b3a2850 x1560271381909940/t0(0) o103-><a class="m_5614911303794612623moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0" target="_blank">bb228923-4216-cc59-d847-<wbr>38b543af1ae2@10.7.17.123@o2ib:<wbr>0/0</a>
      lens 3584/0 e 0 to 0 dl 1488006853 ref 1 fl Interpret:/0/ffffffff
      rc 0/-1</tt><tt><br>
    </tt><tt>Feb 25 02:14:24 10.7.7.8 kernel: Lustre:
      25111:0:(service.c:2052:<wbr>ptlrpc_server_handle_request()<wbr>) @@@
      Request took longer than estimated (6:11s); client may timeout. 
      req@ffff88045b3a2850 x1560271381909940/t0(0) o103-><a class="m_5614911303794612623moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0" target="_blank">bb228923-4216-cc59-d847-<wbr>38b543af1ae2@10.7.17.123@o2ib:<wbr>0/0</a>
      lens 3584/0 e 0 to 0 dl 1488006853 ref 1 fl Interpret:/0/ffffffff
      rc 0/-1</tt><tt><br>
    </tt><tt>Feb 25 02:14:24 10.7.7.8 kernel: LustreError:
      25103:0:(service.c:2020:<wbr>ptlrpc_server_handle_request()<wbr>) Skipped 30
      previous similar messages</tt><tt><br>
    </tt><tt>Feb 25 02:14:24 10.7.7.8 kernel: LustreError:
      25103:0:(service.c:2020:<wbr>ptlrpc_server_handle_request()<wbr>) Skipped 30
      previous similar messages</tt><tt><br>
    </tt><tt>Feb 25 02:14:25 10.7.7.8 kernel: LustreError:
      7526:0:(service.c:2020:ptlrpc_<wbr>server_handle_request()) @@@
      Dropping timed-out request from 12345-10.7.17.123@o2ib: deadline
      6:11s ago</tt><tt><br>
    </tt><tt>Feb 25 02:14:25 10.7.7.8 kernel: LustreError:
      7526:0:(service.c:2020:ptlrpc_<wbr>server_handle_request()) @@@
      Dropping timed-out request from 12345-10.7.17.123@o2ib: deadline
      6:11s ago</tt><tt><br>
    </tt><tt>Feb 25 02:14:25 10.7.7.8 kernel:  req@ffff880149b75850
      x1560271381926356/t0(0) o103-><a class="m_5614911303794612623moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0" target="_blank">bb228923-4216-cc59-d847-<wbr>38b543af1ae2@10.7.17.123@o2ib:<wbr>0/0</a>
      lens 3584/0 e 0 to 0 dl 1488006854 ref 1 fl Interpret:/0/ffffffff
      rc 0/-1</tt><tt><br>
    </tt><tt>Feb 25 02:14:25 10.7.7.8 kernel:  req@ffff880149b75850
      x1560271381926356/t0(0) o103-><a class="m_5614911303794612623moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0" target="_blank">bb228923-4216-cc59-d847-<wbr>38b543af1ae2@10.7.17.123@o2ib:<wbr>0/0</a>
      lens 3584/0 e 0 to 0 dl 1488006854 ref 1 fl Interpret:/0/ffffffff
      rc 0/-1</tt><tt><br>
    </tt><tt>Feb 25 02:14:25 10.7.7.8 kernel: Lustre:
      7528:0:(service.c:2052:ptlrpc_<wbr>server_handle_request()) @@@ Request
      took longer than estimated (6:11s); client may timeout. 
      req@ffff880149bb0050 x1560271381926372/t0(0) o103-><a class="m_5614911303794612623moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0" target="_blank">bb228923-4216-cc59-d847-<wbr>38b543af1ae2@10.7.17.123@o2ib:<wbr>0/0</a>
      lens 3584/0 e 0 to 0 dl 1488006854 ref 1 fl Interpret:/0/ffffffff
      rc 0/-1</tt><tt><br>
    </tt><tt>Feb 25 02:14:25 10.7.7.8 kernel: Lustre:
      7528:0:(service.c:2052:ptlrpc_<wbr>server_handle_request()) @@@ Request
      took longer than estimated (6:11s); client may timeout. 
      req@ffff880149bb0050 x1560271381926372/t0(0) o103-><a class="m_5614911303794612623moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0" target="_blank">bb228923-4216-cc59-d847-<wbr>38b543af1ae2@10.7.17.123@o2ib:<wbr>0/0</a>
      lens 3584/0 e 0 to 0 dl 1488006854 ref 1 fl Interpret:/0/ffffffff
      rc 0/-1</tt><tt><br>
    </tt><tt>Feb 25 02:14:25 10.7.7.8 kernel: Lustre:
      7528:0:(service.c:2052:ptlrpc_<wbr>server_handle_request()) Skipped
      1533 previous similar messages</tt><tt><br>
    </tt><tt>Feb 25 02:14:25 10.7.7.8 kernel: Lustre:
      7528:0:(service.c:2052:ptlrpc_<wbr>server_handle_request()) Skipped
      1533 previous similar messages</tt><tt><br>
    </tt><tt>Feb 25 02:14:25 10.7.7.8 kernel: LustreError:
      7526:0:(service.c:2020:ptlrpc_<wbr>server_handle_request()) Skipped
      1653 previous similar messages</tt><tt><br>
    </tt><tt>Feb 25 02:14:25 10.7.7.8 kernel: LustreError:
      7526:0:(service.c:2020:ptlrpc_<wbr>server_handle_request()) Skipped
      1653 previous similar messages</tt><tt><br>
    </tt><tt>Feb 25 02:14:49 10.7.7.8 kernel: Lustre: naaschpc-MDT0000:
      Client bb228923-4216-cc59-d847-<wbr>38b543af1ae2 (at 10.7.17.123@o2ib)
      reconnecting</tt><tt><br>
    </tt><tt>Feb 25 02:14:49 10.7.7.8 kernel: Lustre: naaschpc-MDT0000:
      Client bb228923-4216-cc59-d847-<wbr>38b543af1ae2 (at 10.7.17.123@o2ib)
      reconnecting</tt><tt><br>
    </tt><tt>Feb 25 02:14:49 10.7.7.8 kernel: Lustre: naaschpc-MDT0000:
      Client bb228923-4216-cc59-d847-<wbr>38b543af1ae2 (at 10.7.17.123@o2ib)
      refused reconnection, still busy with 1 active RPCs</tt><tt><br>
    </tt><tt>Feb 25 02:14:49 10.7.7.8 kernel: Lustre: naaschpc-MDT0000:
      Client bb228923-4216-cc59-d847-<wbr>38b543af1ae2 (at 10.7.17.123@o2ib)
      refused reconnection, still busy with 1 active RPCs</tt><tt><br>
    </tt><tt>Feb 25 02:14:49 10.7.7.8 kernel: Lustre: Skipped 1 previous
      similar message</tt><tt><br>
    </tt><tt>Feb 25 02:14:49 10.7.7.8 kernel: Lustre: Skipped 1 previous
      similar message</tt><tt><br>
    </tt><tt>Feb 25 02:14:49 10.7.7.8 kernel: LustreError:
      9437:0:(ldlm_lib.c:2693:<wbr>target_bulk_io()) @@@ bulk PUT failed: rc
      -107  req@ffff88050290d050 x1560271382966952/t0(0) o37-><a class="m_5614911303794612623moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0" target="_blank">bb228923-4216-cc59-d847-<wbr>38b543af1ae2@10.7.17.123@o2ib:<wbr>0/0</a>
      lens 448/440 e 0 to 0 dl 1488006895 ref 1 fl Interpret:/0/0 rc 0/0</tt><tt><br>
    </tt><tt>Feb 25 02:14:49 10.7.7.8 kernel: LustreError:
      9437:0:(ldlm_lib.c:2693:<wbr>target_bulk_io()) @@@ bulk PUT failed: rc
      -107  req@ffff88050290d050 x1560271382966952/t0(0) o37-><a class="m_5614911303794612623moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0" target="_blank">bb228923-4216-cc59-d847-<wbr>38b543af1ae2@10.7.17.123@o2ib:<wbr>0/0</a>
      lens 448/440 e 0 to 0 dl 1488006895 ref 1 fl Interpret:/0/0 rc 0/0</tt><tt><br>
    </tt><tt>Feb 25 02:15:14 10.7.7.8 kernel: Lustre: naaschpc-MDT0000:
      Client bb228923-4216-cc59-d847-<wbr>38b543af1ae2 (at 10.7.17.123@o2ib)
      reconnecting</tt><tt><br>
    </tt><tt>Feb 25 02:15:14 10.7.7.8 kernel: Lustre: naaschpc-MDT0000:
      Client bb228923-4216-cc59-d847-<wbr>38b543af1ae2 (at 10.7.17.123@o2ib)
      reconnecting</tt><br>
            <br>
    This problem then escalates... the Lustre "reconnects" from the logs
    for March will be 2818; for April <br>
    4574! <b><br>
      <br>
      Grepping for "active RPCs", excluding dates of known downtimes
      (Nov  5,  2016 | Feb 24, 2017 | Apr 21, 2017)". Dates not included
      are zero.<br>
      <br>
    </b><b>2016</b><br>
    Nov 22nd: 72<br>
    Dec 14th: 32<br>
    <br>
    <b>2017</b><br>
    Jan 8th: 20<br>
    Jan 28th: 18<br>
    ---<br>
    Feb 25: 2<br>
    ---<br>
    Mar 13: 56<br>
    Mar 14: 236  First user ticket filed about fs non-responsiveness<br>
    Mar 15: 60<br>
    Mar 16: 90<br>
    Mar 17: 160<br>
    Mar 18: 280<br>
    Mar 19: 178<br>
    Mar 20: 280<br>
    Mar 21: 276<br>
    Mar 22: 140<br>
    Mar 23: 102<br>
    Mar 24: 216<br>
    Mar 25: 278<br>
    Mar 26: 142<br>
    Mar 27: 82<br>
    Mar 28: 52<br>
    Mar 29: 78<br>
    Mar 30: 52<br>
    Mar 31: 52<br>
    --<br>
    Apr 1: 112<br>
    Apr 2: 216<br>
    Apr 3: 276<br>
    Apr 4: 278<br>
    Apr 5: 278<br>
    Apr 6: 278<br>
    Apr 7: 158<br>
    Apr 8: 216<br>
    Apr 9: 278<br>
    Apr 10: 118<br>
    Apr 11: 216<br>
    Apr 12: 156<br>
    Apr 13: 78<br>
    Apr 14: 42<br>
    Apr 15: 74<br>
    Apr 16: 216<br>
    Apr 17: 88<br>
    Apr 18: 62<br>
    Apr 19: 198<br>
    Apr 20: 280<br>
    April 21, 2017 - on naasc lustre only: MDT and OSTs unmounted; MDT
    remounted in ordered mode; lfsck oi_scrub run<br>
    Apr 22: 0<br>
    Apr 23: 0<br>
    Apr 24: 0<br>
    Apr 25: 0<br>
    Apr 26: 0<br>
    Apr 27: 0<br>
    <br>
    On Friday, April 28, I start a file system scan from our 'new'
    robinhood box, akebono, on both production file systems<br>
    <br>
    <tt>2017/04/28 14:38:35 [130550/1] CheckFS | '/.lustre/naasc'
      matches mount point '/.lustre/naasc', type=lustre,
      fs=10.7.17.8@o2ib0:/naaschpc</tt><br>
    <br>
    This scan does not successfully complete. And the RPC resource
    problem reappears: <br>
    Apr 28: 114      The first one is at 3pm... <br>
    <br>
    <tt>Apr 28 15:01:30 10.7.7.8 kernel: Lustre: naaschpc-MDT0000:
      Client cab57f86-2124-884d-49a2-<wbr>ec2871f36f78 (at 10.7.17.122@o2ib)
      refused reconnection, still busy with 1 active RPCs</tt><tt><br>
    </tt><br>
    Apr 29: 282<br>
    Apr 30: 284<br>
    ---<br>
    May 1: 186<br>
    May 2: 248<br>
    May 3: 204 (day of emergency MDT restart)<br>
    <br>
    Since May 4: 0    Robinhood has not been restarted against naasc
    lustre... and rsyncs have been running without issues.<br>
    <br>
    *********<br>
    Robinhood scan/changelog consumption also produced an identical
    situation on our other lustre fs<br>
    <br>
    2017/04/28 14:53:11 [130926/1] CheckFS | '/.lustre/cv' matches mount
    point '/.lustre/cv', type=lustre, fs=10.7.3.9@tcp2:/cvlustre<br>
    <br>
    ***** FROM CV-lustre's MDT *****<br>
    <br>
    Apr 28 14:53:24 10.7.7.9 kernel: Lustre: cvlustre-MDT0000: Client
    deb3834b-6b53-5e68-123b-<wbr>dfaedd352ac6 (at 10.7.17.122@o2ib) refused
    reconnection, still busy with 1 active RPCs<br>
    Apr 28 14:53:24 10.7.7.9 kernel: Lustre: cvlustre-MDT0000: Client
    deb3834b-6b53-5e68-123b-<wbr>dfaedd352ac6 (at 10.7.17.122@o2ib) refused
    reconnection, still busy with 1 active RPCs<br>
    Apr 28 14:53:24 10.7.7.9 kernel: Lustre: Skipped 19 previous similar
    messages<br>
    Apr 28 14:53:24 10.7.7.9 kernel: Lustre: Skipped 19 previous similar
    messages
  </div>

<br>______________________________<wbr>_________________<br>
lustre-discuss mailing list<br>
<a href="mailto:lustre-discuss@lists.lustre.org">lustre-discuss@lists.lustre.<wbr>org</a><br>
<a href="http://lists.lustre.org/listinfo.cgi/lustre-discuss-lustre.org" rel="noreferrer" target="_blank">http://lists.lustre.org/<wbr>listinfo.cgi/lustre-discuss-<wbr>lustre.org</a><br>
<br></blockquote></div></div>