As Jeff recently suggested, here are a few generic patches from my
RPC-with-TLS series that I believe can go in now.
---
Chuck Lever (4):
SUNRPC: Fail faster on bad verifier
SUNRPC: Widen rpc_task::tk_flags
SUNRPC: Replace dprintk() call site in xs_data_ready
NFS: Replace fs_context-related dprintk() call sites with tracepoints
fs/nfs/fs_context.c | 25 +++++++-----
fs/nfs/nfstrace.h | 77 +++++++++++++++++++++++++++++++++++
include/linux/sunrpc/clnt.h | 6 ++-
include/linux/sunrpc/sched.h | 32 +++++++--------
include/trace/events/sunrpc.h | 18 ++++++++
net/sunrpc/clnt.c | 13 +++---
net/sunrpc/debugfs.c | 2 +-
net/sunrpc/xprtsock.c | 6 ++-
8 files changed, 142 insertions(+), 37 deletions(-)
--
Chuck Lever
A bad verifier is not a garbage argument, it's an authentication
failure. Retrying it doesn't make the problem go away, and delays
upper layer recovery steps.
Signed-off-by: Chuck Lever <[email protected]>
Reviewed-by: Jeff Layton <[email protected]>
Signed-off-by: Chuck Lever <[email protected]>
---
net/sunrpc/clnt.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c
index b6781ada3aa8..a97d4e06cae3 100644
--- a/net/sunrpc/clnt.c
+++ b/net/sunrpc/clnt.c
@@ -2650,7 +2650,7 @@ rpc_decode_header(struct rpc_task *task, struct xdr_stream *xdr)
out_verifier:
trace_rpc_bad_verifier(task);
- goto out_garbage;
+ goto out_err;
out_msg_denied:
error = -EACCES;
Signed-off-by: Chuck Lever <[email protected]>
---
include/trace/events/sunrpc.h | 18 ++++++++++++++++++
net/sunrpc/xprtsock.c | 6 ++++--
2 files changed, 22 insertions(+), 2 deletions(-)
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index b61d9c90fa26..04b6903b6c0c 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -1266,6 +1266,24 @@ TRACE_EVENT(xprt_reserve,
)
);
+TRACE_EVENT(xs_data_ready,
+ TP_PROTO(
+ const struct rpc_xprt *xprt
+ ),
+
+ TP_ARGS(xprt),
+
+ TP_STRUCT__entry(
+ __sockaddr(addr, xprt->addrlen)
+ ),
+
+ TP_fast_assign(
+ __assign_sockaddr(addr, &xprt->addr, xprt->addrlen);
+ ),
+
+ TP_printk("peer=%pISpc", __get_sockaddr(addr))
+);
+
TRACE_EVENT(xs_stream_read_data,
TP_PROTO(struct rpc_xprt *xprt, ssize_t err, size_t total),
diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c
index fcdd0fca408e..eba1be9984f8 100644
--- a/net/sunrpc/xprtsock.c
+++ b/net/sunrpc/xprtsock.c
@@ -1378,7 +1378,7 @@ static void xs_udp_data_receive_workfn(struct work_struct *work)
}
/**
- * xs_data_ready - "data ready" callback for UDP sockets
+ * xs_data_ready - "data ready" callback for sockets
* @sk: socket with data to read
*
*/
@@ -1386,11 +1386,13 @@ static void xs_data_ready(struct sock *sk)
{
struct rpc_xprt *xprt;
- dprintk("RPC: xs_data_ready...\n");
xprt = xprt_from_sock(sk);
if (xprt != NULL) {
struct sock_xprt *transport = container_of(xprt,
struct sock_xprt, xprt);
+
+ trace_xs_data_ready(xprt);
+
transport->old_data_ready(sk);
/* Any data means we had a useful conversation, so
* then we don't need to delay the next reconnect
There is just one unused bit left in rpc_task::tk_flags, and I will
need two in subsequent patches. Double the width of the field to
accommodate more flag bits.
Signed-off-by: Chuck Lever <[email protected]>
Reviewed-by: Jeff Layton <[email protected]>
Signed-off-by: Chuck Lever <[email protected]>
---
include/linux/sunrpc/clnt.h | 6 ++++--
include/linux/sunrpc/sched.h | 32 ++++++++++++++++----------------
net/sunrpc/clnt.c | 11 ++++++-----
net/sunrpc/debugfs.c | 2 +-
4 files changed, 27 insertions(+), 24 deletions(-)
diff --git a/include/linux/sunrpc/clnt.h b/include/linux/sunrpc/clnt.h
index 90501404fa49..cbdd20dc84b7 100644
--- a/include/linux/sunrpc/clnt.h
+++ b/include/linux/sunrpc/clnt.h
@@ -193,11 +193,13 @@ void rpc_prepare_reply_pages(struct rpc_rqst *req, struct page **pages,
unsigned int hdrsize);
void rpc_call_start(struct rpc_task *);
int rpc_call_async(struct rpc_clnt *clnt,
- const struct rpc_message *msg, int flags,
+ const struct rpc_message *msg,
+ unsigned int flags,
const struct rpc_call_ops *tk_ops,
void *calldata);
int rpc_call_sync(struct rpc_clnt *clnt,
- const struct rpc_message *msg, int flags);
+ const struct rpc_message *msg,
+ unsigned int flags);
struct rpc_task *rpc_call_null(struct rpc_clnt *clnt, struct rpc_cred *cred,
int flags);
int rpc_restart_call_prepare(struct rpc_task *);
diff --git a/include/linux/sunrpc/sched.h b/include/linux/sunrpc/sched.h
index 1d7a3e51b795..d4b7ebd0a99c 100644
--- a/include/linux/sunrpc/sched.h
+++ b/include/linux/sunrpc/sched.h
@@ -82,7 +82,7 @@ struct rpc_task {
ktime_t tk_start; /* RPC task init timestamp */
pid_t tk_owner; /* Process id for batching tasks */
- unsigned short tk_flags; /* misc flags */
+ unsigned int tk_flags; /* misc flags */
unsigned short tk_timeouts; /* maj timeouts */
#if IS_ENABLED(CONFIG_SUNRPC_DEBUG) || IS_ENABLED(CONFIG_TRACEPOINTS)
@@ -112,27 +112,27 @@ struct rpc_task_setup {
const struct rpc_call_ops *callback_ops;
void *callback_data;
struct workqueue_struct *workqueue;
- unsigned short flags;
+ unsigned int flags;
signed char priority;
};
/*
* RPC task flags
*/
-#define RPC_TASK_ASYNC 0x0001 /* is an async task */
-#define RPC_TASK_SWAPPER 0x0002 /* is swapping in/out */
-#define RPC_TASK_MOVEABLE 0x0004 /* nfs4.1+ rpc tasks */
-#define RPC_TASK_NULLCREDS 0x0010 /* Use AUTH_NULL credential */
-#define RPC_CALL_MAJORSEEN 0x0020 /* major timeout seen */
-#define RPC_TASK_DYNAMIC 0x0080 /* task was kmalloc'ed */
-#define RPC_TASK_NO_ROUND_ROBIN 0x0100 /* send requests on "main" xprt */
-#define RPC_TASK_SOFT 0x0200 /* Use soft timeouts */
-#define RPC_TASK_SOFTCONN 0x0400 /* Fail if can't connect */
-#define RPC_TASK_SENT 0x0800 /* message was sent */
-#define RPC_TASK_TIMEOUT 0x1000 /* fail with ETIMEDOUT on timeout */
-#define RPC_TASK_NOCONNECT 0x2000 /* return ENOTCONN if not connected */
-#define RPC_TASK_NO_RETRANS_TIMEOUT 0x4000 /* wait forever for a reply */
-#define RPC_TASK_CRED_NOREF 0x8000 /* No refcount on the credential */
+#define RPC_TASK_ASYNC 0x00000001 /* is an async task */
+#define RPC_TASK_SWAPPER 0x00000002 /* is swapping in/out */
+#define RPC_TASK_MOVEABLE 0x00000004 /* nfs4.1+ rpc tasks */
+#define RPC_TASK_NULLCREDS 0x00000010 /* Use AUTH_NULL credential */
+#define RPC_CALL_MAJORSEEN 0x00000020 /* major timeout seen */
+#define RPC_TASK_DYNAMIC 0x00000080 /* task was kmalloc'ed */
+#define RPC_TASK_NO_ROUND_ROBIN 0x00000100 /* send requests on "main" xprt */
+#define RPC_TASK_SOFT 0x00000200 /* Use soft timeouts */
+#define RPC_TASK_SOFTCONN 0x00000400 /* Fail if can't connect */
+#define RPC_TASK_SENT 0x00000800 /* message was sent */
+#define RPC_TASK_TIMEOUT 0x00001000 /* fail with ETIMEDOUT on timeout */
+#define RPC_TASK_NOCONNECT 0x00002000 /* return ENOTCONN if not connected */
+#define RPC_TASK_NO_RETRANS_TIMEOUT 0x00004000 /* wait forever for a reply */
+#define RPC_TASK_CRED_NOREF 0x00008000 /* No refcount on the credential */
#define RPC_IS_ASYNC(t) ((t)->tk_flags & RPC_TASK_ASYNC)
#define RPC_IS_SWAPPER(t) ((t)->tk_flags & RPC_TASK_SWAPPER)
diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c
index a97d4e06cae3..476caa4ebf5c 100644
--- a/net/sunrpc/clnt.c
+++ b/net/sunrpc/clnt.c
@@ -1162,7 +1162,8 @@ EXPORT_SYMBOL_GPL(rpc_run_task);
* @msg: RPC call parameters
* @flags: RPC call flags
*/
-int rpc_call_sync(struct rpc_clnt *clnt, const struct rpc_message *msg, int flags)
+int rpc_call_sync(struct rpc_clnt *clnt, const struct rpc_message *msg,
+ unsigned int flags)
{
struct rpc_task *task;
struct rpc_task_setup task_setup_data = {
@@ -1197,9 +1198,9 @@ EXPORT_SYMBOL_GPL(rpc_call_sync);
* @tk_ops: RPC call ops
* @data: user call data
*/
-int
-rpc_call_async(struct rpc_clnt *clnt, const struct rpc_message *msg, int flags,
- const struct rpc_call_ops *tk_ops, void *data)
+int rpc_call_async(struct rpc_clnt *clnt, const struct rpc_message *msg,
+ unsigned int flags, const struct rpc_call_ops *tk_ops,
+ void *data)
{
struct rpc_task *task;
struct rpc_task_setup task_setup_data = {
@@ -3080,7 +3081,7 @@ static void rpc_show_task(const struct rpc_clnt *clnt,
if (RPC_IS_QUEUED(task))
rpc_waitq = rpc_qname(task->tk_waitqueue);
- printk(KERN_INFO "%5u %04x %6d %8p %8p %8ld %8p %sv%u %s a:%ps q:%s\n",
+ printk(KERN_INFO "%5u %08x %6d %8p %8p %8ld %8p %sv%u %s a:%ps q:%s\n",
task->tk_pid, task->tk_flags, task->tk_status,
clnt, task->tk_rqstp, rpc_task_timeout(task), task->tk_ops,
clnt->cl_program->name, clnt->cl_vers, rpc_proc_name(task),
diff --git a/net/sunrpc/debugfs.c b/net/sunrpc/debugfs.c
index 8df634e63f30..60f20be4e7e5 100644
--- a/net/sunrpc/debugfs.c
+++ b/net/sunrpc/debugfs.c
@@ -30,7 +30,7 @@ tasks_show(struct seq_file *f, void *v)
if (task->tk_rqstp)
xid = be32_to_cpu(task->tk_rqstp->rq_xid);
- seq_printf(f, "%5u %04x %6d 0x%x 0x%x %8ld %ps %sv%u %s a:%ps q:%s\n",
+ seq_printf(f, "%5u %08x %6d 0x%x 0x%x %8ld %ps %sv%u %s a:%ps q:%s\n",
task->tk_pid, task->tk_flags, task->tk_status,
clnt->cl_clid, xid, rpc_task_timeout(task), task->tk_ops,
clnt->cl_program->name, clnt->cl_vers, rpc_proc_name(task),
Contributed as part of the long patch series that converts NFS from
using dprintk to tracepoints for observability.
Signed-off-by: Chuck Lever <[email protected]>
Reviewed-by: Jeff Layton <[email protected]>
Signed-off-by: Chuck Lever <[email protected]>
---
fs/nfs/fs_context.c | 25 ++++++++++-------
fs/nfs/nfstrace.h | 77 +++++++++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 92 insertions(+), 10 deletions(-)
diff --git a/fs/nfs/fs_context.c b/fs/nfs/fs_context.c
index 9a16897e8dc6..35e400a557b9 100644
--- a/fs/nfs/fs_context.c
+++ b/fs/nfs/fs_context.c
@@ -21,6 +21,8 @@
#include "nfs.h"
#include "internal.h"
+#include "nfstrace.h"
+
#define NFSDBG_FACILITY NFSDBG_MOUNT
#if IS_ENABLED(CONFIG_NFS_V3)
@@ -284,7 +286,7 @@ static int nfs_verify_server_address(struct sockaddr *addr)
}
}
- dfprintk(MOUNT, "NFS: Invalid IP address specified\n");
+ trace_nfs_mount_addr_err(addr);
return 0;
}
@@ -378,7 +380,7 @@ static int nfs_parse_security_flavors(struct fs_context *fc,
char *string = param->string, *p;
int ret;
- dfprintk(MOUNT, "NFS: parsing %s=%s option\n", param->key, param->string);
+ trace_nfs_mount_assign(param->key, string);
while ((p = strsep(&string, ":")) != NULL) {
if (!*p)
@@ -480,7 +482,7 @@ static int nfs_fs_context_parse_param(struct fs_context *fc,
unsigned int len;
int ret, opt;
- dfprintk(MOUNT, "NFS: parsing nfs mount option '%s'\n", param->key);
+ trace_nfs_mount_option(param);
opt = fs_parse(fc, nfs_fs_parameters, param, &result);
if (opt < 0)
@@ -683,6 +685,7 @@ static int nfs_fs_context_parse_param(struct fs_context *fc,
return ret;
break;
case Opt_vers:
+ trace_nfs_mount_assign(param->key, param->string);
ret = nfs_parse_version_string(fc, param->string);
if (ret < 0)
return ret;
@@ -694,6 +697,7 @@ static int nfs_fs_context_parse_param(struct fs_context *fc,
break;
case Opt_proto:
+ trace_nfs_mount_assign(param->key, param->string);
protofamily = AF_INET;
switch (lookup_constant(nfs_xprt_protocol_tokens, param->string, -1)) {
case Opt_xprt_udp6:
@@ -729,6 +733,7 @@ static int nfs_fs_context_parse_param(struct fs_context *fc,
break;
case Opt_mountproto:
+ trace_nfs_mount_assign(param->key, param->string);
mountfamily = AF_INET;
switch (lookup_constant(nfs_xprt_protocol_tokens, param->string, -1)) {
case Opt_xprt_udp6:
@@ -751,6 +756,7 @@ static int nfs_fs_context_parse_param(struct fs_context *fc,
break;
case Opt_addr:
+ trace_nfs_mount_assign(param->key, param->string);
len = rpc_pton(fc->net_ns, param->string, param->size,
&ctx->nfs_server.address,
sizeof(ctx->nfs_server._address));
@@ -759,16 +765,19 @@ static int nfs_fs_context_parse_param(struct fs_context *fc,
ctx->nfs_server.addrlen = len;
break;
case Opt_clientaddr:
+ trace_nfs_mount_assign(param->key, param->string);
kfree(ctx->client_address);
ctx->client_address = param->string;
param->string = NULL;
break;
case Opt_mounthost:
+ trace_nfs_mount_assign(param->key, param->string);
kfree(ctx->mount_server.hostname);
ctx->mount_server.hostname = param->string;
param->string = NULL;
break;
case Opt_mountaddr:
+ trace_nfs_mount_assign(param->key, param->string);
len = rpc_pton(fc->net_ns, param->string, param->size,
&ctx->mount_server.address,
sizeof(ctx->mount_server._address));
@@ -846,7 +855,6 @@ static int nfs_fs_context_parse_param(struct fs_context *fc,
*/
case Opt_sloppy:
ctx->sloppy = true;
- dfprintk(MOUNT, "NFS: relaxing parsing rules\n");
break;
}
@@ -879,10 +887,8 @@ static int nfs_parse_source(struct fs_context *fc,
size_t len;
const char *end;
- if (unlikely(!dev_name || !*dev_name)) {
- dfprintk(MOUNT, "NFS: device name not specified\n");
+ if (unlikely(!dev_name || !*dev_name))
return -EINVAL;
- }
/* Is the host name protected with square brakcets? */
if (*dev_name == '[') {
@@ -922,7 +928,7 @@ static int nfs_parse_source(struct fs_context *fc,
if (!ctx->nfs_server.export_path)
goto out_nomem;
- dfprintk(MOUNT, "NFS: MNTPATH: '%s'\n", ctx->nfs_server.export_path);
+ trace_nfs_mount_path(ctx->nfs_server.export_path);
return 0;
out_bad_devname:
@@ -1116,7 +1122,6 @@ static int nfs23_parse_monolithic(struct fs_context *fc,
return nfs_invalf(fc, "NFS: nfs_mount_data version supports only AUTH_SYS");
out_nomem:
- dfprintk(MOUNT, "NFS: not enough memory to handle mount options");
return -ENOMEM;
out_no_address:
@@ -1248,7 +1253,7 @@ static int nfs4_parse_monolithic(struct fs_context *fc,
if (IS_ERR(c))
return PTR_ERR(c);
ctx->nfs_server.export_path = c;
- dfprintk(MOUNT, "NFS: MNTPATH: '%s'\n", c);
+ trace_nfs_mount_path(c);
c = strndup_user(data->client_addr.data, 16);
if (IS_ERR(c))
diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
index 012bd7339862..ccaeae42ee77 100644
--- a/fs/nfs/nfstrace.h
+++ b/fs/nfs/nfstrace.h
@@ -1609,6 +1609,83 @@ TRACE_EVENT(nfs_fh_to_dentry,
)
);
+TRACE_EVENT(nfs_mount_addr_err,
+ TP_PROTO(
+ const struct sockaddr *sap
+ ),
+
+ TP_ARGS(sap),
+
+ TP_STRUCT__entry(
+ __array(unsigned char, addr, sizeof(struct sockaddr_in6))
+ ),
+
+ TP_fast_assign(
+ memcpy(__entry->addr, sap, sizeof(__entry->addr));
+ ),
+
+ TP_printk("addr=%pISpc", __entry->addr)
+);
+
+TRACE_EVENT(nfs_mount_assign,
+ TP_PROTO(
+ const char *option,
+ const char *value
+ ),
+
+ TP_ARGS(option, value),
+
+ TP_STRUCT__entry(
+ __string(option, option)
+ __string(value, value)
+ ),
+
+ TP_fast_assign(
+ __assign_str(option, option);
+ __assign_str(value, value);
+ ),
+
+ TP_printk("option %s=%s",
+ __get_str(option), __get_str(value)
+ )
+);
+
+TRACE_EVENT(nfs_mount_option,
+ TP_PROTO(
+ const struct fs_parameter *param
+ ),
+
+ TP_ARGS(param),
+
+ TP_STRUCT__entry(
+ __string(option, param->key)
+ ),
+
+ TP_fast_assign(
+ __assign_str(option, param->key);
+ ),
+
+ TP_printk("option %s", __get_str(option))
+);
+
+TRACE_EVENT(nfs_mount_path,
+ TP_PROTO(
+ const char *path
+ ),
+
+ TP_ARGS(path),
+
+ TP_STRUCT__entry(
+ __string(path, path)
+ ),
+
+ TP_fast_assign(
+ __assign_str(path, path);
+ ),
+
+ TP_printk("path='%s'", __get_str(path))
+);
+
DECLARE_EVENT_CLASS(nfs_xdr_event,
TP_PROTO(
const struct xdr_stream *xdr,
On Fri, 2022-07-22 at 13:25 -0400, Chuck Lever wrote:
> There is just one unused bit left in rpc_task::tk_flags, and I will
> need two in subsequent patches. Double the width of the field to
> accommodate more flag bits.
The values 0x8 and 0x40 are both free, so I'm not seeing why this patch
is needed at this time.
>
> Signed-off-by: Chuck Lever <[email protected]>
> Reviewed-by: Jeff Layton <[email protected]>
> Signed-off-by: Chuck Lever <[email protected]>
> ---
> include/linux/sunrpc/clnt.h | 6 ++++--
> include/linux/sunrpc/sched.h | 32 ++++++++++++++++----------------
> net/sunrpc/clnt.c | 11 ++++++-----
> net/sunrpc/debugfs.c | 2 +-
> 4 files changed, 27 insertions(+), 24 deletions(-)
>
> diff --git a/include/linux/sunrpc/clnt.h
> b/include/linux/sunrpc/clnt.h
> index 90501404fa49..cbdd20dc84b7 100644
> --- a/include/linux/sunrpc/clnt.h
> +++ b/include/linux/sunrpc/clnt.h
> @@ -193,11 +193,13 @@ void rpc_prepare_reply_pages(struct rpc_rqst
> *req, struct page **pages,
> unsigned int hdrsize);
> void rpc_call_start(struct rpc_task *);
> int rpc_call_async(struct rpc_clnt *clnt,
> - const struct rpc_message *msg, int
> flags,
> + const struct rpc_message *msg,
> + unsigned int flags,
> const struct rpc_call_ops *tk_ops,
> void *calldata);
> int rpc_call_sync(struct rpc_clnt *clnt,
> - const struct rpc_message *msg, int
> flags);
> + const struct rpc_message *msg,
> + unsigned int flags);
> struct rpc_task *rpc_call_null(struct rpc_clnt *clnt, struct
> rpc_cred *cred,
> int flags);
> int rpc_restart_call_prepare(struct rpc_task *);
> diff --git a/include/linux/sunrpc/sched.h
> b/include/linux/sunrpc/sched.h
> index 1d7a3e51b795..d4b7ebd0a99c 100644
> --- a/include/linux/sunrpc/sched.h
> +++ b/include/linux/sunrpc/sched.h
> @@ -82,7 +82,7 @@ struct rpc_task {
> ktime_t tk_start; /* RPC task init
> timestamp */
>
> pid_t tk_owner; /* Process id for
> batching tasks */
> - unsigned short tk_flags; /* misc flags */
> + unsigned int tk_flags; /* misc flags */
> unsigned short tk_timeouts; /* maj timeouts */
>
> #if IS_ENABLED(CONFIG_SUNRPC_DEBUG) ||
> IS_ENABLED(CONFIG_TRACEPOINTS)
> @@ -112,27 +112,27 @@ struct rpc_task_setup {
> const struct rpc_call_ops *callback_ops;
> void *callback_data;
> struct workqueue_struct *workqueue;
> - unsigned short flags;
> + unsigned int flags;
> signed char priority;
> };
>
> /*
> * RPC task flags
> */
> -#define RPC_TASK_ASYNC 0x0001 /* is an async task
> */
> -#define RPC_TASK_SWAPPER 0x0002 /* is swapping in/out
> */
> -#define RPC_TASK_MOVEABLE 0x0004 /* nfs4.1+ rpc tasks
> */
> -#define RPC_TASK_NULLCREDS 0x0010 /* Use AUTH_NULL
> credential */
> -#define RPC_CALL_MAJORSEEN 0x0020 /* major timeout seen
> */
> -#define RPC_TASK_DYNAMIC 0x0080 /* task was
> kmalloc'ed */
> -#define RPC_TASK_NO_ROUND_ROBIN 0x0100 /* send
> requests on "main" xprt */
> -#define RPC_TASK_SOFT 0x0200 /* Use soft timeouts
> */
> -#define RPC_TASK_SOFTCONN 0x0400 /* Fail if can't
> connect */
> -#define RPC_TASK_SENT 0x0800 /* message was sent
> */
> -#define RPC_TASK_TIMEOUT 0x1000 /* fail with
> ETIMEDOUT on timeout */
> -#define RPC_TASK_NOCONNECT 0x2000 /* return ENOTCONN if
> not connected */
> -#define RPC_TASK_NO_RETRANS_TIMEOUT 0x4000 /* wait
> forever for a reply */
> -#define RPC_TASK_CRED_NOREF 0x8000 /* No refcount on the
> credential */
> +#define RPC_TASK_ASYNC 0x00000001 /* is an
> async task */
> +#define RPC_TASK_SWAPPER 0x00000002 /* is
> swapping in/out */
> +#define RPC_TASK_MOVEABLE 0x00000004 /* nfs4.1+
> rpc tasks */
> +#define RPC_TASK_NULLCREDS 0x00000010 /* Use
> AUTH_NULL credential */
> +#define RPC_CALL_MAJORSEEN 0x00000020 /* major
> timeout seen */
> +#define RPC_TASK_DYNAMIC 0x00000080 /* task was
> kmalloc'ed */
> +#define RPC_TASK_NO_ROUND_ROBIN 0x00000100 /*
> send requests on "main" xprt */
> +#define RPC_TASK_SOFT 0x00000200 /* Use soft
> timeouts */
> +#define RPC_TASK_SOFTCONN 0x00000400 /* Fail if
> can't connect */
> +#define RPC_TASK_SENT 0x00000800 /* message
> was sent */
> +#define RPC_TASK_TIMEOUT 0x00001000 /* fail with
> ETIMEDOUT on timeout */
> +#define RPC_TASK_NOCONNECT 0x00002000 /* return
> ENOTCONN if not connected */
> +#define RPC_TASK_NO_RETRANS_TIMEOUT 0x00004000 /* wait
> forever for a reply */
> +#define RPC_TASK_CRED_NOREF 0x00008000 /* No
> refcount on the credential */
>
> #define RPC_IS_ASYNC(t) ((t)->tk_flags &
> RPC_TASK_ASYNC)
> #define RPC_IS_SWAPPER(t) ((t)->tk_flags & RPC_TASK_SWAPPER)
> diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c
> index a97d4e06cae3..476caa4ebf5c 100644
> --- a/net/sunrpc/clnt.c
> +++ b/net/sunrpc/clnt.c
> @@ -1162,7 +1162,8 @@ EXPORT_SYMBOL_GPL(rpc_run_task);
> * @msg: RPC call parameters
> * @flags: RPC call flags
> */
> -int rpc_call_sync(struct rpc_clnt *clnt, const struct rpc_message
> *msg, int flags)
> +int rpc_call_sync(struct rpc_clnt *clnt, const struct rpc_message
> *msg,
> + unsigned int flags)
> {
> struct rpc_task *task;
> struct rpc_task_setup task_setup_data = {
> @@ -1197,9 +1198,9 @@ EXPORT_SYMBOL_GPL(rpc_call_sync);
> * @tk_ops: RPC call ops
> * @data: user call data
> */
> -int
> -rpc_call_async(struct rpc_clnt *clnt, const struct rpc_message *msg,
> int flags,
> - const struct rpc_call_ops *tk_ops, void *data)
> +int rpc_call_async(struct rpc_clnt *clnt, const struct rpc_message
> *msg,
> + unsigned int flags, const struct rpc_call_ops
> *tk_ops,
> + void *data)
> {
> struct rpc_task *task;
> struct rpc_task_setup task_setup_data = {
> @@ -3080,7 +3081,7 @@ static void rpc_show_task(const struct rpc_clnt
> *clnt,
> if (RPC_IS_QUEUED(task))
> rpc_waitq = rpc_qname(task->tk_waitqueue);
>
> - printk(KERN_INFO "%5u %04x %6d %8p %8p %8ld %8p %sv%u %s
> a:%ps q:%s\n",
> + printk(KERN_INFO "%5u %08x %6d %8p %8p %8ld %8p %sv%u %s
> a:%ps q:%s\n",
> task->tk_pid, task->tk_flags, task->tk_status,
> clnt, task->tk_rqstp, rpc_task_timeout(task), task-
> >tk_ops,
> clnt->cl_program->name, clnt->cl_vers,
> rpc_proc_name(task),
> diff --git a/net/sunrpc/debugfs.c b/net/sunrpc/debugfs.c
> index 8df634e63f30..60f20be4e7e5 100644
> --- a/net/sunrpc/debugfs.c
> +++ b/net/sunrpc/debugfs.c
> @@ -30,7 +30,7 @@ tasks_show(struct seq_file *f, void *v)
> if (task->tk_rqstp)
> xid = be32_to_cpu(task->tk_rqstp->rq_xid);
>
> - seq_printf(f, "%5u %04x %6d 0x%x 0x%x %8ld %ps %sv%u %s a:%ps
> q:%s\n",
> + seq_printf(f, "%5u %08x %6d 0x%x 0x%x %8ld %ps %sv%u %s a:%ps
> q:%s\n",
> task->tk_pid, task->tk_flags, task->tk_status,
> clnt->cl_clid, xid, rpc_task_timeout(task), task-
> >tk_ops,
> clnt->cl_program->name, clnt->cl_vers,
> rpc_proc_name(task),
>
>
--
Trond Myklebust
Linux NFS client maintainer, Hammerspace
[email protected]
> On Jul 22, 2022, at 1:53 PM, Trond Myklebust <[email protected]> wrote:
>
> On Fri, 2022-07-22 at 13:25 -0400, Chuck Lever wrote:
>> There is just one unused bit left in rpc_task::tk_flags, and I will
>> need two in subsequent patches. Double the width of the field to
>> accommodate more flag bits.
>
> The values 0x8 and 0x40 are both free, so I'm not seeing why this patch
> is needed at this time.
It's not needed now, but as recently as last year, there were no free
bits (and I needed them for RPC-with-TLS support at that time). We will
have to widen this field sooner or later.
I don't have a problem dropping this one if you'd rather wait.
>> Signed-off-by: Chuck Lever <[email protected]>
>> Reviewed-by: Jeff Layton <[email protected]>
>> Signed-off-by: Chuck Lever <[email protected]>
>> ---
>> include/linux/sunrpc/clnt.h | 6 ++++--
>> include/linux/sunrpc/sched.h | 32 ++++++++++++++++----------------
>> net/sunrpc/clnt.c | 11 ++++++-----
>> net/sunrpc/debugfs.c | 2 +-
>> 4 files changed, 27 insertions(+), 24 deletions(-)
>>
>> diff --git a/include/linux/sunrpc/clnt.h
>> b/include/linux/sunrpc/clnt.h
>> index 90501404fa49..cbdd20dc84b7 100644
>> --- a/include/linux/sunrpc/clnt.h
>> +++ b/include/linux/sunrpc/clnt.h
>> @@ -193,11 +193,13 @@ void rpc_prepare_reply_pages(struct rpc_rqst
>> *req, struct page **pages,
>> unsigned int hdrsize);
>> void rpc_call_start(struct rpc_task *);
>> int rpc_call_async(struct rpc_clnt *clnt,
>> - const struct rpc_message *msg, int
>> flags,
>> + const struct rpc_message *msg,
>> + unsigned int flags,
>> const struct rpc_call_ops *tk_ops,
>> void *calldata);
>> int rpc_call_sync(struct rpc_clnt *clnt,
>> - const struct rpc_message *msg, int
>> flags);
>> + const struct rpc_message *msg,
>> + unsigned int flags);
>> struct rpc_task *rpc_call_null(struct rpc_clnt *clnt, struct
>> rpc_cred *cred,
>> int flags);
>> int rpc_restart_call_prepare(struct rpc_task *);
>> diff --git a/include/linux/sunrpc/sched.h
>> b/include/linux/sunrpc/sched.h
>> index 1d7a3e51b795..d4b7ebd0a99c 100644
>> --- a/include/linux/sunrpc/sched.h
>> +++ b/include/linux/sunrpc/sched.h
>> @@ -82,7 +82,7 @@ struct rpc_task {
>> ktime_t tk_start; /* RPC task init
>> timestamp */
>>
>> pid_t tk_owner; /* Process id for
>> batching tasks */
>> - unsigned short tk_flags; /* misc flags */
>> + unsigned int tk_flags; /* misc flags */
>> unsigned short tk_timeouts; /* maj timeouts */
>>
>> #if IS_ENABLED(CONFIG_SUNRPC_DEBUG) ||
>> IS_ENABLED(CONFIG_TRACEPOINTS)
>> @@ -112,27 +112,27 @@ struct rpc_task_setup {
>> const struct rpc_call_ops *callback_ops;
>> void *callback_data;
>> struct workqueue_struct *workqueue;
>> - unsigned short flags;
>> + unsigned int flags;
>> signed char priority;
>> };
>>
>> /*
>> * RPC task flags
>> */
>> -#define RPC_TASK_ASYNC 0x0001 /* is an async task
>> */
>> -#define RPC_TASK_SWAPPER 0x0002 /* is swapping in/out
>> */
>> -#define RPC_TASK_MOVEABLE 0x0004 /* nfs4.1+ rpc tasks
>> */
>> -#define RPC_TASK_NULLCREDS 0x0010 /* Use AUTH_NULL
>> credential */
>> -#define RPC_CALL_MAJORSEEN 0x0020 /* major timeout seen
>> */
>> -#define RPC_TASK_DYNAMIC 0x0080 /* task was
>> kmalloc'ed */
>> -#define RPC_TASK_NO_ROUND_ROBIN 0x0100 /* send
>> requests on "main" xprt */
>> -#define RPC_TASK_SOFT 0x0200 /* Use soft timeouts
>> */
>> -#define RPC_TASK_SOFTCONN 0x0400 /* Fail if can't
>> connect */
>> -#define RPC_TASK_SENT 0x0800 /* message was sent
>> */
>> -#define RPC_TASK_TIMEOUT 0x1000 /* fail with
>> ETIMEDOUT on timeout */
>> -#define RPC_TASK_NOCONNECT 0x2000 /* return ENOTCONN if
>> not connected */
>> -#define RPC_TASK_NO_RETRANS_TIMEOUT 0x4000 /* wait
>> forever for a reply */
>> -#define RPC_TASK_CRED_NOREF 0x8000 /* No refcount on the
>> credential */
>> +#define RPC_TASK_ASYNC 0x00000001 /* is an
>> async task */
>> +#define RPC_TASK_SWAPPER 0x00000002 /* is
>> swapping in/out */
>> +#define RPC_TASK_MOVEABLE 0x00000004 /* nfs4.1+
>> rpc tasks */
>> +#define RPC_TASK_NULLCREDS 0x00000010 /* Use
>> AUTH_NULL credential */
>> +#define RPC_CALL_MAJORSEEN 0x00000020 /* major
>> timeout seen */
>> +#define RPC_TASK_DYNAMIC 0x00000080 /* task was
>> kmalloc'ed */
>> +#define RPC_TASK_NO_ROUND_ROBIN 0x00000100 /*
>> send requests on "main" xprt */
>> +#define RPC_TASK_SOFT 0x00000200 /* Use soft
>> timeouts */
>> +#define RPC_TASK_SOFTCONN 0x00000400 /* Fail if
>> can't connect */
>> +#define RPC_TASK_SENT 0x00000800 /* message
>> was sent */
>> +#define RPC_TASK_TIMEOUT 0x00001000 /* fail with
>> ETIMEDOUT on timeout */
>> +#define RPC_TASK_NOCONNECT 0x00002000 /* return
>> ENOTCONN if not connected */
>> +#define RPC_TASK_NO_RETRANS_TIMEOUT 0x00004000 /* wait
>> forever for a reply */
>> +#define RPC_TASK_CRED_NOREF 0x00008000 /* No
>> refcount on the credential */
>>
>> #define RPC_IS_ASYNC(t) ((t)->tk_flags &
>> RPC_TASK_ASYNC)
>> #define RPC_IS_SWAPPER(t) ((t)->tk_flags & RPC_TASK_SWAPPER)
>> diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c
>> index a97d4e06cae3..476caa4ebf5c 100644
>> --- a/net/sunrpc/clnt.c
>> +++ b/net/sunrpc/clnt.c
>> @@ -1162,7 +1162,8 @@ EXPORT_SYMBOL_GPL(rpc_run_task);
>> * @msg: RPC call parameters
>> * @flags: RPC call flags
>> */
>> -int rpc_call_sync(struct rpc_clnt *clnt, const struct rpc_message
>> *msg, int flags)
>> +int rpc_call_sync(struct rpc_clnt *clnt, const struct rpc_message
>> *msg,
>> + unsigned int flags)
>> {
>> struct rpc_task *task;
>> struct rpc_task_setup task_setup_data = {
>> @@ -1197,9 +1198,9 @@ EXPORT_SYMBOL_GPL(rpc_call_sync);
>> * @tk_ops: RPC call ops
>> * @data: user call data
>> */
>> -int
>> -rpc_call_async(struct rpc_clnt *clnt, const struct rpc_message *msg,
>> int flags,
>> - const struct rpc_call_ops *tk_ops, void *data)
>> +int rpc_call_async(struct rpc_clnt *clnt, const struct rpc_message
>> *msg,
>> + unsigned int flags, const struct rpc_call_ops
>> *tk_ops,
>> + void *data)
>> {
>> struct rpc_task *task;
>> struct rpc_task_setup task_setup_data = {
>> @@ -3080,7 +3081,7 @@ static void rpc_show_task(const struct rpc_clnt
>> *clnt,
>> if (RPC_IS_QUEUED(task))
>> rpc_waitq = rpc_qname(task->tk_waitqueue);
>>
>> - printk(KERN_INFO "%5u %04x %6d %8p %8p %8ld %8p %sv%u %s
>> a:%ps q:%s\n",
>> + printk(KERN_INFO "%5u %08x %6d %8p %8p %8ld %8p %sv%u %s
>> a:%ps q:%s\n",
>> task->tk_pid, task->tk_flags, task->tk_status,
>> clnt, task->tk_rqstp, rpc_task_timeout(task), task-
>>> tk_ops,
>> clnt->cl_program->name, clnt->cl_vers,
>> rpc_proc_name(task),
>> diff --git a/net/sunrpc/debugfs.c b/net/sunrpc/debugfs.c
>> index 8df634e63f30..60f20be4e7e5 100644
>> --- a/net/sunrpc/debugfs.c
>> +++ b/net/sunrpc/debugfs.c
>> @@ -30,7 +30,7 @@ tasks_show(struct seq_file *f, void *v)
>> if (task->tk_rqstp)
>> xid = be32_to_cpu(task->tk_rqstp->rq_xid);
>>
>> - seq_printf(f, "%5u %04x %6d 0x%x 0x%x %8ld %ps %sv%u %s a:%ps
>> q:%s\n",
>> + seq_printf(f, "%5u %08x %6d 0x%x 0x%x %8ld %ps %sv%u %s a:%ps
>> q:%s\n",
>> task->tk_pid, task->tk_flags, task->tk_status,
>> clnt->cl_clid, xid, rpc_task_timeout(task), task-
>>> tk_ops,
>> clnt->cl_program->name, clnt->cl_vers,
>> rpc_proc_name(task),
>>
>>
>
> --
> Trond Myklebust
> Linux NFS client maintainer, Hammerspace
> [email protected]
--
Chuck Lever
On Fri, 2022-07-22 at 13:25 -0400, Chuck Lever wrote:
> Signed-off-by: Chuck Lever <[email protected]>
> ---
> include/trace/events/sunrpc.h | 18 ++++++++++++++++++
> net/sunrpc/xprtsock.c | 6 ++++--
> 2 files changed, 22 insertions(+), 2 deletions(-)
>
> diff --git a/include/trace/events/sunrpc.h
> b/include/trace/events/sunrpc.h
> index b61d9c90fa26..04b6903b6c0c 100644
> --- a/include/trace/events/sunrpc.h
> +++ b/include/trace/events/sunrpc.h
> @@ -1266,6 +1266,24 @@ TRACE_EVENT(xprt_reserve,
> )
> );
>
> +TRACE_EVENT(xs_data_ready,
> + TP_PROTO(
> + const struct rpc_xprt *xprt
> + ),
> +
> + TP_ARGS(xprt),
> +
> + TP_STRUCT__entry(
> + __sockaddr(addr, xprt->addrlen)
> + ),
> +
> + TP_fast_assign(
> + __assign_sockaddr(addr, &xprt->addr, xprt->addrlen);
> + ),
> +
> + TP_printk("peer=%pISpc", __get_sockaddr(addr))
NACK. Please resolve and store the string up front instead of storing
the sockaddr. Most versions of perf can't resolve those kernel-specific
%p printks and just end up barfing on them.
> +);
> +
> TRACE_EVENT(xs_stream_read_data,
> TP_PROTO(struct rpc_xprt *xprt, ssize_t err, size_t total),
>
> diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c
> index fcdd0fca408e..eba1be9984f8 100644
> --- a/net/sunrpc/xprtsock.c
> +++ b/net/sunrpc/xprtsock.c
> @@ -1378,7 +1378,7 @@ static void xs_udp_data_receive_workfn(struct
> work_struct *work)
> }
>
> /**
> - * xs_data_ready - "data ready" callback for UDP sockets
> + * xs_data_ready - "data ready" callback for sockets
> * @sk: socket with data to read
> *
> */
> @@ -1386,11 +1386,13 @@ static void xs_data_ready(struct sock *sk)
> {
> struct rpc_xprt *xprt;
>
> - dprintk("RPC: xs_data_ready...\n");
> xprt = xprt_from_sock(sk);
> if (xprt != NULL) {
> struct sock_xprt *transport = container_of(xprt,
> struct sock_xprt, xprt);
> +
> + trace_xs_data_ready(xprt);
> +
> transport->old_data_ready(sk);
> /* Any data means we had a useful conversation, so
> * then we don't need to delay the next reconnect
>
>
--
Trond Myklebust
Linux NFS client maintainer, Hammerspace
[email protected]
On Fri, 2022-07-22 at 13:25 -0400, Chuck Lever wrote:
> Contributed as part of the long patch series that converts NFS from
> using dprintk to tracepoints for observability.
>
> Signed-off-by: Chuck Lever <[email protected]>
> Reviewed-by: Jeff Layton <[email protected]>
> Signed-off-by: Chuck Lever <[email protected]>
> ---
> fs/nfs/fs_context.c | 25 ++++++++++-------
> fs/nfs/nfstrace.h | 77
> +++++++++++++++++++++++++++++++++++++++++++++++++++
> 2 files changed, 92 insertions(+), 10 deletions(-)
>
> diff --git a/fs/nfs/fs_context.c b/fs/nfs/fs_context.c
> index 9a16897e8dc6..35e400a557b9 100644
> --- a/fs/nfs/fs_context.c
> +++ b/fs/nfs/fs_context.c
> @@ -21,6 +21,8 @@
> #include "nfs.h"
> #include "internal.h"
>
> +#include "nfstrace.h"
> +
> #define NFSDBG_FACILITY NFSDBG_MOUNT
>
> #if IS_ENABLED(CONFIG_NFS_V3)
> @@ -284,7 +286,7 @@ static int nfs_verify_server_address(struct
> sockaddr *addr)
> }
> }
>
> - dfprintk(MOUNT, "NFS: Invalid IP address specified\n");
> + trace_nfs_mount_addr_err(addr);
> return 0;
> }
>
> @@ -378,7 +380,7 @@ static int nfs_parse_security_flavors(struct
> fs_context *fc,
> char *string = param->string, *p;
> int ret;
>
> - dfprintk(MOUNT, "NFS: parsing %s=%s option\n", param->key,
> param->string);
> + trace_nfs_mount_assign(param->key, string);
>
> while ((p = strsep(&string, ":")) != NULL) {
> if (!*p)
> @@ -480,7 +482,7 @@ static int nfs_fs_context_parse_param(struct
> fs_context *fc,
> unsigned int len;
> int ret, opt;
>
> - dfprintk(MOUNT, "NFS: parsing nfs mount option '%s'\n",
> param->key);
> + trace_nfs_mount_option(param);
>
> opt = fs_parse(fc, nfs_fs_parameters, param, &result);
> if (opt < 0)
> @@ -683,6 +685,7 @@ static int nfs_fs_context_parse_param(struct
> fs_context *fc,
> return ret;
> break;
> case Opt_vers:
> + trace_nfs_mount_assign(param->key, param->string);
> ret = nfs_parse_version_string(fc, param->string);
> if (ret < 0)
> return ret;
> @@ -694,6 +697,7 @@ static int nfs_fs_context_parse_param(struct
> fs_context *fc,
> break;
>
> case Opt_proto:
> + trace_nfs_mount_assign(param->key, param->string);
> protofamily = AF_INET;
> switch (lookup_constant(nfs_xprt_protocol_tokens,
> param->string, -1)) {
> case Opt_xprt_udp6:
> @@ -729,6 +733,7 @@ static int nfs_fs_context_parse_param(struct
> fs_context *fc,
> break;
>
> case Opt_mountproto:
> + trace_nfs_mount_assign(param->key, param->string);
> mountfamily = AF_INET;
> switch (lookup_constant(nfs_xprt_protocol_tokens,
> param->string, -1)) {
> case Opt_xprt_udp6:
> @@ -751,6 +756,7 @@ static int nfs_fs_context_parse_param(struct
> fs_context *fc,
> break;
>
> case Opt_addr:
> + trace_nfs_mount_assign(param->key, param->string);
> len = rpc_pton(fc->net_ns, param->string, param-
> >size,
> &ctx->nfs_server.address,
> sizeof(ctx->nfs_server._address));
> @@ -759,16 +765,19 @@ static int nfs_fs_context_parse_param(struct
> fs_context *fc,
> ctx->nfs_server.addrlen = len;
> break;
> case Opt_clientaddr:
> + trace_nfs_mount_assign(param->key, param->string);
> kfree(ctx->client_address);
> ctx->client_address = param->string;
> param->string = NULL;
> break;
> case Opt_mounthost:
> + trace_nfs_mount_assign(param->key, param->string);
> kfree(ctx->mount_server.hostname);
> ctx->mount_server.hostname = param->string;
> param->string = NULL;
> break;
> case Opt_mountaddr:
> + trace_nfs_mount_assign(param->key, param->string);
> len = rpc_pton(fc->net_ns, param->string, param-
> >size,
> &ctx->mount_server.address,
> sizeof(ctx->mount_server._address));
> @@ -846,7 +855,6 @@ static int nfs_fs_context_parse_param(struct
> fs_context *fc,
> */
> case Opt_sloppy:
> ctx->sloppy = true;
> - dfprintk(MOUNT, "NFS: relaxing parsing rules\n");
> break;
> }
>
> @@ -879,10 +887,8 @@ static int nfs_parse_source(struct fs_context
> *fc,
> size_t len;
> const char *end;
>
> - if (unlikely(!dev_name || !*dev_name)) {
> - dfprintk(MOUNT, "NFS: device name not specified\n");
> + if (unlikely(!dev_name || !*dev_name))
> return -EINVAL;
> - }
>
> /* Is the host name protected with square brakcets? */
> if (*dev_name == '[') {
> @@ -922,7 +928,7 @@ static int nfs_parse_source(struct fs_context
> *fc,
> if (!ctx->nfs_server.export_path)
> goto out_nomem;
>
> - dfprintk(MOUNT, "NFS: MNTPATH: '%s'\n", ctx-
> >nfs_server.export_path);
> + trace_nfs_mount_path(ctx->nfs_server.export_path);
> return 0;
>
> out_bad_devname:
> @@ -1116,7 +1122,6 @@ static int nfs23_parse_monolithic(struct
> fs_context *fc,
> return nfs_invalf(fc, "NFS: nfs_mount_data version supports
> only AUTH_SYS");
>
> out_nomem:
> - dfprintk(MOUNT, "NFS: not enough memory to handle mount
> options");
> return -ENOMEM;
>
> out_no_address:
> @@ -1248,7 +1253,7 @@ static int nfs4_parse_monolithic(struct
> fs_context *fc,
> if (IS_ERR(c))
> return PTR_ERR(c);
> ctx->nfs_server.export_path = c;
> - dfprintk(MOUNT, "NFS: MNTPATH: '%s'\n", c);
> + trace_nfs_mount_path(c);
>
> c = strndup_user(data->client_addr.data, 16);
> if (IS_ERR(c))
> diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
> index 012bd7339862..ccaeae42ee77 100644
> --- a/fs/nfs/nfstrace.h
> +++ b/fs/nfs/nfstrace.h
> @@ -1609,6 +1609,83 @@ TRACE_EVENT(nfs_fh_to_dentry,
> )
> );
>
> +TRACE_EVENT(nfs_mount_addr_err,
> + TP_PROTO(
> + const struct sockaddr *sap
> + ),
> +
> + TP_ARGS(sap),
> +
> + TP_STRUCT__entry(
> + __array(unsigned char, addr, sizeof(struct
> sockaddr_in6))
> + ),
> +
> + TP_fast_assign(
> + memcpy(__entry->addr, sap, sizeof(__entry->addr));
> + ),
> +
> + TP_printk("addr=%pISpc", __entry->addr)
Ditto problem with this.
> +);
> +
> +TRACE_EVENT(nfs_mount_assign,
> + TP_PROTO(
> + const char *option,
> + const char *value
> + ),
> +
> + TP_ARGS(option, value),
> +
> + TP_STRUCT__entry(
> + __string(option, option)
> + __string(value, value)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(option, option);
> + __assign_str(value, value);
> + ),
> +
> + TP_printk("option %s=%s",
> + __get_str(option), __get_str(value)
> + )
> +);
> +
> +TRACE_EVENT(nfs_mount_option,
> + TP_PROTO(
> + const struct fs_parameter *param
> + ),
> +
> + TP_ARGS(param),
> +
> + TP_STRUCT__entry(
> + __string(option, param->key)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(option, param->key);
> + ),
> +
> + TP_printk("option %s", __get_str(option))
> +);
> +
> +TRACE_EVENT(nfs_mount_path,
> + TP_PROTO(
> + const char *path
> + ),
> +
> + TP_ARGS(path),
> +
> + TP_STRUCT__entry(
> + __string(path, path)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(path, path);
> + ),
> +
> + TP_printk("path='%s'", __get_str(path))
> +);
> +
> DECLARE_EVENT_CLASS(nfs_xdr_event,
> TP_PROTO(
> const struct xdr_stream *xdr,
>
>
--
Trond Myklebust
Linux NFS client maintainer, Hammerspace
[email protected]
> On Jul 22, 2022, at 1:59 PM, Trond Myklebust <[email protected]> wrote:
>
> On Fri, 2022-07-22 at 13:25 -0400, Chuck Lever wrote:
>> Signed-off-by: Chuck Lever <[email protected]>
>> ---
>> include/trace/events/sunrpc.h | 18 ++++++++++++++++++
>> net/sunrpc/xprtsock.c | 6 ++++--
>> 2 files changed, 22 insertions(+), 2 deletions(-)
>>
>> diff --git a/include/trace/events/sunrpc.h
>> b/include/trace/events/sunrpc.h
>> index b61d9c90fa26..04b6903b6c0c 100644
>> --- a/include/trace/events/sunrpc.h
>> +++ b/include/trace/events/sunrpc.h
>> @@ -1266,6 +1266,24 @@ TRACE_EVENT(xprt_reserve,
>> )
>> );
>>
>> +TRACE_EVENT(xs_data_ready,
>> + TP_PROTO(
>> + const struct rpc_xprt *xprt
>> + ),
>> +
>> + TP_ARGS(xprt),
>> +
>> + TP_STRUCT__entry(
>> + __sockaddr(addr, xprt->addrlen)
>> + ),
>> +
>> + TP_fast_assign(
>> + __assign_sockaddr(addr, &xprt->addr, xprt->addrlen);
>> + ),
>> +
>> + TP_printk("peer=%pISpc", __get_sockaddr(addr))
>
> NACK. Please resolve and store the string up front instead of storing
> the sockaddr. Most versions of perf can't resolve those kernel-specific
> %p printks and just end up barfing on them.
Interesting. We added get_sockaddr() to avoid this issue in
trace-cmd. Sounds like perf needs to be fixed up too, or
maybe this is another case of having an old libtraceevent?
Meanwhile, I can revert this back to the old way of handling
presentation addresses.
>> +);
>> +
>> TRACE_EVENT(xs_stream_read_data,
>> TP_PROTO(struct rpc_xprt *xprt, ssize_t err, size_t total),
>>
>> diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c
>> index fcdd0fca408e..eba1be9984f8 100644
>> --- a/net/sunrpc/xprtsock.c
>> +++ b/net/sunrpc/xprtsock.c
>> @@ -1378,7 +1378,7 @@ static void xs_udp_data_receive_workfn(struct
>> work_struct *work)
>> }
>>
>> /**
>> - * xs_data_ready - "data ready" callback for UDP sockets
>> + * xs_data_ready - "data ready" callback for sockets
>> * @sk: socket with data to read
>> *
>> */
>> @@ -1386,11 +1386,13 @@ static void xs_data_ready(struct sock *sk)
>> {
>> struct rpc_xprt *xprt;
>>
>> - dprintk("RPC: xs_data_ready...\n");
>> xprt = xprt_from_sock(sk);
>> if (xprt != NULL) {
>> struct sock_xprt *transport = container_of(xprt,
>> struct sock_xprt, xprt);
>> +
>> + trace_xs_data_ready(xprt);
>> +
>> transport->old_data_ready(sk);
>> /* Any data means we had a useful conversation, so
>> * then we don't need to delay the next reconnect
>>
>>
>
> --
> Trond Myklebust
> Linux NFS client maintainer, Hammerspace
> [email protected]
--
Chuck Lever
> On Jul 22, 2022, at 2:00 PM, Trond Myklebust <[email protected]> wrote:
>
> On Fri, 2022-07-22 at 13:25 -0400, Chuck Lever wrote:
>> Contributed as part of the long patch series that converts NFS from
>> using dprintk to tracepoints for observability.
>>
>> Signed-off-by: Chuck Lever <[email protected]>
>> Reviewed-by: Jeff Layton <[email protected]>
>> Signed-off-by: Chuck Lever <[email protected]>
>> ---
>> fs/nfs/fs_context.c | 25 ++++++++++-------
>> fs/nfs/nfstrace.h | 77
>> +++++++++++++++++++++++++++++++++++++++++++++++++++
>> 2 files changed, 92 insertions(+), 10 deletions(-)
>>
>> diff --git a/fs/nfs/fs_context.c b/fs/nfs/fs_context.c
>> index 9a16897e8dc6..35e400a557b9 100644
>> --- a/fs/nfs/fs_context.c
>> +++ b/fs/nfs/fs_context.c
>> @@ -21,6 +21,8 @@
>> #include "nfs.h"
>> #include "internal.h"
>>
>> +#include "nfstrace.h"
>> +
>> #define NFSDBG_FACILITY NFSDBG_MOUNT
>>
>> #if IS_ENABLED(CONFIG_NFS_V3)
>> @@ -284,7 +286,7 @@ static int nfs_verify_server_address(struct
>> sockaddr *addr)
>> }
>> }
>>
>> - dfprintk(MOUNT, "NFS: Invalid IP address specified\n");
>> + trace_nfs_mount_addr_err(addr);
>> return 0;
>> }
>>
>> @@ -378,7 +380,7 @@ static int nfs_parse_security_flavors(struct
>> fs_context *fc,
>> char *string = param->string, *p;
>> int ret;
>>
>> - dfprintk(MOUNT, "NFS: parsing %s=%s option\n", param->key,
>> param->string);
>> + trace_nfs_mount_assign(param->key, string);
>>
>> while ((p = strsep(&string, ":")) != NULL) {
>> if (!*p)
>> @@ -480,7 +482,7 @@ static int nfs_fs_context_parse_param(struct
>> fs_context *fc,
>> unsigned int len;
>> int ret, opt;
>>
>> - dfprintk(MOUNT, "NFS: parsing nfs mount option '%s'\n",
>> param->key);
>> + trace_nfs_mount_option(param);
>>
>> opt = fs_parse(fc, nfs_fs_parameters, param, &result);
>> if (opt < 0)
>> @@ -683,6 +685,7 @@ static int nfs_fs_context_parse_param(struct
>> fs_context *fc,
>> return ret;
>> break;
>> case Opt_vers:
>> + trace_nfs_mount_assign(param->key, param->string);
>> ret = nfs_parse_version_string(fc, param->string);
>> if (ret < 0)
>> return ret;
>> @@ -694,6 +697,7 @@ static int nfs_fs_context_parse_param(struct
>> fs_context *fc,
>> break;
>>
>> case Opt_proto:
>> + trace_nfs_mount_assign(param->key, param->string);
>> protofamily = AF_INET;
>> switch (lookup_constant(nfs_xprt_protocol_tokens,
>> param->string, -1)) {
>> case Opt_xprt_udp6:
>> @@ -729,6 +733,7 @@ static int nfs_fs_context_parse_param(struct
>> fs_context *fc,
>> break;
>>
>> case Opt_mountproto:
>> + trace_nfs_mount_assign(param->key, param->string);
>> mountfamily = AF_INET;
>> switch (lookup_constant(nfs_xprt_protocol_tokens,
>> param->string, -1)) {
>> case Opt_xprt_udp6:
>> @@ -751,6 +756,7 @@ static int nfs_fs_context_parse_param(struct
>> fs_context *fc,
>> break;
>>
>> case Opt_addr:
>> + trace_nfs_mount_assign(param->key, param->string);
>> len = rpc_pton(fc->net_ns, param->string, param-
>>> size,
>> &ctx->nfs_server.address,
>> sizeof(ctx->nfs_server._address));
>> @@ -759,16 +765,19 @@ static int nfs_fs_context_parse_param(struct
>> fs_context *fc,
>> ctx->nfs_server.addrlen = len;
>> break;
>> case Opt_clientaddr:
>> + trace_nfs_mount_assign(param->key, param->string);
>> kfree(ctx->client_address);
>> ctx->client_address = param->string;
>> param->string = NULL;
>> break;
>> case Opt_mounthost:
>> + trace_nfs_mount_assign(param->key, param->string);
>> kfree(ctx->mount_server.hostname);
>> ctx->mount_server.hostname = param->string;
>> param->string = NULL;
>> break;
>> case Opt_mountaddr:
>> + trace_nfs_mount_assign(param->key, param->string);
>> len = rpc_pton(fc->net_ns, param->string, param-
>>> size,
>> &ctx->mount_server.address,
>> sizeof(ctx->mount_server._address));
>> @@ -846,7 +855,6 @@ static int nfs_fs_context_parse_param(struct
>> fs_context *fc,
>> */
>> case Opt_sloppy:
>> ctx->sloppy = true;
>> - dfprintk(MOUNT, "NFS: relaxing parsing rules\n");
>> break;
>> }
>>
>> @@ -879,10 +887,8 @@ static int nfs_parse_source(struct fs_context
>> *fc,
>> size_t len;
>> const char *end;
>>
>> - if (unlikely(!dev_name || !*dev_name)) {
>> - dfprintk(MOUNT, "NFS: device name not specified\n");
>> + if (unlikely(!dev_name || !*dev_name))
>> return -EINVAL;
>> - }
>>
>> /* Is the host name protected with square brakcets? */
>> if (*dev_name == '[') {
>> @@ -922,7 +928,7 @@ static int nfs_parse_source(struct fs_context
>> *fc,
>> if (!ctx->nfs_server.export_path)
>> goto out_nomem;
>>
>> - dfprintk(MOUNT, "NFS: MNTPATH: '%s'\n", ctx-
>>> nfs_server.export_path);
>> + trace_nfs_mount_path(ctx->nfs_server.export_path);
>> return 0;
>>
>> out_bad_devname:
>> @@ -1116,7 +1122,6 @@ static int nfs23_parse_monolithic(struct
>> fs_context *fc,
>> return nfs_invalf(fc, "NFS: nfs_mount_data version supports
>> only AUTH_SYS");
>>
>> out_nomem:
>> - dfprintk(MOUNT, "NFS: not enough memory to handle mount
>> options");
>> return -ENOMEM;
>>
>> out_no_address:
>> @@ -1248,7 +1253,7 @@ static int nfs4_parse_monolithic(struct
>> fs_context *fc,
>> if (IS_ERR(c))
>> return PTR_ERR(c);
>> ctx->nfs_server.export_path = c;
>> - dfprintk(MOUNT, "NFS: MNTPATH: '%s'\n", c);
>> + trace_nfs_mount_path(c);
>>
>> c = strndup_user(data->client_addr.data, 16);
>> if (IS_ERR(c))
>> diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
>> index 012bd7339862..ccaeae42ee77 100644
>> --- a/fs/nfs/nfstrace.h
>> +++ b/fs/nfs/nfstrace.h
>> @@ -1609,6 +1609,83 @@ TRACE_EVENT(nfs_fh_to_dentry,
>> )
>> );
>>
>> +TRACE_EVENT(nfs_mount_addr_err,
>> + TP_PROTO(
>> + const struct sockaddr *sap
>> + ),
>> +
>> + TP_ARGS(sap),
>> +
>> + TP_STRUCT__entry(
>> + __array(unsigned char, addr, sizeof(struct
>> sockaddr_in6))
>> + ),
>> +
>> + TP_fast_assign(
>> + memcpy(__entry->addr, sap, sizeof(__entry->addr));
>> + ),
>> +
>> + TP_printk("addr=%pISpc", __entry->addr)
>
> Ditto problem with this.
This tracepoint records a /bad/ address, and the caller does
not have the presentation address value from which it was
derived. I don't see a way to record a presentation address
here, so I will remove trace_nfs_mount_addr_err() in the
next revision of this patch.
>> +);
>> +
>> +TRACE_EVENT(nfs_mount_assign,
>> + TP_PROTO(
>> + const char *option,
>> + const char *value
>> + ),
>> +
>> + TP_ARGS(option, value),
>> +
>> + TP_STRUCT__entry(
>> + __string(option, option)
>> + __string(value, value)
>> + ),
>> +
>> + TP_fast_assign(
>> + __assign_str(option, option);
>> + __assign_str(value, value);
>> + ),
>> +
>> + TP_printk("option %s=%s",
>> + __get_str(option), __get_str(value)
>> + )
>> +);
>> +
>> +TRACE_EVENT(nfs_mount_option,
>> + TP_PROTO(
>> + const struct fs_parameter *param
>> + ),
>> +
>> + TP_ARGS(param),
>> +
>> + TP_STRUCT__entry(
>> + __string(option, param->key)
>> + ),
>> +
>> + TP_fast_assign(
>> + __assign_str(option, param->key);
>> + ),
>> +
>> + TP_printk("option %s", __get_str(option))
>> +);
>> +
>> +TRACE_EVENT(nfs_mount_path,
>> + TP_PROTO(
>> + const char *path
>> + ),
>> +
>> + TP_ARGS(path),
>> +
>> + TP_STRUCT__entry(
>> + __string(path, path)
>> + ),
>> +
>> + TP_fast_assign(
>> + __assign_str(path, path);
>> + ),
>> +
>> + TP_printk("path='%s'", __get_str(path))
>> +);
>> +
>> DECLARE_EVENT_CLASS(nfs_xdr_event,
>> TP_PROTO(
>> const struct xdr_stream *xdr,
>>
>>
>
> --
> Trond Myklebust
> Linux NFS client maintainer, Hammerspace
> [email protected]
--
Chuck Lever
[ Added the user space perf folks ]
On Fri, 22 Jul 2022 18:45:30 +0000
Chuck Lever III <[email protected]> wrote:
> >> +TRACE_EVENT(xs_data_ready,
> >> + TP_PROTO(
> >> + const struct rpc_xprt *xprt
> >> + ),
> >> +
> >> + TP_ARGS(xprt),
> >> +
> >> + TP_STRUCT__entry(
> >> + __sockaddr(addr, xprt->addrlen)
> >> + ),
> >> +
> >> + TP_fast_assign(
> >> + __assign_sockaddr(addr, &xprt->addr, xprt->addrlen);
> >> + ),
> >> +
> >> + TP_printk("peer=%pISpc", __get_sockaddr(addr))
> >
> > NACK. Please resolve and store the string up front instead of storing
> > the sockaddr. Most versions of perf can't resolve those kernel-specific
> > %p printks and just end up barfing on them.
>
> Interesting. We added get_sockaddr() to avoid this issue in
> trace-cmd. Sounds like perf needs to be fixed up too, or
> maybe this is another case of having an old libtraceevent?
>
> Meanwhile, I can revert this back to the old way of handling
> presentation addresses.
>
Hmm, I thought that perf now uses the external libtraceevent.
Perhaps it hasn't been updated to the latest release that has the ability
to parse this.
Maybe just install
git://git.kernel.org/pub/scm/libs/libtrace/libtraceevent.git
?
-- Steve
On Fri, 2022-07-22 at 17:55 +0000, Chuck Lever III wrote:
>
>
> > On Jul 22, 2022, at 1:53 PM, Trond Myklebust
> > <[email protected]> wrote:
> >
> > On Fri, 2022-07-22 at 13:25 -0400, Chuck Lever wrote:
> > > There is just one unused bit left in rpc_task::tk_flags, and I
> > > will
> > > need two in subsequent patches. Double the width of the field to
> > > accommodate more flag bits.
> >
> > The values 0x8 and 0x40 are both free, so I'm not seeing why this
> > patch
> > is needed at this time.
>
> It's not needed now, but as recently as last year, there were no free
> bits (and I needed them for RPC-with-TLS support at that time). We
> will
> have to widen this field sooner or later.
>
> I don't have a problem dropping this one if you'd rather wait.
>
I dropped it after applying the other v2 patches. As I said, I don't
see a need for this expansion yet, and if we do at some point run out
of bits, I can see other flags we can drop (RPC_TASK_ROOTCREDS and
RPC_TASK_NULLCREDS being obvious targets) before we need to consider
actually expanding the size of this field.
In fact, by not expanding it, we can trivially shrink the size of
struct rpc_task by 8 bytes on x86_64 simply by moving the field
tk_rpc_status to eliminate the current 4 byte hole. I've added a patch
to do just that.
--
Trond Myklebust
Linux NFS client maintainer, Hammerspace
[email protected]
> On Jul 23, 2022, at 4:10 PM, Trond Myklebust <[email protected]> wrote:
>
> On Fri, 2022-07-22 at 17:55 +0000, Chuck Lever III wrote:
>>
>>
>>> On Jul 22, 2022, at 1:53 PM, Trond Myklebust
>>> <[email protected]> wrote:
>>>
>>> On Fri, 2022-07-22 at 13:25 -0400, Chuck Lever wrote:
>>>> There is just one unused bit left in rpc_task::tk_flags, and I
>>>> will
>>>> need two in subsequent patches. Double the width of the field to
>>>> accommodate more flag bits.
>>>
>>> The values 0x8 and 0x40 are both free, so I'm not seeing why this
>>> patch
>>> is needed at this time.
>>
>> It's not needed now, but as recently as last year, there were no free
>> bits (and I needed them for RPC-with-TLS support at that time). We
>> will
>> have to widen this field sooner or later.
>>
>> I don't have a problem dropping this one if you'd rather wait.
>>
>
> I dropped it after applying the other v2 patches.
Thanks for applying the others; I'll drop this one from
my private tree.
> As I said, I don't
> see a need for this expansion yet, and if we do at some point run out
> of bits, I can see other flags we can drop (RPC_TASK_ROOTCREDS and
> RPC_TASK_NULLCREDS being obvious targets) before we need to consider
> actually expanding the size of this field.
Agreed, expanding the flags field is no longer necessary for
RPC-with-TLS, as I've converted it to use the layered connect
mechanism you suggested. The flag it waits on now is
XPRT_CONNECTED.
> In fact, by not expanding it, we can trivially shrink the size of
> struct rpc_task by 8 bytes on x86_64 simply by moving the field
> tk_rpc_status to eliminate the current 4 byte hole. I've added a patch
> to do just that.
--
Chuck Lever
Em Fri, Jul 22, 2022 at 04:22:12PM -0400, Steven Rostedt escreveu:
> [ Added the user space perf folks ]
>
> On Fri, 22 Jul 2022 18:45:30 +0000
> Chuck Lever III <[email protected]> wrote:
>
> > >> +TRACE_EVENT(xs_data_ready,
> > >> + TP_PROTO(
> > >> + const struct rpc_xprt *xprt
> > >> + ),
> > >> +
> > >> + TP_ARGS(xprt),
> > >> +
> > >> + TP_STRUCT__entry(
> > >> + __sockaddr(addr, xprt->addrlen)
> > >> + ),
> > >> +
> > >> + TP_fast_assign(
> > >> + __assign_sockaddr(addr, &xprt->addr, xprt->addrlen);
> > >> + ),
> > >> +
> > >> + TP_printk("peer=%pISpc", __get_sockaddr(addr))
> > >
> > > NACK. Please resolve and store the string up front instead of storing
> > > the sockaddr. Most versions of perf can't resolve those kernel-specific
> > > %p printks and just end up barfing on them.
> >
> > Interesting. We added get_sockaddr() to avoid this issue in
> > trace-cmd. Sounds like perf needs to be fixed up too, or
> > maybe this is another case of having an old libtraceevent?
> >
> > Meanwhile, I can revert this back to the old way of handling
> > presentation addresses.
> >
>
> Hmm, I thought that perf now uses the external libtraceevent.
>
> Perhaps it hasn't been updated to the latest release that has the ability
> to parse this.
>
> Maybe just install
>
> git://git.kernel.org/pub/scm/libs/libtrace/libtraceevent.git
To use it one has to use:
make -C tools/perf LIBTRACEEVENT_DYNAMIC=1
Then we get it linked with libtraceevent-devel:
$ ldd ~/bin/perf | grep traceevent
libtraceevent.so.1 => /lib64/libtraceevent.so.1 (0x00007faa50f93000)
$
Perhaps it'd be better to check if libtracevent-devel is installed and
use it, falling back to tools/lib/traceevent/ and then adding a warning
that the in-tree codebase is being used?
- Arnaldo
On Mon, 25 Jul 2022 12:49:20 -0300
Arnaldo Carvalho de Melo <[email protected]> wrote:
> Perhaps it'd be better to check if libtracevent-devel is installed and
> use it, falling back to tools/lib/traceevent/ and then adding a warning
> that the in-tree codebase is being used?
Yeah, this is the way trace-cmd went. For a few releases, it would just
warn that it couldn't find the system libraries, and then fall back to the
internals, and then it finally just removed the internals and failed with a
message stating where to get the necessary libraries.
-- Steve