Skip to content

Commit

Permalink
NFSD: Add tracepoints to the NFSD state management code
Browse files Browse the repository at this point in the history 
Capture obvious events and replace dprintk() call sites. Introduce
infrastructure so that adding more tracepoints in this code later
is simplified.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
  • Loading branch information
@chucklever
chucklever committed May 20, 2020
1 parent 0b175b1 commit dd5e3fb
Show file tree
Hide file tree
Showing 3 changed files with 152 additions and 40 deletions.
52 changes: 19 additions & 33 deletions fs/nfsd/nfs4state.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -51,6 +51,7 @@
#include "netns.h"
#include "pnfs.h"
#include "filecache.h"
#include "trace.h"

#define NFSDDBG_FACILITY NFSDDBG_PROC

Expand Down Expand Up @@ -167,9 +168,6 @@ renew_client_locked(struct nfs4_client *clp)
return;
}

dprintk("renewing client (clientid %08x/%08x)\n",
clp->cl_clientid.cl_boot,
clp->cl_clientid.cl_id);
list_move_tail(&clp->cl_lru, &nn->client_lru);
clp->cl_time = ktime_get_boottime_seconds();
}
Expand Down Expand Up @@ -1922,8 +1920,7 @@ STALE_CLIENTID(clientid_t *clid, struct nfsd_net *nn)
*/
if (clid->cl_boot == (u32)nn->boot_time)
return 0;
dprintk("NFSD stale clientid (%08x/%08x) boot_time %08llx\n",
clid->cl_boot, clid->cl_id, nn->boot_time);
trace_nfsd_clid_stale(clid);
return 1;
}

Expand Down Expand Up @@ -3879,11 +3876,7 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
if (clp_used_exchangeid(conf))
goto out;
if (!same_creds(&conf->cl_cred, &rqstp->rq_cred)) {
char addr_str[INET6_ADDRSTRLEN];
rpc_ntop((struct sockaddr *) &conf->cl_addr, addr_str,
sizeof(addr_str));
dprintk("NFSD: setclientid: string in use by client "
"at %s\n", addr_str);
trace_nfsd_clid_inuse_err(conf);
goto out;
}
}
Expand Down Expand Up @@ -4076,7 +4069,6 @@ nfsd4_init_slabs(void)
out_free_client_slab:
kmem_cache_destroy(client_slab);
out:
dprintk("nfsd4: out of memory while initializing nfsv4\n");
return -ENOMEM;
}

Expand Down Expand Up @@ -4508,6 +4500,8 @@ nfsd_break_deleg_cb(struct file_lock *fl)
struct nfs4_delegation *dp = (struct nfs4_delegation *)fl->fl_owner;
struct nfs4_file *fp = dp->dl_stid.sc_file;

trace_nfsd_deleg_break(&dp->dl_stid.sc_stateid);

/*
* We don't want the locks code to timeout the lease for us;
* we'll remove it ourself if a delegation isn't returned
Expand Down Expand Up @@ -5018,8 +5012,7 @@ nfs4_open_delegation(struct svc_fh *fh, struct nfsd4_open *open,

memcpy(&open->op_delegate_stateid, &dp->dl_stid.sc_stateid, sizeof(dp->dl_stid.sc_stateid));

dprintk("NFSD: delegation stateid=" STATEID_FMT "\n",
STATEID_VAL(&dp->dl_stid.sc_stateid));
trace_nfsd_deleg_open(&dp->dl_stid.sc_stateid);
open->op_delegate_type = NFS4_OPEN_DELEGATE_READ;
nfs4_put_stid(&dp->dl_stid);
return;
Expand Down Expand Up @@ -5136,9 +5129,7 @@ nfsd4_process_open2(struct svc_rqst *rqstp, struct svc_fh *current_fh, struct nf
nfs4_open_delegation(current_fh, open, stp);
nodeleg:
status = nfs_ok;

dprintk("%s: stateid=" STATEID_FMT "\n", __func__,
STATEID_VAL(&stp->st_stid.sc_stateid));
trace_nfsd_deleg_none(&stp->st_stid.sc_stateid);
out:
/* 4.1 client trying to upgrade/downgrade delegation? */
if (open->op_delegate_type == NFS4_OPEN_DELEGATE_NONE && dp &&
Expand Down Expand Up @@ -5192,8 +5183,7 @@ nfsd4_renew(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
__be32 status;
struct nfsd_net *nn = net_generic(SVC_NET(rqstp), nfsd_net_id);

dprintk("process_renew(%08x/%08x): starting\n",
clid->cl_boot, clid->cl_id);
trace_nfsd_clid_renew(clid);
status = lookup_clientid(clid, cstate, nn, false);
if (status)
goto out;
Expand All @@ -5214,6 +5204,7 @@ nfsd4_end_grace(struct nfsd_net *nn)
if (nn->grace_ended)
return;

trace_nfsd_grace_complete(nn);
nn->grace_ended = true;
/*
* If the server goes down again right now, an NFSv4
Expand Down Expand Up @@ -5279,13 +5270,10 @@ nfs4_laundromat(struct nfsd_net *nn)
copy_stateid_t *cps_t;
int i;

dprintk("NFSD: laundromat service - starting\n");

if (clients_still_reclaiming(nn)) {
new_timeo = 0;
goto out;
}
dprintk("NFSD: end of grace period\n");
nfsd4_end_grace(nn);
INIT_LIST_HEAD(&reaplist);

Expand All @@ -5307,17 +5295,15 @@ nfs4_laundromat(struct nfsd_net *nn)
break;
}
if (mark_client_expired_locked(clp)) {
dprintk("NFSD: client in use (clientid %08x)\n",
clp->cl_clientid.cl_id);
trace_nfsd_clid_expired(&clp->cl_clientid);
continue;
}
list_add(&clp->cl_lru, &reaplist);
}
spin_unlock(&nn->client_lock);
list_for_each_safe(pos, next, &reaplist) {
clp = list_entry(pos, struct nfs4_client, cl_lru);
dprintk("NFSD: purging unused client (clientid %08x)\n",
clp->cl_clientid.cl_id);
trace_nfsd_clid_purged(&clp->cl_clientid);
list_del_init(&clp->cl_lru);
expire_client(clp);
}
Expand Down Expand Up @@ -5407,7 +5393,6 @@ laundromat_main(struct work_struct *laundry)
laundromat_work);

t = nfs4_laundromat(nn);
dprintk("NFSD: laundromat_main - sleeping for %lld seconds\n", t);
queue_delayed_work(laundry_wq, &nn->laundromat_work, t*HZ);
}

Expand Down Expand Up @@ -5948,8 +5933,7 @@ nfs4_preprocess_seqid_op(struct nfsd4_compound_state *cstate, u32 seqid,
struct nfs4_stid *s;
struct nfs4_ol_stateid *stp = NULL;

dprintk("NFSD: %s: seqid=%d stateid = " STATEID_FMT "\n", __func__,
seqid, STATEID_VAL(stateid));
trace_nfsd_preprocess(seqid, stateid);

*stpp = NULL;
status = nfsd4_lookup_stateid(cstate, stateid, typemask, &s, nn);
Expand Down Expand Up @@ -6018,9 +6002,7 @@ nfsd4_open_confirm(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
oo->oo_flags |= NFS4_OO_CONFIRMED;
nfs4_inc_and_copy_stateid(&oc->oc_resp_stateid, &stp->st_stid);
mutex_unlock(&stp->st_mutex);
dprintk("NFSD: %s: success, seqid=%d stateid=" STATEID_FMT "\n",
__func__, oc->oc_seqid, STATEID_VAL(&stp->st_stid.sc_stateid));

trace_nfsd_open_confirm(oc->oc_seqid, &stp->st_stid.sc_stateid);
nfsd4_client_record_create(oo->oo_owner.so_client);
status = nfs_ok;
put_stateid:
Expand Down Expand Up @@ -7072,7 +7054,7 @@ nfs4_client_to_reclaim(struct xdr_netobj name, struct xdr_netobj princhash,
unsigned int strhashval;
struct nfs4_client_reclaim *crp;

dprintk("NFSD nfs4_client_to_reclaim NAME: %.*s\n", name.len, name.data);
trace_nfsd_clid_reclaim(nn, name.len, name.data);
crp = alloc_reclaim();
if (crp) {
strhashval = clientstr_hashval(name);
Expand Down Expand Up @@ -7122,7 +7104,7 @@ nfsd4_find_reclaim_client(struct xdr_netobj name, struct nfsd_net *nn)
unsigned int strhashval;
struct nfs4_client_reclaim *crp = NULL;

dprintk("NFSD: nfs4_find_reclaim_client for name %.*s\n", name.len, name.data);
trace_nfsd_clid_find(nn, name.len, name.data);

strhashval = clientstr_hashval(name);
list_for_each_entry(crp, &nn->reclaim_str_hashtbl[strhashval], cr_strhash) {
Expand Down Expand Up @@ -7686,6 +7668,9 @@ nfsd_recall_delegations(struct list_head *reaplist)
list_for_each_entry_safe(dp, next, reaplist, dl_recall_lru) {
list_del_init(&dp->dl_recall_lru);
clp = dp->dl_stid.sc_client;

trace_nfsd_deleg_recall(&dp->dl_stid.sc_stateid);

/*
* We skipped all entries that had a zero dl_time before,
* so we can now reset the dl_time back to 0. If a delegation
Expand Down Expand Up @@ -7868,6 +7853,7 @@ nfs4_state_start_net(struct net *net)
goto skip_grace;
printk(KERN_INFO "NFSD: starting %lld-second grace period (net %x)\n",
nn->nfsd4_grace, net->ns.inum);
trace_nfsd_grace_start(nn);
queue_delayed_work(laundry_wq, &nn->laundromat_work, nn->nfsd4_grace * HZ);
return 0;

Expand Down
7 changes: 0 additions & 7 deletions fs/nfsd/state.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -64,13 +64,6 @@ typedef struct {
refcount_t sc_count;
} copy_stateid_t;

#define STATEID_FMT "(%08x/%08x/%08x/%08x)"
#define STATEID_VAL(s) \
(s)->si_opaque.so_clid.cl_boot, \
(s)->si_opaque.so_clid.cl_id, \
(s)->si_opaque.so_id, \
(s)->si_generation

struct nfsd4_callback {
struct nfs4_client *cb_clp;
struct rpc_message cb_msg;
Expand Down
133 changes: 133 additions & 0 deletions fs/nfsd/trace.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -277,6 +277,7 @@ DECLARE_EVENT_CLASS(nfsd_stateid_class,
DEFINE_EVENT(nfsd_stateid_class, nfsd_##name, \
TP_PROTO(stateid_t *stp), \
TP_ARGS(stp))

DEFINE_STATEID_EVENT(layoutstate_alloc);
DEFINE_STATEID_EVENT(layoutstate_unhash);
DEFINE_STATEID_EVENT(layoutstate_free);
Expand All @@ -288,6 +289,138 @@ DEFINE_STATEID_EVENT(layout_recall_done);
DEFINE_STATEID_EVENT(layout_recall_fail);
DEFINE_STATEID_EVENT(layout_recall_release);

DEFINE_STATEID_EVENT(deleg_open);
DEFINE_STATEID_EVENT(deleg_none);
DEFINE_STATEID_EVENT(deleg_break);
DEFINE_STATEID_EVENT(deleg_recall);

DECLARE_EVENT_CLASS(nfsd_stateseqid_class,
TP_PROTO(u32 seqid, const stateid_t *stp),
TP_ARGS(seqid, stp),
TP_STRUCT__entry(
__field(u32, seqid)
__field(u32, cl_boot)
__field(u32, cl_id)
__field(u32, si_id)
__field(u32, si_generation)
),
TP_fast_assign(
__entry->seqid = seqid;
__entry->cl_boot = stp->si_opaque.so_clid.cl_boot;
__entry->cl_id = stp->si_opaque.so_clid.cl_id;
__entry->si_id = stp->si_opaque.so_id;
__entry->si_generation = stp->si_generation;
),
TP_printk("seqid=%u client %08x:%08x stateid %08x:%08x",
__entry->seqid, __entry->cl_boot, __entry->cl_id,
__entry->si_id, __entry->si_generation)
)

#define DEFINE_STATESEQID_EVENT(name) \
DEFINE_EVENT(nfsd_stateseqid_class, nfsd_##name, \
TP_PROTO(u32 seqid, const stateid_t *stp), \
TP_ARGS(seqid, stp))

DEFINE_STATESEQID_EVENT(preprocess);
DEFINE_STATESEQID_EVENT(open_confirm);

DECLARE_EVENT_CLASS(nfsd_clientid_class,
TP_PROTO(const clientid_t *clid),
TP_ARGS(clid),
TP_STRUCT__entry(
__field(u32, cl_boot)
__field(u32, cl_id)
),
TP_fast_assign(
__entry->cl_boot = clid->cl_boot;
__entry->cl_id = clid->cl_id;
),
TP_printk("client %08x:%08x", __entry->cl_boot, __entry->cl_id)
)

#define DEFINE_CLIENTID_EVENT(name) \
DEFINE_EVENT(nfsd_clientid_class, nfsd_clid_##name, \
TP_PROTO(const clientid_t *clid), \
TP_ARGS(clid))

DEFINE_CLIENTID_EVENT(expired);
DEFINE_CLIENTID_EVENT(purged);
DEFINE_CLIENTID_EVENT(renew);
DEFINE_CLIENTID_EVENT(stale);

DECLARE_EVENT_CLASS(nfsd_net_class,
TP_PROTO(const struct nfsd_net *nn),
TP_ARGS(nn),
TP_STRUCT__entry(
__field(unsigned long long, boot_time)
),
TP_fast_assign(
__entry->boot_time = nn->boot_time;
),
TP_printk("boot_time=%16llx", __entry->boot_time)
)

#define DEFINE_NET_EVENT(name) \
DEFINE_EVENT(nfsd_net_class, nfsd_##name, \
TP_PROTO(const struct nfsd_net *nn), \
TP_ARGS(nn))

DEFINE_NET_EVENT(grace_start);
DEFINE_NET_EVENT(grace_complete);

DECLARE_EVENT_CLASS(nfsd_clid_class,
TP_PROTO(const struct nfsd_net *nn,
unsigned int namelen,
const unsigned char *namedata),
TP_ARGS(nn, namelen, namedata),
TP_STRUCT__entry(
__field(unsigned long long, boot_time)
__field(unsigned int, namelen)
__dynamic_array(unsigned char, name, namelen)
),
TP_fast_assign(
__entry->boot_time = nn->boot_time;
__entry->namelen = namelen;
memcpy(__get_dynamic_array(name), namedata, namelen);
),
TP_printk("boot_time=%16llx nfs4_clientid=%.*s",
__entry->boot_time, __entry->namelen, __get_str(name))
)

#define DEFINE_CLID_EVENT(name) \
DEFINE_EVENT(nfsd_clid_class, nfsd_clid_##name, \
TP_PROTO(const struct nfsd_net *nn, \
unsigned int namelen, \
const unsigned char *namedata), \
TP_ARGS(nn, namelen, namedata))

DEFINE_CLID_EVENT(find);
DEFINE_CLID_EVENT(reclaim);

TRACE_EVENT(nfsd_clid_inuse_err,
TP_PROTO(const struct nfs4_client *clp),
TP_ARGS(clp),
TP_STRUCT__entry(
__field(u32, cl_boot)
__field(u32, cl_id)
__array(unsigned char, addr, sizeof(struct sockaddr_in6))
__field(unsigned int, namelen)
__dynamic_array(unsigned char, name, clp->cl_name.len)
),
TP_fast_assign(
__entry->cl_boot = clp->cl_clientid.cl_boot;
__entry->cl_id = clp->cl_clientid.cl_id;
memcpy(__entry->addr, &clp->cl_addr,
sizeof(struct sockaddr_in6));
__entry->namelen = clp->cl_name.len;
memcpy(__get_dynamic_array(name), clp->cl_name.data,
clp->cl_name.len);
),
TP_printk("nfs4_clientid %.*s already in use by %pISpc, client %08x:%08x",
__entry->namelen, __get_str(name), __entry->addr,
__entry->cl_boot, __entry->cl_id)
)

TRACE_DEFINE_ENUM(NFSD_FILE_HASHED);
TRACE_DEFINE_ENUM(NFSD_FILE_PENDING);
TRACE_DEFINE_ENUM(NFSD_FILE_BREAK_READ);
Expand Down

0 comments on commit dd5e3fb

Please sign in to comment.