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;
From:   Chuck Lever III <chuck.lever@oracle.com>
To:     Mike Javorski <mike.javorski@gmail.com>
CC:     Linux NFS Mailing List <linux-nfs@vger.kernel.org>,
        Neil Brown <neilb@suse.de>
Subject: Re: NFS server regression in kernel 5.13 (tested w/ 5.13.9)
Thread-Topic: NFS server regression in kernel 5.13 (tested w/ 5.13.9)
Thread-Index: AQHXjKYRxKTFwD0+C02+ZMVduTdsB6tqSi4AgAAHiwCAAZhPAIAACtMAgAS9YICAAA1rAIAAA7UAgAMLuwCAAZFegIAAyYQA
Date:   Mon, 16 Aug 2021 13:21:34 +0000
Message-ID: <87777C39-BDDA-4E1E-83FA-5B46918A66D3@oracle.com>
References: <CAOv1SKCmdtchm5Z2NU80o49tkrHpAkPFaHKj4-vLDN5bZNCz-Q@mail.gmail.com>
 <162846730406.22632.14734595494457390936@noble.neil.brown.name>
 <CAOv1SKBZ7sGBnvG9-M+De+s=CfU=H_GBs4hJah1E4ks+NSMyPw@mail.gmail.com>
 <CAOv1SKCUM5cGuXWAc7dsXtbmPMATqd245juC+S9gVXHWiZsvmQ@mail.gmail.com>
 <162855893202.12431.3423894387218130632@noble.neil.brown.name>
 <CAOv1SKAaSbfw53LWCCrvGCHESgdtCf5h275Zkzi9_uHkqnCrdg@mail.gmail.com>
 <162882238416.1695.4958036322575947783@noble.neil.brown.name>
 <CAOv1SKB_dsam7P9pzzh_SKCtA8uE9cyFdJ=qquEfhLT42-szPA@mail.gmail.com>
 <CAOv1SKDDOj5UeUwztrMSNJnLgSoEgD8OU55hqtLHffHvaCQzzA@mail.gmail.com>
 <162907681945.1695.10796003189432247877@noble.neil.brown.name>
In-Reply-To: <162907681945.1695.10796003189432247877@noble.neil.brown.name>
Accept-Language: en-US
Content-Language: en-US
x-ms-exchange-antispam-messagedata-chunkcount: 1
x-ms-exchange-antispam-messagedata-0: =?us-ascii?Q?UgtCTFFWoO/08jtEcTsF6Ecj9d2gzhnBq+l3vF4Jc5fAQTYLfShDPaI6+JaO?=
 =?us-ascii?Q?GqVXv/bo+nqauHN+LKzkoAXSdf2AGD6pu3/RxUJ2KRoSZ8zoMerbJ1cuVkyA?=
 =?us-ascii?Q?ZiqAB2RWk50XEVUAmUmJyD1IY83q3zIJ9QH+dqSUYdOjQIt0iEP/nViaga7m?=
 =?us-ascii?Q?oD5zZUoGE+zo7H/Ge3R7HY4WtZcnIkNgktlUns10K/eM+60juzcdWHqHbaW5?=
 =?us-ascii?Q?JrV/++uPYqcc3gHyznoFlTAP+C4z2OWVwN8PWiayLf8fUj3MpjmiaXS7IoC1?=
 =?us-ascii?Q?ruE9lB4Rg24r5FC+NIps406z1Jp2vFB4MXc6e9Ju5OqN57jo7CgwIfEMFeNT?=
 =?us-ascii?Q?mfTUwREAQr55ZSaRpl/af3kHEcqQPAfUDFcCg9x/ZRwrbAn0skoOQ6s28OD/?=
 =?us-ascii?Q?HxVr5r5UwHyScD1cQS4KevxDXDyGYgSXY49U7iA7E4yrlGFHRNu64GBhvk9Y?=
 =?us-ascii?Q?vJqW6baPCYjOHF2k+4vldMrv6DINALUnYk3nTDfUC5zi4oAs1ZXz0aS8Q9aH?=
 =?us-ascii?Q?QmKZyW5NDNWOfQupqjxaAylED+XXx5GxYIOABjzHVdvLsbEdAxrD0uAfDm+6?=
 =?us-ascii?Q?h9g5naGk1BYtdpRlORFOAsvoyyVrl3R5Sw31jDf2q0L65kOWNoVb2uiQhFQG?=
 =?us-ascii?Q?gRA/Tda+uAmifbUUs95ky3Jk7zN3Ch/Y3BaurM7Xk3DW2JFgqONhnsIwZc1j?=
 =?us-ascii?Q?Q2aDwTbchdO0LXCnMVDVoCxM3/J5N2/8dpgSXiFip4c8w5+HZLapN/Vvvjhs?=
 =?us-ascii?Q?E556IOK5Ta3KiN5cwAoNIa9G6QyxqIN5eHp7EbJOfemWAynv5nw6clHCCT/m?=
 =?us-ascii?Q?qSovCVEjg7nP52OR0teglrVJnJnB1FzEzHt5HboahmATfSzTtUMH2Qpo1gyj?=
 =?us-ascii?Q?0Xj2VwAe8xr+mFSWW72bCij6JWlTWw6XO0iADJXn6YnsOsZoA0QWySWRsYGw?=
 =?us-ascii?Q?8yrAsBf65AqfwgLI3a8hJNF11gcPScFo66mxcUo4rOLY3E3rXg9HO619CXn3?=
 =?us-ascii?Q?WzvYinozfnXowPicfUweaO+7TxW8/WnHtnecTlbhhg32M0f8pfhEz76tP4eh?=
 =?us-ascii?Q?dkXZ688U2/j1FkVJ8dMwkAWVhfaG2zN1l1JWtNHjLi/lIUW5OGITCoUaLzwX?=
 =?us-ascii?Q?8wIiU4SKKBy1kjcy9k2OYsBmKJ9ZaCik597GSye2PQaiwtwxrYDPBjLpCnDE?=
 =?us-ascii?Q?KxsD4rFCiAkkT39t6Y/eFb5rBeTU+SsHh1sNJvd2IiIuv5cuN1kXA7PfhV+l?=
 =?us-ascii?Q?RFr0JompbQUUAvdpaHMr1zfXlu9wky75kfNiwlgKNCjHTpul8rtXc2mGBESG?=
 =?us-ascii?Q?ro7gjCukcBQFHPBP6ffaG9VwSbGZHOZo2NPuIwY1/6jXoyDQJxOWtucrrE2j?=
 =?us-ascii?Q?IlGZVAx+ndjjrKVoG4Hgmqj6FQqJ?=
x-ms-exchange-transport-forked: True
Content-Type: text/plain; charset="us-ascii"
Content-ID: <07361B05A1275146AC1AD276DC874068@namprd10.prod.outlook.com>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-OriginatorOrg: oracle.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-AuthSource: SJ0PR10MB4688.namprd10.prod.outlook.com
X-MS-Exchange-CrossTenant-Network-Message-Id: 21ee8dfe-1945-431f-c8a3-08d960b8c536
X-MS-Exchange-CrossTenant-originalarrivaltime: 16 Aug 2021 13:21:34.7282
 (UTC)
X-MS-Exchange-CrossTenant-fromentityheader: Hosted
X-MS-Exchange-CrossTenant-id: 4e2c6054-71cb-48f1-bd6c-3a9705aca71b
X-MS-Exchange-CrossTenant-mailboxtype: HOSTED
X-MS-Exchange-CrossTenant-userprincipalname: rnkRPo0OStqYwis/e+MHHCwrMlHDnFP7yr2FkhpCTM6HRANX7PAYe0Y/kqKRS48hpCpdYb+CKZh+eHCjOtMfbg==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: BYAPR10MB2519
X-Proofpoint-Virus-Version: vendor=nai engine=6200 definitions=10077 signatures=668682
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 adultscore=0 bulkscore=0 malwarescore=0
 mlxscore=0 spamscore=0 suspectscore=0 mlxlogscore=999 phishscore=0
 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-2107140000
 definitions=main-2108160084
X-Proofpoint-ORIG-GUID: SG7hpDOZvxTqQucBNhhvPUFcl0ByRiG_
X-Proofpoint-GUID: SG7hpDOZvxTqQucBNhhvPUFcl0ByRiG_
Precedence: bulk
List-ID: <linux-nfs.vger.kernel.org>
X-Mailing-List: linux-nfs@vger.kernel.org


> On Aug 15, 2021, at 9:20 PM, NeilBrown <neilb@suse.de> wrote:
>=20
> On Sun, 15 Aug 2021, Mike Javorski wrote:
>> I managed to get a cap with several discreet freezes in it, and I
>> included a chunk with 5 of them in the span of ~3000 frames. I added
>> packet comments at each frame that the tshark command reported as > 1
>> sec RPC wait. Just search for "Freeze" in (wire|t)shark in packet
>> details. This is with kernel 5.13.10 provided by Arch (See
>> https://github.com/archlinux/linux/compare/a37da2be8e6c85...v5.13.10-arc=
h1
>> for diff vs mainline, nothing NFS/RPC related I can identify).
>>=20
>> I tried unsuccessfully to get any failures with the 5.12.15 kernel.
>>=20
>> https://drive.google.com/file/d/1T42iX9xCdF9Oe4f7JXsnWqD8oJPrpMqV/view?u=
sp=3Dsharing
>>=20
>> File should be downloadable anonymously.
>=20
> Got it, thanks.
>=20
> There are 3 RPC replies that are more than 1 second after the request.
> The replies are in frames 983, 1005, 1777 These roughly correspond to
> where you added the "Freeze" annotation (I didn't know you could do that!=
).
>=20
> 983:
>  This is the (Start of the) reply to a READ Request in frame 980.
>  It is a 128K read.  The whole reply has arrived by frame 1004, 2ms
>  later.
>  The request (Frame 980) is followed 13ms later by a TCP retransmit
>  of the request and the (20usec later) a TCP ACK from the server.
>=20
>  The fact that the client needed to retransmit seems a little odd
>  but as it is the only retransmit in the whole capture, I don't think
>  we can read much into it.
>=20
> 1005:
>  This is the reply to a 128K READ request in frame 793 - earlier than
>  previous one.
>  So there were two READ requests, then a 2 second delay then both
>  replies in reverse order.
>=20
> 1777:
>  This is a similar READ reply - to 1761.
>  There were READs in 1760, 1761, and 1775
>  1760 is replied to almost immediately
>  1761 gets a reply in 4 seconds (1777)
>  1775 never gets a reply (in the available packet capture).
>=20
> Looking at other delays ... most READs get a reply in under a millisec.
> There are about 20 where the reply is more than 1ms - the longest delay
> not already mentioned is 90ms with reply 1857.
> The pattern here is=20
>   READ req (1)
>   GETATTR req
>   GETATTR reply
>   READ req (2)
>   READ reply (1)
>  pause
>   READ reply (2)
>=20
> I suspect this is the same problem occurring, but it isn't so
> noticeable.
>=20
> My first thought was that the reply might be getting stuck in the TCP
> transmit queue on the server, but checking the TSval in the TCP
> timestamp option shows that - for frame 983 which shows a 2second delay
> - the TSval is also 2seconds later than the previous packet.  So the
> delay happens before the TCP-level decision to create the packet.
>=20
> So I cannot see any real evidence to suggest a TCP-level problem.
> The time of 2 or 4 seconds - and maybe even 90ms - seem unlikely to be
> caused by an NFSd problem.
>=20
> So my guess is that the delay comes from the filesystem.  Maybe.
> What filesystem are you exporting?
>=20
> How can we check this? Probably by turning on nfsd tracing.
> There are a bunch of tracepoints that related to reading:
>=20
> 	trace_nfsd_read_start
> 	trace_nfsd_read_done
> 	trace_nfsd_read_io_done
> 	trace_nfsd_read_err
> 	trace_nfsd_read_splice
> 	trace_nfsd_read_vector
> 	trace_nfsd_read_start
> 	trace_nfsd_read_done
>=20
> Maybe enabling them might be useful as you should be able to see if the
> delay was within one read request, or between two read requests.
> But I don't have much (if any) experience in enabling trace points.  I
> really should try that some day.  Maybe you can find guidance on using
> these tracepoint somewhere ... or maybe you already know how :-)

Try something like:

# trace-cmd record -e nfsd:nfsd_read_\*

When the test is done, ^C the trace-cmd program. The trace records
are stored in a file called trace.dat. You can view them with:

# trace-cmd report | less

The trace.dat file is portable. It carries the format specifiers
for all records events, so the trace records can be viewed on=20
other systems.


--
Chuck Lever