[PATCH 0/4] A collection of NFS client tracepoint patches

[PATCH 0/4] A collection of NFS client tracepoint patches

[Chuck Lever]

Hi-

This series proposes a small handful of tracepoint-related changes.

The first patch is clean-up.

The second and third patches are part of the ongoing effort to
replace dprintk with tracepoints.

The last patch adds some tracepoints I found useful while diagnosing
the recent NFSv3 fsx failures.

---

Chuck Lever (4):
      NFS: Remove unnecessary TRACE_DEFINE_ENUM()s
      SUNRPC: Tracepoints should store tk_pid and cl_clid as a signed int
      SUNRPC: Per-rpc_clnt task PIDs
      NFS: Instrument i_size_write()


 fs/nfs/inode.c                 |   9 +--
 fs/nfs/nfs4trace.h             |  12 +--
 fs/nfs/nfstrace.h              | 122 ++++++++++++----------------
 fs/nfs/write.c                 |   1 +
 include/linux/sunrpc/clnt.h    |   3 +-
 include/trace/events/rpcgss.h  |  30 +++----
 include/trace/events/rpcrdma.h |  90 ++++++++++-----------
 include/trace/events/sunrpc.h  | 140 ++++++++++++++++-----------------
 net/sunrpc/sched.c             |  12 ++-
 9 files changed, 204 insertions(+), 215 deletions(-)

--
Chuck Lever

[PATCH 1/4] NFS: Remove unnecessary TRACE_DEFINE_ENUM()s

[Chuck Lever]

Clean up: TRACE_DEFINE_ENUM is unnecessary because the target
symbols are all C macros, not enums.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfs/nfstrace.h |   68 -----------------------------------------------------
 1 file changed, 68 deletions(-)

diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
index 8a224871be74..589f32fdbe63 100644
--- a/fs/nfs/nfstrace.h
+++ b/fs/nfs/nfstrace.h
@@ -11,16 +11,6 @@
 #include <linux/tracepoint.h>
 #include <linux/iversion.h>
 
-TRACE_DEFINE_ENUM(DT_UNKNOWN);
-TRACE_DEFINE_ENUM(DT_FIFO);
-TRACE_DEFINE_ENUM(DT_CHR);
-TRACE_DEFINE_ENUM(DT_DIR);
-TRACE_DEFINE_ENUM(DT_BLK);
-TRACE_DEFINE_ENUM(DT_REG);
-TRACE_DEFINE_ENUM(DT_LNK);
-TRACE_DEFINE_ENUM(DT_SOCK);
-TRACE_DEFINE_ENUM(DT_WHT);
-
 #define nfs_show_file_type(ftype) \
 	__print_symbolic(ftype, \
 			{ DT_UNKNOWN, "UNKNOWN" }, \
@@ -33,24 +23,6 @@ TRACE_DEFINE_ENUM(DT_WHT);
 			{ DT_SOCK, "SOCK" }, \
 			{ DT_WHT, "WHT" })
 
-TRACE_DEFINE_ENUM(NFS_INO_INVALID_DATA);
-TRACE_DEFINE_ENUM(NFS_INO_INVALID_ATIME);
-TRACE_DEFINE_ENUM(NFS_INO_INVALID_ACCESS);
-TRACE_DEFINE_ENUM(NFS_INO_INVALID_ACL);
-TRACE_DEFINE_ENUM(NFS_INO_REVAL_PAGECACHE);
-TRACE_DEFINE_ENUM(NFS_INO_REVAL_FORCED);
-TRACE_DEFINE_ENUM(NFS_INO_INVALID_LABEL);
-TRACE_DEFINE_ENUM(NFS_INO_INVALID_CHANGE);
-TRACE_DEFINE_ENUM(NFS_INO_INVALID_CTIME);
-TRACE_DEFINE_ENUM(NFS_INO_INVALID_MTIME);
-TRACE_DEFINE_ENUM(NFS_INO_INVALID_SIZE);
-TRACE_DEFINE_ENUM(NFS_INO_INVALID_OTHER);
-TRACE_DEFINE_ENUM(NFS_INO_DATA_INVAL_DEFER);
-TRACE_DEFINE_ENUM(NFS_INO_INVALID_BLOCKS);
-TRACE_DEFINE_ENUM(NFS_INO_INVALID_XATTR);
-TRACE_DEFINE_ENUM(NFS_INO_INVALID_NLINK);
-TRACE_DEFINE_ENUM(NFS_INO_INVALID_MODE);
-
 #define nfs_show_cache_validity(v) \
 	__print_flags(v, "|", \
 			{ NFS_INO_INVALID_DATA, "INVALID_DATA" }, \
@@ -71,17 +43,6 @@ TRACE_DEFINE_ENUM(NFS_INO_INVALID_MODE);
 			{ NFS_INO_INVALID_NLINK, "INVALID_NLINK" }, \
 			{ NFS_INO_INVALID_MODE, "INVALID_MODE" })
 
-TRACE_DEFINE_ENUM(NFS_INO_ADVISE_RDPLUS);
-TRACE_DEFINE_ENUM(NFS_INO_STALE);
-TRACE_DEFINE_ENUM(NFS_INO_ACL_LRU_SET);
-TRACE_DEFINE_ENUM(NFS_INO_INVALIDATING);
-TRACE_DEFINE_ENUM(NFS_INO_FSCACHE);
-TRACE_DEFINE_ENUM(NFS_INO_FSCACHE_LOCK);
-TRACE_DEFINE_ENUM(NFS_INO_LAYOUTCOMMIT);
-TRACE_DEFINE_ENUM(NFS_INO_LAYOUTCOMMITTING);
-TRACE_DEFINE_ENUM(NFS_INO_LAYOUTSTATS);
-TRACE_DEFINE_ENUM(NFS_INO_ODIRECT);
-
 #define nfs_show_nfsi_flags(v) \
 	__print_flags(v, "|", \
 			{ BIT(NFS_INO_ADVISE_RDPLUS), "ADVISE_RDPLUS" }, \
@@ -270,19 +231,6 @@ TRACE_EVENT(nfs_access_exit,
 		)
 );
 
-TRACE_DEFINE_ENUM(LOOKUP_FOLLOW);
-TRACE_DEFINE_ENUM(LOOKUP_DIRECTORY);
-TRACE_DEFINE_ENUM(LOOKUP_AUTOMOUNT);
-TRACE_DEFINE_ENUM(LOOKUP_PARENT);
-TRACE_DEFINE_ENUM(LOOKUP_REVAL);
-TRACE_DEFINE_ENUM(LOOKUP_RCU);
-TRACE_DEFINE_ENUM(LOOKUP_OPEN);
-TRACE_DEFINE_ENUM(LOOKUP_CREATE);
-TRACE_DEFINE_ENUM(LOOKUP_EXCL);
-TRACE_DEFINE_ENUM(LOOKUP_RENAME_TARGET);
-TRACE_DEFINE_ENUM(LOOKUP_EMPTY);
-TRACE_DEFINE_ENUM(LOOKUP_DOWN);
-
 #define show_lookup_flags(flags) \
 	__print_flags(flags, "|", \
 			{ LOOKUP_FOLLOW, "FOLLOW" }, \
@@ -392,22 +340,6 @@ DEFINE_NFS_LOOKUP_EVENT_DONE(nfs_lookup_exit);
 DEFINE_NFS_LOOKUP_EVENT(nfs_lookup_revalidate_enter);
 DEFINE_NFS_LOOKUP_EVENT_DONE(nfs_lookup_revalidate_exit);
 
-TRACE_DEFINE_ENUM(O_WRONLY);
-TRACE_DEFINE_ENUM(O_RDWR);
-TRACE_DEFINE_ENUM(O_CREAT);
-TRACE_DEFINE_ENUM(O_EXCL);
-TRACE_DEFINE_ENUM(O_NOCTTY);
-TRACE_DEFINE_ENUM(O_TRUNC);
-TRACE_DEFINE_ENUM(O_APPEND);
-TRACE_DEFINE_ENUM(O_NONBLOCK);
-TRACE_DEFINE_ENUM(O_DSYNC);
-TRACE_DEFINE_ENUM(O_DIRECT);
-TRACE_DEFINE_ENUM(O_LARGEFILE);
-TRACE_DEFINE_ENUM(O_DIRECTORY);
-TRACE_DEFINE_ENUM(O_NOFOLLOW);
-TRACE_DEFINE_ENUM(O_NOATIME);
-TRACE_DEFINE_ENUM(O_CLOEXEC);
-
 #define show_open_flags(flags) \
 	__print_flags(flags, "|", \
 		{ O_WRONLY, "O_WRONLY" }, \

[PATCH 2/4] SUNRPC: Tracepoints should store tk_pid and cl_clid as a signed int

[Chuck Lever]

ida_simple_get() returns a signed integer. Negative values are error
returns, but this suggests the range of valid client IDs is zero to
2^31 - 1.

tk_pid is currently an unsigned short, so its range is zero to
65535.

For certain special cases, RPC-related tracepoints record a -1 as
the task ID or the client ID. It's ugly for a trace event to display
4 billion in these cases.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfs/nfs4trace.h             |   12 ++-
 fs/nfs/nfstrace.h              |    6 +-
 include/linux/sunrpc/clnt.h    |    2 -
 include/trace/events/rpcgss.h  |   30 ++++-----
 include/trace/events/rpcrdma.h |   90 +++++++++++++-------------
 include/trace/events/sunrpc.h  |  140 ++++++++++++++++++++--------------------
 6 files changed, 140 insertions(+), 140 deletions(-)

diff --git a/fs/nfs/nfs4trace.h b/fs/nfs/nfs4trace.h
index 7a2567aa2b86..440f88ec20b8 100644
--- a/fs/nfs/nfs4trace.h
+++ b/fs/nfs/nfs4trace.h
@@ -676,8 +676,8 @@ TRACE_EVENT(nfs4_xdr_bad_operation,
 		TP_ARGS(xdr, op, expected),
 
 		TP_STRUCT__entry(
-			__field(unsigned int, task_id)
-			__field(unsigned int, client_id)
+			__field(int, task_id)
+			__field(int, client_id)
 			__field(u32, xid)
 			__field(u32, op)
 			__field(u32, expected)
@@ -695,7 +695,7 @@ TRACE_EVENT(nfs4_xdr_bad_operation,
 		),
 
 		TP_printk(
-			"task:%u@%d xid=0x%08x operation=%u, expected=%u",
+			"task:%d@%d xid=0x%08x operation=%u, expected=%u",
 			__entry->task_id, __entry->client_id, __entry->xid,
 			__entry->op, __entry->expected
 		)
@@ -711,8 +711,8 @@ DECLARE_EVENT_CLASS(nfs4_xdr_event,
 		TP_ARGS(xdr, op, error),
 
 		TP_STRUCT__entry(
-			__field(unsigned int, task_id)
-			__field(unsigned int, client_id)
+			__field(int, task_id)
+			__field(int, client_id)
 			__field(u32, xid)
 			__field(u32, op)
 			__field(unsigned long, error)
@@ -730,7 +730,7 @@ DECLARE_EVENT_CLASS(nfs4_xdr_event,
 		),
 
 		TP_printk(
-			"task:%u@%d xid=0x%08x error=%ld (%s) operation=%u",
+			"task:%d@%d xid=0x%08x error=%ld (%s) operation=%u",
 			__entry->task_id, __entry->client_id, __entry->xid,
 			-__entry->error, show_nfsv4_errors(__entry->error),
 			__entry->op
diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
index 589f32fdbe63..4094e2856cf9 100644
--- a/fs/nfs/nfstrace.h
+++ b/fs/nfs/nfstrace.h
@@ -1334,8 +1334,8 @@ DECLARE_EVENT_CLASS(nfs_xdr_event,
 		TP_ARGS(xdr, error),
 
 		TP_STRUCT__entry(
-			__field(unsigned int, task_id)
-			__field(unsigned int, client_id)
+			__field(int, task_id)
+			__field(int, client_id)
 			__field(u32, xid)
 			__field(int, version)
 			__field(unsigned long, error)
@@ -1360,7 +1360,7 @@ DECLARE_EVENT_CLASS(nfs_xdr_event,
 		),
 
 		TP_printk(
-			"task:%u@%d xid=0x%08x %sv%d %s error=%ld (%s)",
+			"task:%d@%d xid=0x%08x %sv%d %s error=%ld (%s)",
 			__entry->task_id, __entry->client_id, __entry->xid,
 			__get_str(program), __entry->version,
 			__get_str(procedure), -__entry->error,
diff --git a/include/linux/sunrpc/clnt.h b/include/linux/sunrpc/clnt.h
index a4661646adc9..bd22f14c4b19 100644
--- a/include/linux/sunrpc/clnt.h
+++ b/include/linux/sunrpc/clnt.h
@@ -37,7 +37,7 @@ struct rpc_sysfs_client;
  */
 struct rpc_clnt {
 	refcount_t		cl_count;	/* Number of references */
-	unsigned int		cl_clid;	/* client id */
+	int			cl_clid;	/* client id */
 	struct list_head	cl_clients;	/* Global list of clients */
 	struct list_head	cl_tasks;	/* List of tasks */
 	spinlock_t		cl_lock;	/* spinlock */
diff --git a/include/trace/events/rpcgss.h b/include/trace/events/rpcgss.h
index b2a2672e6632..746965228585 100644
--- a/include/trace/events/rpcgss.h
+++ b/include/trace/events/rpcgss.h
@@ -87,8 +87,8 @@ DECLARE_EVENT_CLASS(rpcgss_gssapi_event,
 	TP_ARGS(task, maj_stat),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, maj_stat)
 
 	),
@@ -99,7 +99,7 @@ DECLARE_EVENT_CLASS(rpcgss_gssapi_event,
 		__entry->maj_stat = maj_stat;
 	),
 
-	TP_printk("task:%u@%u maj_stat=%s",
+	TP_printk("task:%d@%d maj_stat=%s",
 		__entry->task_id, __entry->client_id,
 		__entry->maj_stat == 0 ?
 		"GSS_S_COMPLETE" : show_gss_status(__entry->maj_stat))
@@ -323,8 +323,8 @@ TRACE_EVENT(rpcgss_unwrap_failed,
 	TP_ARGS(task),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 	),
 
 	TP_fast_assign(
@@ -332,7 +332,7 @@ TRACE_EVENT(rpcgss_unwrap_failed,
 		__entry->client_id = task->tk_client->cl_clid;
 	),
 
-	TP_printk("task:%u@%u", __entry->task_id, __entry->client_id)
+	TP_printk("task:%d@%d", __entry->task_id, __entry->client_id)
 );
 
 TRACE_EVENT(rpcgss_bad_seqno,
@@ -345,8 +345,8 @@ TRACE_EVENT(rpcgss_bad_seqno,
 	TP_ARGS(task, expected, received),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, expected)
 		__field(u32, received)
 	),
@@ -358,7 +358,7 @@ TRACE_EVENT(rpcgss_bad_seqno,
 		__entry->received = received;
 	),
 
-	TP_printk("task:%u@%u expected seqno %u, received seqno %u",
+	TP_printk("task:%d@%d expected seqno %u, received seqno %u",
 		__entry->task_id, __entry->client_id,
 		__entry->expected, __entry->received)
 );
@@ -372,7 +372,7 @@ TRACE_EVENT(rpcgss_seqno,
 
 	TP_STRUCT__entry(
 		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, client_id)
 		__field(u32, xid)
 		__field(u32, seqno)
 	),
@@ -386,7 +386,7 @@ TRACE_EVENT(rpcgss_seqno,
 		__entry->seqno = rqst->rq_seqno;
 	),
 
-	TP_printk("task:%u@%u xid=0x%08x seqno=%u",
+	TP_printk("task:%u@%d xid=0x%08x seqno=%u",
 		__entry->task_id, __entry->client_id,
 		__entry->xid, __entry->seqno)
 );
@@ -402,7 +402,7 @@ TRACE_EVENT(rpcgss_need_reencode,
 
 	TP_STRUCT__entry(
 		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, client_id)
 		__field(u32, xid)
 		__field(u32, seq_xmit)
 		__field(u32, seqno)
@@ -418,7 +418,7 @@ TRACE_EVENT(rpcgss_need_reencode,
 		__entry->ret = ret;
 	),
 
-	TP_printk("task:%u@%u xid=0x%08x rq_seqno=%u seq_xmit=%u reencode %sneeded",
+	TP_printk("task:%u@%d xid=0x%08x rq_seqno=%u seq_xmit=%u reencode %sneeded",
 		__entry->task_id, __entry->client_id,
 		__entry->xid, __entry->seqno, __entry->seq_xmit,
 		__entry->ret ? "" : "un")
@@ -434,7 +434,7 @@ TRACE_EVENT(rpcgss_update_slack,
 
 	TP_STRUCT__entry(
 		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, client_id)
 		__field(u32, xid)
 		__field(const void *, auth)
 		__field(unsigned int, rslack)
@@ -452,7 +452,7 @@ TRACE_EVENT(rpcgss_update_slack,
 		__entry->verfsize = auth->au_verfsize;
 	),
 
-	TP_printk("task:%u@%u xid=0x%08x auth=%p rslack=%u ralign=%u verfsize=%u\n",
+	TP_printk("task:%u@%d xid=0x%08x auth=%p rslack=%u ralign=%u verfsize=%u\n",
 		__entry->task_id, __entry->client_id, __entry->xid,
 		__entry->auth, __entry->rslack, __entry->ralign,
 		__entry->verfsize)
diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index afb2e394797c..b174ef8d168e 100644
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -258,8 +258,8 @@ DECLARE_EVENT_CLASS(xprtrdma_rdch_event,
 	TP_ARGS(task, pos, mr, nsegs),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(unsigned int, pos)
 		__field(int, nents)
 		__field(u32, handle)
@@ -279,7 +279,7 @@ DECLARE_EVENT_CLASS(xprtrdma_rdch_event,
 		__entry->nsegs = nsegs;
 	),
 
-	TP_printk("task:%u@%u pos=%u %u@0x%016llx:0x%08x (%s)",
+	TP_printk("task:%d@%d pos=%u %u@0x%016llx:0x%08x (%s)",
 		__entry->task_id, __entry->client_id,
 		__entry->pos, __entry->length,
 		(unsigned long long)__entry->offset, __entry->handle,
@@ -307,8 +307,8 @@ DECLARE_EVENT_CLASS(xprtrdma_wrch_event,
 	TP_ARGS(task, mr, nsegs),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(int, nents)
 		__field(u32, handle)
 		__field(u32, length)
@@ -326,7 +326,7 @@ DECLARE_EVENT_CLASS(xprtrdma_wrch_event,
 		__entry->nsegs = nsegs;
 	),
 
-	TP_printk("task:%u@%u %u@0x%016llx:0x%08x (%s)",
+	TP_printk("task:%d@%d %u@0x%016llx:0x%08x (%s)",
 		__entry->task_id, __entry->client_id,
 		__entry->length, (unsigned long long)__entry->offset,
 		__entry->handle,
@@ -363,8 +363,8 @@ DECLARE_EVENT_CLASS(xprtrdma_mr_class,
 	TP_ARGS(mr),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, mr_id)
 		__field(int, nents)
 		__field(u32, handle)
@@ -393,7 +393,7 @@ DECLARE_EVENT_CLASS(xprtrdma_mr_class,
 		__entry->dir    = mr->mr_dir;
 	),
 
-	TP_printk("task:%u@%u mr.id=%u nents=%d %u@0x%016llx:0x%08x (%s)",
+	TP_printk("task:%d@%d mr.id=%u nents=%d %u@0x%016llx:0x%08x (%s)",
 		__entry->task_id, __entry->client_id,
 		__entry->mr_id, __entry->nents, __entry->length,
 		(unsigned long long)__entry->offset, __entry->handle,
@@ -621,8 +621,8 @@ TRACE_EVENT(xprtrdma_nomrs_err,
 	TP_ARGS(r_xprt, req),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__string(addr, rpcrdma_addrstr(r_xprt))
 		__string(port, rpcrdma_portstr(r_xprt))
 	),
@@ -636,7 +636,7 @@ TRACE_EVENT(xprtrdma_nomrs_err,
 		__assign_str(port, rpcrdma_portstr(r_xprt));
 	),
 
-	TP_printk("peer=[%s]:%s task:%u@%u",
+	TP_printk("peer=[%s]:%s task:%d@%d",
 		__get_str(addr), __get_str(port),
 		__entry->task_id, __entry->client_id
 	)
@@ -675,8 +675,8 @@ TRACE_EVENT(xprtrdma_marshal,
 	TP_ARGS(req, rtype, wtype),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, xid)
 		__field(unsigned int, hdrlen)
 		__field(unsigned int, headlen)
@@ -700,7 +700,7 @@ TRACE_EVENT(xprtrdma_marshal,
 		__entry->wtype = wtype;
 	),
 
-	TP_printk("task:%u@%u xid=0x%08x: hdr=%u xdr=%u/%u/%u %s/%s",
+	TP_printk("task:%d@%d xid=0x%08x: hdr=%u xdr=%u/%u/%u %s/%s",
 		__entry->task_id, __entry->client_id, __entry->xid,
 		__entry->hdrlen,
 		__entry->headlen, __entry->pagelen, __entry->taillen,
@@ -717,8 +717,8 @@ TRACE_EVENT(xprtrdma_marshal_failed,
 	TP_ARGS(rqst, ret),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, xid)
 		__field(int, ret)
 	),
@@ -730,7 +730,7 @@ TRACE_EVENT(xprtrdma_marshal_failed,
 		__entry->ret = ret;
 	),
 
-	TP_printk("task:%u@%u xid=0x%08x: ret=%d",
+	TP_printk("task:%d@%d xid=0x%08x: ret=%d",
 		__entry->task_id, __entry->client_id, __entry->xid,
 		__entry->ret
 	)
@@ -744,8 +744,8 @@ TRACE_EVENT(xprtrdma_prepsend_failed,
 	TP_ARGS(rqst, ret),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, xid)
 		__field(int, ret)
 	),
@@ -757,7 +757,7 @@ TRACE_EVENT(xprtrdma_prepsend_failed,
 		__entry->ret = ret;
 	),
 
-	TP_printk("task:%u@%u xid=0x%08x: ret=%d",
+	TP_printk("task:%d@%d xid=0x%08x: ret=%d",
 		__entry->task_id, __entry->client_id, __entry->xid,
 		__entry->ret
 	)
@@ -773,8 +773,8 @@ TRACE_EVENT(xprtrdma_post_send,
 	TP_STRUCT__entry(
 		__field(u32, cq_id)
 		__field(int, completion_id)
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(int, num_sge)
 		__field(int, signaled)
 	),
@@ -792,7 +792,7 @@ TRACE_EVENT(xprtrdma_post_send,
 		__entry->signaled = req->rl_wr.send_flags & IB_SEND_SIGNALED;
 	),
 
-	TP_printk("task:%u@%u cq.id=%u cid=%d (%d SGE%s) %s",
+	TP_printk("task:%d@%d cq.id=%u cid=%d (%d SGE%s) %s",
 		__entry->task_id, __entry->client_id,
 		__entry->cq_id, __entry->completion_id,
 		__entry->num_sge, (__entry->num_sge == 1 ? "" : "s"),
@@ -926,8 +926,8 @@ TRACE_EVENT(xprtrdma_post_linv_err,
 	TP_ARGS(req, status),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(int, status)
 	),
 
@@ -939,7 +939,7 @@ TRACE_EVENT(xprtrdma_post_linv_err,
 		__entry->status = status;
 	),
 
-	TP_printk("task:%u@%u status=%d",
+	TP_printk("task:%d@%d status=%d",
 		__entry->task_id, __entry->client_id, __entry->status
 	)
 );
@@ -1114,8 +1114,8 @@ TRACE_EVENT(xprtrdma_reply,
 	TP_ARGS(task, rep, credits),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, xid)
 		__field(unsigned int, credits)
 	),
@@ -1127,7 +1127,7 @@ TRACE_EVENT(xprtrdma_reply,
 		__entry->credits = credits;
 	),
 
-	TP_printk("task:%u@%u xid=0x%08x credits=%u",
+	TP_printk("task:%d@%d xid=0x%08x credits=%u",
 		__entry->task_id, __entry->client_id, __entry->xid,
 		__entry->credits
 	)
@@ -1148,8 +1148,8 @@ TRACE_EVENT(xprtrdma_err_vers,
 	TP_ARGS(rqst, min, max),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, xid)
 		__field(u32, min)
 		__field(u32, max)
@@ -1163,7 +1163,7 @@ TRACE_EVENT(xprtrdma_err_vers,
 		__entry->max = be32_to_cpup(max);
 	),
 
-	TP_printk("task:%u@%u xid=0x%08x versions=[%u, %u]",
+	TP_printk("task:%d@%d xid=0x%08x versions=[%u, %u]",
 		__entry->task_id, __entry->client_id, __entry->xid,
 		__entry->min, __entry->max
 	)
@@ -1177,8 +1177,8 @@ TRACE_EVENT(xprtrdma_err_chunk,
 	TP_ARGS(rqst),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, xid)
 	),
 
@@ -1188,7 +1188,7 @@ TRACE_EVENT(xprtrdma_err_chunk,
 		__entry->xid = be32_to_cpu(rqst->rq_xid);
 	),
 
-	TP_printk("task:%u@%u xid=0x%08x",
+	TP_printk("task:%d@%d xid=0x%08x",
 		__entry->task_id, __entry->client_id, __entry->xid
 	)
 );
@@ -1202,8 +1202,8 @@ TRACE_EVENT(xprtrdma_err_unrecognized,
 	TP_ARGS(rqst, procedure),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, xid)
 		__field(u32, procedure)
 	),
@@ -1214,7 +1214,7 @@ TRACE_EVENT(xprtrdma_err_unrecognized,
 		__entry->procedure = be32_to_cpup(procedure);
 	),
 
-	TP_printk("task:%u@%u xid=0x%08x procedure=%u",
+	TP_printk("task:%d@%d xid=0x%08x procedure=%u",
 		__entry->task_id, __entry->client_id, __entry->xid,
 		__entry->procedure
 	)
@@ -1229,8 +1229,8 @@ TRACE_EVENT(xprtrdma_fixup,
 	TP_ARGS(rqst, fixup),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(unsigned long, fixup)
 		__field(size_t, headlen)
 		__field(unsigned int, pagelen)
@@ -1246,7 +1246,7 @@ TRACE_EVENT(xprtrdma_fixup,
 		__entry->taillen = rqst->rq_rcv_buf.tail[0].iov_len;
 	),
 
-	TP_printk("task:%u@%u fixup=%lu xdr=%zu/%u/%zu",
+	TP_printk("task:%d@%d fixup=%lu xdr=%zu/%u/%zu",
 		__entry->task_id, __entry->client_id, __entry->fixup,
 		__entry->headlen, __entry->pagelen, __entry->taillen
 	)
@@ -1287,8 +1287,8 @@ TRACE_EVENT(xprtrdma_mrs_zap,
 	TP_ARGS(task),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 	),
 
 	TP_fast_assign(
@@ -1296,7 +1296,7 @@ TRACE_EVENT(xprtrdma_mrs_zap,
 		__entry->client_id = task->tk_client->cl_clid;
 	),
 
-	TP_printk("task:%u@%u",
+	TP_printk("task:%d@%d",
 		__entry->task_id, __entry->client_id
 	)
 );
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 2d04eb96d418..ce6f717efac3 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -56,8 +56,8 @@ DECLARE_EVENT_CLASS(rpc_xdr_buf_class,
 	TP_ARGS(task, xdr),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(const void *, head_base)
 		__field(size_t, head_len)
 		__field(const void *, tail_base)
@@ -78,7 +78,7 @@ DECLARE_EVENT_CLASS(rpc_xdr_buf_class,
 		__entry->msg_len = xdr->len;
 	),
 
-	TP_printk("task:%u@%u head=[%p,%zu] page=%u tail=[%p,%zu] len=%u",
+	TP_printk("task:%d@%d head=[%p,%zu] page=%u tail=[%p,%zu] len=%u",
 		__entry->task_id, __entry->client_id,
 		__entry->head_base, __entry->head_len, __entry->page_len,
 		__entry->tail_base, __entry->tail_len, __entry->msg_len
@@ -107,14 +107,14 @@ DECLARE_EVENT_CLASS(rpc_clnt_class,
 	TP_ARGS(clnt),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, client_id)
+		__field(int, client_id)
 	),
 
 	TP_fast_assign(
 		__entry->client_id = clnt->cl_clid;
 	),
 
-	TP_printk("clid=%u", __entry->client_id)
+	TP_printk("clid=%d", __entry->client_id)
 );
 
 #define DEFINE_RPC_CLNT_EVENT(name)					\
@@ -143,7 +143,7 @@ TRACE_EVENT(rpc_clnt_new,
 	TP_ARGS(clnt, xprt, program, server),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, client_id)
+		__field(int, client_id)
 		__string(addr, xprt->address_strings[RPC_DISPLAY_ADDR])
 		__string(port, xprt->address_strings[RPC_DISPLAY_PORT])
 		__string(program, program)
@@ -158,7 +158,7 @@ TRACE_EVENT(rpc_clnt_new,
 		__assign_str(server, server);
 	),
 
-	TP_printk("client=%u peer=[%s]:%s program=%s server=%s",
+	TP_printk("client=%d peer=[%s]:%s program=%s server=%s",
 		__entry->client_id, __get_str(addr), __get_str(port),
 		__get_str(program), __get_str(server))
 );
@@ -197,7 +197,7 @@ TRACE_EVENT(rpc_clnt_clone_err,
 	TP_ARGS(clnt, error),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, client_id)
+		__field(int, client_id)
 		__field(int, error)
 	),
 
@@ -206,7 +206,7 @@ TRACE_EVENT(rpc_clnt_clone_err,
 		__entry->error = error;
 	),
 
-	TP_printk("client=%u error=%d", __entry->client_id, __entry->error)
+	TP_printk("client=%d error=%d", __entry->client_id, __entry->error)
 );
 
 
@@ -237,8 +237,8 @@ DECLARE_EVENT_CLASS(rpc_task_status,
 	TP_ARGS(task),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(int, status)
 	),
 
@@ -248,7 +248,7 @@ DECLARE_EVENT_CLASS(rpc_task_status,
 		__entry->status = task->tk_status;
 	),
 
-	TP_printk("task:%u@%u status=%d",
+	TP_printk("task:%d@%d status=%d",
 		__entry->task_id, __entry->client_id,
 		__entry->status)
 );
@@ -271,8 +271,8 @@ TRACE_EVENT(rpc_request,
 	TP_ARGS(task),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(int, version)
 		__field(bool, async)
 		__string(progname, task->tk_client->cl_program->name)
@@ -288,7 +288,7 @@ TRACE_EVENT(rpc_request,
 		__assign_str(procname, rpc_proc_name(task));
 	),
 
-	TP_printk("task:%u@%u %sv%d %s (%ssync)",
+	TP_printk("task:%d@%d %sv%d %s (%ssync)",
 		__entry->task_id, __entry->client_id,
 		__get_str(progname), __entry->version,
 		__get_str(procname), __entry->async ? "a": ""
@@ -330,8 +330,8 @@ DECLARE_EVENT_CLASS(rpc_task_running,
 	TP_ARGS(task, action),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(const void *, action)
 		__field(unsigned long, runstate)
 		__field(int, status)
@@ -348,7 +348,7 @@ DECLARE_EVENT_CLASS(rpc_task_running,
 		__entry->flags = task->tk_flags;
 		),
 
-	TP_printk("task:%u@%d flags=%s runstate=%s status=%d action=%ps",
+	TP_printk("task:%d@%d flags=%s runstate=%s status=%d action=%ps",
 		__entry->task_id, __entry->client_id,
 		rpc_show_task_flags(__entry->flags),
 		rpc_show_runstate(__entry->runstate),
@@ -380,8 +380,8 @@ DECLARE_EVENT_CLASS(rpc_task_queued,
 	TP_ARGS(task, q),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(unsigned long, timeout)
 		__field(unsigned long, runstate)
 		__field(int, status)
@@ -400,7 +400,7 @@ DECLARE_EVENT_CLASS(rpc_task_queued,
 		__assign_str(q_name, rpc_qname(q));
 		),
 
-	TP_printk("task:%u@%d flags=%s runstate=%s status=%d timeout=%lu queue=%s",
+	TP_printk("task:%d@%d flags=%s runstate=%s status=%d timeout=%lu queue=%s",
 		__entry->task_id, __entry->client_id,
 		rpc_show_task_flags(__entry->flags),
 		rpc_show_runstate(__entry->runstate),
@@ -427,8 +427,8 @@ DECLARE_EVENT_CLASS(rpc_failure,
 	TP_ARGS(task),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 	),
 
 	TP_fast_assign(
@@ -436,7 +436,7 @@ DECLARE_EVENT_CLASS(rpc_failure,
 		__entry->client_id = task->tk_client->cl_clid;
 	),
 
-	TP_printk("task:%u@%u",
+	TP_printk("task:%d@%d",
 		__entry->task_id, __entry->client_id)
 );
 
@@ -459,8 +459,8 @@ DECLARE_EVENT_CLASS(rpc_reply_event,
 	TP_ARGS(task),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, xid)
 		__string(progname, task->tk_client->cl_program->name)
 		__field(u32, version)
@@ -478,7 +478,7 @@ DECLARE_EVENT_CLASS(rpc_reply_event,
 		__assign_str(servername, task->tk_xprt->servername);
 	),
 
-	TP_printk("task:%u@%d server=%s xid=0x%08x %sv%d %s",
+	TP_printk("task:%d@%d server=%s xid=0x%08x %sv%d %s",
 		__entry->task_id, __entry->client_id, __get_str(servername),
 		__entry->xid, __get_str(progname), __entry->version,
 		__get_str(procname))
@@ -523,8 +523,8 @@ TRACE_EVENT(rpc_buf_alloc,
 	TP_ARGS(task, status),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(size_t, callsize)
 		__field(size_t, recvsize)
 		__field(int, status)
@@ -538,7 +538,7 @@ TRACE_EVENT(rpc_buf_alloc,
 		__entry->status = status;
 	),
 
-	TP_printk("task:%u@%u callsize=%zu recvsize=%zu status=%d",
+	TP_printk("task:%d@%d callsize=%zu recvsize=%zu status=%d",
 		__entry->task_id, __entry->client_id,
 		__entry->callsize, __entry->recvsize, __entry->status
 	)
@@ -554,8 +554,8 @@ TRACE_EVENT(rpc_call_rpcerror,
 	TP_ARGS(task, tk_status, rpc_status),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(int, tk_status)
 		__field(int, rpc_status)
 	),
@@ -567,7 +567,7 @@ TRACE_EVENT(rpc_call_rpcerror,
 		__entry->rpc_status = rpc_status;
 	),
 
-	TP_printk("task:%u@%u tk_status=%d rpc_status=%d",
+	TP_printk("task:%d@%d tk_status=%d rpc_status=%d",
 		__entry->task_id, __entry->client_id,
 		__entry->tk_status, __entry->rpc_status)
 );
@@ -584,8 +584,8 @@ TRACE_EVENT(rpc_stats_latency,
 	TP_ARGS(task, backlog, rtt, execute),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, xid)
 		__field(int, version)
 		__string(progname, task->tk_client->cl_program->name)
@@ -607,7 +607,7 @@ TRACE_EVENT(rpc_stats_latency,
 		__entry->execute = ktime_to_us(execute);
 	),
 
-	TP_printk("task:%u@%d xid=0x%08x %sv%d %s backlog=%lu rtt=%lu execute=%lu",
+	TP_printk("task:%d@%d xid=0x%08x %sv%d %s backlog=%lu rtt=%lu execute=%lu",
 		__entry->task_id, __entry->client_id, __entry->xid,
 		__get_str(progname), __entry->version, __get_str(procname),
 		__entry->backlog, __entry->rtt, __entry->execute)
@@ -622,8 +622,8 @@ TRACE_EVENT(rpc_xdr_overflow,
 	TP_ARGS(xdr, requested),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(int, version)
 		__field(size_t, requested)
 		__field(const void *, end)
@@ -651,8 +651,8 @@ TRACE_EVENT(rpc_xdr_overflow,
 			__entry->version = task->tk_client->cl_vers;
 			__assign_str(procedure, task->tk_msg.rpc_proc->p_name);
 		} else {
-			__entry->task_id = 0;
-			__entry->client_id = 0;
+			__entry->task_id = -1;
+			__entry->client_id = -1;
 			__assign_str(progname, "unknown");
 			__entry->version = 0;
 			__assign_str(procedure, "unknown");
@@ -669,7 +669,7 @@ TRACE_EVENT(rpc_xdr_overflow,
 	),
 
 	TP_printk(
-		"task:%u@%u %sv%d %s requested=%zu p=%p end=%p xdr=[%p,%zu]/%u/[%p,%zu]/%u\n",
+		"task:%d@%d %sv%d %s requested=%zu p=%p end=%p xdr=[%p,%zu]/%u/[%p,%zu]/%u\n",
 		__entry->task_id, __entry->client_id,
 		__get_str(progname), __entry->version, __get_str(procedure),
 		__entry->requested, __entry->p, __entry->end,
@@ -690,8 +690,8 @@ TRACE_EVENT(rpc_xdr_alignment,
 	TP_ARGS(xdr, offset, copied),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(int, version)
 		__field(size_t, offset)
 		__field(unsigned int, copied)
@@ -728,7 +728,7 @@ TRACE_EVENT(rpc_xdr_alignment,
 	),
 
 	TP_printk(
-		"task:%u@%u %sv%d %s offset=%zu copied=%u xdr=[%p,%zu]/%u/[%p,%zu]/%u\n",
+		"task:%d@%d %sv%d %s offset=%zu copied=%u xdr=[%p,%zu]/%u/[%p,%zu]/%u\n",
 		__entry->task_id, __entry->client_id,
 		__get_str(progname), __entry->version, __get_str(procedure),
 		__entry->offset, __entry->copied,
@@ -904,8 +904,8 @@ TRACE_EVENT(rpc_socket_nospace,
 	TP_ARGS(rqst, transport),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(unsigned int, total)
 		__field(unsigned int, remaining)
 	),
@@ -917,7 +917,7 @@ TRACE_EVENT(rpc_socket_nospace,
 		__entry->remaining = rqst->rq_slen - transport->xmit.offset;
 	),
 
-	TP_printk("task:%u@%u total=%u remaining=%u",
+	TP_printk("task:%d@%d total=%u remaining=%u",
 		__entry->task_id, __entry->client_id,
 		__entry->total, __entry->remaining
 	)
@@ -1026,8 +1026,8 @@ TRACE_EVENT(xprt_transmit,
 	TP_ARGS(rqst, status),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, xid)
 		__field(u32, seqno)
 		__field(int, status)
@@ -1043,7 +1043,7 @@ TRACE_EVENT(xprt_transmit,
 	),
 
 	TP_printk(
-		"task:%u@%u xid=0x%08x seqno=%u status=%d",
+		"task:%d@%d xid=0x%08x seqno=%u status=%d",
 		__entry->task_id, __entry->client_id, __entry->xid,
 		__entry->seqno, __entry->status)
 );
@@ -1056,8 +1056,8 @@ TRACE_EVENT(xprt_retransmit,
 	TP_ARGS(rqst),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, xid)
 		__field(int, ntrans)
 		__field(int, version)
@@ -1083,7 +1083,7 @@ TRACE_EVENT(xprt_retransmit,
 	),
 
 	TP_printk(
-		"task:%u@%u xid=0x%08x %sv%d %s ntrans=%d timeout=%lu",
+		"task:%d@%d xid=0x%08x %sv%d %s ntrans=%d timeout=%lu",
 		__entry->task_id, __entry->client_id, __entry->xid,
 		__get_str(progname), __entry->version, __get_str(procname),
 		__entry->ntrans, __entry->timeout
@@ -1119,9 +1119,9 @@ DECLARE_EVENT_CLASS(xprt_writelock_event,
 	TP_ARGS(xprt, task),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
-		__field(unsigned int, snd_task_id)
+		__field(int, task_id)
+		__field(int, client_id)
+		__field(int, snd_task_id)
 	),
 
 	TP_fast_assign(
@@ -1137,7 +1137,7 @@ DECLARE_EVENT_CLASS(xprt_writelock_event,
 					xprt->snd_task->tk_pid : -1;
 	),
 
-	TP_printk("task:%u@%u snd_task:%u",
+	TP_printk("task:%d@%d snd_task:%d",
 			__entry->task_id, __entry->client_id,
 			__entry->snd_task_id)
 );
@@ -1161,9 +1161,9 @@ DECLARE_EVENT_CLASS(xprt_cong_event,
 	TP_ARGS(xprt, task),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
-		__field(unsigned int, snd_task_id)
+		__field(int, task_id)
+		__field(int, client_id)
+		__field(int, snd_task_id)
 		__field(unsigned long, cong)
 		__field(unsigned long, cwnd)
 		__field(bool, wait)
@@ -1185,7 +1185,7 @@ DECLARE_EVENT_CLASS(xprt_cong_event,
 		__entry->wait = test_bit(XPRT_CWND_WAIT, &xprt->state);
 	),
 
-	TP_printk("task:%u@%u snd_task:%u cong=%lu cwnd=%lu%s",
+	TP_printk("task:%d@%d snd_task:%d cong=%lu cwnd=%lu%s",
 			__entry->task_id, __entry->client_id,
 			__entry->snd_task_id, __entry->cong, __entry->cwnd,
 			__entry->wait ? " (wait)" : "")
@@ -1212,8 +1212,8 @@ TRACE_EVENT(xprt_reserve,
 	TP_ARGS(rqst),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(u32, xid)
 	),
 
@@ -1223,7 +1223,7 @@ TRACE_EVENT(xprt_reserve,
 		__entry->xid = be32_to_cpu(rqst->rq_xid);
 	),
 
-	TP_printk("task:%u@%u xid=0x%08x",
+	TP_printk("task:%d@%d xid=0x%08x",
 		__entry->task_id, __entry->client_id, __entry->xid
 	)
 );
@@ -1293,8 +1293,8 @@ TRACE_EVENT(rpcb_getport,
 	TP_ARGS(clnt, task, bind_version),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(unsigned int, program)
 		__field(unsigned int, version)
 		__field(int, protocol)
@@ -1312,7 +1312,7 @@ TRACE_EVENT(rpcb_getport,
 		__assign_str(servername, task->tk_xprt->servername);
 	),
 
-	TP_printk("task:%u@%u server=%s program=%u version=%u protocol=%d bind_version=%u",
+	TP_printk("task:%d@%d server=%s program=%u version=%u protocol=%d bind_version=%u",
 		__entry->task_id, __entry->client_id, __get_str(servername),
 		__entry->program, __entry->version, __entry->protocol,
 		__entry->bind_version
@@ -1329,8 +1329,8 @@ TRACE_EVENT(rpcb_setport,
 	TP_ARGS(task, status, port),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, task_id)
-		__field(unsigned int, client_id)
+		__field(int, task_id)
+		__field(int, client_id)
 		__field(int, status)
 		__field(unsigned short, port)
 	),
@@ -1342,7 +1342,7 @@ TRACE_EVENT(rpcb_setport,
 		__entry->port = port;
 	),
 
-	TP_printk("task:%u@%u status=%d port=%u",
+	TP_printk("task:%d@%d status=%d port=%u",
 		__entry->task_id, __entry->client_id,
 		__entry->status, __entry->port
 	)

Re: [PATCH 2/4] SUNRPC: Tracepoints should store tk_pid and cl_clid as a signed int

[Trond Myklebust]

On Mon, 2021-10-04 at 10:10 -0400, Chuck Lever wrote:
> ida_simple_get() returns a signed integer. Negative values are error
> returns, but this suggests the range of valid client IDs is zero to
> 2^31 - 1.
> 
> tk_pid is currently an unsigned short, so its range is zero to
> 65535.
> 
> For certain special cases, RPC-related tracepoints record a -1 as
> the task ID or the client ID. It's ugly for a trace event to display
> 4 billion in these cases.

Ugh... I emphatically do not like the idea of an identifier field that
is signed, whatever its range of validity may be.

If we're going to change anything, then let's rather turn that
identifier into a fixed size hex field in the traces.

-- 
Trond Myklebust
Linux NFS client maintainer, Hammerspace
trond.myklebust@hammerspace.com

Re: [PATCH 2/4] SUNRPC: Tracepoints should store tk_pid and cl_clid as a signed int

[Chuck Lever III]

> On Oct 4, 2021, at 11:41 AM, Trond Myklebust <trondmy@hammerspace.com> wrote:
> 
> On Mon, 2021-10-04 at 10:10 -0400, Chuck Lever wrote:
>> ida_simple_get() returns a signed integer. Negative values are error
>> returns, but this suggests the range of valid client IDs is zero to
>> 2^31 - 1.
>> 
>> tk_pid is currently an unsigned short, so its range is zero to
>> 65535.
>> 
>> For certain special cases, RPC-related tracepoints record a -1 as
>> the task ID or the client ID. It's ugly for a trace event to display
>> 4 billion in these cases.
> 
> Ugh... I emphatically do not like the idea of an identifier field that
> is signed, whatever its range of validity may be.
> 
> If we're going to change anything, then let's rather turn that
> identifier into a fixed size hex field in the traces.

A fixed-size field might be more legible for eyeballing large
complex traces, so I can do that.

Thanks for having a look!


--
Chuck Lever

[PATCH 3/4] SUNRPC: Per-rpc_clnt task PIDs

[Chuck Lever]

The current range of RPC task PIDs is 0..65535. That's not adequate
for distinguishing tasks across multiple rpc_clnts running high
throughput workloads.

To help relieve this situation and to reduce the bottleneck of
having a single atomic for assigning all RPC task PIDs, assign task
PIDs per rpc_clnt.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/linux/sunrpc/clnt.h |    1 +
 net/sunrpc/sched.c          |   12 ++++++++++--
 2 files changed, 11 insertions(+), 2 deletions(-)

diff --git a/include/linux/sunrpc/clnt.h b/include/linux/sunrpc/clnt.h
index bd22f14c4b19..d5860a000806 100644
--- a/include/linux/sunrpc/clnt.h
+++ b/include/linux/sunrpc/clnt.h
@@ -40,6 +40,7 @@ struct rpc_clnt {
 	int			cl_clid;	/* client id */
 	struct list_head	cl_clients;	/* Global list of clients */
 	struct list_head	cl_tasks;	/* List of tasks */
+	atomic_t		cl_pid;		/* task PID counter */
 	spinlock_t		cl_lock;	/* spinlock */
 	struct rpc_xprt __rcu *	cl_xprt;	/* transport */
 	const struct rpc_procinfo *cl_procinfo;	/* procedure info */
diff --git a/net/sunrpc/sched.c b/net/sunrpc/sched.c
index c045f63d11fa..b3402aeb8f30 100644
--- a/net/sunrpc/sched.c
+++ b/net/sunrpc/sched.c
@@ -277,9 +277,17 @@ static int rpc_wait_bit_killable(struct wait_bit_key *key, int mode)
 #if IS_ENABLED(CONFIG_SUNRPC_DEBUG) || IS_ENABLED(CONFIG_TRACEPOINTS)
 static void rpc_task_set_debuginfo(struct rpc_task *task)
 {
-	static atomic_t rpc_pid;
+	struct rpc_clnt *clnt = task->tk_client;
 
-	task->tk_pid = atomic_inc_return(&rpc_pid);
+	/* Might be a task carrying a reverse-direction operation */
+	if (!clnt) {
+		static atomic_t rpc_pid;
+
+		task->tk_pid = atomic_inc_return(&rpc_pid);
+		return;
+	}
+
+	task->tk_pid = atomic_inc_return(&clnt->cl_pid);
 }
 #else
 static inline void rpc_task_set_debuginfo(struct rpc_task *task)

[PATCH 4/4] NFS: Instrument i_size_write()

[Chuck Lever]

Generate a trace event whenever the NFS client modifies the size of
a file. These new events aid troubleshooting workloads that trigger
races around size updates.

There are four new trace points, all named nfs_size_something so
they are easy to grep for or enable as a group with a single glob.

Size updated on the server:

  kworker/u24:10-194   [010]   369.939174: nfs_size_update:      fileid=00:28:2 fhandle=0x36fbbe51 version=1752899344277980615 cursize=250471 newsize=172083

Server-side size update reported via NFSv3 WCC attributes:

             fsx-1387  [006]   380.760686: nfs_size_wcc:         fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355909932456 cursize=146792 newsize=171216

File has been truncated locally:

             fsx-1387  [007]   369.437421: nfs_size_truncate:    fileid=00:28:2 fhandle=0x36fbbe51 version=1752899231200117272 cursize=215244 newsize=0

File has been extended locally:

             fsx-1387  [007]   369.439213: nfs_size_grow:        fileid=00:28:2 fhandle=0x36fbbe51 version=1752899343704248410 cursize=258048 newsize=262144

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfs/inode.c    |    9 +++------
 fs/nfs/nfstrace.h |   50 ++++++++++++++++++++++++++++++++++++++++++++++++++
 fs/nfs/write.c    |    1 +
 3 files changed, 54 insertions(+), 6 deletions(-)

diff --git a/fs/nfs/inode.c b/fs/nfs/inode.c
index 853213b3a209..7994a3629ccb 100644
--- a/fs/nfs/inode.c
+++ b/fs/nfs/inode.c
@@ -666,6 +666,7 @@ static int nfs_vmtruncate(struct inode * inode, loff_t offset)
 	if (err)
 		goto out;
 
+	trace_nfs_size_truncate(inode, offset);
 	i_size_write(inode, offset);
 	/* Optimisation */
 	if (offset == 0)
@@ -1453,6 +1454,7 @@ static void nfs_wcc_update_inode(struct inode *inode, struct nfs_fattr *fattr)
 			&& (fattr->valid & NFS_ATTR_FATTR_SIZE)
 			&& i_size_read(inode) == nfs_size_to_loff_t(fattr->pre_size)
 			&& !nfs_have_writebacks(inode)) {
+		trace_nfs_size_wcc(inode, fattr->size);
 		i_size_write(inode, nfs_size_to_loff_t(fattr->size));
 	}
 }
@@ -2095,16 +2097,11 @@ static int nfs_update_inode(struct inode *inode, struct nfs_fattr *fattr)
 			/* Do we perhaps have any outstanding writes, or has
 			 * the file grown beyond our last write? */
 			if (!nfs_have_writebacks(inode) || new_isize > cur_isize) {
+				trace_nfs_size_update(inode, new_isize);
 				i_size_write(inode, new_isize);
 				if (!have_writers)
 					invalid |= NFS_INO_INVALID_DATA;
 			}
-			dprintk("NFS: isize change on server for file %s/%ld "
-					"(%Ld to %Ld)\n",
-					inode->i_sb->s_id,
-					inode->i_ino,
-					(long long)cur_isize,
-					(long long)new_isize);
 		}
 		if (new_isize == 0 &&
 		    !(fattr->valid & (NFS_ATTR_FATTR_SPACE_USED |
diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
index 4094e2856cf9..228bdf010eb6 100644
--- a/fs/nfs/nfstrace.h
+++ b/fs/nfs/nfstrace.h
@@ -231,6 +231,56 @@ TRACE_EVENT(nfs_access_exit,
 		)
 );
 
+DECLARE_EVENT_CLASS(nfs_update_size_class,
+		TP_PROTO(
+			const struct inode *inode,
+			loff_t new_size
+		),
+
+		TP_ARGS(inode, new_size),
+
+		TP_STRUCT__entry(
+			__field(dev_t, dev)
+			__field(u32, fhandle)
+			__field(u64, fileid)
+			__field(u64, version)
+			__field(loff_t, cur_size)
+			__field(loff_t, new_size)
+		),
+
+		TP_fast_assign(
+			const struct nfs_inode *nfsi = NFS_I(inode);
+
+			__entry->dev = inode->i_sb->s_dev;
+			__entry->fhandle = nfs_fhandle_hash(&nfsi->fh);
+			__entry->fileid = nfsi->fileid;
+			__entry->version = inode_peek_iversion_raw(inode);
+			__entry->cur_size = i_size_read(inode);
+			__entry->new_size = new_size;
+		),
+
+		TP_printk(
+			"fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu cursize=%lld newsize=%lld",
+			MAJOR(__entry->dev), MINOR(__entry->dev),
+			(unsigned long long)__entry->fileid,
+			__entry->fhandle, __entry->version,
+			__entry->cur_size, __entry->new_size
+		)
+);
+
+#define DEFINE_NFS_UPDATE_SIZE_EVENT(name) \
+	DEFINE_EVENT(nfs_update_size_class, nfs_size_##name, \
+			TP_PROTO( \
+				const struct inode *inode, \
+				loff_t new_size \
+			), \
+			TP_ARGS(inode, new_size))
+
+DEFINE_NFS_UPDATE_SIZE_EVENT(truncate);
+DEFINE_NFS_UPDATE_SIZE_EVENT(wcc);
+DEFINE_NFS_UPDATE_SIZE_EVENT(update);
+DEFINE_NFS_UPDATE_SIZE_EVENT(grow);
+
 #define show_lookup_flags(flags) \
 	__print_flags(flags, "|", \
 			{ LOOKUP_FOLLOW, "FOLLOW" }, \
diff --git a/fs/nfs/write.c b/fs/nfs/write.c
index eae9bf114041..1ded0d232ece 100644
--- a/fs/nfs/write.c
+++ b/fs/nfs/write.c
@@ -288,6 +288,7 @@ static void nfs_grow_file(struct page *page, unsigned int offset, unsigned int c
 	end = page_file_offset(page) + ((loff_t)offset+count);
 	if (i_size >= end)
 		goto out;
+	trace_nfs_size_grow(inode, end);
 	i_size_write(inode, end);
 	NFS_I(inode)->cache_validity &= ~NFS_INO_INVALID_SIZE;
 	nfs_inc_stats(inode, NFSIOS_EXTENDWRITE);

Re: [PATCH 0/4] A collection of NFS client tracepoint patches

[Trond Myklebust]

On Mon, 2021-10-04 at 10:09 -0400, Chuck Lever wrote:
> Hi-
> 
> This series proposes a small handful of tracepoint-related changes.
> 
> The first patch is clean-up.
> 
> The second and third patches are part of the ongoing effort to
> replace dprintk with tracepoints.
> 
> The last patch adds some tracepoints I found useful while diagnosing
> the recent NFSv3 fsx failures.
> 
> ---
> 
> Chuck Lever (4):
>       NFS: Remove unnecessary TRACE_DEFINE_ENUM()s
>       SUNRPC: Tracepoints should store tk_pid and cl_clid as a signed
> int
>       SUNRPC: Per-rpc_clnt task PIDs
>       NFS: Instrument i_size_write()

I'm fine with applying patches 1, 3 and 4 for now, but I have strong
reservations about patch 2.

-- 
Trond Myklebust
Linux NFS client maintainer, Hammerspace
trond.myklebust@hammerspace.com