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:   "Robert Milkowski" <rmilkowski@gmail.com>
To:     <linux-nfs@vger.kernel.org>, <trond.myklebust@hammerspace.com>,
        "'Chuck Lever'" <chuck.lever@oracle.com>,
        "'Schumaker, Anna'" <Anna.Schumaker@netapp.com>,
        <trondmy@hammerspace.com>
References: <20ce01d62303$70571e80$51055b80$@gmail.com> <109301d62a2f$b88f0ae0$29ad20a0$@gmail.com>
In-Reply-To: <109301d62a2f$b88f0ae0$29ad20a0$@gmail.com>
Subject: RE: NFS v4 + kerberos: 4 minute window of slowness
Date:   Wed, 20 May 2020 11:48:08 +0100
Message-ID: <07d501d62e94$26c72070$74556150$@gmail.com>
MIME-Version: 1.0
Content-Type: text/plain;
        charset="iso-8859-1"
Content-Transfer-Encoding: quoted-printable
Thread-Index: AQJApAoYzJ+3B0ZhSERbG+lQVfHW2gDn9MP3p9SggcA=
Content-Language: en-gb
Sender: linux-nfs-owner@vger.kernel.org
Precedence: bulk

Polite ping...

> -----Original Message-----
> From: Robert Milkowski <rmilkowski@gmail.com>
> Sent: 14 May 2020 21:39
> To: linux-nfs@vger.kernel.org; trond.myklebust@hammerspace.com; 'Chuck
> Lever' <chuck.lever@oracle.com>; 'Schumaker, Anna'
> <Anna.Schumaker@netapp.com>
> Subject: RE: NFS v4 + kerberos: 4 minute window of slowness
>=20
> +Trond, Chuck, Anna
>=20
>=20
> Ping...
>=20
> > -----Original Message-----
> > From: Robert Milkowski <rmilkowski@gmail.com>
> > Sent: 05 May 2020 18:35
> > To: linux-nfs@vger.kernel.org
> > Subject: NFS v4 + kerberos: 4 minute window of slowness
> >
> > Hi,
> >
> > Currently the last 4 minutes before kernel gss context expires, all
> > writes to NFSv4 are synchronous and all dirty pages associated with
> > the file being written to are being destaged.
> > This will continue for the 4 minutes until the context expires, at
> > which point it gets refreshed and everything gets back to normal.
> >
> > The rpc.gssd by default sets the timeout to match the Kerberos =
service
> > ticket, but this can be lowered by using -t option.
> > In fact many sites set it to lower value, like for example 30 =
minutes.
> > This means that every 30 minutes, the last 4 minutes results in
> > severely slower writes (assuming these are buffered - no O_DSYNC,
> etc.).
> >
> > In extreme case, when one sets the timeout to 5 minutes, during the =
4
> > minutes out of the minutes, there will be the slowness observed.
> >
> >
> > I understand the idea behind this mechanism - I guess it tries to
> > avoid situation when a gss context can't be refreshed (due to error =
or
> > account disabled, etc.), and it expires suddenly nfs client wouldn't
> > be able to destage all the buffered writes. The way it is currently
> > implemented though is rather crude.
> > In my opinion, instead of making everything slow for the whole 4
> > minutes, it should first try to refresh the context immediately and =
if
> > successful things go back to normal, if it can't refresh the context
> > then it should continue with the previous one and revert to the
> > current behaviour. I implemented a na=EFve quick fix which does =
exactly
> > that (attached at the end of this email).
> >
> >
> > How to re-produce.
> >
> >
> > $ uname -r
> > 5.7.0-rc4+
> >
> > $ grep -- -t /etc/sysconfig/nfs
> > RPCGSSDARGS=3D"-t 300"
> >
> > I'm setting it to 5 minutes so I can quickly see the behaviour =
without
> > having to wait for too long.
> >
> >
> > Now, let's generate a small write every 10s to a file on
> > nfsv4,sec=3Dkrb5 filesystem and record how long each write takes.
> > Since these are buffered writes it should be very quick most of the
> > time.
> >
> > $ while [ 1 ]; do strace -qq -tT -v -e trace=3Dwrite /bin/echo aa =
>f1;
> > rm f1; sleep 10; done
> >
> > 15:22:41 write(1, "aa\n", 3)            =3D 3 <0.000108>
> > 15:22:51 write(1, "aa\n", 3)            =3D 3 <0.000113>
> > 15:23:01 write(1, "aa\n", 3)            =3D 3 <0.000111>
> > 15:23:11 write(1, "aa\n", 3)            =3D 3 <0.000112>
> > 15:23:21 write(1, "aa\n", 3)            =3D 3 <0.001510>     <<<<<<
> > becomes
> > slow
> > 15:23:31 write(1, "aa\n", 3)            =3D 3 <0.001622>
> > 15:23:41 write(1, "aa\n", 3)            =3D 3 <0.001553>
> > 15:23:51 write(1, "aa\n", 3)            =3D 3 <0.001495>
> > ...
> > 15:27:01 write(1, "aa\n", 3)            =3D 3 <0.001528>
> > 15:27:12 write(1, "aa\n", 3)            =3D 3 <0.001553>
> > 15:27:22 write(1, "aa\n", 3)            =3D 3 <0.000104>     <<<<<<
> > becomes
> > fast again
> > 15:27:32 write(1, "aa\n", 3)            =3D 3 <0.000125>
> > 15:27:42 write(1, "aa\n", 3)            =3D 3 <0.000129>
> > 15:27:52 write(1, "aa\n", 3)            =3D 3 <0.000113>
> > 15:28:02 write(1, "aa\n", 3)            =3D 3 <0.000112>
> > 15:28:12 write(1, "aa\n", 3)            =3D 3 <0.000112>
> > 15:28:22 write(1, "aa\n", 3)            =3D 3 <0.001510>     <<<<<< =
slow
> > ...
> > 15:32:02 write(1, "aa\n", 3)            =3D 3 <0.001501>
> > 15:32:12 write(1, "aa\n", 3)            =3D 3 <0.001440>
> > 15:32:22 write(1, "aa\n", 3)            =3D 3 <0.000136>     <<<<<< =
fast
> > 15:32:32 write(1, "aa\n", 3)            =3D 3 <0.000109>
> > 15:32:42 write(1, "aa\n", 3)            =3D 3 <0.000110>
> > 15:32:52 write(1, "aa\n", 3)            =3D 3 <0.000112>
> > 15:33:02 write(1, "aa\n", 3)            =3D 3 <0.000103>
> > 15:33:12 write(1, "aa\n", 3)            =3D 3 <0.000112>
> > 15:33:22 write(1, "aa\n", 3)            =3D 3 <0.001405>     <<<<<< =
slow
> > 15:33:32 write(1, "aa\n", 3)            =3D 3 <0.001393>
> > 15:33:42 write(1, "aa\n", 3)            =3D 3 <0.001479>
> > ...
> >
> >
> >
> > So we have 4 minute long windows of slowness followed by 1 minute
> > window when writes are fast.
> >
> > 	15:23:21  -  15:27:22        slow
> > 	15:27:22  -  15:28:22        fast
> > 	15:28:22  -  15:32:22        slow
> > 	15:32:22  -  15:33:22        fast
> >
> >
> >
> > After some tracing with systemtap and looking at the source code, I
> > found where the issue is coming from.
> > The nfs_file_write() function ends up calling =
nfs_ctx_key_to_expire()
> > on each write, which in turn calls gss_key_timeout() which has
> > hard-coded value of 240s =
(GSS_KEY_EXPIRE_TIMEO/gss_key_expire_timeo).
> >
> >
> > nfs_file_write()
> > ...
> >         result =3D nfs_key_timeout_notify(file, inode);
> >         if (result)
> >                 return result;
> > ...
> >         if (nfs_need_check_write(file, inode)) {
> >                 int err =3D nfs_wb_all(inode); ...
> >
> >
> > /*
> >  * Avoid buffered writes when a open context credential's key would
> >  * expire soon.
> >  *
> >  * Returns -EACCES if the key will expire within =
RPC_KEY_EXPIRE_FAIL.
> >  *
> >  * Return 0 and set a credential flag which triggers the inode to
> > flush
> >  * and performs  NFS_FILE_SYNC writes if the key will expired within
> >  * RPC_KEY_EXPIRE_TIMEO.
> >  */
> > int
> > nfs_key_timeout_notify(struct file *filp, struct inode *inode) {
> >         struct nfs_open_context *ctx =3D =
nfs_file_open_context(filp);
> >
> >         if (nfs_ctx_key_to_expire(ctx, inode) &&
> >             !ctx->ll_cred)
> >                 /* Already expired! */
> >                 return -EACCES;
> >         return 0;
> > }
> >
> >
> > nfs_need_check_write()
> > ...
> >         if (nfs_ctx_key_to_expire(ctx, inode))
> >                 return 1;
> >         return 0;
> >
> >
> >
> > nfs_write_end()
> > ...
> >         if (nfs_ctx_key_to_expire(ctx, mapping->host)) {
> >                 status =3D nfs_wb_all(mapping->host); ...
> >
> >
> >
> > /*
> >  * Test if the open context credential key is marked to expire soon.
> >  */
> > bool nfs_ctx_key_to_expire(struct nfs_open_context *ctx, struct =
inode
> > *inode)
> > {
> >         struct rpc_auth *auth =3D =
NFS_SERVER(inode)->client->cl_auth;
> >         struct rpc_cred *cred =3D ctx->ll_cred;
> >         struct auth_cred acred =3D {
> >                 .cred =3D ctx->cred,
> >         };
> >
> >         if (cred && !cred->cr_ops->crmatch(&acred, cred, 0)) {
> >                 put_rpccred(cred);
> >                 ctx->ll_cred =3D NULL;
> >                 cred =3D NULL;
> >         }
> >         if (!cred)
> >                 cred =3D auth->au_ops->lookup_cred(auth, &acred, 0);
> >         if (!cred || IS_ERR(cred))
> >                 return true;
> >         ctx->ll_cred =3D cred;
> >         return !!(cred->cr_ops->crkey_timeout &&
> >                   cred->cr_ops->crkey_timeout(cred));
> > }
> >
> >
> >
> > net/sunrpc/auth_gss/auth_gss.c: .crkey_timeout          =3D
> > gss_key_timeout,
> >
> >
> > /*
> >  * Returns -EACCES if GSS context is NULL or will expire within the
> >  * timeout (miliseconds)
> >  */
> > static int
> > gss_key_timeout(struct rpc_cred *rc)
> > {
> >         struct gss_cred *gss_cred =3D container_of(rc, struct =
gss_cred,
> > gc_base);
> >         struct gss_cl_ctx *ctx;
> >         unsigned long timeout =3D jiffies + (gss_key_expire_timeo * =
HZ);
> >         int ret =3D 0;
> >
> >         rcu_read_lock();
> >         ctx =3D rcu_dereference(gss_cred->gc_ctx);
> >         if (!ctx || time_after(timeout, ctx->gc_expiry))
> >                 ret =3D -EACCES;
> >         rcu_read_unlock();
> >
> >         return ret;
> > }
> >
> >
> >
> >
> > #define GSS_KEY_EXPIRE_TIMEO 240
> > static unsigned int gss_key_expire_timeo =3D GSS_KEY_EXPIRE_TIMEO;
> >
> >
> >
> >
> >
> > A na=EFve attempt at a fix:
> >
> >
> > diff --git a/net/sunrpc/auth_gss/auth_gss.c
> > b/net/sunrpc/auth_gss/auth_gss.c index 25fbd8d9de74..864661bdfdf3
> > 100644
> > --- a/net/sunrpc/auth_gss/auth_gss.c
> > +++ b/net/sunrpc/auth_gss/auth_gss.c
> > @@ -1477,6 +1477,8 @@ gss_key_timeout(struct rpc_cred *rc)
> >
> >         rcu_read_lock();
> >         ctx =3D rcu_dereference(gss_cred->gc_ctx);
> > +        if (ctx && time_after(timeout + (60 * HZ), ctx->gc_expiry))
> > +               clear_bit(RPCAUTH_CRED_UPTODATE, &rc->cr_flags);
> >         if (!ctx || time_after(timeout, ctx->gc_expiry))
> >                 ret =3D -EACCES;
> >         rcu_read_unlock();
> >
> >
> >
> >
> > With the above patch, if there is a write within 300s before a =
context
> > is to expire (use RPCGSSDARGS=3D"-t 400" or any value larger than =
300 to
> > test), it will now try to refresh the context and if successful then
> > writes will be fast again (assuming -t option is >300s and/or krb
> > ticket is valid for more than 300s).
> >
> > What I haven't tested nor analysed code is what would happen if it =
now
> > fails to refresh the context, but after a quick glance at
> > gss_refresh() it does seem it would continue using the previous
> cred...
> >
> > Is this the correct approach to fix the issue, or can you suggest =
some
> > other approach?
> >
> >
> >
> > --
> > Robert Milkowski
>=20