Daniel Kobras
2008-Jul-28 14:50 UTC
[Lustre-discuss] Early replies from pre-1.6.5 servers?
Hi! While debugging connection problems on a Lustre client running 1.6.5.1 on RHEL5, I discovered early replies in the client debug output. Adaptive timeouts are disabled on the client, and our server infrastructure in running stock 1.6.4.3 (RHEL5), still. As far as I understood, early replies should only occur post 1.6.5 when adaptive timeouts are active. Did I get this wrong, and early replies are prefectly valid even in our setup? Or is the 1.6.5.1 client misinterpreting message headers? I''m attaching a debug trace for a single XID on the client and the MDS/MGS. Thanks, Daniel. -------------- next part -------------- ==========> client (10.1.2.123 at o2ib, Lustre 1.6.5.1) <========= root at client123 # lctl debug_file /tmp/lustre-debug.client.log | grep 266023 00000100:00100000:2:1217244344.471204:0:9991:0:(client.c:1784:ptlrpc_queue_wait()) Sending RPC pname:cluuid:pid:xid:nid:opc ll_cfg_requeue:38cc9155-5e64-1d01-bbf2-8b621120e1b0:9991:x266023:10.1.2.3 at o2ib:101 00000100:00000200:2:1217244344.471250:0:9991:0:(niobuf.c:540:ptl_send_rpc()) Setup reply buffer: 368 bytes, xid 266023, portal 25 00000100:00000040:2:1217244344.471269:0:9991:0:(niobuf.c:561:ptl_send_rpc()) @@@ send flg=0 req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 0 to 100 dl 1217244444 ref 2 fl Rpc:/0/0 rc 0/0 00000100:00000200:2:1217244344.471299:0:9991:0:(niobuf.c:70:ptl_send_buf()) Sending 232 bytes to portal 26, xid 266023, offset 0 00000100:00000200:2:1217244344.471379:0:9991:0:(client.c:1871:ptlrpc_queue_wait()) @@@ -- sleeping for 100000 ticks req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 0 to 100 dl 1217244444 ref 2 fl Rpc:/0/0 rc 0/0 00000100:00000200:2:1217244344.471399:0:9991:0:(client.c:771:ptlrpc_check_reply()) @@@ rc = 0 for req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 0 to 100 dl 1217244444 ref 2 fl Rpc:/0/0 rc 0/0 00000100:00000200:2:1217244344.471416:0:9991:0:(client.c:771:ptlrpc_check_reply()) @@@ rc = 0 for req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 0 to 100 dl 1217244444 ref 2 fl Rpc:/0/0 rc 0/0 00000100:00000200:1:1217244344.471440:0:3049:0:(events.c:55:request_out_callback()) @@@ type 4, status 0 req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 0 to 100 dl 1217244444 ref 2 fl Rpc:/0/0 rc 0/0 00000100:00000040:1:1217244344.471458:0:3049:0:(client.c:1526:__ptlrpc_req_finished()) @@@ refcount now 1 req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 0 to 100 dl 1217244444 ref 2 fl Rpc:/0/0 rc 0/0 00000100:00000200:1:1217244344.471565:0:3049:0:(events.c:84:reply_in_callback()) @@@ type 1, status 0 req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 0 to 100 dl 1217244444 ref 1 fl Rpc:/0/0 rc 0/0 00000100:00001000:1:1217244344.471578:0:3049:0:(events.c:112:reply_in_callback()) @@@ Early reply received: mlen=240 offset=0 replen=368 replied=0 unlinked=0 req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 0 to 100 dl 1217244444 ref 1 fl Rpc:/0/0 rc 0/0 00000100:00000200:2:1217244344.471652:0:9991:0:(client.c:771:ptlrpc_check_reply()) @@@ rc = 0 for req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 1 to 100 dl 1217244444 ref 1 fl Rpc:/0/0 rc 0/0 00000100:00000200:2:1217244344.471668:0:9991:0:(client.c:771:ptlrpc_check_reply()) @@@ rc = 0 for req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 1 to 100 dl 1217244444 ref 1 fl Rpc:/0/0 rc 0/0 00000100:00000100:2:1217244444.471354:0:9991:0:(client.c:1198:ptlrpc_expire_one_request()) @@@ timeout (sent at 1217244344, 100s ago) req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 1 to 100 dl 1217244444 ref 1 fl Rpc:/0/0 rc 0/0 00000100:02000400:2:1217244444.471376:0:9991:0:(client.c:1206:ptlrpc_expire_one_request()) Request x266023 sent from MGC10.1.2.3 at o2ib to NID 10.1.2.3 at o2ib 100s ago has timed out (limit 100s). 00000100:00000200:2:1217244444.471845:0:9991:0:(events.c:84:reply_in_callback()) @@@ type 5, status 0 req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 1 to 100 dl 1217244444 ref 1 fl Rpc:X/0/0 rc 0/0 00000100:00100000:2:1217244444.471859:0:9991:0:(events.c:102:reply_in_callback()) @@@ unlink req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 1 to 100 dl 1217244444 ref 1 fl Rpc:X/0/0 rc 0/0 00000100:00100000:2:1217244444.471970:0:9991:0:(client.c:2091:ptlrpc_abort_inflight()) @@@ inflight req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 1 to 100 dl 1217244444 ref 1 fl Rpc:X/0/0 rc 0/0 00000100:00000200:2:1217244444.472014:0:9991:0:(client.c:771:ptlrpc_check_reply()) @@@ rc = 1 for req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 1 to 100 dl 1217244444 ref 1 fl Rpc:EX/0/0 rc -4/0 00000100:00100000:2:1217244444.472029:0:9991:0:(client.c:1891:ptlrpc_queue_wait()) Completed RPC pname:cluuid:pid:xid:nid:opc ll_cfg_requeue:38cc9155-5e64-1d01-bbf2-8b621120e1b0:9991:x266023:10.1.2.3 at o2ib:101 00000100:00100000:2:1217244444.472038:0:9991:0:(client.c:1905:ptlrpc_queue_wait()) @@@ err rc=0 status=-4 req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 1 to 100 dl 1217244444 ref 1 fl Rpc:EX/0/0 rc -4/0 00000100:00000040:2:1217244444.472229:0:9991:0:(client.c:1526:__ptlrpc_req_finished()) @@@ refcount now 0 req at ffff810194886a00 x266023/t0 o101->MGS at MGC10.1.2.3@o2ib_0:26/25 lens 232/368 e 1 to 100 dl 1217244444 ref 1 fl Interpret:EX/0/0 rc -4/0 root at client123 # ps xa | grep -E ''3049|9991'' | grep -v grep 3049 ? S 0:00 [kiblnd_sd_01] 9991 ? S 0:00 [ll_cfg_requeue] ==========> MDS (10.1.2.3 at o2ib, Lustre 1.6.4.3) <========= root at mds # lctl debug_file /tmp/lustre-debug.mds.log | grep 266023 20000000:01000000:2:1217244344.469271:0:5378:0:(mgs_handler.c:549:mgs_handle()) @@@ enqueue req at ffff810107882050 x266023/t0 o101->38cc9155-5e64-1d01-bbf2-8b621120e1b0 at NET_0x500000a01027b_UUID:-1 lens 232/0 ref 0 fl Interpret:/0/0 rc 0/0 root at mds # ps xa | grep 5378 | grep -v grep 5378 ? S 2:23 [ll_mgs_01]
Daniel, Daniel Kobras wrote:> Hi! > > While debugging connection problems on a Lustre client running 1.6.5.1 > on RHEL5, I discovered early replies in the client debug output. > Adaptive timeouts are disabled on the client, and our server > infrastructure in running stock 1.6.4.3 (RHEL5), still. As far as I > understood, early replies should only occur post 1.6.5 when adaptive > timeouts are active. Did I get this wrong, and early replies are > prefectly valid even in our setup? Or is the 1.6.5.1 client > misinterpreting message headers?You''re right, in your setup we shouldn''t expect any early reply at all. The 1.6.4 server perhaps immediately send a reply in which a reserved field was not initialize to 0, which was interpreted by 1.6.5 client as an early reply, then be discarded because of size doesn''t match. I guess it''s not easy to reproduce, right? You can file a bug on our bugzilla, with as much information as possible. Thanks a lot. -- Eric
Brian Behlendorf
2008-Jul-30 22:36 UTC
[Lustre-discuss] Early replies from pre-1.6.5 servers?
Daniel,> Daniel Kobras wrote: > > Hi! > > > > While debugging connection problems on a Lustre client running 1.6.5.1 > > on RHEL5, I discovered early replies in the client debug output. > > Adaptive timeouts are disabled on the client, and our server > > infrastructure in running stock 1.6.4.3 (RHEL5), still. As far as I > > understood, early replies should only occur post 1.6.5 when adaptive > > timeouts are active. Did I get this wrong, and early replies are > > prefectly valid even in our setup? Or is the 1.6.5.1 client > > misinterpreting message headers? > > You''re right, in your setup we shouldn''t expect any early reply at all. > The 1.6.4 server perhaps immediately send a reply in which a reserved > field was not initialize to 0, which was interpreted by 1.6.5 client as > an early reply, then be discarded because of size doesn''t match. > > I guess it''s not easy to reproduce, right? You can file a bug on our > bugzilla, with as much information as possible. Thanks a lot.I ran in to the same problem while testing 1.6.5. I saw bug 16237 was already open on the issue so I attached a proposed fix. Details can be found in the bug. https://bugzilla.lustre.org/show_bug.cgi?id=16237 -- Thanks, Brian -------------- next part -------------- A non-text attachment was scrubbed... Name: not available Type: application/pgp-signature Size: 189 bytes Desc: not available Url : http://lists.lustre.org/pipermail/lustre-discuss/attachments/20080730/b9cb43b2/attachment.bin