Received-SPF: pass (google.com: domain of linux-nfs-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
MIME-Version: 1.0
References: <57f67888-160f-891c-6217-69e174d7e42b@rothenpieler.org>
 <CAN-5tyE4OyNOZRXGnyONcdGsHaRAF39LSE5416Kj964m-+_C2A@mail.gmail.com>
 <81cb9aef-c10d-f11c-42c0-5144ee2608bc@rothenpieler.org> <0e49471c-e640-a331-c7b4-4e0a49a7a967@rothenpieler.org>
 <CAN-5tyG9Ly9tqKxguFNhg_PGXCxE2=Zn6LQPLY59twdVkD3Auw@mail.gmail.com> <51a8caa7-52c2-8155-10a7-1e8d21866924@rothenpieler.org>
In-Reply-To: <51a8caa7-52c2-8155-10a7-1e8d21866924@rothenpieler.org>
From:   Olga Kornievskaia <aglo@umich.edu>
Date:   Wed, 17 Feb 2021 22:52:34 -0500
Message-ID: <CAN-5tyFT4+kkqk6E0Jxe-vMYm7q5mHyTeq0Ht7AEYasA30ZaGw@mail.gmail.com>
Subject: Re: copy_file_range() infinitely hangs on NFSv4.2 over RDMA
To:     Timo Rothenpieler <timo@rothenpieler.org>
Cc:     linux-rdma <linux-rdma@vger.kernel.org>,
        Linux NFS Mailing List <linux-nfs@vger.kernel.org>
Content-Type: text/plain; charset="UTF-8"
Precedence: bulk

On Wed, Feb 17, 2021 at 8:12 PM Timo Rothenpieler <timo@rothenpieler.org> wrote:
>
> On 17.02.2021 23:37, Olga Kornievskaia wrote:
> > On Tue, Feb 16, 2021 at 5:27 PM Timo Rothenpieler <timo@rothenpieler.org> wrote:
> >>
> >> On 16.02.2021 21:37, Timo Rothenpieler wrote:
> >>> I can't get a network (I assume just TCP/20049 is fine, and not also
> >>> some RDMA trace?) right now, but I will once a user has finished their
> >>> work on the machine.
> >>
> >> There wasn't any TCP traffic to dump on the NFSoRDMA Port, probably
> >> because everything is handled via RDMA/IB.
> >
> > Yeah, I'm not sure if tcpdump can snoop on the IB traffic. I know that
> > upstream tcpdump can snoop on RDMA mellanox card (but I only know
> > about the Roce mode).
>
> I managed to get https://github.com/Mellanox/ibdump working. Attached is
> what it records when I run the xfs_io copy_range command that gets
> stuck(sniffer.pcap).
> Additionally, I rebooted the client machine, and captured the traffic
> when it does a then successful copy during the first few minutes of
> uptime(sniffer2.pcap).
>
> Both those commands were run on a the same 500M file.
>
> >> But I recorded a trace log of rpcrdma and sunrpc observing the situation.
> >>
> >> To me it looks like the COPY task (task:15886@7) completes successfully?
> >> The compressed trace.dat is attached.
> >
> > I'm having a hard time reproducing the problem. But I only tried
> > "xfs", "btrfs", "ext4" (first two send a CLONE since the file system
> > supports it), the last one exercises a copy. In all my tries your
>
> I can also reproduce this on a test NFS share from an ext4 filesystem.
> Have not tested xfs yet.
>
> > xfs_io commands succeed. The differences between our environments are
> > (1) ZFS vs (xfs, etc) and (2) IB vs RoCE. Question is: does any
> > copy_file_range work over RDMA/IB. One thing to try a synchronous
>
> It works, on any size of file, when the client machine is freshly booted
> (within its first 10~30 minutes of uptime).

Reboot of the client or the server machine?

> > copy: create a small file 10bytes and do a copy. Is this the case
> > where we have copy and the callback racing, so instead do a really
> > large copy: create a >=1GB file and do a copy. that will be an async
> > copy but will not have a racy condition. Can you try those 2 examples
> > for me?
>
> I have observed in the past, that the xfs_io copy is more likely to
> succeed the smaller the file is, though I did not make out a definite
> pattern.

That's because small files are done with a synchronous copy. Your
network captures (while not fully decodable by wireshark because the
trace lacks the connection establishment needed for the wireshark to
parse the RDMA replies) the fact that no callback is sent from the
server and thus the client is stuck waiting for it. So the focus
should be on the server piece as to why it's not sending it. There are
some error conditions on the server that if that happens, it will not
be able to send a callback. What springs to mind looking thru the code
is that somehow the server thinks there is no callback channel.  Can
you turn on nfsd tracepoints please? I wonder if we can see something
of interest there.

The logic for determining whether the copy is sent sync or async
depends on server's rsize, if a file smaller than 2 RPC payloads, it's
sent synchronously.

> I did some bisecting on the number of bytes, and came up with the following:
> A 2097153 byte sized file gets stuck, while a 2097152(=2^21) sized one
> still works.
>
> It's been stable at that cutoff point for a while now, so I think that's
> actually the point where it starts happening, and different behaviour I
> saw in the past was an issue in my testing.
>
> > Not sure how useful tracepoints here are. The results of the COPY
> > isn't interesting as this is an async copy. The server should have
> > sent a CB_COMPOUND with the copy's results. The process stack tells me
> > that COPY is waiting for the results (waiting for the callback). So
> > the question is there a problem of sending a callback over RDMA/IB? Or
> > did the client receive it and missed it somehow? We really do need
> > some better tracepoints in the copy (but we don't have them
> > currently).
> >
> > Would you be willing to install the upstream libpcap/tcpdump to see if
> > it can capture RDMA/IB traffic or perhaps Chunk knows that it doesn't
> > work for sure?
>
> Managed to get ibdump working, as stated above.