netdev: show a process of packets

[RFC PATCH v3 4/5] skb: add tracepoints to freeing skb
This patch adds tracepoint to consume_skb, dev_kfree_skb_irq and skb_free_datagram_locked. Combinating with tracepoint on dev_hard_start_xmit, we can check how long it takes to free transmited packets. And using it, we can calculate how many packets driver had at that time. It is useful when a drop of transmited packet is a problem.

          <idle>-0     [001] 241409.218333: consume_skb: skbaddr=dd6b2fb8
          <idle>-0     [001] 241409.490555: dev_kfree_skb_irq: skbaddr=f5e29840

        udp-recv-302   [001] 515031.206008: skb_free_datagram_locked: skbaddr=f5b1d900

Signed-off-by Koki Sanagi <[email protected]>

---
 include/trace/events/skb.h |   42 ++++++++++++++++++++++++++++++++++++++++++
 net/core/datagram.c        |    1 +
 net/core/dev.c             |    2 ++
 net/core/skbuff.c          |    1 +
 4 files changed, 46 insertions(+), 0 deletions(-)

include/trace/events/skb.h +42 -0

index 4b2be6d..84c9041 100644
@@ -35,6 +35,48 @@ TRACE_EVENT(kfree_skb,
 		__entry->skbaddr, __entry->protocol, __entry->location)
 );
 
+DECLARE_EVENT_CLASS(free_skb,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb),
+
+	TP_STRUCT__entry(
+		__field(	void *,	skbaddr	)
+	),
+
+	TP_fast_assign(
+		__entry->skbaddr = skb;
+	),
+
+	TP_printk("skbaddr=%p", __entry->skbaddr)
+
+);
+
+DEFINE_EVENT(free_skb, consume_skb,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+
+DEFINE_EVENT(free_skb, dev_kfree_skb_irq,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+
+DEFINE_EVENT(free_skb, skb_free_datagram_locked,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+
 TRACE_EVENT(skb_copy_datagram_iovec,
 
 	TP_PROTO(const struct sk_buff *skb, int len),

net/core/datagram.c +0 -0

index f5b6f43..1ea32a0 100644

net/core/datagram.c +0 -0

 	if (likely(atomic_read(&skb->users) == 1))
 		smp_rmb();
 	else if (likely(!atomic_dec_and_test(&skb->users)))

net/core/dev.c +2 -0

index 4acfec6..d979847 100644
@@ -131,6 +131,7 @@
 #include <linux/random.h>
 #include <trace/events/napi.h>
 #include <trace/events/net.h>
+#include <trace/events/skb.h>
 #include <linux/pci.h>
 
 #include "net-sysfs.h"

@@ -1581,6 +1582,7 @@ void dev_kfree_skb_irq(struct sk_buff *skb)
 		struct softnet_data *sd;
 		unsigned long flags;
 
+		trace_dev_kfree_skb_irq(skb);
 		local_irq_save(flags);
 		sd = &__get_cpu_var(softnet_data);
 		skb->next = sd->completion_queue;

net/core/skbuff.c +0 -0

index 34432b4..a7b4036 100644

net/core/skbuff.c +1 -0

+	trace_consume_skb(skb);
 	__kfree_skb(skb);
 }
 EXPORT_SYMBOL(consume_skb);

Quoted 79 lines · Koki Sanagi

[RFC PATCH v3 4/5] skb: add tracepoints to freeing skb
This patch adds tracepoint to consume_skb, dev_kfree_skb_irq and skb_free_datagram_locked. Combinating with tracepoint on dev_hard_start_xmit, we can check how long it takes to free transmited packets. And using it, we can calculate how many packets driver had at that time. It is useful when a drop of transmited packet is a problem.

          <idle>-0     [001] 241409.218333: consume_skb: skbaddr=dd6b2fb8
          <idle>-0     [001] 241409.490555: dev_kfree_skb_irq: skbaddr=f5e29840

        udp-recv-302   [001] 515031.206008: skb_free_datagram_locked: skbaddr=f5b1d900

Signed-off-by Koki Sanagi <[email protected]>

---
 include/trace/events/skb.h |   42 ++++++++++++++++++++++++++++++++++++++++++
 net/core/datagram.c        |    1 +
 net/core/dev.c             |    2 ++
 net/core/skbuff.c          |    1 +
 4 files changed, 46 insertions(+), 0 deletions(-)

include/trace/events/skb.h +42 -0

index 4b2be6d..84c9041 100644
@@ -35,6 +35,48 @@ TRACE_EVENT(kfree_skb,
 		__entry->skbaddr, __entry->protocol, __entry->location)
 );
 
+DECLARE_EVENT_CLASS(free_skb,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb),
+
+	TP_STRUCT__entry(
+		__field(	void *,	skbaddr	)
+	),
+
+	TP_fast_assign(
+		__entry->skbaddr = skb;
+	),
+
+	TP_printk("skbaddr=%p", __entry->skbaddr)
+
+);
+
+DEFINE_EVENT(free_skb, consume_skb,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+
+DEFINE_EVENT(free_skb, dev_kfree_skb_irq,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+
+DEFINE_EVENT(free_skb, skb_free_datagram_locked,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+
 TRACE_EVENT(skb_copy_datagram_iovec,
 
 	TP_PROTO(const struct sk_buff *skb, int len),

net/core/datagram.c +0 -0

index f5b6f43..1ea32a0 100644

net/core/datagram.c void skb_free_datagram_locked(struct sock *sk, struct sk_buff *skb) · line 234

Quoted 4 lines

net/core/datagram.c +1 -0

@@ -231,6 +231,7 @@ void skb_free_datagram_locked(struct sock *sk, struct sk_buff *skb)
 {
 	bool slow;
 
+	trace_skb_free_datagram_locked(skb);

Here you unconditionally trace before the test on skb->users

Quoted 19 lines

net/core/datagram.c +0 -0

 	if (likely(atomic_read(&skb->users) == 1))
 		smp_rmb();
 	else if (likely(!atomic_dec_and_test(&skb->users)))

net/core/dev.c +1 -0

index 4acfec6..d979847 100644
@@ -131,6 +131,7 @@
 #include <linux/random.h>
 #include <trace/events/napi.h>
 #include <trace/events/net.h>
+#include <trace/events/skb.h>
 #include <linux/pci.h>
 
 #include "net-sysfs.h"

@@ -1581,6 +1582,7 @@ void dev_kfree_skb_irq(struct sk_buff *skb)
 		struct softnet_data *sd;
 		unsigned long flags;
 

net/core/skbuff.c void consume_skb(struct sk_buff *skb) · line 468

Quoted 12 lines

net/core/dev.c +1 -0

+		trace_dev_kfree_skb_irq(skb);
 		local_irq_save(flags);
 		sd = &__get_cpu_var(softnet_data);
 		skb->next = sd->completion_queue;

net/core/skbuff.c +0 -0

index 34432b4..a7b4036 100644
@@ -466,6 +466,7 @@ void consume_skb(struct sk_buff *skb)
 		smp_rmb();
 	else if (likely(!atomic_dec_and_test(&skb->users)))
 		return;

While here you trace _after_ the test on skb->users - and a "return;" , so you miss some consume_skb() calls

Quoted 6 lines

net/core/skbuff.c +1 -0

+	trace_consume_skb(skb);
 	__kfree_skb(skb);
 }
 EXPORT_SYMBOL(consume_skb);

From: Lai Jiangshan <[email protected]>

Add a tracepoint for tracing when softirq action is raised.

It and the existed tracepoints complete softirq's tracepoints:
softirq_raise, softirq_entry and softirq_exit.

And when this tracepoint is used in combination with the softirq_entry tracepoint we can determine the softirq raise latency.

Signed-off-by Lai Jiangshan <[email protected]>

Acked-by Mathieu Desnoyers <[email protected]>

Acked-by Frederic Weisbecker <[email protected]>

[ factorize softirq events with DECLARE_EVENT_CLASS ]

Signed-off-by Koki Sanagi <[email protected]>

---
 include/linux/interrupt.h  |    8 +++++-
 include/trace/events/irq.h |   57 ++++++++++++++++++++++++++-----------------
 kernel/softirq.c           |    4 +-
 3 files changed, 43 insertions(+), 26 deletions(-)

include/linux/interrupt.h +1 -0

index c233113..1cb5726 100644
@@ -18,6 +18,7 @@
 #include <asm/atomic.h>
 #include <asm/ptrace.h>
 #include <asm/system.h>
+#include <trace/events/irq.h>
 
 /*
  * These correspond to the IORESOURCE_IRQ_* defines in

include/linux/interrupt.h +0 -0

 extern void raise_softirq_irqoff(unsigned int nr);
 extern void raise_softirq(unsigned int nr);
 extern void wakeup_softirqd(void);

include/trace/events/irq.h +34 -23

index 0e4cfb6..717744c 100644
@@ -5,7 +5,9 @@
 #define _TRACE_IRQ_H
 
 #include <linux/tracepoint.h>
-#include <linux/interrupt.h>
+
+struct irqaction;
+struct softirq_action;
 
 #define softirq_name(sirq) { sirq##_SOFTIRQ, #sirq }
 #define show_softirq_name(val)				\

@@ -84,56 +86,65 @@ TRACE_EVENT(irq_handler_exit,
 
 DECLARE_EVENT_CLASS(softirq,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int nr),
 
-	TP_ARGS(h, vec),
+	TP_ARGS(nr),
 
 	TP_STRUCT__entry(
-		__field(	int,	vec			)
+		__field(	unsigned int,	vec	)
 	),
 
 	TP_fast_assign(
-		__entry->vec = (int)(h - vec);
+		__entry->vec	= nr;
 	),
 
 	TP_printk("vec=%d [action=%s]", __entry->vec,
-		  show_softirq_name(__entry->vec))
+		show_softirq_name(__entry->vec))
+);
+
+/**
+ * softirq_raise - called immediately when a softirq is raised
+ * @nr: softirq vector number
+ *
+ * Tracepoint for tracing when softirq action is raised.
+ * Also, when used in combination with the softirq_entry tracepoint
+ * we can determine the softirq raise latency.
+ */
+DEFINE_EVENT(softirq, softirq_raise,
+
+	TP_PROTO(unsigned int nr),
+
+	TP_ARGS(nr)
 );
 
 /**
  * softirq_entry - called immediately before the softirq handler
- * @h: pointer to struct softirq_action
- * @vec: pointer to first struct softirq_action in softirq_vec array
+ * @nr: softirq vector number
  *
- * The @h parameter, contains a pointer to the struct softirq_action
- * which has a pointer to the action handler that is called. By subtracting
- * the @vec pointer from the @h pointer, we can determine the softirq
- * number. Also, when used in combination with the softirq_exit tracepoint
+ * Tracepoint for tracing when softirq action starts.
+ * Also, when used in combination with the softirq_exit tracepoint
  * we can determine the softirq latency.
  */
 DEFINE_EVENT(softirq, softirq_entry,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int nr),
 
-	TP_ARGS(h, vec)
+	TP_ARGS(nr)
 );
 
 /**
  * softirq_exit - called immediately after the softirq handler returns
- * @h: pointer to struct softirq_action
- * @vec: pointer to first struct softirq_action in softirq_vec array
+ * @nr: softirq vector number
  *
- * The @h parameter contains a pointer to the struct softirq_action
- * that has handled the softirq. By subtracting the @vec pointer from
- * the @h pointer, we can determine the softirq number. Also, when used in
- * combination with the softirq_entry tracepoint we can determine the softirq
- * latency.
+ * Tracepoint for tracing when softirq action ends.
+ * Also, when used in combination with the softirq_entry tracepoint
+ * we can determine the softirq latency.
  */
 DEFINE_EVENT(softirq, softirq_exit,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int nr),
 
-	TP_ARGS(h, vec)
+	TP_ARGS(nr)
 );
 
 #endif /*  _TRACE_IRQ_H */

kernel/softirq.c +0 -0

index 825e112..6790599 100644

kernel/softirq.c +0 -1

 			if (unlikely(prev_count != preempt_count())) {
 				printk(KERN_ERR "huh, entered softirq %td %s %p"
 				       "with preempt_count %08x,"
 
--

To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

From: Neil Horman <[email protected]>

This patch converts trace_napi_poll from DECLARE_EVENT to TRACE_EVENT to improve the usability of napi_poll tracepoint.

          <idle>-0     [001] 241302.750777: napi_poll: napi poll on napi struct f6acc480 for device eth3
          <idle>-0     [000] 241302.852389: napi_poll: napi poll on napi struct f5d0d70c for device eth1

An original patch is below.
http://marc.info/?l=linux-kernel&m=126021713809450&w=2

Signed-off-by Neil Horman <[email protected]>

And add a fix by Steven Rostedt.
http://marc.info/?l=linux-kernel&m=126150506519173&w=2

Signed-off-by Koki Sanagi <[email protected]>

---
 include/trace/events/napi.h |   25 +++++++++++++++++++++++--
 1 files changed, 23 insertions(+), 2 deletions(-)

include/trace/events/napi.h +16 -2

index 188deca..8fe1e93 100644
@@ -6,10 +6,31 @@
 
 #include <linux/netdevice.h>
 #include <linux/tracepoint.h>
+#include <linux/ftrace.h>
+
+#define NO_DEV "(no_device)"
+
+TRACE_EVENT(napi_poll,
 
-DECLARE_TRACE(napi_poll,
 	TP_PROTO(struct napi_struct *napi),
-	TP_ARGS(napi));
+
+	TP_ARGS(napi),
+
+	TP_STRUCT__entry(
+		__field(	struct napi_struct *,	napi)
+		__string(	dev_name, napi->dev ? napi->dev->name : NO_DEV)
+	),
+
+	TP_fast_assign(
+		__entry->napi = napi;
+		__assign_str(dev_name, napi->dev ? napi->dev->name : NO_DEV);

This patch adds tracepoint to dev_queue_xmit, dev_hard_start_xmit and netif_receive_skb. These tracepoints help you to monitor network driver's input/output.

            sshd-4445  [001] 241367.066046: net_dev_queue: dev=eth3 skbaddr=dd6b2538 len=114
            sshd-4445  [001] 241367.066047: net_dev_xmit: dev=eth3 skbaddr=dd6b2538 len=114 rc=0
          <idle>-0     [001] 241367.067472: net_dev_receive: dev=eth3 skbaddr=f5e59000 len=52

Signed-off-by Koki Sanagi <[email protected]>

---
 include/trace/events/net.h |   75 ++++++++++++++++++++++++++++++++++++++++++++
 net/core/dev.c             |    5 +++
 net/core/net-traces.c      |    1 +
 3 files changed, 81 insertions(+), 0 deletions(-)

include/trace/events/net.h new file +75 -0

new file mode 100644
index 0000000..8a21361
@@ -0,0 +1,75 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM net
+
+#if !defined(_TRACE_NET_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_NET_H
+
+#include <linux/skbuff.h>
+#include <linux/netdevice.h>
+#include <linux/ip.h>
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(net_dev_xmit,
+
+	TP_PROTO(struct sk_buff *skb,
+		 int rc),
+
+	TP_ARGS(skb, rc),
+
+	TP_STRUCT__entry(
+		__field(	void *,		skbaddr		)
+		__field(	unsigned int,	len		)
+		__field(	int,		rc		)
+		__string(	name,		skb->dev->name	)
+	),
+
+	TP_fast_assign(
+		__entry->skbaddr = skb;
+		__entry->len = skb->len;
+		__entry->rc = rc;
+		__assign_str(name, skb->dev->name);
+	),
+
+	TP_printk("dev=%s skbaddr=%p len=%u rc=%d",
+		__get_str(name), __entry->skbaddr, __entry->len, __entry->rc)
+);
+
+DECLARE_EVENT_CLASS(net_dev_template,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb),
+
+	TP_STRUCT__entry(
+		__field(	void *,		skbaddr		)
+		__field(	unsigned int,	len		)
+		__string(	name,		skb->dev->name	)
+	),
+
+	TP_fast_assign(
+		__entry->skbaddr = skb;
+		__entry->len = skb->len;
+		__assign_str(name, skb->dev->name);
+	),
+
+	TP_printk("dev=%s skbaddr=%p len=%u",
+		__get_str(name), __entry->skbaddr, __entry->len)
+)
+
+DEFINE_EVENT(net_dev_template, net_dev_queue,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+);
+
+DEFINE_EVENT(net_dev_template, net_dev_receive,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+);
+#endif /* _TRACE_NET_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

net/core/dev.c +4 -0

index 93b8929..4acfec6 100644
@@ -130,6 +130,7 @@
 #include <linux/jhash.h>
 #include <linux/random.h>
 #include <trace/events/napi.h>
+#include <trace/events/net.h>
 #include <linux/pci.h>
 
 #include "net-sysfs.h"

@@ -1955,6 +1956,7 @@ int dev_hard_start_xmit(struct sk_buff *skb, struct net_device *dev,
 		}
 
 		rc = ops->ndo_start_xmit(skb, dev);
+		trace_net_dev_xmit(skb, rc);
 		if (rc == NETDEV_TX_OK)
 			txq_trans_update(txq);
 		return rc;

@@ -1975,6 +1977,7 @@ gso:
 			skb_dst_drop(nskb);
 
 		rc = ops->ndo_start_xmit(nskb, dev);
+		trace_net_dev_xmit(nskb, rc);
 		if (unlikely(rc != NETDEV_TX_OK)) {
 			if (rc & ~NETDEV_TX_MASK)
 				goto out_kfree_gso_skb;

@@ -2165,6 +2168,7 @@ int dev_queue_xmit(struct sk_buff *skb)
 #ifdef CONFIG_NET_CLS_ACT
 	skb->tc_verd = SET_TC_AT(skb->tc_verd, AT_EGRESS);
 #endif
+	trace_net_dev_queue(skb);
 	if (q->enqueue) {
 		rc = __dev_xmit_skb(skb, q, dev, txq);
 		goto out;

[RFC PATCH v3 4/5] skb: add tracepoints to freeing skb
This patch adds tracepoint to consume_skb, dev_kfree_skb_irq and skb_free_datagram_locked. Combinating with tracepoint on dev_hard_start_xmit, we can check how long it takes to free transmited packets. And using it, we can calculate how many packets driver had at that time. It is useful when a drop of transmited packet is a problem.

          <idle>-0     [001] 241409.218333: consume_skb: skbaddr=dd6b2fb8
          <idle>-0     [001] 241409.490555: dev_kfree_skb_irq: skbaddr=f5e29840

        udp-recv-302   [001] 515031.206008: skb_free_datagram_locked: skbaddr=f5b1d900

Signed-off-by Koki Sanagi <[email protected]>

---
 include/trace/events/skb.h |   42 ++++++++++++++++++++++++++++++++++++++++++
 net/core/datagram.c        |    1 +
 net/core/dev.c             |    2 ++
 net/core/skbuff.c          |    1 +
 4 files changed, 46 insertions(+), 0 deletions(-)

include/trace/events/skb.h +32 -0

index 4b2be6d..84c9041 100644
@@ -35,6 +35,48 @@ TRACE_EVENT(kfree_skb,
 		__entry->skbaddr, __entry->protocol, __entry->location)
 );
 
+DECLARE_EVENT_CLASS(free_skb,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb),
+
+	TP_STRUCT__entry(
+		__field(	void *,	skbaddr	)
+	),
+
+	TP_fast_assign(
+		__entry->skbaddr = skb;
+	),
+
+	TP_printk("skbaddr=%p", __entry->skbaddr)
+
+);
+
+DEFINE_EVENT(free_skb, consume_skb,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+
+DEFINE_EVENT(free_skb, dev_kfree_skb_irq,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+

Quoted 33 lines · Koki Sanagi

From: Lai Jiangshan <[email protected]>

Add a tracepoint for tracing when softirq action is raised.

It and the existed tracepoints complete softirq's tracepoints:
softirq_raise, softirq_entry and softirq_exit.

And when this tracepoint is used in combination with the softirq_entry tracepoint we can determine the softirq raise latency.

Signed-off-by Lai Jiangshan <[email protected]>

Acked-by Mathieu Desnoyers <[email protected]>

Acked-by Frederic Weisbecker <[email protected]>

[ factorize softirq events with DECLARE_EVENT_CLASS ]

Signed-off-by Koki Sanagi <[email protected]>

---
 include/linux/interrupt.h  |    8 +++++-
 include/trace/events/irq.h |   57 ++++++++++++++++++++++++++-----------------
 kernel/softirq.c           |    4 +-
 3 files changed, 43 insertions(+), 26 deletions(-)

include/linux/interrupt.h +1 -0

index c233113..1cb5726 100644
@@ -18,6 +18,7 @@
 #include <asm/atomic.h>
 #include <asm/ptrace.h>
 #include <asm/system.h>
+#include <trace/events/irq.h>
 

include/linux/interrupt.h asmlinkage void do_softirq(void); · line 411

Quoted 13 lines

include/linux/interrupt.h +6 -1

 /*
  * These correspond to the IORESOURCE_IRQ_* defines in

@@ -402,7 +403,12 @@ asmlinkage void do_softirq(void);
 asmlinkage void __do_softirq(void);
 extern void open_softirq(int nr, void (*action)(struct softirq_action *));
 extern void softirq_init(void);
-#define __raise_softirq_irqoff(nr) do { or_softirq_pending(1UL << (nr)); } while (0)
+static inline void __raise_softirq_irqoff(unsigned int nr)
+{
+	trace_softirq_raise(nr);
+	or_softirq_pending(1UL << nr);
+}
+

We already have tracepoints in irq_enter and irq_exit. If the goal here is to detect latency during packet processing, cant the delta in time between those two points be used to determine interrupt handling latency?

Quoted 116 lines

include/linux/interrupt.h +0 -0

 extern void raise_softirq_irqoff(unsigned int nr);
 extern void raise_softirq(unsigned int nr);
 extern void wakeup_softirqd(void);

include/trace/events/irq.h +34 -23

index 0e4cfb6..717744c 100644
@@ -5,7 +5,9 @@
 #define _TRACE_IRQ_H
 
 #include <linux/tracepoint.h>
-#include <linux/interrupt.h>
+
+struct irqaction;
+struct softirq_action;
 
 #define softirq_name(sirq) { sirq##_SOFTIRQ, #sirq }
 #define show_softirq_name(val)				\

@@ -84,56 +86,65 @@ TRACE_EVENT(irq_handler_exit,
 
 DECLARE_EVENT_CLASS(softirq,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int nr),
 
-	TP_ARGS(h, vec),
+	TP_ARGS(nr),
 
 	TP_STRUCT__entry(
-		__field(	int,	vec			)
+		__field(	unsigned int,	vec	)
 	),
 
 	TP_fast_assign(
-		__entry->vec = (int)(h - vec);
+		__entry->vec	= nr;
 	),
 
 	TP_printk("vec=%d [action=%s]", __entry->vec,
-		  show_softirq_name(__entry->vec))
+		show_softirq_name(__entry->vec))
+);
+
+/**
+ * softirq_raise - called immediately when a softirq is raised
+ * @nr: softirq vector number
+ *
+ * Tracepoint for tracing when softirq action is raised.
+ * Also, when used in combination with the softirq_entry tracepoint
+ * we can determine the softirq raise latency.
+ */
+DEFINE_EVENT(softirq, softirq_raise,
+
+	TP_PROTO(unsigned int nr),
+
+	TP_ARGS(nr)
 );
 
 /**
  * softirq_entry - called immediately before the softirq handler
- * @h: pointer to struct softirq_action
- * @vec: pointer to first struct softirq_action in softirq_vec array
+ * @nr: softirq vector number
  *
- * The @h parameter, contains a pointer to the struct softirq_action
- * which has a pointer to the action handler that is called. By subtracting
- * the @vec pointer from the @h pointer, we can determine the softirq
- * number. Also, when used in combination with the softirq_exit tracepoint
+ * Tracepoint for tracing when softirq action starts.
+ * Also, when used in combination with the softirq_exit tracepoint
  * we can determine the softirq latency.
  */
 DEFINE_EVENT(softirq, softirq_entry,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int nr),
 
-	TP_ARGS(h, vec)
+	TP_ARGS(nr)
 );
 
 /**
  * softirq_exit - called immediately after the softirq handler returns
- * @h: pointer to struct softirq_action
- * @vec: pointer to first struct softirq_action in softirq_vec array
+ * @nr: softirq vector number
  *
- * The @h parameter contains a pointer to the struct softirq_action
- * that has handled the softirq. By subtracting the @vec pointer from
- * the @h pointer, we can determine the softirq number. Also, when used in
- * combination with the softirq_entry tracepoint we can determine the softirq
- * latency.
+ * Tracepoint for tracing when softirq action ends.
+ * Also, when used in combination with the softirq_entry tracepoint
+ * we can determine the softirq latency.
  */
 DEFINE_EVENT(softirq, softirq_exit,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int nr),
 
-	TP_ARGS(h, vec)
+	TP_ARGS(nr)
 );
 
 #endif /*  _TRACE_IRQ_H */

kernel/softirq.c +0 -0

index 825e112..6790599 100644
@@ -215,9 +215,9 @@ restart:
 			int prev_count = preempt_count();
 			kstat_incr_softirqs_this_cpu(h - softirq_vec);
 

kernel/softirq.c restart: · line 220

Quoted 5 lines

kernel/softirq.c +2 -2

-			trace_softirq_entry(h, softirq_vec);
+			trace_softirq_entry(h - softirq_vec);
 			h->action(h);
-			trace_softirq_exit(h, softirq_vec);
+			trace_softirq_exit(h - softirq_vec);

You're loosing information here by reducing the numbers of parameters in this tracepoint. How many other tracepoint scripts rely on having both pointers handy? Why not just do the pointer math inside your tracehook instead?

Quoted 10 lines

kernel/softirq.c +0 -1

 			if (unlikely(prev_count != preempt_count())) {
 				printk(KERN_ERR "huh, entered softirq %td %s %p"
 				       "with preempt_count %08x,"
 
--

To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Quoted 56 lines · Koki Sanagi

From: Neil Horman <[email protected]>

This patch converts trace_napi_poll from DECLARE_EVENT to TRACE_EVENT to improve the usability of napi_poll tracepoint.

          <idle>-0     [001] 241302.750777: napi_poll: napi poll on napi struct f6acc480 for device eth3
          <idle>-0     [000] 241302.852389: napi_poll: napi poll on napi struct f5d0d70c for device eth1

An original patch is below.
http://marc.info/?l=linux-kernel&m=126021713809450&w=2

Signed-off-by Neil Horman <[email protected]>

And add a fix by Steven Rostedt.
http://marc.info/?l=linux-kernel&m=126150506519173&w=2

Signed-off-by Koki Sanagi <[email protected]>

---
 include/trace/events/napi.h |   25 +++++++++++++++++++++++--
 1 files changed, 23 insertions(+), 2 deletions(-)

include/trace/events/napi.h +23 -2

index 188deca..8fe1e93 100644
@@ -6,10 +6,31 @@
 
 #include <linux/netdevice.h>
 #include <linux/tracepoint.h>
+#include <linux/ftrace.h>
+
+#define NO_DEV "(no_device)"
+
+TRACE_EVENT(napi_poll,
 
-DECLARE_TRACE(napi_poll,
 	TP_PROTO(struct napi_struct *napi),
-	TP_ARGS(napi));
+
+	TP_ARGS(napi),
+
+	TP_STRUCT__entry(
+		__field(	struct napi_struct *,	napi)
+		__string(	dev_name, napi->dev ? napi->dev->name : NO_DEV)
+	),
+
+	TP_fast_assign(
+		__entry->napi = napi;
+		__assign_str(dev_name, napi->dev ? napi->dev->name : NO_DEV);
+	),
+
+	TP_printk("napi poll on napi struct %p for device %s",
+		__entry->napi, __get_str(dev_name))
+);
+
+#undef NO_DEV
 

include/trace/events/napi.h line 36

Quoted 3 lines

include/trace/events/napi.h +0 -0

 #endif /* _TRACE_NAPI_H_ */
 

NAK, This change will create a build break in the drop monitor code. You'll need to fix that up if you want to make this change.
Neil

--
To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Quoted 136 lines · Koki Sanagi

This patch adds tracepoint to dev_queue_xmit, dev_hard_start_xmit and netif_receive_skb. These tracepoints help you to monitor network driver's input/output.

            sshd-4445  [001] 241367.066046: net_dev_queue: dev=eth3 skbaddr=dd6b2538 len=114
            sshd-4445  [001] 241367.066047: net_dev_xmit: dev=eth3 skbaddr=dd6b2538 len=114 rc=0
          <idle>-0     [001] 241367.067472: net_dev_receive: dev=eth3 skbaddr=f5e59000 len=52

Signed-off-by Koki Sanagi <[email protected]>

---
 include/trace/events/net.h |   75 ++++++++++++++++++++++++++++++++++++++++++++
 net/core/dev.c             |    5 +++
 net/core/net-traces.c      |    1 +
 3 files changed, 81 insertions(+), 0 deletions(-)

include/trace/events/net.h new file +75 -0

new file mode 100644
index 0000000..8a21361
@@ -0,0 +1,75 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM net
+
+#if !defined(_TRACE_NET_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_NET_H
+
+#include <linux/skbuff.h>
+#include <linux/netdevice.h>
+#include <linux/ip.h>
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(net_dev_xmit,
+
+	TP_PROTO(struct sk_buff *skb,
+		 int rc),
+
+	TP_ARGS(skb, rc),
+
+	TP_STRUCT__entry(
+		__field(	void *,		skbaddr		)
+		__field(	unsigned int,	len		)
+		__field(	int,		rc		)
+		__string(	name,		skb->dev->name	)
+	),
+
+	TP_fast_assign(
+		__entry->skbaddr = skb;
+		__entry->len = skb->len;
+		__entry->rc = rc;
+		__assign_str(name, skb->dev->name);
+	),
+
+	TP_printk("dev=%s skbaddr=%p len=%u rc=%d",
+		__get_str(name), __entry->skbaddr, __entry->len, __entry->rc)
+);
+
+DECLARE_EVENT_CLASS(net_dev_template,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb),
+
+	TP_STRUCT__entry(
+		__field(	void *,		skbaddr		)
+		__field(	unsigned int,	len		)
+		__string(	name,		skb->dev->name	)
+	),
+
+	TP_fast_assign(
+		__entry->skbaddr = skb;
+		__entry->len = skb->len;
+		__assign_str(name, skb->dev->name);
+	),
+
+	TP_printk("dev=%s skbaddr=%p len=%u",
+		__get_str(name), __entry->skbaddr, __entry->len)
+)
+
+DEFINE_EVENT(net_dev_template, net_dev_queue,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+);
+
+DEFINE_EVENT(net_dev_template, net_dev_receive,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+);
+#endif /* _TRACE_NET_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

net/core/dev.c +4 -0

index 93b8929..4acfec6 100644
@@ -130,6 +130,7 @@
 #include <linux/jhash.h>
 #include <linux/random.h>
 #include <trace/events/napi.h>
+#include <trace/events/net.h>
 #include <linux/pci.h>
 
 #include "net-sysfs.h"

@@ -1955,6 +1956,7 @@ int dev_hard_start_xmit(struct sk_buff *skb, struct net_device *dev,
 		}
 
 		rc = ops->ndo_start_xmit(skb, dev);
+		trace_net_dev_xmit(skb, rc);
 		if (rc == NETDEV_TX_OK)
 			txq_trans_update(txq);
 		return rc;

@@ -1975,6 +1977,7 @@ gso:
 			skb_dst_drop(nskb);
 
 		rc = ops->ndo_start_xmit(nskb, dev);
+		trace_net_dev_xmit(nskb, rc);
 		if (unlikely(rc != NETDEV_TX_OK)) {
 			if (rc & ~NETDEV_TX_MASK)
 				goto out_kfree_gso_skb;

@@ -2165,6 +2168,7 @@ int dev_queue_xmit(struct sk_buff *skb)
 #ifdef CONFIG_NET_CLS_ACT
 	skb->tc_verd = SET_TC_AT(skb->tc_verd, AT_EGRESS);
 #endif
+	trace_net_dev_queue(skb);
 	if (q->enqueue) {
 		rc = __dev_xmit_skb(skb, q, dev, txq);
 		goto out;

@@ -2939,6 +2943,7 @@ int netif_receive_skb(struct sk_buff *skb)
 	if (netdev_tstamp_prequeue)
 		net_timestamp_check(skb);
 

net/core/dev.c int netif_receive_skb(struct sk_buff *skb) · line 2946

Quoted 1 line

net/core/dev.c +1 -0

+	trace_net_dev_receive(skb);

I imagine for completeness you'll want to make a call to this in netif_rx and netif_rx_ni as well.

Quoted 61 lines · Koki Sanagi

[RFC PATCH v3 4/5] skb: add tracepoints to freeing skb
This patch adds tracepoint to consume_skb, dev_kfree_skb_irq and skb_free_datagram_locked. Combinating with tracepoint on dev_hard_start_xmit, we can check how long it takes to free transmited packets. And using it, we can calculate how many packets driver had at that time. It is useful when a drop of transmited packet is a problem.

          <idle>-0     [001] 241409.218333: consume_skb: skbaddr=dd6b2fb8
          <idle>-0     [001] 241409.490555: dev_kfree_skb_irq: skbaddr=f5e29840

        udp-recv-302   [001] 515031.206008: skb_free_datagram_locked: skbaddr=f5b1d900

Signed-off-by Koki Sanagi <[email protected]>

---
 include/trace/events/skb.h |   42 ++++++++++++++++++++++++++++++++++++++++++
 net/core/datagram.c        |    1 +
 net/core/dev.c             |    2 ++
 net/core/skbuff.c          |    1 +
 4 files changed, 46 insertions(+), 0 deletions(-)

include/trace/events/skb.h +32 -0

index 4b2be6d..84c9041 100644
@@ -35,6 +35,48 @@ TRACE_EVENT(kfree_skb,
 		__entry->skbaddr, __entry->protocol, __entry->location)
 );
 
+DECLARE_EVENT_CLASS(free_skb,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb),
+
+	TP_STRUCT__entry(
+		__field(	void *,	skbaddr	)
+	),
+
+	TP_fast_assign(
+		__entry->skbaddr = skb;
+	),
+
+	TP_printk("skbaddr=%p", __entry->skbaddr)
+
+);
+
+DEFINE_EVENT(free_skb, consume_skb,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+
+DEFINE_EVENT(free_skb, dev_kfree_skb_irq,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+

include/trace/events/skb.h TRACE_EVENT(kfree_skb, · line 79

Quoted 10 lines

include/trace/events/skb.h +10 -0

+);
+
+DEFINE_EVENT(free_skb, skb_free_datagram_locked,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+

Why create these last two tracepoints at all? dev_kfree_skb_irq will eventually pass through kfree_skb anyway, getting picked up by the tracepoint there, the while the latter won't (since it uses __kfree_skb instead), I think that could be fixed up by add a call to trace_kfree_skb there directly, saving you two tracepoints.

Neil

Quoted 1 line

Quoted 79 lines · Neil Horman

Quoted 61 lines · Koki Sanagi

[RFC PATCH v3 4/5] skb: add tracepoints to freeing skb
This patch adds tracepoint to consume_skb, dev_kfree_skb_irq and skb_free_datagram_locked. Combinating with tracepoint on dev_hard_start_xmit, we can check how long it takes to free transmited packets. And using it, we can calculate how many packets driver had at that time. It is useful when a drop of transmited packet is a problem.

          <idle>-0     [001] 241409.218333: consume_skb: skbaddr=dd6b2fb8
          <idle>-0     [001] 241409.490555: dev_kfree_skb_irq: skbaddr=f5e29840

        udp-recv-302   [001] 515031.206008: skb_free_datagram_locked: skbaddr=f5b1d900

Signed-off-by Koki Sanagi <[email protected]>

---
 include/trace/events/skb.h |   42 ++++++++++++++++++++++++++++++++++++++++++
 net/core/datagram.c        |    1 +
 net/core/dev.c             |    2 ++
 net/core/skbuff.c          |    1 +
 4 files changed, 46 insertions(+), 0 deletions(-)

include/trace/events/skb.h +32 -0

index 4b2be6d..84c9041 100644
@@ -35,6 +35,48 @@ TRACE_EVENT(kfree_skb,
 		__entry->skbaddr, __entry->protocol, __entry->location)
 );
 
+DECLARE_EVENT_CLASS(free_skb,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb),
+
+	TP_STRUCT__entry(
+		__field(	void *,	skbaddr	)
+	),
+
+	TP_fast_assign(
+		__entry->skbaddr = skb;
+	),
+
+	TP_printk("skbaddr=%p", __entry->skbaddr)
+
+);
+
+DEFINE_EVENT(free_skb, consume_skb,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+
+DEFINE_EVENT(free_skb, dev_kfree_skb_irq,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+

include/trace/events/skb.h TRACE_EVENT(kfree_skb, · line 79

Quoted 10 lines

include/trace/events/skb.h +10 -0

+);
+
+DEFINE_EVENT(free_skb, skb_free_datagram_locked,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+

Why create these last two tracepoints at all? dev_kfree_skb_irq will eventually pass through kfree_skb anyway, getting picked up by the tracepoint there, the while the latter won't (since it uses __kfree_skb instead), I think that could be fixed up by add a call to trace_kfree_skb there directly, saving you two tracepoints.

Quoted 2 lines

Neil

I think dev_kfree_skb_irq isn't chased by trace_kfree_skb or trace_consume_skb completely. Because net_tx_action frees skb by __kfree_skb. So it is better to add trace_kfree_skb before it. skb_free_datagram_locked is same.

Thanks,
Koki Sanagi.

Quoted 3 lines

Quoted 1 line

Quoted 34 lines · Neil Horman

Quoted 33 lines · Koki Sanagi

From: Lai Jiangshan <[email protected]>

Add a tracepoint for tracing when softirq action is raised.

It and the existed tracepoints complete softirq's tracepoints:
softirq_raise, softirq_entry and softirq_exit.

And when this tracepoint is used in combination with the softirq_entry tracepoint we can determine the softirq raise latency.

Signed-off-by Lai Jiangshan <[email protected]>

Acked-by Mathieu Desnoyers <[email protected]>

Acked-by Frederic Weisbecker <[email protected]>

[ factorize softirq events with DECLARE_EVENT_CLASS ]

Signed-off-by Koki Sanagi <[email protected]>

---
 include/linux/interrupt.h  |    8 +++++-
 include/trace/events/irq.h |   57 ++++++++++++++++++++++++++-----------------
 kernel/softirq.c           |    4 +-
 3 files changed, 43 insertions(+), 26 deletions(-)

include/linux/interrupt.h +1 -0

index c233113..1cb5726 100644
@@ -18,6 +18,7 @@
 #include <asm/atomic.h>
 #include <asm/ptrace.h>
 #include <asm/system.h>
+#include <trace/events/irq.h>
 

Quoted 16 lines

include/linux/interrupt.h asmlinkage void do_softirq(void); · line 411

Quoted 13 lines

include/linux/interrupt.h +6 -1

 /*
  * These correspond to the IORESOURCE_IRQ_* defines in

@@ -402,7 +403,12 @@ asmlinkage void do_softirq(void);
 asmlinkage void __do_softirq(void);
 extern void open_softirq(int nr, void (*action)(struct softirq_action *));
 extern void softirq_init(void);
-#define __raise_softirq_irqoff(nr) do { or_softirq_pending(1UL << (nr)); } while (0)
+static inline void __raise_softirq_irqoff(unsigned int nr)
+{
+	trace_softirq_raise(nr);
+	or_softirq_pending(1UL << nr);
+}
+

We already have tracepoints in irq_enter and irq_exit. If the goal here is to detect latency during packet processing, cant the delta in time between those two points be used to determine interrupt handling latency?

Certainly, the time between irq_entry and irq_exit is not directly related to latency during packet processing. But it's indirectly related it. Because softirq_entry isn't passed until irq exits and softirq_entry time is related to packet processing latency. So I show it as a reference.

Quoted 116 lines

Quoted 116 lines

include/linux/interrupt.h +0 -0

 extern void raise_softirq_irqoff(unsigned int nr);
 extern void raise_softirq(unsigned int nr);
 extern void wakeup_softirqd(void);

include/trace/events/irq.h +34 -23

index 0e4cfb6..717744c 100644
@@ -5,7 +5,9 @@
 #define _TRACE_IRQ_H
 
 #include <linux/tracepoint.h>
-#include <linux/interrupt.h>
+
+struct irqaction;
+struct softirq_action;
 
 #define softirq_name(sirq) { sirq##_SOFTIRQ, #sirq }
 #define show_softirq_name(val)				\

@@ -84,56 +86,65 @@ TRACE_EVENT(irq_handler_exit,
 
 DECLARE_EVENT_CLASS(softirq,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int nr),
 
-	TP_ARGS(h, vec),
+	TP_ARGS(nr),
 
 	TP_STRUCT__entry(
-		__field(	int,	vec			)
+		__field(	unsigned int,	vec	)
 	),
 
 	TP_fast_assign(
-		__entry->vec = (int)(h - vec);
+		__entry->vec	= nr;
 	),
 
 	TP_printk("vec=%d [action=%s]", __entry->vec,
-		  show_softirq_name(__entry->vec))
+		show_softirq_name(__entry->vec))
+);
+
+/**
+ * softirq_raise - called immediately when a softirq is raised
+ * @nr: softirq vector number
+ *
+ * Tracepoint for tracing when softirq action is raised.
+ * Also, when used in combination with the softirq_entry tracepoint
+ * we can determine the softirq raise latency.
+ */
+DEFINE_EVENT(softirq, softirq_raise,
+
+	TP_PROTO(unsigned int nr),
+
+	TP_ARGS(nr)
 );
 
 /**
  * softirq_entry - called immediately before the softirq handler
- * @h: pointer to struct softirq_action
- * @vec: pointer to first struct softirq_action in softirq_vec array
+ * @nr: softirq vector number
  *
- * The @h parameter, contains a pointer to the struct softirq_action
- * which has a pointer to the action handler that is called. By subtracting
- * the @vec pointer from the @h pointer, we can determine the softirq
- * number. Also, when used in combination with the softirq_exit tracepoint
+ * Tracepoint for tracing when softirq action starts.
+ * Also, when used in combination with the softirq_exit tracepoint
  * we can determine the softirq latency.
  */
 DEFINE_EVENT(softirq, softirq_entry,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int nr),
 
-	TP_ARGS(h, vec)
+	TP_ARGS(nr)
 );
 
 /**
  * softirq_exit - called immediately after the softirq handler returns
- * @h: pointer to struct softirq_action
- * @vec: pointer to first struct softirq_action in softirq_vec array
+ * @nr: softirq vector number
  *
- * The @h parameter contains a pointer to the struct softirq_action
- * that has handled the softirq. By subtracting the @vec pointer from
- * the @h pointer, we can determine the softirq number. Also, when used in
- * combination with the softirq_entry tracepoint we can determine the softirq
- * latency.
+ * Tracepoint for tracing when softirq action ends.
+ * Also, when used in combination with the softirq_entry tracepoint
+ * we can determine the softirq latency.
  */
 DEFINE_EVENT(softirq, softirq_exit,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int nr),
 
-	TP_ARGS(h, vec)
+	TP_ARGS(nr)
 );
 
 #endif /*  _TRACE_IRQ_H */

kernel/softirq.c +0 -0

index 825e112..6790599 100644
@@ -215,9 +215,9 @@ restart:
 			int prev_count = preempt_count();
 			kstat_incr_softirqs_this_cpu(h - softirq_vec);
 

Quoted 9 lines

kernel/softirq.c restart: · line 220

Quoted 5 lines

kernel/softirq.c +2 -2

-			trace_softirq_entry(h, softirq_vec);
+			trace_softirq_entry(h - softirq_vec);
 			h->action(h);
-			trace_softirq_exit(h, softirq_vec);
+			trace_softirq_exit(h - softirq_vec);

You're loosing information here by reducing the numbers of parameters in this tracepoint. How many other tracepoint scripts rely on having both pointers handy? Why not just do the pointer math inside your tracehook instead?

In __raise_softirq_irqoff macro there is no method to refer softirq_vec, so it can't use softirq DECLARE_EVENT_CLASS as is.
Currently, there is no script using softirq_entry or softirq_exit.

Thanks,
Koki Sanagi.

Quoted 12 lines

Quoted 10 lines

kernel/softirq.c +0 -1

 			if (unlikely(prev_count != preempt_count())) {
 				printk(KERN_ERR "huh, entered softirq %td %s %p"
 				       "with preempt_count %08x,"
 
--

To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Quoted 57 lines · Neil Horman

Quoted 56 lines · Koki Sanagi

From: Neil Horman <[email protected]>

This patch converts trace_napi_poll from DECLARE_EVENT to TRACE_EVENT to improve the usability of napi_poll tracepoint.

          <idle>-0     [001] 241302.750777: napi_poll: napi poll on napi struct f6acc480 for device eth3
          <idle>-0     [000] 241302.852389: napi_poll: napi poll on napi struct f5d0d70c for device eth1

An original patch is below.
http://marc.info/?l=linux-kernel&m=126021713809450&w=2

Signed-off-by Neil Horman <[email protected]>

And add a fix by Steven Rostedt.
http://marc.info/?l=linux-kernel&m=126150506519173&w=2

Signed-off-by Koki Sanagi <[email protected]>

---
 include/trace/events/napi.h |   25 +++++++++++++++++++++++--
 1 files changed, 23 insertions(+), 2 deletions(-)

include/trace/events/napi.h +23 -2

index 188deca..8fe1e93 100644
@@ -6,10 +6,31 @@
 
 #include <linux/netdevice.h>
 #include <linux/tracepoint.h>
+#include <linux/ftrace.h>
+
+#define NO_DEV "(no_device)"
+
+TRACE_EVENT(napi_poll,
 
-DECLARE_TRACE(napi_poll,
 	TP_PROTO(struct napi_struct *napi),
-	TP_ARGS(napi));
+
+	TP_ARGS(napi),
+
+	TP_STRUCT__entry(
+		__field(	struct napi_struct *,	napi)
+		__string(	dev_name, napi->dev ? napi->dev->name : NO_DEV)
+	),
+
+	TP_fast_assign(
+		__entry->napi = napi;
+		__assign_str(dev_name, napi->dev ? napi->dev->name : NO_DEV);
+	),
+
+	TP_printk("napi poll on napi struct %p for device %s",
+		__entry->napi, __get_str(dev_name))
+);
+
+#undef NO_DEV
 

Quoted 7 lines

include/trace/events/napi.h line 36

Quoted 3 lines

include/trace/events/napi.h +0 -0

 #endif /* _TRACE_NAPI_H_ */
 

NAK, This change will create a build break in the drop monitor code. You'll need to fix that up if you want to make this change.
Neil

I built a kernel with CONFIG_NET_DROP_MONITOR=y.
But build break did not occur.

Thanks,
Koki Sanagi.

Quoted 6 lines

--
To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Quoted 19 lines

Quoted 9 lines

Quoted 9 lines

#endif /* _TRACE_IRQ_H */

kernel/softirq.c +0 -0

index 825e112..6790599 100644
@@ -215,9 +215,9 @@ restart:
 			int prev_count = preempt_count();
 			kstat_incr_softirqs_this_cpu(h - softirq_vec);
 

Quoted 9 lines

kernel/softirq.c restart: · line 220

Quoted 5 lines

kernel/softirq.c +2 -2

-			trace_softirq_entry(h, softirq_vec);
+			trace_softirq_entry(h - softirq_vec);
 			h->action(h);
-			trace_softirq_exit(h, softirq_vec);
+			trace_softirq_exit(h - softirq_vec);

You're loosing information here by reducing the numbers of parameters in this tracepoint. How many other tracepoint scripts rely on having both pointers handy? Why not just do the pointer math inside your tracehook instead?

Quoted 4 lines

In __raise_softirq_irqoff macro there is no method to refer softirq_vec, so it can't use softirq DECLARE_EVENT_CLASS as is.
Currently, there is no script using softirq_entry or softirq_exit.

That shouldn't matter, just pass in NULL for softirq_vec in __raise_softirq_irqoff as the second argument to the trace function. You may need to fix up the class definition so that the assignment or printk doesn't try to dereference that pointer when its NULL, but thats easy enough, and it avoids breaking any other perf scripts floating out there.

Quoted 23 lines

Quoted 19 lines

Quoted 9 lines

Quoted 9 lines

#endif /* _TRACE_IRQ_H */

kernel/softirq.c +0 -0

index 825e112..6790599 100644
@@ -215,9 +215,9 @@ restart:
 			int prev_count = preempt_count();
 			kstat_incr_softirqs_this_cpu(h - softirq_vec);
 

Quoted 9 lines

kernel/softirq.c restart: · line 220

Quoted 5 lines

kernel/softirq.c +2 -2

-			trace_softirq_entry(h, softirq_vec);
+			trace_softirq_entry(h - softirq_vec);
 			h->action(h);
-			trace_softirq_exit(h, softirq_vec);
+			trace_softirq_exit(h - softirq_vec);

You're loosing information here by reducing the numbers of parameters in this tracepoint. How many other tracepoint scripts rely on having both pointers handy? Why not just do the pointer math inside your tracehook instead?

Quoted 4 lines

In __raise_softirq_irqoff macro there is no method to refer softirq_vec, so it can't use softirq DECLARE_EVENT_CLASS as is.
Currently, there is no script using softirq_entry or softirq_exit.

Quoted 5 lines

That shouldn't matter, just pass in NULL for softirq_vec in __raise_softirq_irqoff as the second argument to the trace function. You may need to fix up the class definition so that the assignment or printk doesn't try to dereference that pointer when its NULL, but thats easy enough, and it avoids breaking any other perf scripts floating out there.

please see 5 lines above. we already have 'h - softirq_vec' calculation in this function. so, Sanagi-san's change don't makes any overhead.

So, if the overhead is zero, I'd prefer simplest tracepoint definition :)

--
To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Quoted 80 lines · Koki Sanagi

Quoted 79 lines · Neil Horman

Quoted 61 lines · Koki Sanagi

[RFC PATCH v3 4/5] skb: add tracepoints to freeing skb
This patch adds tracepoint to consume_skb, dev_kfree_skb_irq and skb_free_datagram_locked. Combinating with tracepoint on dev_hard_start_xmit, we can check how long it takes to free transmited packets. And using it, we can calculate how many packets driver had at that time. It is useful when a drop of transmited packet is a problem.

          <idle>-0     [001] 241409.218333: consume_skb: skbaddr=dd6b2fb8
          <idle>-0     [001] 241409.490555: dev_kfree_skb_irq: skbaddr=f5e29840

        udp-recv-302   [001] 515031.206008: skb_free_datagram_locked: skbaddr=f5b1d900

Signed-off-by Koki Sanagi <[email protected]>

---
 include/trace/events/skb.h |   42 ++++++++++++++++++++++++++++++++++++++++++
 net/core/datagram.c        |    1 +
 net/core/dev.c             |    2 ++
 net/core/skbuff.c          |    1 +
 4 files changed, 46 insertions(+), 0 deletions(-)

include/trace/events/skb.h +32 -0

index 4b2be6d..84c9041 100644
@@ -35,6 +35,48 @@ TRACE_EVENT(kfree_skb,
 		__entry->skbaddr, __entry->protocol, __entry->location)
 );
 
+DECLARE_EVENT_CLASS(free_skb,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb),
+
+	TP_STRUCT__entry(
+		__field(	void *,	skbaddr	)
+	),
+
+	TP_fast_assign(
+		__entry->skbaddr = skb;
+	),
+
+	TP_printk("skbaddr=%p", __entry->skbaddr)
+
+);
+
+DEFINE_EVENT(free_skb, consume_skb,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+
+DEFINE_EVENT(free_skb, dev_kfree_skb_irq,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+

include/trace/events/skb.h TRACE_EVENT(kfree_skb, · line 79

Quoted 10 lines

include/trace/events/skb.h +10 -0

+);
+
+DEFINE_EVENT(free_skb, skb_free_datagram_locked,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+

Why create these last two tracepoints at all? dev_kfree_skb_irq will eventually pass through kfree_skb anyway, getting picked up by the tracepoint there, the while the latter won't (since it uses __kfree_skb instead), I think that could be fixed up by add a call to trace_kfree_skb there directly, saving you two tracepoints.

Quoted 6 lines

Quoted 2 lines

Neil

I think dev_kfree_skb_irq isn't chased by trace_kfree_skb or trace_consume_skb completely. Because net_tx_action frees skb by __kfree_skb. So it is better to add trace_kfree_skb before it. skb_free_datagram_locked is same.

It isn't, you're right, but that was the point I made above. Those missed areas could be easily handled by adding calls to trace_kfree_skb which already exists, to the missed areas. Then you don't need to create those new tracepoints. The way your doing this, if someone wants to trace all skb frees in debugfs, they would have to enable three tracepoints, not just one. Not that thats the point of your patch, but its something to consider, and it simplifies your code. Neil

Quoted 52 lines · Koki Sanagi

Quoted 34 lines · Neil Horman

Quoted 33 lines · Koki Sanagi

From: Lai Jiangshan <[email protected]>

Add a tracepoint for tracing when softirq action is raised.

It and the existed tracepoints complete softirq's tracepoints:
softirq_raise, softirq_entry and softirq_exit.

And when this tracepoint is used in combination with the softirq_entry tracepoint we can determine the softirq raise latency.

Signed-off-by Lai Jiangshan <[email protected]>

Acked-by Mathieu Desnoyers <[email protected]>

Acked-by Frederic Weisbecker <[email protected]>

[ factorize softirq events with DECLARE_EVENT_CLASS ]

Signed-off-by Koki Sanagi <[email protected]>

---
 include/linux/interrupt.h  |    8 +++++-
 include/trace/events/irq.h |   57 ++++++++++++++++++++++++++-----------------
 kernel/softirq.c           |    4 +-
 3 files changed, 43 insertions(+), 26 deletions(-)

include/linux/interrupt.h +1 -0

index c233113..1cb5726 100644
@@ -18,6 +18,7 @@
 #include <asm/atomic.h>
 #include <asm/ptrace.h>
 #include <asm/system.h>
+#include <trace/events/irq.h>
 

Quoted 16 lines

include/linux/interrupt.h asmlinkage void do_softirq(void); · line 411

Quoted 13 lines

include/linux/interrupt.h +6 -1

 /*
  * These correspond to the IORESOURCE_IRQ_* defines in

@@ -402,7 +403,12 @@ asmlinkage void do_softirq(void);
 asmlinkage void __do_softirq(void);
 extern void open_softirq(int nr, void (*action)(struct softirq_action *));
 extern void softirq_init(void);
-#define __raise_softirq_irqoff(nr) do { or_softirq_pending(1UL << (nr)); } while (0)
+static inline void __raise_softirq_irqoff(unsigned int nr)
+{
+	trace_softirq_raise(nr);
+	or_softirq_pending(1UL << nr);
+}
+

We already have tracepoints in irq_enter and irq_exit. If the goal here is to detect latency during packet processing, cant the delta in time between those two points be used to determine interrupt handling latency?

Quoted 5 lines

Certainly, the time between irq_entry and irq_exit is not directly related to latency during packet processing. But it's indirectly related it. Because softirq_entry isn't passed until irq exits and softirq_entry time is related to packet processing latency. So I show it as a reference.

Its not directly related no, but look at it, the amount of processing between irq_exit and softirq_entry is minimal. The information you are trying to extract by computing the delta from irq_entry to softirq_entry is almost exactly the same as that from irq_entry to irq_exit. For that matter, since you're trying to guage lantency for packet processing, I expect you could get the same delta by measuring irq_entry to napi_poll tracepoint time, and save the hassle of needing to filter on softirq processing that doesn't relate to packet processing.

Quoted 127 lines

Quoted 117 lines

Quoted 117 lines

include/linux/interrupt.h +0 -0

 extern void raise_softirq_irqoff(unsigned int nr);
 extern void raise_softirq(unsigned int nr);
 extern void wakeup_softirqd(void);

include/trace/events/irq.h +34 -23

index 0e4cfb6..717744c 100644
@@ -5,7 +5,9 @@
 #define _TRACE_IRQ_H
 
 #include <linux/tracepoint.h>
-#include <linux/interrupt.h>
+
+struct irqaction;
+struct softirq_action;
 
 #define softirq_name(sirq) { sirq##_SOFTIRQ, #sirq }
 #define show_softirq_name(val)				\

@@ -84,56 +86,65 @@ TRACE_EVENT(irq_handler_exit,
 
 DECLARE_EVENT_CLASS(softirq,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int nr),
 
-	TP_ARGS(h, vec),
+	TP_ARGS(nr),
 
 	TP_STRUCT__entry(
-		__field(	int,	vec			)
+		__field(	unsigned int,	vec	)
 	),
 
 	TP_fast_assign(
-		__entry->vec = (int)(h - vec);
+		__entry->vec	= nr;
 	),
 
 	TP_printk("vec=%d [action=%s]", __entry->vec,
-		  show_softirq_name(__entry->vec))
+		show_softirq_name(__entry->vec))
+);
+
+/**
+ * softirq_raise - called immediately when a softirq is raised
+ * @nr: softirq vector number
+ *
+ * Tracepoint for tracing when softirq action is raised.
+ * Also, when used in combination with the softirq_entry tracepoint
+ * we can determine the softirq raise latency.
+ */
+DEFINE_EVENT(softirq, softirq_raise,
+
+	TP_PROTO(unsigned int nr),
+
+	TP_ARGS(nr)
 );
 
 /**
  * softirq_entry - called immediately before the softirq handler
- * @h: pointer to struct softirq_action
- * @vec: pointer to first struct softirq_action in softirq_vec array
+ * @nr: softirq vector number
  *
- * The @h parameter, contains a pointer to the struct softirq_action
- * which has a pointer to the action handler that is called. By subtracting
- * the @vec pointer from the @h pointer, we can determine the softirq
- * number. Also, when used in combination with the softirq_exit tracepoint
+ * Tracepoint for tracing when softirq action starts.
+ * Also, when used in combination with the softirq_exit tracepoint
  * we can determine the softirq latency.
  */
 DEFINE_EVENT(softirq, softirq_entry,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int nr),
 
-	TP_ARGS(h, vec)
+	TP_ARGS(nr)
 );
 
 /**
  * softirq_exit - called immediately after the softirq handler returns
- * @h: pointer to struct softirq_action
- * @vec: pointer to first struct softirq_action in softirq_vec array
+ * @nr: softirq vector number
  *
- * The @h parameter contains a pointer to the struct softirq_action
- * that has handled the softirq. By subtracting the @vec pointer from
- * the @h pointer, we can determine the softirq number. Also, when used in
- * combination with the softirq_entry tracepoint we can determine the softirq
- * latency.
+ * Tracepoint for tracing when softirq action ends.
+ * Also, when used in combination with the softirq_entry tracepoint
+ * we can determine the softirq latency.
  */
 DEFINE_EVENT(softirq, softirq_exit,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int nr),
 
-	TP_ARGS(h, vec)
+	TP_ARGS(nr)
 );
 
 #endif /*  _TRACE_IRQ_H */

kernel/softirq.c +0 -0

index 825e112..6790599 100644
@@ -215,9 +215,9 @@ restart:
 			int prev_count = preempt_count();
 			kstat_incr_softirqs_this_cpu(h - softirq_vec);
 

Quoted 9 lines

kernel/softirq.c restart: · line 220

Quoted 5 lines

kernel/softirq.c +2 -2

-			trace_softirq_entry(h, softirq_vec);
+			trace_softirq_entry(h - softirq_vec);
 			h->action(h);
-			trace_softirq_exit(h, softirq_vec);
+			trace_softirq_exit(h - softirq_vec);

You're loosing information here by reducing the numbers of parameters in this tracepoint. How many other tracepoint scripts rely on having both pointers handy? Why not just do the pointer math inside your tracehook instead?

Quoted 4 lines

In __raise_softirq_irqoff macro there is no method to refer softirq_vec, so it can't use softirq DECLARE_EVENT_CLASS as is.
Currently, there is no script using softirq_entry or softirq_exit.

That shouldn't matter, just pass in NULL for softirq_vec in __raise_softirq_irqoff as the second argument to the trace function. You may need to fix up the class definition so that the assignment or printk doesn't try to dereference that pointer when its NULL, but thats easy enough, and it avoids breaking any other perf scripts floating out there.
Neil

Quoted 18 lines

Thanks,
Koki Sanagi.

Quoted 12 lines

Quoted 10 lines

kernel/softirq.c +0 -1

 			if (unlikely(prev_count != preempt_count())) {
 				printk(KERN_ERR "huh, entered softirq %td %s %p"
 				       "with preempt_count %08x,"
 
--

To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Quoted 87 lines · Neil Horman

Quoted 80 lines · Koki Sanagi

Quoted 79 lines · Neil Horman

Quoted 61 lines · Koki Sanagi

[RFC PATCH v3 4/5] skb: add tracepoints to freeing skb
This patch adds tracepoint to consume_skb, dev_kfree_skb_irq and skb_free_datagram_locked. Combinating with tracepoint on dev_hard_start_xmit, we can check how long it takes to free transmited packets. And using it, we can calculate how many packets driver had at that time. It is useful when a drop of transmited packet is a problem.

          <idle>-0     [001] 241409.218333: consume_skb: skbaddr=dd6b2fb8
          <idle>-0     [001] 241409.490555: dev_kfree_skb_irq: skbaddr=f5e29840

        udp-recv-302   [001] 515031.206008: skb_free_datagram_locked: skbaddr=f5b1d900

Signed-off-by Koki Sanagi <[email protected]>

---
 include/trace/events/skb.h |   42 ++++++++++++++++++++++++++++++++++++++++++
 net/core/datagram.c        |    1 +
 net/core/dev.c             |    2 ++
 net/core/skbuff.c          |    1 +
 4 files changed, 46 insertions(+), 0 deletions(-)

include/trace/events/skb.h +32 -0

index 4b2be6d..84c9041 100644
@@ -35,6 +35,48 @@ TRACE_EVENT(kfree_skb,
 		__entry->skbaddr, __entry->protocol, __entry->location)
 );
 
+DECLARE_EVENT_CLASS(free_skb,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb),
+
+	TP_STRUCT__entry(
+		__field(	void *,	skbaddr	)
+	),
+
+	TP_fast_assign(
+		__entry->skbaddr = skb;
+	),
+
+	TP_printk("skbaddr=%p", __entry->skbaddr)
+
+);
+
+DEFINE_EVENT(free_skb, consume_skb,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+
+DEFINE_EVENT(free_skb, dev_kfree_skb_irq,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+

include/trace/events/skb.h TRACE_EVENT(kfree_skb, · line 79

Quoted 10 lines

include/trace/events/skb.h +10 -0

+);
+
+DEFINE_EVENT(free_skb, skb_free_datagram_locked,
+
+	TP_PROTO(struct sk_buff *skb),
+
+	TP_ARGS(skb)
+
+);
+

Why create these last two tracepoints at all? dev_kfree_skb_irq will eventually pass through kfree_skb anyway, getting picked up by the tracepoint there, the while the latter won't (since it uses __kfree_skb instead), I think that could be fixed up by add a call to trace_kfree_skb there directly, saving you two tracepoints.

Quoted 6 lines

Quoted 2 lines

Neil

I think dev_kfree_skb_irq isn't chased by trace_kfree_skb or trace_consume_skb completely. Because net_tx_action frees skb by __kfree_skb. So it is better to add trace_kfree_skb before it. skb_free_datagram_locked is same.

Quoted 8 lines

It isn't, you're right, but that was the point I made above. Those missed areas could be easily handled by adding calls to trace_kfree_skb which already exists, to the missed areas. Then you don't need to create those new tracepoints. The way your doing this, if someone wants to trace all skb frees in debugfs, they would have to enable three tracepoints, not just one. Not that thats the point of your patch, but its something to consider, and it simplifies your code. Neil

O.K. I've re-made a patch to use trace_kfree_skb instead of trace_dev_kfree_skb_irq and trace_skb_free_datagram_locked.
But I've got a problem.
I should use not __builtin_return_address, but macro or function which returns current address. But I don't know any macro like that. Do you know any solution ?

Quoted 32 lines

Quoted 23 lines

Quoted 19 lines

Quoted 9 lines

Quoted 9 lines

#endif /* _TRACE_IRQ_H */

kernel/softirq.c +0 -0

index 825e112..6790599 100644
@@ -215,9 +215,9 @@ restart:
 			int prev_count = preempt_count();
 			kstat_incr_softirqs_this_cpu(h - softirq_vec);
 

Quoted 9 lines

kernel/softirq.c restart: · line 220

Quoted 5 lines

kernel/softirq.c +2 -2

-			trace_softirq_entry(h, softirq_vec);
+			trace_softirq_entry(h - softirq_vec);
 			h->action(h);
-			trace_softirq_exit(h, softirq_vec);
+			trace_softirq_exit(h - softirq_vec);

You're loosing information here by reducing the numbers of parameters in this tracepoint. How many other tracepoint scripts rely on having both pointers handy? Why not just do the pointer math inside your tracehook instead?

Quoted 4 lines

In __raise_softirq_irqoff macro there is no method to refer softirq_vec, so it can't use softirq DECLARE_EVENT_CLASS as is.
Currently, there is no script using softirq_entry or softirq_exit.

Quoted 5 lines

That shouldn't matter, just pass in NULL for softirq_vec in __raise_softirq_irqoff as the second argument to the trace function. You may need to fix up the class definition so that the assignment or printk doesn't try to dereference that pointer when its NULL, but thats easy enough, and it avoids breaking any other perf scripts floating out there.

please see 5 lines above. we already have 'h - softirq_vec' calculation in this function. so, Sanagi-san's change don't makes any overhead.

Quoted 2 lines

So, if the overhead is zero, I'd prefer simplest tracepoint definition :)

I never complained about performance here, I complained about information loss. You have a tracepoint that provides two arguments here, and you're eliminating one of them. That will potentially break other users of this tracepoint. I understand we don't normally care about that with tracepoints as much, but if we can avoid it, why don't we?