<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=us-ascii">
</head>
<body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space;" class="">
How is it you are getting the same NID registering twice in the log file:
<div class=""><br class="">
</div>
<div class=""><tt style="background-color: rgb(255, 255, 255);" class="">Feb 24 20:46:44 10.7.7.8 kernel: LNet: Added LNI 10.7.17.8@o2ib [8/256/0/180]</tt><tt style="background-color: rgb(255, 255, 255);" class=""><br class="">
</tt><tt style="background-color: rgb(255, 255, 255);" class="">Feb 24 20:46:44 10.7.7.8 kernel: LNet: Added LNI 10.7.17.8@o2ib [8/256/0/180]</tt><tt style="background-color: rgb(255, 255, 255);" class=""><br class="">
</tt>
<div><br class="">
</div>
<div>Doug</div>
<div><br class="">
<blockquote type="cite" class="">
<div class="">On May 17, 2017, at 11:04 AM, Jessica Otey <<a href="mailto:jotey@nrao.edu" class="">jotey@nrao.edu</a>> wrote:</div>
<br class="Apple-interchange-newline">
<div class="">
<div bgcolor="#FFFFFF" text="#000000" class="">
<p class="">All,</p>
<p class="">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 class="">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 class="">
</p>
<p class="">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 class="">
</p>
<p class="">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 class="">
</p>
<p class="">If we don't run robinhood at all, the file system performs (after a remount of the MDT) as expected.
<br class="">
</p>
<p class="">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 class="">Any thoughts on this matter would be appreciated. (We miss using Robinhood!)<br class="">
</p>
<p class="">Thanks,</p>
<p class="">Jessica<br class="">
</p>
<p class="">************************************************************<br class="">
</p>
<p class="">More data for those who cannot help themselves:<br class="">
</p>
April 2016 - Robinhood comes into production use against both our 1.8.9 file systems.<br class="">
<p class="">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 class=""> Lustre "reconnects" (from /var/log/messages on one of the MDTs):
<br class="">
</p>
<p class=""> July 2016: 4<br class="">
</p>
<p class=""> Aug 2016: 20<br class="">
</p>
<p class=""> Sept 2016: 8<br class="">
</p>
<p class=""> Oct 2016: 8<br class="">
</p>
<p class="">Nov 4-6, 2016 - Upgrade to 2.5.3 (on both production lustre file systems) -- Robinhood rebuilt against 2.5.3 client.</p>
<p class=""> Lustre "reconnects": <br class="">
</p>
<p class="">Nov. 2016: 180</p>
<p class="">Dec. 2016: 62 <br class="">
</p>
<p class="">Jan. 2017: 96 <br class="">
</p>
<p class="">Feb 1-24, 2017: 2</p>
<p class="">Feb 24, 2017 - Upgrade to 2.5.5 (on both production lustre file systems)
<br class="">
</p>
<p class=""><tt class="">**** NAASC-Lustre MDT coming back ****</tt><br class="">
</p>
<tt class="">Feb 24 20:46:44 10.7.7.8 kernel: Lustre: Lustre: Build Version: 2.5.5-g22a210f-CHANGED-2.6.32-642.6.2.el6_lustre.2.5.5.x86_64</tt><tt class=""><br class="">
</tt><tt class="">Feb 24 20:46:44 10.7.7.8 kernel: Lustre: Lustre: Build Version: 2.5.5-g22a210f-CHANGED-2.6.32-642.6.2.el6_lustre.2.5.5.x86_64</tt><tt class=""><br class="">
</tt><tt class="">Feb 24 20:46:44 10.7.7.8 kernel: LNet: Added LNI 10.7.17.8@o2ib [8/256/0/180]</tt><tt class=""><br class="">
</tt><tt class="">Feb 24 20:46:44 10.7.7.8 kernel: LNet: Added LNI 10.7.17.8@o2ib [8/256/0/180]</tt><tt class=""><br class="">
</tt><tt class="">Feb 24 20:46:45 10.7.7.8 kernel: LDISKFS-fs (md127): mounted filesystem with ordered data mode. quota=off. Opts:
</tt><tt class=""><br class="">
</tt><tt class="">Feb 24 20:46:45 10.7.7.8 kernel: LDISKFS-fs (md127): mounted filesystem with ordered data mode. quota=off. Opts:
</tt><tt class=""><br class="">
</tt><tt class="">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 class=""><br class="">
</tt><tt class="">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 class=""><br class="">
</tt><tt class="">Feb 24 20:46:47 10.7.7.8 kernel: Lustre: naaschpc-MDT0000: used disk, loading</tt><tt class=""><br class="">
</tt><tt class="">Feb 24 20:46:47 10.7.7.8 kernel: Lustre: naaschpc-MDT0000: used disk, loading</tt><br class="">
<br class="">
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 class="">
<tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:24 10.7.7.8 kernel: LustreError: 25103:0:(service.c:2020:ptlrpc_server_handle_request()) @@@ Dropping timed-out request from 12345-10.7.17.123@o2ib: deadline 6:11s ago</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:24 10.7.7.8 kernel: LustreError: 25103:0:(service.c:2020:ptlrpc_server_handle_request()) @@@ Dropping timed-out request from 12345-10.7.17.123@o2ib: deadline 6:11s ago</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:24 10.7.7.8 kernel: req@ffff88045b3a2050 x1560271381909936/t0(0) o103-><a moz-do-not-send="true" class="moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0">bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0</a>
lens 3584/0 e 0 to 0 dl 1488006853 ref 1 fl Interpret:/0/ffffffff rc 0/-1</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:24 10.7.7.8 kernel: req@ffff88045b3a2050 x1560271381909936/t0(0) o103-><a moz-do-not-send="true" class="moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0">bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0</a>
lens 3584/0 e 0 to 0 dl 1488006853 ref 1 fl Interpret:/0/ffffffff rc 0/-1</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:24 10.7.7.8 kernel: Lustre: 25111:0:(service.c:2052:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (6:11s); client may timeout. req@ffff88045b3a2850 x1560271381909940/t0(0) o103-><a moz-do-not-send="true" class="moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0">bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0</a>
lens 3584/0 e 0 to 0 dl 1488006853 ref 1 fl Interpret:/0/ffffffff rc 0/-1</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:24 10.7.7.8 kernel: Lustre: 25111:0:(service.c:2052:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (6:11s); client may timeout. req@ffff88045b3a2850 x1560271381909940/t0(0) o103-><a moz-do-not-send="true" class="moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0">bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0</a>
lens 3584/0 e 0 to 0 dl 1488006853 ref 1 fl Interpret:/0/ffffffff rc 0/-1</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:24 10.7.7.8 kernel: LustreError: 25103:0:(service.c:2020:ptlrpc_server_handle_request()) Skipped 30 previous similar messages</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:24 10.7.7.8 kernel: LustreError: 25103:0:(service.c:2020:ptlrpc_server_handle_request()) Skipped 30 previous similar messages</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:25 10.7.7.8 kernel: LustreError: 7526:0:(service.c:2020:ptlrpc_server_handle_request()) @@@ Dropping timed-out request from 12345-10.7.17.123@o2ib: deadline 6:11s ago</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:25 10.7.7.8 kernel: LustreError: 7526:0:(service.c:2020:ptlrpc_server_handle_request()) @@@ Dropping timed-out request from 12345-10.7.17.123@o2ib: deadline 6:11s ago</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:25 10.7.7.8 kernel: req@ffff880149b75850 x1560271381926356/t0(0) o103-><a moz-do-not-send="true" class="moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0">bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0</a>
lens 3584/0 e 0 to 0 dl 1488006854 ref 1 fl Interpret:/0/ffffffff rc 0/-1</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:25 10.7.7.8 kernel: req@ffff880149b75850 x1560271381926356/t0(0) o103-><a moz-do-not-send="true" class="moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0">bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0</a>
lens 3584/0 e 0 to 0 dl 1488006854 ref 1 fl Interpret:/0/ffffffff rc 0/-1</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:25 10.7.7.8 kernel: Lustre: 7528:0:(service.c:2052:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (6:11s); client may timeout. req@ffff880149bb0050 x1560271381926372/t0(0) o103-><a moz-do-not-send="true" class="moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0">bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0</a>
lens 3584/0 e 0 to 0 dl 1488006854 ref 1 fl Interpret:/0/ffffffff rc 0/-1</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:25 10.7.7.8 kernel: Lustre: 7528:0:(service.c:2052:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (6:11s); client may timeout. req@ffff880149bb0050 x1560271381926372/t0(0) o103-><a moz-do-not-send="true" class="moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0">bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0</a>
lens 3584/0 e 0 to 0 dl 1488006854 ref 1 fl Interpret:/0/ffffffff rc 0/-1</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:25 10.7.7.8 kernel: Lustre: 7528:0:(service.c:2052:ptlrpc_server_handle_request()) Skipped 1533 previous similar messages</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:25 10.7.7.8 kernel: Lustre: 7528:0:(service.c:2052:ptlrpc_server_handle_request()) Skipped 1533 previous similar messages</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:25 10.7.7.8 kernel: LustreError: 7526:0:(service.c:2020:ptlrpc_server_handle_request()) Skipped 1653 previous similar messages</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:25 10.7.7.8 kernel: LustreError: 7526:0:(service.c:2020:ptlrpc_server_handle_request()) Skipped 1653 previous similar messages</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:49 10.7.7.8 kernel: Lustre: naaschpc-MDT0000: Client bb228923-4216-cc59-d847-38b543af1ae2 (at 10.7.17.123@o2ib) reconnecting</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:49 10.7.7.8 kernel: Lustre: naaschpc-MDT0000: Client bb228923-4216-cc59-d847-38b543af1ae2 (at 10.7.17.123@o2ib) reconnecting</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:49 10.7.7.8 kernel: Lustre: naaschpc-MDT0000: Client bb228923-4216-cc59-d847-38b543af1ae2 (at 10.7.17.123@o2ib) refused reconnection, still busy with 1 active RPCs</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:49 10.7.7.8 kernel: Lustre: naaschpc-MDT0000: Client bb228923-4216-cc59-d847-38b543af1ae2 (at 10.7.17.123@o2ib) refused reconnection, still busy with 1 active RPCs</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:49 10.7.7.8 kernel: Lustre: Skipped 1 previous similar message</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:49 10.7.7.8 kernel: Lustre: Skipped 1 previous similar message</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:49 10.7.7.8 kernel: LustreError: 9437:0:(ldlm_lib.c:2693:target_bulk_io()) @@@ bulk PUT failed: rc -107 req@ffff88050290d050 x1560271382966952/t0(0) o37-><a moz-do-not-send="true" class="moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0">bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0</a>
lens 448/440 e 0 to 0 dl 1488006895 ref 1 fl Interpret:/0/0 rc 0/0</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:14:49 10.7.7.8 kernel: LustreError: 9437:0:(ldlm_lib.c:2693:target_bulk_io()) @@@ bulk PUT failed: rc -107 req@ffff88050290d050 x1560271382966952/t0(0) o37-><a moz-do-not-send="true" class="moz-txt-link-abbreviated" href="mailto:bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0">bb228923-4216-cc59-d847-38b543af1ae2@10.7.17.123@o2ib:0/0</a>
lens 448/440 e 0 to 0 dl 1488006895 ref 1 fl Interpret:/0/0 rc 0/0</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:15:14 10.7.7.8 kernel: Lustre: naaschpc-MDT0000: Client bb228923-4216-cc59-d847-38b543af1ae2 (at 10.7.17.123@o2ib) reconnecting</tt><tt class=""><br class="">
</tt><tt class="">Feb 25 02:15:14 10.7.7.8 kernel: Lustre: naaschpc-MDT0000: Client bb228923-4216-cc59-d847-38b543af1ae2 (at 10.7.17.123@o2ib) reconnecting</tt><br class="">
<br class="">
This problem then escalates... the Lustre "reconnects" from the logs for March will be 2818; for April
<br class="">
4574! <b class=""><br class="">
<br class="">
Grepping for "active RPCs", excluding dates of known downtimes (Nov 5, 2016 | Feb 24, 2017 | Apr 21, 2017)". Dates not included are zero.<br class="">
<br class="">
</b><b class="">2016</b><br class="">
Nov 22nd: 72<br class="">
Dec 14th: 32<br class="">
<br class="">
<b class="">2017</b><br class="">
Jan 8th: 20<br class="">
Jan 28th: 18<br class="">
---<br class="">
Feb 25: 2<br class="">
---<br class="">
Mar 13: 56<br class="">
Mar 14: 236 First user ticket filed about fs non-responsiveness<br class="">
Mar 15: 60<br class="">
Mar 16: 90<br class="">
Mar 17: 160<br class="">
Mar 18: 280<br class="">
Mar 19: 178<br class="">
Mar 20: 280<br class="">
Mar 21: 276<br class="">
Mar 22: 140<br class="">
Mar 23: 102<br class="">
Mar 24: 216<br class="">
Mar 25: 278<br class="">
Mar 26: 142<br class="">
Mar 27: 82<br class="">
Mar 28: 52<br class="">
Mar 29: 78<br class="">
Mar 30: 52<br class="">
Mar 31: 52<br class="">
--<br class="">
Apr 1: 112<br class="">
Apr 2: 216<br class="">
Apr 3: 276<br class="">
Apr 4: 278<br class="">
Apr 5: 278<br class="">
Apr 6: 278<br class="">
Apr 7: 158<br class="">
Apr 8: 216<br class="">
Apr 9: 278<br class="">
Apr 10: 118<br class="">
Apr 11: 216<br class="">
Apr 12: 156<br class="">
Apr 13: 78<br class="">
Apr 14: 42<br class="">
Apr 15: 74<br class="">
Apr 16: 216<br class="">
Apr 17: 88<br class="">
Apr 18: 62<br class="">
Apr 19: 198<br class="">
Apr 20: 280<br class="">
April 21, 2017 - on naasc lustre only: MDT and OSTs unmounted; MDT remounted in ordered mode; lfsck oi_scrub run<br class="">
Apr 22: 0<br class="">
Apr 23: 0<br class="">
Apr 24: 0<br class="">
Apr 25: 0<br class="">
Apr 26: 0<br class="">
Apr 27: 0<br class="">
<br class="">
On Friday, April 28, I start a file system scan from our 'new' robinhood box, akebono, on both production file systems<br class="">
<br class="">
<tt class="">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 class="">
<br class="">
This scan does not successfully complete. And the RPC resource problem reappears:
<br class="">
Apr 28: 114 The first one is at 3pm... <br class="">
<br class="">
<tt class="">Apr 28 15:01:30 10.7.7.8 kernel: Lustre: naaschpc-MDT0000: Client cab57f86-2124-884d-49a2-ec2871f36f78 (at 10.7.17.122@o2ib) refused reconnection, still busy with 1 active RPCs</tt><tt class=""><br class="">
</tt><br class="">
Apr 29: 282<br class="">
Apr 30: 284<br class="">
---<br class="">
May 1: 186<br class="">
May 2: 248<br class="">
May 3: 204 (day of emergency MDT restart)<br class="">
<br class="">
Since May 4: 0 Robinhood has not been restarted against naasc lustre... and rsyncs have been running without issues.<br class="">
<br class="">
*********<br class="">
Robinhood scan/changelog consumption also produced an identical situation on our other lustre fs<br class="">
<br class="">
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 class="">
<br class="">
***** FROM CV-lustre's MDT *****<br class="">
<br class="">
Apr 28 14:53:24 10.7.7.9 kernel: Lustre: cvlustre-MDT0000: Client deb3834b-6b53-5e68-123b-dfaedd352ac6 (at 10.7.17.122@o2ib) refused reconnection, still busy with 1 active RPCs<br class="">
Apr 28 14:53:24 10.7.7.9 kernel: Lustre: cvlustre-MDT0000: Client deb3834b-6b53-5e68-123b-dfaedd352ac6 (at 10.7.17.122@o2ib) refused reconnection, still busy with 1 active RPCs<br class="">
Apr 28 14:53:24 10.7.7.9 kernel: Lustre: Skipped 19 previous similar messages<br class="">
Apr 28 14:53:24 10.7.7.9 kernel: Lustre: Skipped 19 previous similar messages </div>
_______________________________________________<br class="">
lustre-discuss mailing list<br class="">
<a href="mailto:lustre-discuss@lists.lustre.org" class="">lustre-discuss@lists.lustre.org</a><br class="">
http://lists.lustre.org/listinfo.cgi/lustre-discuss-lustre.org<br class="">
</div>
</blockquote>
</div>
<br class="">
</div>
</body>
</html>