For each running RPC task, rpc_show_tasks displays the hex address of the
call_foo function that the task is running. To make debugging slightly
nicer, let's display the call_foo function name instead.
Sample output:
-pid- flgs status -client- --rqstp- -timeout ---ops--
27915 0001 0 ee84a460 eedf00d0 60000 f8fa677c nfs3 COMMIT act:status wq:xprt_pending
27918 0080 0 ee84a460 eedf0000 60000 f8d527a8 nfs3 SETATTR act:status wq:xprt_pending
-pid- flgs status -client- --rqstp- -timeout ---ops--
60859 0001 0 ee84a460 eedf00d0 0 f8fa66c8 nfs3 READ act:status
60860 0080 0 ee84a460 eedf0000 0 f8d527a8 nfs3 GETATTR act:status
Signed-off-by: Chuck Lever <[email protected]>
---
include/linux/sunrpc/sched.h | 1 +
net/sunrpc/clnt.c | 52 +++++++++++++++++++++++++++++++++++++++---
net/sunrpc/sched.c | 2 +-
3 files changed, 50 insertions(+), 5 deletions(-)
diff --git a/include/linux/sunrpc/sched.h b/include/linux/sunrpc/sched.h
index d1a5c8c..108342e 100644
--- a/include/linux/sunrpc/sched.h
+++ b/include/linux/sunrpc/sched.h
@@ -212,6 +212,7 @@ struct rpc_wait_queue {
struct rpc_task *rpc_new_task(const struct rpc_task_setup *);
struct rpc_task *rpc_run_task(const struct rpc_task_setup *);
void rpc_put_task(struct rpc_task *);
+void rpc_prepare_task(struct rpc_task *);
void rpc_exit_task(struct rpc_task *);
void rpc_release_calldata(const struct rpc_call_ops *, void *);
void rpc_killall_tasks(struct rpc_clnt *);
diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c
index c33d727..ec9c072 100644
--- a/net/sunrpc/clnt.c
+++ b/net/sunrpc/clnt.c
@@ -1510,24 +1510,68 @@ struct rpc_task *rpc_call_null(struct rpc_clnt *clnt, struct rpc_cred *cred, int
EXPORT_SYMBOL_GPL(rpc_call_null);
#ifdef RPC_DEBUG
+/*
+ * To make it easier to tell what action each running RPC task
+ * is executing, use a table to map the content of tk_action to
+ * a human-readable name. This uses a little extra memory, but
+ * causes no additional run-time overhead per RPC request.
+ */
+typedef void (*rpc_task_action)(struct rpc_task *);
+
+static struct {
+ rpc_task_action action;
+ const char *name;
+} rpc_action_table[] = {
+ { rpc_prepare_task, "prepare" },
+ { call_start, "start" },
+ { call_reserve, "reserve" },
+ { call_reserveresult, "reserveresult" },
+ { call_allocate, "allocate" },
+ { call_bind, "bind" },
+ { call_bind_status, "bindstatus" },
+ { call_connect, "connect" },
+ { call_connect_status, "connectstatus" },
+ { call_transmit, "transmit" },
+ { call_transmit_status, "transmitstatus" },
+ { call_status, "status" },
+ { call_timeout, "timeout" },
+ { call_decode, "decode" },
+ { call_refresh, "refresh" },
+ { call_refreshresult, "refreshresult" },
+ { rpc_exit_task, "exit" },
+ { NULL, "null" },
+};
+
+static const char *rpc_show_action(rpc_task_action action)
+{
+ unsigned int i;
+
+ for (i = 0; i <= ARRAY_SIZE(rpc_action_table); i++)
+ if (rpc_action_table[i].action == action)
+ return rpc_action_table[i].name;
+
+ return "unknown";
+}
+
static void rpc_show_header(void)
{
printk(KERN_INFO "-pid- flgs status -client- --rqstp- "
- "-timeout -action- ---ops--\n");
+ "-timeout ---ops--\n");
}
static void rpc_show_task(const struct rpc_clnt *clnt,
const struct rpc_task *task)
{
- printk(KERN_INFO "%5u %04x %6d %8p %8p %8ld %8p %8p %s%u",
+ printk(KERN_INFO "%5u %04x %6d %8p %8p %8ld %8p %s%u",
task->tk_pid, task->tk_flags, task->tk_status,
clnt, task->tk_rqstp, task->tk_timeout,
- task->tk_action, task->tk_ops, clnt->cl_protname,
- clnt->cl_vers);
+ task->tk_ops, clnt->cl_protname, clnt->cl_vers);
if (task->tk_msg.rpc_proc)
printk(KERN_CONT " %s", task->tk_msg.rpc_proc->p_name);
+ printk(KERN_CONT " act:%s", rpc_show_action(task->tk_action));
+
if (RPC_IS_QUEUED(task))
printk(KERN_CONT " wq:%s", rpc_qname(task->tk_waitqueue));
diff --git a/net/sunrpc/sched.c b/net/sunrpc/sched.c
index 6eab9bf..9aa9948 100644
--- a/net/sunrpc/sched.c
+++ b/net/sunrpc/sched.c
@@ -574,7 +574,7 @@ EXPORT_SYMBOL_GPL(rpc_delay);
/*
* Helper to call task->tk_ops->rpc_call_prepare
*/
-static void rpc_prepare_task(struct rpc_task *task)
+void rpc_prepare_task(struct rpc_task *task)
{
lock_kernel();
task->tk_ops->rpc_call_prepare(task, task->tk_calldata);
On Tue, 2008-05-20 at 16:30 -0400, Chuck Lever wrote:
> For each running RPC task, rpc_show_tasks displays the hex address of=
the
> call_foo function that the task is running. To make debugging slight=
ly
> nicer, let's display the call_foo function name instead.
>=20
> Sample output:
>=20
> -pid- flgs status -client- --rqstp- -timeout ---ops--
> 27915 0001 0 ee84a460 eedf00d0 60000 f8fa677c nfs3 COMMIT ac=
t:status wq:xprt_pending
> 27918 0080 0 ee84a460 eedf0000 60000 f8d527a8 nfs3 SETATTR a=
ct:status wq:xprt_pending
>=20
> -pid- flgs status -client- --rqstp- -timeout ---ops--
> 60859 0001 0 ee84a460 eedf00d0 0 f8fa66c8 nfs3 READ act:=
status
> 60860 0080 0 ee84a460 eedf0000 0 f8d527a8 nfs3 GETATTR a=
ct:status
>=20
>=20
> Signed-off-by: Chuck Lever <[email protected]>
> ---
>=20
> include/linux/sunrpc/sched.h | 1 +
> net/sunrpc/clnt.c | 52 ++++++++++++++++++++++++++++++++=
+++++++---
> net/sunrpc/sched.c | 2 +-
> 3 files changed, 50 insertions(+), 5 deletions(-)
>=20
>=20
> diff --git a/include/linux/sunrpc/sched.h b/include/linux/sunrpc/sche=
d.h
> index d1a5c8c..108342e 100644
> --- a/include/linux/sunrpc/sched.h
> +++ b/include/linux/sunrpc/sched.h
> @@ -212,6 +212,7 @@ struct rpc_wait_queue {
> struct rpc_task *rpc_new_task(const struct rpc_task_setup *);
> struct rpc_task *rpc_run_task(const struct rpc_task_setup *);
> void rpc_put_task(struct rpc_task *);
> +void rpc_prepare_task(struct rpc_task *);
> void rpc_exit_task(struct rpc_task *);
> void rpc_release_calldata(const struct rpc_call_ops *, void *);
> void rpc_killall_tasks(struct rpc_clnt *);
> diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c
> index c33d727..ec9c072 100644
> --- a/net/sunrpc/clnt.c
> +++ b/net/sunrpc/clnt.c
> @@ -1510,24 +1510,68 @@ struct rpc_task *rpc_call_null(struct rpc_cln=
t *clnt, struct rpc_cred *cred, int
> EXPORT_SYMBOL_GPL(rpc_call_null);
> =20
> #ifdef RPC_DEBUG
> +/*
> + * To make it easier to tell what action each running RPC task
> + * is executing, use a table to map the content of tk_action to
> + * a human-readable name. This uses a little extra memory, but
> + * causes no additional run-time overhead per RPC request.
> + */
> +typedef void (*rpc_task_action)(struct rpc_task *);
> +
> +static struct {
> + rpc_task_action action;
> + const char *name;
> +} rpc_action_table[] =3D {
> + { rpc_prepare_task, "prepare" },
> + { call_start, "start" },
> + { call_reserve, "reserve" },
> + { call_reserveresult, "reserveresult" },
> + { call_allocate, "allocate" },
> + { call_bind, "bind" },
> + { call_bind_status, "bindstatus" },
> + { call_connect, "connect" },
> + { call_connect_status, "connectstatus" },
> + { call_transmit, "transmit" },
> + { call_transmit_status, "transmitstatus" },
> + { call_status, "status" },
> + { call_timeout, "timeout" },
> + { call_decode, "decode" },
> + { call_refresh, "refresh" },
> + { call_refreshresult, "refreshresult" },
> + { rpc_exit_task, "exit" },
> + { NULL, "null" },
> +};
>
> +
> +static const char *rpc_show_action(rpc_task_action action)
> +{
> + unsigned int i;
> +
> + for (i =3D 0; i <=3D ARRAY_SIZE(rpc_action_table); i++)
> + if (rpc_action_table[i].action =3D=3D action)
> + return rpc_action_table[i].name;
> +
> + return "unknown";
> +}
=EF=BB=BF
NACK. Maintaining tables like the above in the long run is a nightmare.
What's more, by eliminating the printout of the actual pointer you are
potentially replacing useful information that could otherwise easily be
looked up using /proc/kallsyms with "unknown".
The above translation could easily be done using a simple script in
userspace instead.
--=20
Trond Myklebust
Linux NFS client maintainer
NetApp
[email protected]
http://www.netapp.com
On May 20, 2008, at 5:11 PM, Trond Myklebust wrote:
> On Tue, 2008-05-20 at 16:30 -0400, Chuck Lever wrote:
>> For each running RPC task, rpc_show_tasks displays the hex address
>> of the
>> call_foo function that the task is running. To make debugging
>> slightly
>> nicer, let's display the call_foo function name instead.
>>
>> Sample output:
>>
>> -pid- flgs status -client- --rqstp- -timeout ---ops--
>> 27915 0001 0 ee84a460 eedf00d0 60000 f8fa677c nfs3 COMMIT
>> act:status wq:xprt_pending
>> 27918 0080 0 ee84a460 eedf0000 60000 f8d527a8 nfs3 SETATTR
>> act:status wq:xprt_pending
>>
>> -pid- flgs status -client- --rqstp- -timeout ---ops--
>> 60859 0001 0 ee84a460 eedf00d0 0 f8fa66c8 nfs3 READ
>> act:status
>> 60860 0080 0 ee84a460 eedf0000 0 f8d527a8 nfs3 GETATTR
>> act:status
>>
>>
>> Signed-off-by: Chuck Lever <[email protected]>
>> ---
>>
>> include/linux/sunrpc/sched.h | 1 +
>> net/sunrpc/clnt.c | 52 ++++++++++++++++++++++++++++++++
>> +++++++---
>> net/sunrpc/sched.c | 2 +-
>> 3 files changed, 50 insertions(+), 5 deletions(-)
>>
>>
>> diff --git a/include/linux/sunrpc/sched.h b/include/linux/sunrpc/
>> sched.h
>> index d1a5c8c..108342e 100644
>> --- a/include/linux/sunrpc/sched.h
>> +++ b/include/linux/sunrpc/sched.h
>> @@ -212,6 +212,7 @@ struct rpc_wait_queue {
>> struct rpc_task *rpc_new_task(const struct rpc_task_setup *);
>> struct rpc_task *rpc_run_task(const struct rpc_task_setup *);
>> void rpc_put_task(struct rpc_task *);
>> +void rpc_prepare_task(struct rpc_task *);
>> void rpc_exit_task(struct rpc_task *);
>> void rpc_release_calldata(const struct rpc_call_ops *, void *);
>> void rpc_killall_tasks(struct rpc_clnt *);
>> diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c
>> index c33d727..ec9c072 100644
>> --- a/net/sunrpc/clnt.c
>> +++ b/net/sunrpc/clnt.c
>> @@ -1510,24 +1510,68 @@ struct rpc_task *rpc_call_null(struct
>> rpc_clnt *clnt, struct rpc_cred *cred, int
>> EXPORT_SYMBOL_GPL(rpc_call_null);
>>
>> #ifdef RPC_DEBUG
>> +/*
>> + * To make it easier to tell what action each running RPC task
>> + * is executing, use a table to map the content of tk_action to
>> + * a human-readable name. This uses a little extra memory, but
>> + * causes no additional run-time overhead per RPC request.
>> + */
>> +typedef void (*rpc_task_action)(struct rpc_task *);
>> +
>> +static struct {
>> + rpc_task_action action;
>> + const char *name;
>> +} rpc_action_table[] = {
>> + { rpc_prepare_task, "prepare" },
>> + { call_start, "start" },
>> + { call_reserve, "reserve" },
>> + { call_reserveresult, "reserveresult" },
>> + { call_allocate, "allocate" },
>> + { call_bind, "bind" },
>> + { call_bind_status, "bindstatus" },
>> + { call_connect, "connect" },
>> + { call_connect_status, "connectstatus" },
>> + { call_transmit, "transmit" },
>> + { call_transmit_status, "transmitstatus" },
>> + { call_status, "status" },
>> + { call_timeout, "timeout" },
>> + { call_decode, "decode" },
>> + { call_refresh, "refresh" },
>> + { call_refreshresult, "refreshresult" },
>> + { rpc_exit_task, "exit" },
>> + { NULL, "null" },
>> +};
>>
>> +
>> +static const char *rpc_show_action(rpc_task_action action)
>> +{
>> + unsigned int i;
>> +
>> + for (i = 0; i <= ARRAY_SIZE(rpc_action_table); i++)
>> + if (rpc_action_table[i].action == action)
>> + return rpc_action_table[i].name;
>> +
>> + return "unknown";
>> +}
>
>
> NACK. Maintaining tables like the above in the long run is a
> nightmare.
> What's more, by eliminating the printout of the actual pointer you are
> potentially replacing useful information that could otherwise easily
> be
> looked up using /proc/kallsyms with "unknown".
> The above translation could easily be done using a simple script in
> userspace instead.
Except when you don't have access to the kernel image and modules
where the dump was generated. Why would I want to run a script to do
this, when Oops output already displays symbolic function addresses in
a callback trace?
We can drop this one for now. Please let me know about the
disposition of the other seven.
--
Chuck Lever
chuck[dot]lever[at]oracle[dot]com
On Tue, 2008-05-20 at 17:37 -0400, Chuck Lever wrote:
> Except when you don't have access to the kernel image and modules
> where the dump was generated. Why would I want to run a script to do
> this, when Oops output already displays symbolic function addresses in
> a callback trace?
If you can generate the names in the same way that the Oops output does
(i.e. without having to maintain a table of function names), then I
withdraw my opposition.
--
Trond Myklebust
Linux NFS client maintainer
NetApp
[email protected]
http://www.netapp.com