* [PATCH RESEND net-next] netlink: add tracepoint at NL_SET_ERR_MSG
@ 2021-02-01 18:12 Marcelo Ricardo Leitner
2021-02-02 1:34 ` Jakub Kicinski
2021-02-03 22:31 ` Jakub Kicinski
0 siblings, 2 replies; 6+ messages in thread
From: Marcelo Ricardo Leitner @ 2021-02-01 18:12 UTC (permalink / raw)
To: netdev; +Cc: Marcelo Ricardo Leitner
Often userspace won't request the extack information, or they don't log it
because of log level or so, and even when they do, sometimes it's not
enough to know exactly what caused the error.
Netlink extack is the standard way of reporting erros with descriptive
error messages. With a trace point on it, we then can know exactly where
the error happened, regardless of userspace app. Also, we can even see if
the err msg was overwritten.
The wrapper do_trace_netlink_extack() is because trace points shouldn't be
called from .h files, as trace points are not that small, and the function
call to do_trace_netlink_extack() on the macros is not protected by
tracepoint_enabled() because the macros are called from modules, and this
would require exporting some trace structs. As this is error path, it's
better to export just the wrapper instead.
Signed-off-by: Marcelo Ricardo Leitner <marcelo.leitner@gmail.com>
---
include/linux/netlink.h | 8 ++++++++
include/trace/events/netlink.h | 29 +++++++++++++++++++++++++++++
net/netlink/af_netlink.c | 8 ++++++++
3 files changed, 45 insertions(+)
create mode 100644 include/trace/events/netlink.h
diff --git a/include/linux/netlink.h b/include/linux/netlink.h
index 9f118771e24808623287d46157046749ec96a2b5..fe77f30aabfdde8882f6de99ecf633b79e903b77 100644
--- a/include/linux/netlink.h
+++ b/include/linux/netlink.h
@@ -6,11 +6,15 @@
#include <linux/capability.h>
#include <linux/skbuff.h>
#include <linux/export.h>
+#include <linux/tracepoint.h>
#include <net/scm.h>
#include <uapi/linux/netlink.h>
struct net;
+DECLARE_TRACEPOINT(netlink_extack);
+void do_trace_netlink_extack(const char *msg);
+
static inline struct nlmsghdr *nlmsg_hdr(const struct sk_buff *skb)
{
return (struct nlmsghdr *)skb->data;
@@ -90,6 +94,8 @@ struct netlink_ext_ack {
static const char __msg[] = msg; \
struct netlink_ext_ack *__extack = (extack); \
\
+ do_trace_netlink_extack(__msg); \
+ \
if (__extack) \
__extack->_msg = __msg; \
} while (0)
@@ -110,6 +116,8 @@ struct netlink_ext_ack {
static const char __msg[] = msg; \
struct netlink_ext_ack *__extack = (extack); \
\
+ do_trace_netlink_extack(__msg); \
+ \
if (__extack) { \
__extack->_msg = __msg; \
__extack->bad_attr = (attr); \
diff --git a/include/trace/events/netlink.h b/include/trace/events/netlink.h
new file mode 100644
index 0000000000000000000000000000000000000000..3b7be3b386a4f3976738a107fe4b7e0915ae58bb
--- /dev/null
+++ b/include/trace/events/netlink.h
@@ -0,0 +1,29 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM netlink
+
+#if !defined(_TRACE_NETLINK_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_NETLINK_H
+
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(netlink_extack,
+
+ TP_PROTO(const char *msg),
+
+ TP_ARGS(msg),
+
+ TP_STRUCT__entry(
+ __string( msg, msg )
+ ),
+
+ TP_fast_assign(
+ __assign_str(msg, msg);
+ ),
+
+ TP_printk("msg=%s", __get_str(msg))
+);
+
+#endif /* _TRACE_NETLINK_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/net/netlink/af_netlink.c b/net/netlink/af_netlink.c
index daca50d6bb1283f3b04b585217f2aea6ba279b8b..dd488938447f9735daf1fb727c339a9874bab38b 100644
--- a/net/netlink/af_netlink.c
+++ b/net/netlink/af_netlink.c
@@ -67,6 +67,8 @@
#include <net/sock.h>
#include <net/scm.h>
#include <net/netlink.h>
+#define CREATE_TRACE_POINTS
+#include <trace/events/netlink.h>
#include "af_netlink.h"
@@ -147,6 +149,12 @@ static BLOCKING_NOTIFIER_HEAD(netlink_chain);
static const struct rhashtable_params netlink_rhashtable_params;
+void do_trace_netlink_extack(const char *msg)
+{
+ trace_netlink_extack(msg);
+}
+EXPORT_SYMBOL(do_trace_netlink_extack);
+
static inline u32 netlink_group_mask(u32 group)
{
return group ? 1 << (group - 1) : 0;
--
2.29.2
^ permalink raw reply related [flat|nested] 6+ messages in thread* Re: [PATCH RESEND net-next] netlink: add tracepoint at NL_SET_ERR_MSG
2021-02-01 18:12 [PATCH RESEND net-next] netlink: add tracepoint at NL_SET_ERR_MSG Marcelo Ricardo Leitner
@ 2021-02-02 1:34 ` Jakub Kicinski
2021-02-02 12:30 ` Marcelo Ricardo Leitner
2021-02-03 22:31 ` Jakub Kicinski
1 sibling, 1 reply; 6+ messages in thread
From: Jakub Kicinski @ 2021-02-02 1:34 UTC (permalink / raw)
To: Marcelo Ricardo Leitner; +Cc: netdev
On Mon, 1 Feb 2021 15:12:19 -0300 Marcelo Ricardo Leitner wrote:
> Often userspace won't request the extack information, or they don't log it
> because of log level or so, and even when they do, sometimes it's not
> enough to know exactly what caused the error.
>
> Netlink extack is the standard way of reporting erros with descriptive
> error messages. With a trace point on it, we then can know exactly where
> the error happened, regardless of userspace app. Also, we can even see if
> the err msg was overwritten.
>
> The wrapper do_trace_netlink_extack() is because trace points shouldn't be
> called from .h files, as trace points are not that small, and the function
> call to do_trace_netlink_extack() on the macros is not protected by
> tracepoint_enabled() because the macros are called from modules, and this
> would require exporting some trace structs. As this is error path, it's
> better to export just the wrapper instead.
>
> Signed-off-by: Marcelo Ricardo Leitner <marcelo.leitner@gmail.com>
Did you measure the allyesconfig bloat from this?
How valuable is it to have the tracepoint in at the time it's set?
IIRC extack is passed in to the callbacks from the netlink core, it's
just not reported to user space if not requested. So we could capture
the message in af_netlink.c, no?
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH RESEND net-next] netlink: add tracepoint at NL_SET_ERR_MSG
2021-02-02 1:34 ` Jakub Kicinski
@ 2021-02-02 12:30 ` Marcelo Ricardo Leitner
2021-02-02 16:16 ` David Ahern
0 siblings, 1 reply; 6+ messages in thread
From: Marcelo Ricardo Leitner @ 2021-02-02 12:30 UTC (permalink / raw)
To: Jakub Kicinski; +Cc: netdev
On Mon, Feb 01, 2021 at 05:34:00PM -0800, Jakub Kicinski wrote:
> On Mon, 1 Feb 2021 15:12:19 -0300 Marcelo Ricardo Leitner wrote:
> > Often userspace won't request the extack information, or they don't log it
> > because of log level or so, and even when they do, sometimes it's not
> > enough to know exactly what caused the error.
> >
> > Netlink extack is the standard way of reporting erros with descriptive
> > error messages. With a trace point on it, we then can know exactly where
> > the error happened, regardless of userspace app. Also, we can even see if
> > the err msg was overwritten.
> >
> > The wrapper do_trace_netlink_extack() is because trace points shouldn't be
> > called from .h files, as trace points are not that small, and the function
> > call to do_trace_netlink_extack() on the macros is not protected by
> > tracepoint_enabled() because the macros are called from modules, and this
> > would require exporting some trace structs. As this is error path, it's
> > better to export just the wrapper instead.
> >
> > Signed-off-by: Marcelo Ricardo Leitner <marcelo.leitner@gmail.com>
>
> Did you measure the allyesconfig bloat from this?
Now I did:
$ ./scripts/bloat-o-meter -t out/{orig,new}/vmlinux
...
Total: Before=212077464, After=212108056, chg +0.01%
$ size out/{orig,new}/vmlinux
text data bss dec hex filename
267409181 333328965 83018348 683756494 28c14bce out/orig/vmlinux
267413171 333337273 83010156 683760600 28c15bd8 out/new/vmlinux
with the commit on top of 46eb3c108fe1744d0a6abfda69ef8c1d4f0e92d4.
It's not much because it's adding just a function call to the macro,
rather than the tracepoint itself.
> How valuable is it to have the tracepoint in at the time it's set?
To know exactly its source. It's very helpful to track down some
EINVALs reported to userspace. If not, we have to rely on the errmsg
and grep the code afterwards.
Also, if the message is a common one, one may not be able to easily
distinguish them. Ideally this shouldn't happen, but when debugging
applications such as OVS, where lots of netlink requests are flying,
it saves us time. I can, for example, look at a perf capture and
search for cls_flower or so. Otherwise, it will all show up as
"af_netlink: <err_msg>"
Also, it allows tracking when a previous errmsg (which would have been
a warning) is overwritten with a new one.
> IIRC extack is passed in to the callbacks from the netlink core, it's
> just not reported to user space if not requested. So we could capture
> the message in af_netlink.c, no?
If 4k is too much, yes. It looses practicality, per above, but should
be doable.
Marcelo
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: [PATCH RESEND net-next] netlink: add tracepoint at NL_SET_ERR_MSG
2021-02-02 12:30 ` Marcelo Ricardo Leitner
@ 2021-02-02 16:16 ` David Ahern
2021-02-02 19:30 ` Marcelo Ricardo Leitner
0 siblings, 1 reply; 6+ messages in thread
From: David Ahern @ 2021-02-02 16:16 UTC (permalink / raw)
To: Marcelo Ricardo Leitner, Jakub Kicinski; +Cc: netdev
On 2/2/21 5:30 AM, Marcelo Ricardo Leitner wrote:
>
> Also, if the message is a common one, one may not be able to easily
> distinguish them. Ideally this shouldn't happen, but when debugging
> applications such as OVS, where lots of netlink requests are flying,
> it saves us time. I can, for example, look at a perf capture and
> search for cls_flower or so. Otherwise, it will all show up as
> "af_netlink: <err_msg>"
Modules should be using the NL_SET_ERR_MSG_MOD variant, so the message
would be ""af_netlink: cls_flower: <err_msg>"
I get the value in knowing the call site, so not arguing against that.
Just hoping that your experience matches theory.
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH RESEND net-next] netlink: add tracepoint at NL_SET_ERR_MSG
2021-02-02 16:16 ` David Ahern
@ 2021-02-02 19:30 ` Marcelo Ricardo Leitner
0 siblings, 0 replies; 6+ messages in thread
From: Marcelo Ricardo Leitner @ 2021-02-02 19:30 UTC (permalink / raw)
To: David Ahern; +Cc: Jakub Kicinski, netdev
On Tue, Feb 02, 2021 at 09:16:28AM -0700, David Ahern wrote:
> On 2/2/21 5:30 AM, Marcelo Ricardo Leitner wrote:
> >
> > Also, if the message is a common one, one may not be able to easily
> > distinguish them. Ideally this shouldn't happen, but when debugging
> > applications such as OVS, where lots of netlink requests are flying,
> > it saves us time. I can, for example, look at a perf capture and
> > search for cls_flower or so. Otherwise, it will all show up as
> > "af_netlink: <err_msg>"
>
> Modules should be using the NL_SET_ERR_MSG_MOD variant, so the message
> would be ""af_netlink: cls_flower: <err_msg>"
Ah, right. They don't always do, though (and that probably should be
fixed). Also, currently there is no _MOD variant for NL_SET_ERR_MSG_ATTR.
For example:
$ git grep NL_SET_ERR_MSG -- cls_flower.c
cls_flower.c: NL_SET_ERR_MSG_MOD(extack, "Failed to setup flow action");
cls_flower.c: NL_SET_ERR_MSG_ATTR(extack,
cls_flower.c: NL_SET_ERR_MSG_ATTR(extack,
cls_flower.c: NL_SET_ERR_MSG(extack, "Missing MPLS option \"depth\"");
...
>
> I get the value in knowing the call site, so not arguing against that.
> Just hoping that your experience matches theory.
Okay.
Thanks,
Marcelo
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH RESEND net-next] netlink: add tracepoint at NL_SET_ERR_MSG
2021-02-01 18:12 [PATCH RESEND net-next] netlink: add tracepoint at NL_SET_ERR_MSG Marcelo Ricardo Leitner
2021-02-02 1:34 ` Jakub Kicinski
@ 2021-02-03 22:31 ` Jakub Kicinski
1 sibling, 0 replies; 6+ messages in thread
From: Jakub Kicinski @ 2021-02-03 22:31 UTC (permalink / raw)
To: Marcelo Ricardo Leitner; +Cc: netdev
On Mon, 1 Feb 2021 15:12:19 -0300 Marcelo Ricardo Leitner wrote:
> Often userspace won't request the extack information, or they don't log it
> because of log level or so, and even when they do, sometimes it's not
> enough to know exactly what caused the error.
>
> Netlink extack is the standard way of reporting erros with descriptive
> error messages. With a trace point on it, we then can know exactly where
> the error happened, regardless of userspace app. Also, we can even see if
> the err msg was overwritten.
>
> The wrapper do_trace_netlink_extack() is because trace points shouldn't be
> called from .h files, as trace points are not that small, and the function
> call to do_trace_netlink_extack() on the macros is not protected by
> tracepoint_enabled() because the macros are called from modules, and this
> would require exporting some trace structs. As this is error path, it's
> better to export just the wrapper instead.
>
> Signed-off-by: Marcelo Ricardo Leitner <marcelo.leitner@gmail.com>
> --- a/include/linux/netlink.h
> +++ b/include/linux/netlink.h
> @@ -6,11 +6,15 @@
> #include <linux/capability.h>
> #include <linux/skbuff.h>
> #include <linux/export.h>
> +#include <linux/tracepoint.h>
Do we need the include...
> #include <net/scm.h>
> #include <uapi/linux/netlink.h>
>
> struct net;
>
> +DECLARE_TRACEPOINT(netlink_extack);
... and the declaration? Seems to be a leftover.
> +void do_trace_netlink_extack(const char *msg);
> +
> static inline struct nlmsghdr *nlmsg_hdr(const struct sk_buff *skb)
> {
> return (struct nlmsghdr *)skb->data;
> @@ -90,6 +94,8 @@ struct netlink_ext_ack {
> static const char __msg[] = msg; \
> struct netlink_ext_ack *__extack = (extack); \
> \
> + do_trace_netlink_extack(__msg); \
> + \
> if (__extack) \
> __extack->_msg = __msg; \
> } while (0)
> @@ -110,6 +116,8 @@ struct netlink_ext_ack {
> static const char __msg[] = msg; \
> struct netlink_ext_ack *__extack = (extack); \
> \
> + do_trace_netlink_extack(__msg); \
> + \
> if (__extack) { \
> __extack->_msg = __msg; \
> __extack->bad_attr = (attr); \
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2021-02-03 22:32 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2021-02-01 18:12 [PATCH RESEND net-next] netlink: add tracepoint at NL_SET_ERR_MSG Marcelo Ricardo Leitner
2021-02-02 1:34 ` Jakub Kicinski
2021-02-02 12:30 ` Marcelo Ricardo Leitner
2021-02-02 16:16 ` David Ahern
2021-02-02 19:30 ` Marcelo Ricardo Leitner
2021-02-03 22:31 ` Jakub Kicinski
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).