Add basic tracing for debugging the sunrpc cache events.
Signed-off-by: Trond Myklebust <[email protected]>
---
include/trace/events/sunrpc.h | 33 +++++++++++++++++++++++++++++++++
net/sunrpc/cache.c | 35 ++++++++++++++++++++++++++---------
2 files changed, 59 insertions(+), 9 deletions(-)
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index ee993575d2fa..236d42539c7b 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -1292,6 +1292,39 @@ DECLARE_EVENT_CLASS(svc_deferred_event,
DEFINE_SVC_DEFERRED_EVENT(drop);
DEFINE_SVC_DEFERRED_EVENT(revisit);
+DECLARE_EVENT_CLASS(cache_event,
+ TP_PROTO(
+ const struct cache_detail *cd,
+ const struct cache_head *h
+ ),
+
+ TP_ARGS(cd, h),
+
+ TP_STRUCT__entry(
+ __field(const struct cache_head *, h)
+ __string(name, cd->name)
+ ),
+
+ TP_fast_assign(
+ __entry->h = h;
+ __assign_str(name, cd->name);
+ ),
+
+ TP_printk("cache=%s entry=%p", __get_str(name), __entry->h)
+);
+#define DEFINE_CACHE_EVENT(name) \
+ DEFINE_EVENT(cache_event, name, \
+ TP_PROTO( \
+ const struct cache_detail *cd, \
+ const struct cache_head *h \
+ ), \
+ TP_ARGS(cd, h))
+DEFINE_CACHE_EVENT(cache_entry_expired);
+DEFINE_CACHE_EVENT(cache_entry_upcall);
+DEFINE_CACHE_EVENT(cache_entry_update);
+DEFINE_CACHE_EVENT(cache_entry_make_negative);
+DEFINE_CACHE_EVENT(cache_entry_no_listener);
+
#endif /* _TRACE_SUNRPC_H */
#include <trace/define_trace.h>
diff --git a/net/sunrpc/cache.c b/net/sunrpc/cache.c
index b7ddb2affb7e..559a61644037 100644
--- a/net/sunrpc/cache.c
+++ b/net/sunrpc/cache.c
@@ -32,6 +32,7 @@
#include <linux/sunrpc/cache.h>
#include <linux/sunrpc/stats.h>
#include <linux/sunrpc/rpc_pipe_fs.h>
+#include <trace/events/sunrpc.h>
#include "netns.h"
#define RPCDBG_FACILITY RPCDBG_CACHE
@@ -119,6 +120,7 @@ static struct cache_head *sunrpc_cache_add_entry(struct cache_detail *detail,
if (test_bit(CACHE_VALID, &tmp->flags) &&
cache_is_expired(detail, tmp)) {
sunrpc_begin_cache_remove_entry(tmp, detail);
+ trace_cache_entry_expired(detail, tmp);
freeme = tmp;
break;
}
@@ -175,6 +177,24 @@ static void cache_fresh_unlocked(struct cache_head *head,
}
}
+static void cache_make_negative(struct cache_detail *detail,
+ struct cache_head *h)
+{
+ set_bit(CACHE_NEGATIVE, &h->flags);
+ trace_cache_entry_make_negative(detail, h);
+}
+
+static void cache_entry_update(struct cache_detail *detail,
+ struct cache_head *h,
+ struct cache_head *new)
+{
+ if (!test_bit(CACHE_NEGATIVE, &new->flags)) {
+ detail->update(h, new);
+ trace_cache_entry_update(detail, h);
+ } else
+ cache_make_negative(detail, h);
+}
+
struct cache_head *sunrpc_cache_update(struct cache_detail *detail,
struct cache_head *new, struct cache_head *old, int hash)
{
@@ -187,10 +207,7 @@ struct cache_head *sunrpc_cache_update(struct cache_detail *detail,
if (!test_bit(CACHE_VALID, &old->flags)) {
spin_lock(&detail->hash_lock);
if (!test_bit(CACHE_VALID, &old->flags)) {
- if (test_bit(CACHE_NEGATIVE, &new->flags))
- set_bit(CACHE_NEGATIVE, &old->flags);
- else
- detail->update(old, new);
+ cache_entry_update(detail, old, new);
cache_fresh_locked(old, new->expiry_time, detail);
spin_unlock(&detail->hash_lock);
cache_fresh_unlocked(old, detail);
@@ -208,10 +225,7 @@ struct cache_head *sunrpc_cache_update(struct cache_detail *detail,
detail->init(tmp, old);
spin_lock(&detail->hash_lock);
- if (test_bit(CACHE_NEGATIVE, &new->flags))
- set_bit(CACHE_NEGATIVE, &tmp->flags);
- else
- detail->update(tmp, new);
+ cache_entry_update(detail, tmp, new);
hlist_add_head(&tmp->cache_list, &detail->hash_table[hash]);
detail->entries++;
cache_get(tmp);
@@ -253,7 +267,7 @@ static int try_to_negate_entry(struct cache_detail *detail, struct cache_head *h
spin_lock(&detail->hash_lock);
rv = cache_is_valid(h);
if (rv == -EAGAIN) {
- set_bit(CACHE_NEGATIVE, &h->flags);
+ cache_make_negative(detail, h);
cache_fresh_locked(h, seconds_since_boot()+CACHE_NEW_EXPIRY,
detail);
rv = -ENOENT;
@@ -459,6 +473,7 @@ static int cache_clean(void)
continue;
sunrpc_begin_cache_remove_entry(ch, current_detail);
+ trace_cache_entry_expired(current_detail, ch);
rv = 1;
break;
}
@@ -1214,6 +1229,7 @@ static int cache_pipe_upcall(struct cache_detail *detail, struct cache_head *h)
if (test_bit(CACHE_PENDING, &h->flags)) {
crq->item = cache_get(h);
list_add_tail(&crq->q.list, &detail->queue);
+ trace_cache_entry_upcall(detail, h);
} else
/* Lost a race, no longer PENDING, so don't enqueue */
ret = -EAGAIN;
@@ -1239,6 +1255,7 @@ int sunrpc_cache_pipe_upcall_timeout(struct cache_detail *detail,
{
if (!cache_listeners_exist(detail)) {
warn_no_listener(detail);
+ trace_cache_entry_no_listener(detail, h);
return -EINVAL;
}
return sunrpc_cache_pipe_upcall(detail, h);
--
2.24.1
If a server wants to drop a request, then it should also drop the
connection, in order to let the client know.
Signed-off-by: Trond Myklebust <[email protected]>
---
net/sunrpc/svc_xprt.c | 10 ++++++++++
1 file changed, 10 insertions(+)
diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
index de3c077733a7..83a527e56c87 100644
--- a/net/sunrpc/svc_xprt.c
+++ b/net/sunrpc/svc_xprt.c
@@ -873,6 +873,13 @@ int svc_recv(struct svc_rqst *rqstp, long timeout)
}
EXPORT_SYMBOL_GPL(svc_recv);
+static void svc_drop_connection(struct svc_xprt *xprt)
+{
+ if (test_bit(XPT_TEMP, &xprt->xpt_flags) &&
+ !test_and_set_bit(XPT_CLOSE, &xprt->xpt_flags))
+ svc_xprt_enqueue(xprt);
+}
+
/*
* Drop request
*/
@@ -880,6 +887,8 @@ void svc_drop(struct svc_rqst *rqstp)
{
trace_svc_drop(rqstp);
dprintk("svc: xprt %p dropped request\n", rqstp->rq_xprt);
+ /* Close the connection when dropping a request */
+ svc_drop_connection(rqstp->rq_xprt);
svc_xprt_release(rqstp);
}
EXPORT_SYMBOL_GPL(svc_drop);
@@ -1148,6 +1157,7 @@ static void svc_revisit(struct cache_deferred_req *dreq, int too_many)
if (too_many || test_bit(XPT_DEAD, &xprt->xpt_flags)) {
spin_unlock(&xprt->xpt_lock);
dprintk("revisit canceled\n");
+ svc_drop_connection(xprt);
svc_xprt_put(xprt);
trace_svc_drop_deferred(dr);
kfree(dr);
--
2.24.1
On Sun, Mar 1, 2020 at 6:25 PM Trond Myklebust <[email protected]> wrote:
>
> If a server wants to drop a request, then it should also drop the
> connection, in order to let the client know.
>
> Signed-off-by: Trond Myklebust <[email protected]>
> ---
> net/sunrpc/svc_xprt.c | 10 ++++++++++
> 1 file changed, 10 insertions(+)
>
> diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
> index de3c077733a7..83a527e56c87 100644
> --- a/net/sunrpc/svc_xprt.c
> +++ b/net/sunrpc/svc_xprt.c
> @@ -873,6 +873,13 @@ int svc_recv(struct svc_rqst *rqstp, long timeout)
> }
> EXPORT_SYMBOL_GPL(svc_recv);
>
> +static void svc_drop_connection(struct svc_xprt *xprt)
> +{
> + if (test_bit(XPT_TEMP, &xprt->xpt_flags) &&
> + !test_and_set_bit(XPT_CLOSE, &xprt->xpt_flags))
> + svc_xprt_enqueue(xprt);
> +}
> +
> /*
> * Drop request
> */
> @@ -880,6 +887,8 @@ void svc_drop(struct svc_rqst *rqstp)
> {
> trace_svc_drop(rqstp);
> dprintk("svc: xprt %p dropped request\n", rqstp->rq_xprt);
> + /* Close the connection when dropping a request */
> + svc_drop_connection(rqstp->rq_xprt);
> svc_xprt_release(rqstp);
> }
> EXPORT_SYMBOL_GPL(svc_drop);
> @@ -1148,6 +1157,7 @@ static void svc_revisit(struct cache_deferred_req *dreq, int too_many)
> if (too_many || test_bit(XPT_DEAD, &xprt->xpt_flags)) {
> spin_unlock(&xprt->xpt_lock);
> dprintk("revisit canceled\n");
> + svc_drop_connection(xprt);
> svc_xprt_put(xprt);
> trace_svc_drop_deferred(dr);
> kfree(dr);
> --
> 2.24.1
>
Trond, back in 2014 you had this NFSv4 only patch that took a more
surgical approach:
https://marc.info/?l=linux-nfs&m=141414531832768&w=2
It looks like discussion died out on it after it was ineffective to
solve a different problem.
Is there a reason why you don't want to do that approach now?
On Mon, 2020-03-02 at 11:27 -0500, David Wysochanski wrote:
> On Sun, Mar 1, 2020 at 6:25 PM Trond Myklebust <[email protected]>
> wrote:
> > If a server wants to drop a request, then it should also drop the
> > connection, in order to let the client know.
> >
> > Signed-off-by: Trond Myklebust <[email protected]>
> > ---
> > net/sunrpc/svc_xprt.c | 10 ++++++++++
> > 1 file changed, 10 insertions(+)
> >
> > diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
> > index de3c077733a7..83a527e56c87 100644
> > --- a/net/sunrpc/svc_xprt.c
> > +++ b/net/sunrpc/svc_xprt.c
> > @@ -873,6 +873,13 @@ int svc_recv(struct svc_rqst *rqstp, long
> > timeout)
> > }
> > EXPORT_SYMBOL_GPL(svc_recv);
> >
> > +static void svc_drop_connection(struct svc_xprt *xprt)
> > +{
> > + if (test_bit(XPT_TEMP, &xprt->xpt_flags) &&
> > + !test_and_set_bit(XPT_CLOSE, &xprt->xpt_flags))
> > + svc_xprt_enqueue(xprt);
> > +}
> > +
> > /*
> > * Drop request
> > */
> > @@ -880,6 +887,8 @@ void svc_drop(struct svc_rqst *rqstp)
> > {
> > trace_svc_drop(rqstp);
> > dprintk("svc: xprt %p dropped request\n", rqstp->rq_xprt);
> > + /* Close the connection when dropping a request */
> > + svc_drop_connection(rqstp->rq_xprt);
> > svc_xprt_release(rqstp);
> > }
> > EXPORT_SYMBOL_GPL(svc_drop);
> > @@ -1148,6 +1157,7 @@ static void svc_revisit(struct
> > cache_deferred_req *dreq, int too_many)
> > if (too_many || test_bit(XPT_DEAD, &xprt->xpt_flags)) {
> > spin_unlock(&xprt->xpt_lock);
> > dprintk("revisit canceled\n");
> > + svc_drop_connection(xprt);
> > svc_xprt_put(xprt);
> > trace_svc_drop_deferred(dr);
> > kfree(dr);
> > --
> > 2.24.1
> >
>
> Trond, back in 2014 you had this NFSv4 only patch that took a more
> surgical approach:
> https://marc.info/?l=linux-nfs&m=141414531832768&w=2
>
> It looks like discussion died out on it after it was ineffective to
> solve a different problem.
> Is there a reason why you don't want to do that approach now?
>
Let me resend this patch with a better proposal. I think the main 2
problems here are really
1. the svc_revisit() case, where we cancel the revisit. That case
affects all versions of NFS, and can lead to performance issues.
2. the NFSv2,v3,v4.0 replay cache, where dropping the replay (e.g.
after a connection breakage) can cause a performance hit, and for
something like TCP, which has long (usually 60 second) timeouts it
could cause the replay to be delayed until after the reply gets
kicked out of the cache. This is the case where NFSv4.0 can probably
end up hanging, since the replay won't be forthcoming until a new
connection breakage occurs.
I think (1) is best served by a patch like this one.
Perhaps (2) is better served by adopting the svc_defer() mechanism?
Hmm... Perhaps 2 patches are in order...
--
Trond Myklebust
Linux NFS client maintainer, Hammerspace
[email protected]
> On Mar 2, 2020, at 3:12 PM, Trond Myklebust <[email protected]> wrote:
>
> On Mon, 2020-03-02 at 11:27 -0500, David Wysochanski wrote:
>> On Sun, Mar 1, 2020 at 6:25 PM Trond Myklebust <[email protected]>
>> wrote:
>>> If a server wants to drop a request, then it should also drop the
>>> connection, in order to let the client know.
>>>
>>> Signed-off-by: Trond Myklebust <[email protected]>
>>> ---
>>> net/sunrpc/svc_xprt.c | 10 ++++++++++
>>> 1 file changed, 10 insertions(+)
>>>
>>> diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
>>> index de3c077733a7..83a527e56c87 100644
>>> --- a/net/sunrpc/svc_xprt.c
>>> +++ b/net/sunrpc/svc_xprt.c
>>> @@ -873,6 +873,13 @@ int svc_recv(struct svc_rqst *rqstp, long
>>> timeout)
>>> }
>>> EXPORT_SYMBOL_GPL(svc_recv);
>>>
>>> +static void svc_drop_connection(struct svc_xprt *xprt)
>>> +{
>>> + if (test_bit(XPT_TEMP, &xprt->xpt_flags) &&
>>> + !test_and_set_bit(XPT_CLOSE, &xprt->xpt_flags))
>>> + svc_xprt_enqueue(xprt);
>>> +}
>>> +
>>> /*
>>> * Drop request
>>> */
>>> @@ -880,6 +887,8 @@ void svc_drop(struct svc_rqst *rqstp)
>>> {
>>> trace_svc_drop(rqstp);
>>> dprintk("svc: xprt %p dropped request\n", rqstp->rq_xprt);
>>> + /* Close the connection when dropping a request */
>>> + svc_drop_connection(rqstp->rq_xprt);
>>> svc_xprt_release(rqstp);
>>> }
>>> EXPORT_SYMBOL_GPL(svc_drop);
>>> @@ -1148,6 +1157,7 @@ static void svc_revisit(struct
>>> cache_deferred_req *dreq, int too_many)
>>> if (too_many || test_bit(XPT_DEAD, &xprt->xpt_flags)) {
>>> spin_unlock(&xprt->xpt_lock);
>>> dprintk("revisit canceled\n");
>>> + svc_drop_connection(xprt);
>>> svc_xprt_put(xprt);
>>> trace_svc_drop_deferred(dr);
>>> kfree(dr);
>>> --
>>> 2.24.1
>>>
>>
>> Trond, back in 2014 you had this NFSv4 only patch that took a more
>> surgical approach:
>> https://marc.info/?l=linux-nfs&m=141414531832768&w=2
>>
>> It looks like discussion died out on it after it was ineffective to
>> solve a different problem.
>> Is there a reason why you don't want to do that approach now?
>>
>
> Let me resend this patch with a better proposal.
Hey Trond, any progress here?
> I think the main 2
> problems here are really
>
> 1. the svc_revisit() case, where we cancel the revisit. That case
> affects all versions of NFS, and can lead to performance issues.
> 2. the NFSv2,v3,v4.0 replay cache, where dropping the replay (e.g.
> after a connection breakage) can cause a performance hit, and for
> something like TCP, which has long (usually 60 second) timeouts it
> could cause the replay to be delayed until after the reply gets
> kicked out of the cache. This is the case where NFSv4.0 can probably
> end up hanging, since the replay won't be forthcoming until a new
> connection breakage occurs.
>
> I think (1) is best served by a patch like this one.
> Perhaps (2) is better served by adopting the svc_defer() mechanism?
>
> Hmm... Perhaps 2 patches are in order...
--
Chuck Lever