[PATCH 0/2] SUNRPC: Added Tracing Points

[PATCH 0/2] SUNRPC: Added Tracing Points

[Steve Dickson]

This series combines the trace points that Trond
posted, than now handle strings properly, and the
trace points I posted, in which I integrated the 
review comments.

All these trace point were tested/enable through the
debugfs interface as well as being called from a 
systemtab prob.

Steve Dickson (1):
  SUNRPC: Adding status trace points

Trond Myklebust (1):
  SUNRPC: Add trace events to the sunrpc subsystem

 include/linux/sunrpc/sched.h  |    2 +-
 include/trace/events/sunrpc.h |  177 +++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/clnt.c             |    6 +-
 net/sunrpc/sched.c            |   12 +++
 4 files changed, 195 insertions(+), 2 deletions(-)
 create mode 100644 include/trace/events/sunrpc.h

[PATCH v3 1/2] SUNRPC: Add trace events to the sunrpc subsystem

[Steve Dickson]

From: Trond Myklebust <Trond.Myklebust@netapp.com>

Add declarations to allow tracing of RPC call creation, running,
sleeping, and destruction.

Signed-off-by: Trond Myklebust <Trond.Myklebust@netapp.com>
Signed-off-by: Steve Dickson <steved@redhat.com>
---
 include/linux/sunrpc/sched.h  |    2 +-
 include/trace/events/sunrpc.h |  124 +++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/sched.c            |   12 ++++
 3 files changed, 137 insertions(+), 1 deletions(-)
 create mode 100644 include/trace/events/sunrpc.h

diff --git a/include/linux/sunrpc/sched.h b/include/linux/sunrpc/sched.h
index fe2d8e6..855cb43 100644
--- a/include/linux/sunrpc/sched.h
+++ b/include/linux/sunrpc/sched.h
@@ -263,7 +263,7 @@ static inline int rpc_task_has_priority(struct rpc_task *task, unsigned char pri
 }
 
 #ifdef RPC_DEBUG
-static inline const char * rpc_qname(struct rpc_wait_queue *q)
+static inline const char * rpc_qname(const struct rpc_wait_queue *q)
 {
 	return ((q && q->name) ? q->name : "unknown");
 }
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
new file mode 100644
index 0000000..2f82de9
--- /dev/null
+++ b/include/trace/events/sunrpc.h
@@ -0,0 +1,124 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM sunrpc
+
+#if !defined(_TRACE_SUNRPC_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_SUNRPC_H
+
+#include <linux/sunrpc/sched.h>
+#include <linux/sunrpc/clnt.h>
+#include <linux/tracepoint.h>
+
+DECLARE_EVENT_CLASS(rpc_task_running,
+
+	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action),
+
+	TP_ARGS(clnt, task, action),
+
+	TP_STRUCT__entry(
+		__field(const struct rpc_clnt *, clnt)
+		__field(const struct rpc_task *, task)
+		__field(const void *, action)
+		__field(unsigned long, runstate)
+		__field(int, status)
+		__field(unsigned short, flags)
+		),
+
+	TP_fast_assign(
+		__entry->clnt = clnt;
+		__entry->task = task;
+		__entry->action = action;
+		__entry->runstate = task->tk_runstate;
+		__entry->status = task->tk_status;
+		__entry->flags = task->tk_flags;
+		),
+
+	TP_printk("task:%p@%p flags=%4.4x state=%4.4lx status=%d action=%pf",
+		__entry->task,
+		__entry->clnt,
+		__entry->flags,
+		__entry->runstate,
+		__entry->status,
+		__entry->action
+		)
+);
+
+DEFINE_EVENT(rpc_task_running, rpc_task_begin,
+
+	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action),
+
+	TP_ARGS(clnt, task, action)
+
+);
+
+DEFINE_EVENT(rpc_task_running, rpc_task_run_action,
+
+	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action),
+
+	TP_ARGS(clnt, task, action)
+
+);
+
+DEFINE_EVENT(rpc_task_running, rpc_task_complete,
+
+	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action),
+
+	TP_ARGS(clnt, task, action)
+
+);
+
+DECLARE_EVENT_CLASS(rpc_task_queued,
+
+	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const struct rpc_wait_queue *q),
+
+	TP_ARGS(clnt, task, q),
+
+	TP_STRUCT__entry(
+		__field(const struct rpc_clnt *, clnt)
+		__field(const struct rpc_task *, task)
+		__string(    qname, rpc_qname(q))
+		__field(unsigned long, timeout)
+		__field(unsigned long, runstate)
+		__field(int, status)
+		__field(unsigned short, flags)
+		),
+
+	TP_fast_assign(
+		__entry->clnt = clnt;
+		__entry->task = task;
+		__assign_str(qname, rpc_qname(q));
+		__entry->timeout = task->tk_timeout;
+		__entry->runstate = task->tk_runstate;
+		__entry->status = task->tk_status;
+		__entry->flags = task->tk_flags;
+		),
+
+	TP_printk("task:%p@%p flags=%4.4x state=%4.4lx status=%d timeout=%lu queue=%s",
+		__entry->task,
+		__entry->clnt,
+		__entry->flags,
+		__entry->runstate,
+		__entry->status,
+		__entry->timeout,
+		__get_str(qname)
+		)
+);
+
+DEFINE_EVENT(rpc_task_queued, rpc_task_sleep,
+
+	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const struct rpc_wait_queue *q),
+
+	TP_ARGS(clnt, task, q)
+
+);
+
+DEFINE_EVENT(rpc_task_queued, rpc_task_wakeup,
+
+	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const struct rpc_wait_queue *q),
+
+	TP_ARGS(clnt, task, q)
+
+);
+
+#endif /* _TRACE_SUNRPC_H */
+
+#include <trace/define_trace.h>
diff --git a/net/sunrpc/sched.c b/net/sunrpc/sched.c
index ec94a55..d77c41a 100644
--- a/net/sunrpc/sched.c
+++ b/net/sunrpc/sched.c
@@ -27,6 +27,9 @@
 #define RPCDBG_FACILITY		RPCDBG_SCHED
 #endif
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/sunrpc.h>
+
 /*
  * RPC slabs and memory pools
  */
@@ -246,6 +249,8 @@ static inline void rpc_task_set_debuginfo(struct rpc_task *task)
 
 static void rpc_set_active(struct rpc_task *task)
 {
+	trace_rpc_task_begin(task->tk_client, task, NULL);
+
 	rpc_task_set_debuginfo(task);
 	set_bit(RPC_TASK_ACTIVE, &task->tk_runstate);
 }
@@ -262,6 +267,8 @@ static int rpc_complete_task(struct rpc_task *task)
 	unsigned long flags;
 	int ret;
 
+	trace_rpc_task_complete(task->tk_client, task, NULL);
+
 	spin_lock_irqsave(&wq->lock, flags);
 	clear_bit(RPC_TASK_ACTIVE, &task->tk_runstate);
 	ret = atomic_dec_and_test(&task->tk_count);
@@ -317,6 +324,8 @@ static void __rpc_sleep_on(struct rpc_wait_queue *q, struct rpc_task *task,
 	dprintk("RPC: %5u sleep_on(queue \"%s\" time %lu)\n",
 			task->tk_pid, rpc_qname(q), jiffies);
 
+	trace_rpc_task_sleep(task->tk_client, task, q);
+
 	__rpc_add_wait_queue(q, task);
 
 	BUG_ON(task->tk_callback != NULL);
@@ -357,6 +366,8 @@ static void __rpc_do_wake_up_task(struct rpc_wait_queue *queue, struct rpc_task
 		return;
 	}
 
+	trace_rpc_task_wakeup(task->tk_client, task, queue);
+
 	__rpc_remove_wait_queue(queue, task);
 
 	rpc_make_runnable(task);
@@ -634,6 +645,7 @@ static void __rpc_execute(struct rpc_task *task)
 			if (do_action == NULL)
 				break;
 		}
+		trace_rpc_task_run_action(task->tk_client, task, task->tk_action);
 		do_action(task);
 
 		/*
-- 
1.7.1

[PATCH v2 2/2] SUNRPC: Adding status trace points

[Steve Dickson]

This patch adds three trace points to the status routines
in the sunrpc state machine.

The goal of these trace points is to give an Admin
the ability to check on binding status or connection
status to see if there is a potential problem.

Signed-off-by: Steve Dickson <steved@redhat.com>
---
 include/trace/events/sunrpc.h |   53 +++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/clnt.c             |    6 ++++-
 2 files changed, 58 insertions(+), 1 deletions(-)

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 2f82de9..abcf45d 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -8,6 +8,59 @@
 #include <linux/sunrpc/clnt.h>
 #include <linux/tracepoint.h>
 
+DECLARE_EVENT_CLASS(rpc_task_status,
+
+	TP_PROTO(struct rpc_task *task),
+
+	TP_ARGS(task),
+
+	TP_STRUCT__entry(
+		__field(const struct rpc_task *, task)
+		__field(const struct rpc_clnt *, clnt)
+		__field(int, status)
+	),
+
+	TP_fast_assign(
+		__entry->task = task;
+		__entry->clnt = task->tk_client;
+		__entry->status = task->tk_status;
+	),
+
+	TP_printk("task:%p@%p, status %d",__entry->task, __entry->clnt, __entry->status)
+);
+
+DEFINE_EVENT(rpc_task_status, rpc_call_status,
+	TP_PROTO(struct rpc_task *task), 
+
+	TP_ARGS(task)
+);
+
+DEFINE_EVENT(rpc_task_status, rpc_bind_status,
+	TP_PROTO(struct rpc_task *task), 
+
+	TP_ARGS(task)
+);
+
+TRACE_EVENT(rpc_connect_status,
+	TP_PROTO(struct rpc_task *task, int status),
+
+	TP_ARGS(task, status),
+
+	TP_STRUCT__entry(
+		__field(const struct rpc_task *, task)
+		__field(const struct rpc_clnt *, clnt)
+		__field(int, status)
+	),
+
+	TP_fast_assign(
+		__entry->task = task;
+		__entry->clnt = task->tk_client;
+		__entry->status = status;
+	),
+
+	TP_printk("task:%p@%p, status %d",__entry->task, __entry->clnt, __entry->status)
+);
+
 DECLARE_EVENT_CLASS(rpc_task_running,
 
 	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action),
diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c
index b783f2f..89ea1f9 100644
--- a/net/sunrpc/clnt.c
+++ b/net/sunrpc/clnt.c
@@ -38,6 +38,8 @@
 #include <linux/sunrpc/rpc_pipe_fs.h>
 #include <linux/sunrpc/metrics.h>
 #include <linux/sunrpc/bc_xprt.h>
+#include <trace/events/sunrpc.h>
+
 
 #include "sunrpc.h"
 
@@ -57,7 +59,6 @@ static DEFINE_SPINLOCK(rpc_client_lock);
 
 static DECLARE_WAIT_QUEUE_HEAD(destroy_wait);
 
-
 static void	call_start(struct rpc_task *task);
 static void	call_reserve(struct rpc_task *task);
 static void	call_reserveresult(struct rpc_task *task);
@@ -1159,6 +1160,7 @@ call_bind_status(struct rpc_task *task)
 		return;
 	}
 
+	trace_rpc_bind_status(task);
 	switch (task->tk_status) {
 	case -ENOMEM:
 		dprintk("RPC: %5u rpcbind out of memory\n", task->tk_pid);
@@ -1258,6 +1260,7 @@ call_connect_status(struct rpc_task *task)
 		return;
 	}
 
+	trace_rpc_connect_status(task, status);
 	switch (status) {
 		/* if soft mounted, test if we've timed out */
 	case -ETIMEDOUT:
@@ -1446,6 +1449,7 @@ call_status(struct rpc_task *task)
 		return;
 	}
 
+	trace_rpc_call_status(task);
 	task->tk_status = 0;
 	switch(status) {
 	case -EHOSTDOWN:
-- 
1.7.1

[PATCH v3 1/2] SUNRPC: Add trace events to the sunrpc subsystem

[Steve Dickson]

From: Trond Myklebust <Trond.Myklebust@netapp.com>

Add declarations to allow tracing of RPC call creation, running,
sleeping, and destruction.

Signed-off-by: Trond Myklebust <Trond.Myklebust@netapp.com>
Signed-off-by: Steve Dickson <steved@redhat.com>
---
 include/linux/sunrpc/sched.h  |    2 +-
 include/trace/events/sunrpc.h |  124 +++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/sched.c            |   12 ++++
 3 files changed, 137 insertions(+), 1 deletions(-)
 create mode 100644 include/trace/events/sunrpc.h

diff --git a/include/linux/sunrpc/sched.h b/include/linux/sunrpc/sched.h
index e775689..c600035 100644
--- a/include/linux/sunrpc/sched.h
+++ b/include/linux/sunrpc/sched.h
@@ -267,7 +267,7 @@ static inline int rpc_task_has_priority(struct rpc_task *task, unsigned char pri
 }
 
 #ifdef RPC_DEBUG
-static inline const char * rpc_qname(struct rpc_wait_queue *q)
+static inline const char * rpc_qname(const struct rpc_wait_queue *q)
 {
 	return ((q && q->name) ? q->name : "unknown");
 }
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
new file mode 100644
index 0000000..2f82de9
--- /dev/null
+++ b/include/trace/events/sunrpc.h
@@ -0,0 +1,124 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM sunrpc
+
+#if !defined(_TRACE_SUNRPC_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_SUNRPC_H
+
+#include <linux/sunrpc/sched.h>
+#include <linux/sunrpc/clnt.h>
+#include <linux/tracepoint.h>
+
+DECLARE_EVENT_CLASS(rpc_task_running,
+
+	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action),
+
+	TP_ARGS(clnt, task, action),
+
+	TP_STRUCT__entry(
+		__field(const struct rpc_clnt *, clnt)
+		__field(const struct rpc_task *, task)
+		__field(const void *, action)
+		__field(unsigned long, runstate)
+		__field(int, status)
+		__field(unsigned short, flags)
+		),
+
+	TP_fast_assign(
+		__entry->clnt = clnt;
+		__entry->task = task;
+		__entry->action = action;
+		__entry->runstate = task->tk_runstate;
+		__entry->status = task->tk_status;
+		__entry->flags = task->tk_flags;
+		),
+
+	TP_printk("task:%p@%p flags=%4.4x state=%4.4lx status=%d action=%pf",
+		__entry->task,
+		__entry->clnt,
+		__entry->flags,
+		__entry->runstate,
+		__entry->status,
+		__entry->action
+		)
+);
+
+DEFINE_EVENT(rpc_task_running, rpc_task_begin,
+
+	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action),
+
+	TP_ARGS(clnt, task, action)
+
+);
+
+DEFINE_EVENT(rpc_task_running, rpc_task_run_action,
+
+	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action),
+
+	TP_ARGS(clnt, task, action)
+
+);
+
+DEFINE_EVENT(rpc_task_running, rpc_task_complete,
+
+	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action),
+
+	TP_ARGS(clnt, task, action)
+
+);
+
+DECLARE_EVENT_CLASS(rpc_task_queued,
+
+	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const struct rpc_wait_queue *q),
+
+	TP_ARGS(clnt, task, q),
+
+	TP_STRUCT__entry(
+		__field(const struct rpc_clnt *, clnt)
+		__field(const struct rpc_task *, task)
+		__string(    qname, rpc_qname(q))
+		__field(unsigned long, timeout)
+		__field(unsigned long, runstate)
+		__field(int, status)
+		__field(unsigned short, flags)
+		),
+
+	TP_fast_assign(
+		__entry->clnt = clnt;
+		__entry->task = task;
+		__assign_str(qname, rpc_qname(q));
+		__entry->timeout = task->tk_timeout;
+		__entry->runstate = task->tk_runstate;
+		__entry->status = task->tk_status;
+		__entry->flags = task->tk_flags;
+		),
+
+	TP_printk("task:%p@%p flags=%4.4x state=%4.4lx status=%d timeout=%lu queue=%s",
+		__entry->task,
+		__entry->clnt,
+		__entry->flags,
+		__entry->runstate,
+		__entry->status,
+		__entry->timeout,
+		__get_str(qname)
+		)
+);
+
+DEFINE_EVENT(rpc_task_queued, rpc_task_sleep,
+
+	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const struct rpc_wait_queue *q),
+
+	TP_ARGS(clnt, task, q)
+
+);
+
+DEFINE_EVENT(rpc_task_queued, rpc_task_wakeup,
+
+	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const struct rpc_wait_queue *q),
+
+	TP_ARGS(clnt, task, q)
+
+);
+
+#endif /* _TRACE_SUNRPC_H */
+
+#include <trace/define_trace.h>
diff --git a/net/sunrpc/sched.c b/net/sunrpc/sched.c
index 3341d89..2ba5739 100644
--- a/net/sunrpc/sched.c
+++ b/net/sunrpc/sched.c
@@ -28,6 +28,9 @@
 #define RPCDBG_FACILITY		RPCDBG_SCHED
 #endif
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/sunrpc.h>
+
 /*
  * RPC slabs and memory pools
  */
@@ -251,6 +254,8 @@ static inline void rpc_task_set_debuginfo(struct rpc_task *task)
 
 static void rpc_set_active(struct rpc_task *task)
 {
+	trace_rpc_task_begin(task->tk_client, task, NULL);
+
 	rpc_task_set_debuginfo(task);
 	set_bit(RPC_TASK_ACTIVE, &task->tk_runstate);
 }
@@ -267,6 +272,8 @@ static int rpc_complete_task(struct rpc_task *task)
 	unsigned long flags;
 	int ret;
 
+	trace_rpc_task_complete(task->tk_client, task, NULL);
+
 	spin_lock_irqsave(&wq->lock, flags);
 	clear_bit(RPC_TASK_ACTIVE, &task->tk_runstate);
 	ret = atomic_dec_and_test(&task->tk_count);
@@ -324,6 +331,8 @@ static void __rpc_sleep_on_priority(struct rpc_wait_queue *q,
 	dprintk("RPC: %5u sleep_on(queue \"%s\" time %lu)\n",
 			task->tk_pid, rpc_qname(q), jiffies);
 
+	trace_rpc_task_sleep(task->tk_client, task, q);
+
 	__rpc_add_wait_queue(q, task, queue_priority);
 
 	BUG_ON(task->tk_callback != NULL);
@@ -378,6 +387,8 @@ static void __rpc_do_wake_up_task(struct rpc_wait_queue *queue, struct rpc_task
 		return;
 	}
 
+	trace_rpc_task_wakeup(task->tk_client, task, queue);
+
 	__rpc_remove_wait_queue(queue, task);
 
 	rpc_make_runnable(task);
@@ -677,6 +688,7 @@ static void __rpc_execute(struct rpc_task *task)
 			if (do_action == NULL)
 				break;
 		}
+		trace_rpc_task_run_action(task->tk_client, task, task->tk_action);
 		do_action(task);
 
 		/*
-- 
1.7.7.5

Re: [PATCH v3 1/2] SUNRPC: Add trace events to the sunrpc subsystem

[Christoph Hellwig]

> +	TP_STRUCT__entry(
> +		__field(const struct rpc_clnt *, clnt)
> +		__field(const struct rpc_task *, task)
> +		__field(const void *, action)
> +		__field(unsigned long, runstate)
> +		__field(int, status)
> +		__field(unsigned short, flags)

Storing pointers in the trace buffer is not safe for reuse later,
and just printing the pointer values isn't overly useful either.  Please
redesign these tracepoint to be a bit more useful.

Re: [PATCH v3 1/2] SUNRPC: Add trace events to the sunrpc subsystem

[Myklebust, Trond]

T24gTW9uLCAyMDEyLTAyLTA2IGF0IDEyOjQ3IC0wNTAwLCBDaHJpc3RvcGggSGVsbHdpZyB3cm90
ZToNCj4gPiArCVRQX1NUUlVDVF9fZW50cnkoDQo+ID4gKwkJX19maWVsZChjb25zdCBzdHJ1Y3Qg
cnBjX2NsbnQgKiwgY2xudCkNCj4gPiArCQlfX2ZpZWxkKGNvbnN0IHN0cnVjdCBycGNfdGFzayAq
LCB0YXNrKQ0KPiA+ICsJCV9fZmllbGQoY29uc3Qgdm9pZCAqLCBhY3Rpb24pDQo+ID4gKwkJX19m
aWVsZCh1bnNpZ25lZCBsb25nLCBydW5zdGF0ZSkNCj4gPiArCQlfX2ZpZWxkKGludCwgc3RhdHVz
KQ0KPiA+ICsJCV9fZmllbGQodW5zaWduZWQgc2hvcnQsIGZsYWdzKQ0KPiANCj4gU3RvcmluZyBw
b2ludGVycyBpbiB0aGUgdHJhY2UgYnVmZmVyIGlzIG5vdCBzYWZlIGZvciByZXVzZSBsYXRlciwN
Cj4gYW5kIGp1c3QgcHJpbnRpbmcgdGhlIHBvaW50ZXIgdmFsdWVzIGlzbid0IG92ZXJseSB1c2Vm
dWwgZWl0aGVyLiAgUGxlYXNlDQo+IHJlZGVzaWduIHRoZXNlIHRyYWNlcG9pbnQgdG8gYmUgYSBi
aXQgbW9yZSB1c2VmdWwuDQoNClRoZSBwb2ludGVyIHZhbHVlcyBhcmUganVzdCB1c2VkIGFzIGxh
YmVscyB0byBpZGVudGlmeSB0aGUgcnBjX3Rhc2sgYW5kDQpycGNfY2xudCB0aGF0IGlzIGJlaW5n
IHRyYWNrZWQuIFRoZSBtYWluIGluZm9ybWF0aW9uIGlzIGNhcnJpZWQgaW4gdGhlDQpydW5zdGF0
ZSwgc3RhdHVzIGFuZCBmbGFncywgd2hpY2ggYXJlIHN0b3JlZCBhcy1pcy4NCg0KDQo=