netdev: show a process of packets

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]>

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

          <idle>-0     [001] 112447.902030: netif_rx: dev=eth1 skbaddr=f3ef0900 len=84
          <idle>-0     [001] 112447.902039: netif_receive_skb: dev=eth1 skbaddr=f3ef0900 len=84
            sshd-6828  [000] 112447.903257: net_dev_queue: dev=eth4 skbaddr=f3fca538 len=226
            sshd-6828  [000] 112447.903260: net_dev_xmit: dev=eth4 skbaddr=f3fca538 len=226 rc=0

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

This patch adds tracepoint to consume_skb and add trace_kfree_skb before __kfree_skb in skb_free_datagram_locked and net_tx_action. 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.

            sshd-6828  [000] 112689.258154: consume_skb: skbaddr=f2d99bb8

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

Add a perf script which shows a process of packets and processed time. It helps us to investigate networking or network device.

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

Rebase to the latest net-next.

CHANGE-LOG since v3:
1) change arguments of softirq tracepoint into original one.
2) remove tracepoint of dev_kfree_skb_irq and skb_free_datagram_locked and add trace_kfree_skb before __kfree_skb instead of them.
3) add tracepoint to netif_rx and display it by netdev-times script.

These patch-set adds tracepoints to show us a process of packets. Using these tracepoints and existing points, we can get the time when packet passes through some points in transmit or receive sequence. For example, this is an output of perf script which is attached by patch 5/5.

106133.171439sec cpu=0
irq_entry(+0.000msec irq=24:eth4)

         |
  softirq_entry(+0.006msec)
         |
         |---netif_receive_skb(+0.010msec skb=f2d15900 len=100)
         |            |
         |      skb_copy_datagram_iovec(+0.039msec 10291::10291)
         |

napi_poll_exit(+0.022msec eth4)

106134.175634sec cpu=1
irq_entry(+0.000msec irq=28:eth1)

         |
         |---netif_rx(+0.009msec skb=f3ef0a00)
         |
  softirq_entry(+0.018msec)
         |
         |---netif_receive_skb(+0.021msec skb=f3ef0a00 len=84)
         |            |
         |      skb_copy_datagram_iovec(+0.033msec 0:swapper)
         |

napi_poll_exit(+0.035msec (no_device))

The above is a receive side(eth4 is NAPI. eth1 is non-NAPI). Like this, it can show receive sequence frominterrupt(irq_entry) to application (skb_copy_datagram_iovec).
This script shows one NET_RX softirq and events related to it. All relative time bases on first irq_entry which raise NET_RX softirq.

   dev    len      Qdisc               netdevice             free
   eth4    74 106125.030004sec        0.006msec             0.009msec
   eth4    87 106125.041020sec        0.007msec             0.023msec
   eth4    66 106125.042291sec        0.003msec             0.012msec
   eth4    66 106125.043274sec        0.006msec             0.004msec
   eth4   850 106125.044283sec        0.007msec             0.018msec

The above is a transmit side. There are three check-time-points. Point1 is before putting a packet to Qdisc. point2 is after ndo_start_xmit in dev_hard_start_xmit. It indicates finishing putting a packet to driver. point3 is in consume_skb and kfree_skb. It indicates freeing a transmitted packet. Values of this script are, from left, device name, length of a packet, a time of point1, an interval time between point1 and point2 and an interval time between point2 and point3.

These times are useful to analyze a performance or to detect a point where packet delays. For example,
- NET_RX softirq calling is late.
- Application is late to take a packet.
- It takes much time to put a transmitting packet to driver (It may be caused by packed queue)

And also, these tracepoint help us to investigate a network driver's trouble from memory dump because ftrace records it to memory. And ftrace is so light even if always trace on. So, in a case investigating a problem which doesn't reproduce, it is useful.

Quoted 65 lines · Koki Sanagi

Rebase to the latest net-next.

CHANGE-LOG since v3:
1) change arguments of softirq tracepoint into original one.
2) remove tracepoint of dev_kfree_skb_irq and skb_free_datagram_locked and add trace_kfree_skb before __kfree_skb instead of them.
3) add tracepoint to netif_rx and display it by netdev-times script.

These patch-set adds tracepoints to show us a process of packets. Using these tracepoints and existing points, we can get the time when packet passes through some points in transmit or receive sequence. For example, this is an output of perf script which is attached by patch 5/5.

106133.171439sec cpu=0
irq_entry(+0.000msec irq=24:eth4)

         |
  softirq_entry(+0.006msec)
         |
         |---netif_receive_skb(+0.010msec skb=f2d15900 len=100)
         |            |
         |      skb_copy_datagram_iovec(+0.039msec 10291::10291)
         |

napi_poll_exit(+0.022msec eth4)

106134.175634sec cpu=1
irq_entry(+0.000msec irq=28:eth1)

         |
         |---netif_rx(+0.009msec skb=f3ef0a00)
         |
  softirq_entry(+0.018msec)
         |
         |---netif_receive_skb(+0.021msec skb=f3ef0a00 len=84)
         |            |
         |      skb_copy_datagram_iovec(+0.033msec 0:swapper)
         |

napi_poll_exit(+0.035msec (no_device))

The above is a receive side(eth4 is NAPI. eth1 is non-NAPI). Like this, it can show receive sequence frominterrupt(irq_entry) to application (skb_copy_datagram_iovec).
This script shows one NET_RX softirq and events related to it. All relative time bases on first irq_entry which raise NET_RX softirq.

   dev    len      Qdisc               netdevice             free
   eth4    74 106125.030004sec        0.006msec             0.009msec
   eth4    87 106125.041020sec        0.007msec             0.023msec
   eth4    66 106125.042291sec        0.003msec             0.012msec
   eth4    66 106125.043274sec        0.006msec             0.004msec
   eth4   850 106125.044283sec        0.007msec             0.018msec

The above is a transmit side. There are three check-time-points. Point1 is before putting a packet to Qdisc. point2 is after ndo_start_xmit in dev_hard_start_xmit. It indicates finishing putting a packet to driver. point3 is in consume_skb and kfree_skb. It indicates freeing a transmitted packet. Values of this script are, from left, device name, length of a packet, a time of point1, an interval time between point1 and point2 and an interval time between point2 and point3.

These times are useful to analyze a performance or to detect a point where packet delays. For example,
- NET_RX softirq calling is late.
- Application is late to take a packet.
- It takes much time to put a transmitting packet to driver (It may be caused by packed queue)

Quoted 5 lines

And also, these tracepoint help us to investigate a network driver's trouble from memory dump because ftrace records it to memory. And ftrace is so light even if always trace on. So, in a case investigating a problem which doesn't reproduce, it is useful.

The entire series:

Acked-by Steven Rostedt <[email protected]>

-- Steve

Thanks many acks. and I have one question.

These patches have several component.

Patch1 is kernel component, but patch2-5 are netdev component. What tree is good to be included ?
If it is not net-next, I must rebase to another tree.

From: Koki Sanagi <[email protected]>
Date: Fri, 03 Sep 2010 11:10:51 +0900

Quoted 2 lines

Thanks many acks. and I have one question.

Quoted 5 lines

These patches have several component.

Patch1 is kernel component, but patch2-5 are netdev component. What tree is good to be included ?
If it is not net-next, I must rebase to another tree.

I would prefer it goes into the tracing tree or whatever is the most appropriate for patch #1.

Quoted 11 lines · David Miller

From: Koki Sanagi <[email protected]>
Date: Fri, 03 Sep 2010 11:10:51 +0900

Quoted 7 lines

Thanks many acks. and I have one question.

These patches have several component.

Patch1 is kernel component, but patch2-5 are netdev component. What tree is good to be included ?
If it is not net-next, I must rebase to another tree.

Quoted 3 lines

I would prefer it goes into the tracing tree or whatever is the most appropriate for patch #1.

O.K. I'll rebase to linux-2.6-tip.

Quoted 16 lines · Koki Sanagi

Quoted 14 lines · David Miller

From: Koki Sanagi <[email protected]>
Date: Fri, 03 Sep 2010 11:10:51 +0900

Quoted 7 lines

Thanks many acks. and I have one question.

These patches have several component.

Patch1 is kernel component, but patch2-5 are netdev component. What tree is good to be included ?
If it is not net-next, I must rebase to another tree.

I would prefer it goes into the tracing tree or whatever is the most appropriate for patch #1.

Quoted 1 line

O.K. I'll rebase to linux-2.6-tip.

No need, they apply very well :)

I'll push that to -tip soon.

Thanks.

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 |   26 ++++++++++++++++++++++++--
 2 files changed, 31 insertions(+), 3 deletions(-)

include/linux/interrupt.h +7 -1

index a0384a4..d3e8e90 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

@@ -407,7 +408,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((struct softirq_action *)&nr, NULL);
+	or_softirq_pending(1UL << nr);
+}
+
 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 +3 -1

index 0e4cfb6..3ddda02 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)				\

Quoted 5 lines

#define softirq_name(sirq) { sirq##_SOFTIRQ, #sirq }
#define show_softirq_name(val) \

(quoted diff) +0 -0

@@ -93,7 +95,10 @@ DECLARE_EVENT_CLASS(softirq,
 	),
 

include/trace/events/irq.h DECLARE_EVENT_CLASS(softirq, · line 102

Quoted 7 lines

include/trace/events/irq.h +4 -1

 	TP_fast_assign(
-		__entry->vec = (int)(h - vec);
+		if (vec)
+			__entry->vec = (int)(h - vec);
+		else
+			__entry->vec = *((int *)h);
 	),

It seems that this will break softirq_entry/exit tracepoints. __entry->vec will deref vec->action() for these two, which is not what we want.

If you can't have the same tracepoint signature for the three, just split the new one in a seperate TRACE_EVENT().

Quoted 5 lines · Frederic Weisbecker

Quoted 5 lines

#define softirq_name(sirq) { sirq##_SOFTIRQ, #sirq }
#define show_softirq_name(val) \

(quoted diff) +0 -0

@@ -93,7 +95,10 @@ DECLARE_EVENT_CLASS(softirq,
 	),
 

Quoted 13 lines

include/trace/events/irq.h DECLARE_EVENT_CLASS(softirq, · line 102

Quoted 7 lines

include/trace/events/irq.h +4 -1

 	TP_fast_assign(
-		__entry->vec = (int)(h - vec);
+		if (vec)
+			__entry->vec = (int)(h - vec);
+		else
+			__entry->vec = *((int *)h);
 	),

It seems that this will break softirq_entry/exit tracepoints. __entry->vec will deref vec->action() for these two, which is not what we want.

But for trace_softirq_entry and trace_softirq_exit, vec will not be NULL.

Quoted 4 lines

If you can't have the same tracepoint signature for the three, just split the new one in a seperate TRACE_EVENT().

It may be a bit of a hack, and questionable about adding another TRACE_EVENT(). There still is a pretty good space savings in using DEFINE_EVENT() over TRACE_EVENT() though.

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

Quoted 10 lines

/*
* These correspond to the IORESOURCE_IRQ_* defines in

include/linux/interrupt.h +3 -1

@@ -407,7 +408,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((struct softirq_action *)&nr, NULL);

Quoted 24 lines

include/linux/interrupt.h +3 -0

+	or_softirq_pending(1UL << nr);
+}
+
 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 +3 -1

index 0e4cfb6..3ddda02 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)				\

@@ -93,7 +95,10 @@ DECLARE_EVENT_CLASS(softirq,
 	),
 

include/trace/events/irq.h DECLARE_EVENT_CLASS(softirq, · line 101

Quoted 6 lines

include/trace/events/irq.h +4 -1

 	TP_fast_assign(
-		__entry->vec = (int)(h - vec);
+		if (vec)
+			__entry->vec = (int)(h - vec);
+		else
+			__entry->vec = *((int *)h);

include/trace/events/irq.h DECLARE_EVENT_CLASS(softirq, · line 102

Quoted 1 line

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

 	),

It seems that this will break softirq_entry/exit tracepoints. __entry->vec will deref vec->action() for these two, which is not what we want.

If you can't have the same tracepoint signature for the three, just split the new one in a seperate TRACE_EVENT().

Quoted 10 lines · Frederic Weisbecker

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

Quoted 10 lines

/*
* These correspond to the IORESOURCE_IRQ_* defines in

include/linux/interrupt.h +3 -1

@@ -407,7 +408,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((struct softirq_action *)&nr, NULL);

Perhaps doing:

	trace_softirq_raise((struct softirq_action *)((unsigend long)nr),
				NULL);

and ...

Quoted 24 lines

Quoted 24 lines

include/linux/interrupt.h +3 -0

+	or_softirq_pending(1UL << nr);
+}
+
 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 +3 -1

index 0e4cfb6..3ddda02 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)				\

@@ -93,7 +95,10 @@ DECLARE_EVENT_CLASS(softirq,
 	),
 

Quoted 6 lines

include/trace/events/irq.h DECLARE_EVENT_CLASS(softirq, · line 101

Quoted 6 lines

include/trace/events/irq.h +4 -1

 	TP_fast_assign(
-		__entry->vec = (int)(h - vec);
+		if (vec)
+			__entry->vec = (int)(h - vec);
+		else
+			__entry->vec = *((int *)h);

			__entry->vec = (int)h;

would be better.

Quoted 4 lines

Quoted 1 line

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

 	),

Quoted 6 lines

It seems that this will break softirq_entry/exit tracepoints. __entry->vec will deref vec->action() for these two, which is not what we want.

If you can't have the same tracepoint signature for the three, just split the new one in a seperate TRACE_EVENT().

Doing the above will at least be a bit safer.

Quoted 67 lines · Steven Rostedt

Quoted 10 lines · Frederic Weisbecker

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

Quoted 10 lines

/*
* These correspond to the IORESOURCE_IRQ_* defines in

include/linux/interrupt.h +3 -1

@@ -407,7 +408,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((struct softirq_action *)&nr, NULL);

Perhaps doing:

	trace_softirq_raise((struct softirq_action *)((unsigend long)nr),
				NULL);

and ...

Quoted 24 lines

Quoted 24 lines

include/linux/interrupt.h +3 -0

+	or_softirq_pending(1UL << nr);
+}
+
 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 +3 -1

index 0e4cfb6..3ddda02 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)				\

@@ -93,7 +95,10 @@ DECLARE_EVENT_CLASS(softirq,
 	),
 

Quoted 6 lines

include/trace/events/irq.h DECLARE_EVENT_CLASS(softirq, · line 101

Quoted 6 lines

include/trace/events/irq.h +4 -1

 	TP_fast_assign(
-		__entry->vec = (int)(h - vec);
+		if (vec)
+			__entry->vec = (int)(h - vec);
+		else
+			__entry->vec = *((int *)h);

			__entry->vec = (int)h;

would be better.

Quoted 10 lines

include/trace/events/irq.h DECLARE_EVENT_CLASS(softirq, · line 102

Quoted 1 line

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

 	),

It seems that this will break softirq_entry/exit tracepoints. __entry->vec will deref vec->action() for these two, which is not what we want.

If you can't have the same tracepoint signature for the three, just split the new one in a seperate TRACE_EVENT().

Quoted 1 line

Doing the above will at least be a bit safer.

Agreed, I'm going to change that in the patch.

Thanks.

Add a perf script which shows a process of packets and processed time. It helps us to investigate networking or network device.

If you want to use it, install perf and record perf.data like following.

#perf trace record netdev-times [script]

If you set script, perf gathers records until it ends. If not, you must Ctrl-C to stop recording.

And if you want a report from record,

#perf trace report netdev-times [options]

If you use some options, you can limit an output.
Option is below.

tx: show only process of tx packets
rx: show only process of rx packets
dev=: show a process specified with this option
debug: work with debug mode. It shows buffer status.

For example, if you want to show a process of received packets associated with eth4,

#perf trace report netdev-times rx dev=eth4
106133.171439sec cpu=0
irq_entry(+0.000msec irq=24:eth4)

         |
  softirq_entry(+0.006msec)
         |
         |---netif_receive_skb(+0.010msec skb=f2d15900 len=100)
         |            |
         |      skb_copy_datagram_iovec(+0.039msec 10291::10291)
         |

napi_poll_exit(+0.022msec eth4)

This perf script helps us to analyze a process time of transmit/receive sequence.

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

---
 tools/perf/scripts/python/bin/netdev-times-record |    8 +
 tools/perf/scripts/python/bin/netdev-times-report |    5 +
 tools/perf/scripts/python/netdev-times.py         |  464 +++++++++++++++++++++
 3 files changed, 477 insertions(+), 0 deletions(-)

tools/perf/scripts/python/bin/netdev-times-record new file +0 -0

new file mode 100644
index 0000000..2b59511

Commit-ID:  2bf2160d8805de64308e2e7c3cd97813cb58ed2f
Gitweb:     http://git.kernel.org/tip/2bf2160d8805de64308e2e7c3cd97813cb58ed2f
Author:     Lai Jiangshan <[email protected]>
AuthorDate: Mon, 23 Aug 2010 18:42:48 +0900
Committer:  Frederic Weisbecker <[email protected]>
CommitDate: Tue, 7 Sep 2010 17:49:34 +0200

irq: Add tracepoint to softirq_raise

Add a tracepoint for tracing when softirq action is raised.

This and the existing 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 Neil Horman <[email protected]>

Cc David Miller <[email protected]>

Cc Kaneshige Kenji <[email protected]>

Cc Izumo Taku <[email protected]>

Cc Kosaki Motohiro <[email protected]>

Cc Lai Jiangshan <[email protected]>

Cc Scott Mcmillan <[email protected]>

Cc Steven Rostedt <[email protected]>

Cc Eric Dumazet <[email protected]>

LKML-Reference: <[email protected]>

[ factorize softirq events with DECLARE_EVENT_CLASS ]

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

Signed-off-by Frederic Weisbecker <[email protected]>

---
 include/linux/interrupt.h  |    8 +++++++-
 include/trace/events/irq.h |   26 ++++++++++++++++++++++++--
 2 files changed, 31 insertions(+), 3 deletions(-)

Quoted 29 lines · tip-bot for Lai Jiangshan

Commit-ID:  2bf2160d8805de64308e2e7c3cd97813cb58ed2f
Gitweb:     http://git.kernel.org/tip/2bf2160d8805de64308e2e7c3cd97813cb58ed2f
Author:     Lai Jiangshan <[email protected]>
AuthorDate: Mon, 23 Aug 2010 18:42:48 +0900
Committer:  Frederic Weisbecker <[email protected]>
CommitDate: Tue, 7 Sep 2010 17:49:34 +0200

irq: Add tracepoint to softirq_raise

Add a tracepoint for tracing when softirq action is raised.

This and the existing 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 Neil Horman <[email protected]>

Cc David Miller <[email protected]>

Cc Kaneshige Kenji <[email protected]>

Cc Izumo Taku <[email protected]>

Cc Kosaki Motohiro <[email protected]>

Cc Lai Jiangshan <[email protected]>

Cc Scott Mcmillan <[email protected]>

Cc Steven Rostedt <[email protected]>

Cc Eric Dumazet <[email protected]>

Quoted 8 lines

LKML-Reference: <[email protected]>

[ factorize softirq events with DECLARE_EVENT_CLASS ]

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

Signed-off-by Frederic Weisbecker <[email protected]>

---
 include/linux/interrupt.h  |    8 +++++++-
 include/trace/events/irq.h |   26 ++++++++++++++++++++++++--
 2 files changed, 31 insertions(+), 3 deletions(-)

FYI, this commit broke the Sparc build:

In file included from /home/mingo/tip/arch/sparc/include/asm/irq_32.h:11,

                 from /home/mingo/tip/arch/sparc/include/asm/irq.h:6,
                 from /home/mingo/tip/include/linux/irqnr.h:10,
                 from /home/mingo/tip/include/linux/irq.h:22,
                 from /home/mingo/tip/include/asm-generic/hardirq.h:6,
                 from /home/mingo/tip/arch/sparc/include/asm/hardirq_32.h:11,
                 from /home/mingo/tip/arch/sparc/include/asm/hardirq.h:6,
                 from /home/mingo/tip/include/linux/hardirq.h:10,
                 from /home/mingo/tip/include/linux/ftrace_event.h:7,
                 from /home/mingo/tip/include/trace/syscall.h:6,
                 from /home/mingo/tip/include/linux/syscalls.h:76,
                 from /home/mingo/tip/init/initramfs.c:9:

/home/mingo/tip/include/linux/interrupt.h: In function '__raise_softirq_irqoff':
/home/mingo/tip/include/linux/interrupt.h:414: error: implicit declaration of function 'local_softirq_pending' /home/mingo/tip/include/linux/interrupt.h:414: error: lvalue required as left operand of assignment make[2]: *** [init/initramfs.o] Error 1
make[2]: *** Waiting for unfinished jobs....
In file included from /home/mingo/tip/arch/sparc/include/asm/irq_32.h:11,

Ingo

From fc21eaa02d4a6f0af396af6a106587e61515cd86 Mon Sep 17 00:00:00 2001

Quoted 29 lines · tip-bot for Lai Jiangshan

Commit-ID:  2bf2160d8805de64308e2e7c3cd97813cb58ed2f
Gitweb:     http://git.kernel.org/tip/2bf2160d8805de64308e2e7c3cd97813cb58ed2f
Author:     Lai Jiangshan <[email protected]>
AuthorDate: Mon, 23 Aug 2010 18:42:48 +0900
Committer:  Frederic Weisbecker <[email protected]>
CommitDate: Tue, 7 Sep 2010 17:49:34 +0200

irq: Add tracepoint to softirq_raise

Add a tracepoint for tracing when softirq action is raised.

This and the existing 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 Neil Horman <[email protected]>

Cc David Miller <[email protected]>

Cc Kaneshige Kenji <[email protected]>

Cc Izumo Taku <[email protected]>

Cc Kosaki Motohiro <[email protected]>

Cc Lai Jiangshan <[email protected]>

Cc Scott Mcmillan <[email protected]>

Cc Steven Rostedt <[email protected]>

Cc Eric Dumazet <[email protected]>

Quoted 8 lines

LKML-Reference: <[email protected]>

[ factorize softirq events with DECLARE_EVENT_CLASS ]

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

Signed-off-by Frederic Weisbecker <[email protected]>

---
 include/linux/interrupt.h  |    8 +++++++-
 include/trace/events/irq.h |   26 ++++++++++++++++++++++++--
 2 files changed, 31 insertions(+), 3 deletions(-)

FYI, this commit broke the Sparc build:

In file included from /home/mingo/tip/arch/sparc/include/asm/irq_32.h:11,

                 from /home/mingo/tip/arch/sparc/include/asm/irq.h:6,
                 from /home/mingo/tip/include/linux/irqnr.h:10,
                 from /home/mingo/tip/include/linux/irq.h:22,
                 from /home/mingo/tip/include/asm-generic/hardirq.h:6,
                 from /home/mingo/tip/arch/sparc/include/asm/hardirq_32.h:11,
                 from /home/mingo/tip/arch/sparc/include/asm/hardirq.h:6,
                 from /home/mingo/tip/include/linux/hardirq.h:10,
                 from /home/mingo/tip/include/linux/ftrace_event.h:7,
                 from /home/mingo/tip/include/trace/syscall.h:6,
                 from /home/mingo/tip/include/linux/syscalls.h:76,
                 from /home/mingo/tip/init/initramfs.c:9:

/home/mingo/tip/include/linux/interrupt.h: In function '__raise_softirq_irqoff':
/home/mingo/tip/include/linux/interrupt.h:414: error: implicit declaration of function 'local_softirq_pending' /home/mingo/tip/include/linux/interrupt.h:414: error: lvalue required as left operand of assignment make[2]: *** [init/initramfs.o] Error 1
make[2]: *** Waiting for unfinished jobs....
In file included from /home/mingo/tip/arch/sparc/include/asm/irq_32.h:11,

Quoted 31 lines · Ingo Molnar

Quoted 29 lines · tip-bot for Lai Jiangshan

Commit-ID:  2bf2160d8805de64308e2e7c3cd97813cb58ed2f
Gitweb:     http://git.kernel.org/tip/2bf2160d8805de64308e2e7c3cd97813cb58ed2f
Author:     Lai Jiangshan <[email protected]>
AuthorDate: Mon, 23 Aug 2010 18:42:48 +0900
Committer:  Frederic Weisbecker <[email protected]>
CommitDate: Tue, 7 Sep 2010 17:49:34 +0200

irq: Add tracepoint to softirq_raise

Add a tracepoint for tracing when softirq action is raised.

This and the existing 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 Neil Horman <[email protected]>

Cc David Miller <[email protected]>

Cc Kaneshige Kenji <[email protected]>

Cc Izumo Taku <[email protected]>

Cc Kosaki Motohiro <[email protected]>

Cc Lai Jiangshan <[email protected]>

Cc Scott Mcmillan <[email protected]>

Cc Steven Rostedt <[email protected]>

Cc Eric Dumazet <[email protected]>

Quoted 9 lines

Quoted 8 lines

LKML-Reference: <[email protected]>

[ factorize softirq events with DECLARE_EVENT_CLASS ]

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

Signed-off-by Frederic Weisbecker <[email protected]>

---
 include/linux/interrupt.h  |    8 +++++++-
 include/trace/events/irq.h |   26 ++++++++++++++++++++++++--
 2 files changed, 31 insertions(+), 3 deletions(-)

I could build sparc64_defconfig, but s390 is broken for me by this...

Quoted 1 line

I could build sparc64_defconfig, but s390 is broken for me by this...

the below makes s390 build again, not sure its completely safe for all configs though...

Heiko?

---
 arch/s390/include/asm/hardirq.h |    1 -
 1 files changed, 0 insertions(+), 1 deletions(-)

arch/s390/include/asm/hardirq.h +0 -1

index 498bc38..9558a71 100644
@@ -15,7 +15,6 @@
 #include <linux/threads.h>
 #include <linux/sched.h>
 #include <linux/cache.h>
-#include <linux/interrupt.h>
 #include <asm/lowcore.h>
 
 #define local_softirq_pending() (S390_lowcore.softirq_pending)

Quoted 33 lines · Ingo Molnar

Quoted 9 lines · tip-bot for Lai Jiangshan

Commit-ID:  2bf2160d8805de64308e2e7c3cd97813cb58ed2f
Gitweb:     http://git.kernel.org/tip/2bf2160d8805de64308e2e7c3cd97813cb58ed2f
Author:     Lai Jiangshan <[email protected]>
AuthorDate: Mon, 23 Aug 2010 18:42:48 +0900
Committer:  Frederic Weisbecker <[email protected]>
CommitDate: Tue, 7 Sep 2010 17:49:34 +0200

irq: Add tracepoint to softirq_raise

Quoted 9 lines

Add a tracepoint for tracing when softirq action is raised.

This and the existing 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.

In file included from /home/mingo/tip/arch/sparc/include/asm/irq_32.h:11,

                 from /home/mingo/tip/arch/sparc/include/asm/irq.h:6,
                 from /home/mingo/tip/include/linux/irqnr.h:10,
                 from /home/mingo/tip/include/linux/irq.h:22,
                 from /home/mingo/tip/include/asm-generic/hardirq.h:6,
                 from /home/mingo/tip/arch/sparc/include/asm/hardirq_32.h:11,
                 from /home/mingo/tip/arch/sparc/include/asm/hardirq.h:6,
                 from /home/mingo/tip/include/linux/hardirq.h:10,
                 from /home/mingo/tip/include/linux/ftrace_event.h:7,
                 from /home/mingo/tip/include/trace/syscall.h:6,
                 from /home/mingo/tip/include/linux/syscalls.h:76,
                 from /home/mingo/tip/init/initramfs.c:9:

Quoted 6 lines

/home/mingo/tip/include/linux/interrupt.h: In function '__raise_softirq_irqoff':
/home/mingo/tip/include/linux/interrupt.h:414: error: implicit declaration of function 'local_softirq_pending' /home/mingo/tip/include/linux/interrupt.h:414: error: lvalue required as left operand of assignment make[2]: *** [init/initramfs.o] Error 1
make[2]: *** Waiting for unfinished jobs....
In file included from /home/mingo/tip/arch/sparc/include/asm/irq_32.h:11,

I could build sparc64_defconfig, but s390 is broken for me by this...

Quoted 41 lines · Peter Zijlstra

Quoted 39 lines · Ingo Molnar

Quoted 9 lines · tip-bot for Lai Jiangshan

Commit-ID:  2bf2160d8805de64308e2e7c3cd97813cb58ed2f
Gitweb:     http://git.kernel.org/tip/2bf2160d8805de64308e2e7c3cd97813cb58ed2f
Author:     Lai Jiangshan <[email protected]>
AuthorDate: Mon, 23 Aug 2010 18:42:48 +0900
Committer:  Frederic Weisbecker <[email protected]>
CommitDate: Tue, 7 Sep 2010 17:49:34 +0200

irq: Add tracepoint to softirq_raise

Quoted 9 lines

Add a tracepoint for tracing when softirq action is raised.

This and the existing 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.

In file included from /home/mingo/tip/arch/sparc/include/asm/irq_32.h:11,

                 from /home/mingo/tip/arch/sparc/include/asm/irq.h:6,
                 from /home/mingo/tip/include/linux/irqnr.h:10,
                 from /home/mingo/tip/include/linux/irq.h:22,
                 from /home/mingo/tip/include/asm-generic/hardirq.h:6,
                 from /home/mingo/tip/arch/sparc/include/asm/hardirq_32.h:11,
                 from /home/mingo/tip/arch/sparc/include/asm/hardirq.h:6,
                 from /home/mingo/tip/include/linux/hardirq.h:10,
                 from /home/mingo/tip/include/linux/ftrace_event.h:7,
                 from /home/mingo/tip/include/trace/syscall.h:6,
                 from /home/mingo/tip/include/linux/syscalls.h:76,
                 from /home/mingo/tip/init/initramfs.c:9:

/home/mingo/tip/include/linux/interrupt.h: In function '__raise_softirq_irqoff':
/home/mingo/tip/include/linux/interrupt.h:414: error: implicit declaration of function 'local_softirq_pending' /home/mingo/tip/include/linux/interrupt.h:414: error: lvalue required as left operand of assignment make[2]: *** [init/initramfs.o] Error 1
make[2]: *** Waiting for unfinished jobs....
In file included from /home/mingo/tip/arch/sparc/include/asm/irq_32.h:11,

Quoted 1 line

I could build sparc64_defconfig, but s390 is broken for me by this...

/me being very grumpy @ Lai.. ia64 is broken too!

/me goes revert this shite

Quoted 1 line

Quoted 1 line

I could build sparc64_defconfig, but s390 is broken for me by

this...

Quoted 5 lines

/me being very grumpy @ Lai.. ia64 is broken too!

/me goes revert this shite

Now it is fixed.

http://git.kernel.org/?p=linux/kernel/git/next/linux-next.git;a=commitdiff;h=9f081ce5da2c8af297a0a7d15a57fb4beeed374b;hp=43e3bf203456c4f06bdd6060426976ad2bed9081

With the addition of trace_softirq_raise() the softirq tracepoint got even more convoluted. Why the tracepoints take two pointers to assign an integer is beyond my comprehension.

But adding an extra case which treats the first pointer as an unsigned long when the second pointer is NULL including the back and forth type casting is just horrible.

Convert the softirq tracepoints to take a single unsigned int argument for the softirq vector number and fix the call sites.

Signed-off-by Thomas Gleixner <[email protected]>

With the addition of trace_softirq_raise() the softirq tracepoint got even more convoluted. Why the tracepoints take two pointers to assign an integer is beyond my comprehension.

But adding an extra case which treats the first pointer as an unsigned long when the second pointer is NULL including the back and forth type casting is just horrible.

Convert the softirq tracepoints to take a single unsigned int argument for the softirq vector number and fix the call sites.

Signed-off-by Thomas Gleixner <[email protected]>

---
 include/linux/interrupt.h  |    2 -
 include/trace/events/irq.h |   54 ++++++++++++++++-----------------------------
 kernel/softirq.c           |   14 ++++++-----
 3 files changed, 29 insertions(+), 41 deletions(-)

include/linux/interrupt.h +1 -1

index 531495d..0ac1949 100644
@@ -410,7 +410,7 @@ extern void open_softirq(int nr, void (*action)(struct softirq_action *));
 extern void softirq_init(void);
 static inline void __raise_softirq_irqoff(unsigned int nr)
 {
-	trace_softirq_raise((struct softirq_action *)(unsigned long)nr, NULL);
+	trace_softirq_raise(nr);
 	or_softirq_pending(1UL << nr);
 }
 

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

index 6fa7cba..1c09820 100644
@@ -86,76 +86,62 @@ TRACE_EVENT(irq_handler_exit,
 
 DECLARE_EVENT_CLASS(softirq,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int vec_nr),
 
-	TP_ARGS(h, vec),
+	TP_ARGS(vec_nr),
 
 	TP_STRUCT__entry(
-		__field(	int,	vec			)
+		__field(	unsigned int,	vec	)
 	),
 
 	TP_fast_assign(
-		if (vec)
-			__entry->vec = (int)(h - vec);
-		else
-			__entry->vec = (int)(long)h;
+		__entry->vec = vec_nr;
 	),
 
-	TP_printk("vec=%d [action=%s]", __entry->vec,
+	TP_printk("vec=%u [action=%s]", __entry->vec,
 		  show_softirq_name(__entry->vec))
 );
 
 /**
  * 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
+ * @vec_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
- * we can determine the softirq latency.
+ * When used in combination with the softirq_exit tracepoint
+ * we can determine the softirq handler runtine.
  */
 DEFINE_EVENT(softirq, softirq_entry,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int vec_nr),
 
-	TP_ARGS(h, vec)
+	TP_ARGS(vec_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
+ * @vec_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.
+ * When used in combination with the softirq_entry tracepoint
+ * we can determine the softirq handler runtine.
  */
 DEFINE_EVENT(softirq, softirq_exit,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int vec_nr),
 
-	TP_ARGS(h, vec)
+	TP_ARGS(vec_nr)
 );
 
 /**
  * softirq_raise - called immediately when a softirq is raised
- * @h: pointer to struct softirq_action
- * @vec: pointer to first struct softirq_action in softirq_vec array
+ * @vec_nr:  softirq vector number
  *
- * The @h parameter contains a pointer to the softirq vector number which is
- * raised. @vec is NULL and it means @h includes vector number not
- * softirq_action. When used in combination with the softirq_entry tracepoint
- * we can determine the softirq raise latency.
+ * When used in combination with the softirq_entry tracepoint
+ * we can determine the softirq raise to run latency.
  */
 DEFINE_EVENT(softirq, softirq_raise,
 
-	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_PROTO(unsigned int vec_nr),
 
-	TP_ARGS(h, vec)
+	TP_ARGS(vec_nr)
 );
 
 #endif /*  _TRACE_IRQ_H */

kernel/softirq.c +8 -6

index 07b4f1b..c0a9ea5 100644
@@ -212,18 +212,20 @@ restart:
 
 	do {
 		if (pending & 1) {
+			unsigned int vec_nr = h - softirq_vec;
 			int prev_count = preempt_count();
-			kstat_incr_softirqs_this_cpu(h - softirq_vec);
 
-			trace_softirq_entry(h, softirq_vec);
+			kstat_incr_softirqs_this_cpu(vec_nr);
+
+			trace_softirq_entry(vec_nr);
 			h->action(h);
-			trace_softirq_exit(h, softirq_vec);
+			trace_softirq_exit(vec_nr);
 			if (unlikely(prev_count != preempt_count())) {
 				printk(KERN_ERR "huh, entered softirq %td %s %p"
 				       "with preempt_count %08x,"
-				       " exited with %08x?\n", h - softirq_vec,
-				       softirq_to_name[h - softirq_vec],
-				       h->action, prev_count, preempt_count());
+				       " exited with %08x?\n", vec_nr,
+				       softirq_to_name[vec_nr], h->action,
+				       prev_count, preempt_count());
 				preempt_count() = prev_count;
 			}
 

Quoted 8 lines · * Thomas Gleixner ([email protected]) wrote:

With the addition of trace_softirq_raise() the softirq tracepoint got even more convoluted. Why the tracepoints take two pointers to assign an integer is beyond my comprehension.

But adding an extra case which treats the first pointer as an unsigned long when the second pointer is NULL including the back and forth type casting is just horrible.

Quoted 2 lines

Convert the softirq tracepoints to take a single unsigned int argument for the softirq vector number and fix the call sites.

Well, there was originally a reason for this oddness. The in __do_softirq(), "h - softirq_ve"c computation was not needed outside of the tracepoint handler in the past, but it now seems to be required with the new inlined "kstat_incr_softirqs_this_cpu()".

On Tue, 19 Oct 2010, Mathieu Desnoyers wrote:

Dudes, a vector computation is hardly a performance problem in that function and definitely not an excuse for designing such horrible interfaces.

Quoted 12 lines · Mathieu Desnoyers

Quoted 10 lines · * Thomas Gleixner ([email protected]) wrote:

With the addition of trace_softirq_raise() the softirq tracepoint got even more convoluted. Why the tracepoints take two pointers to assign an integer is beyond my comprehension.

But adding an extra case which treats the first pointer as an unsigned long when the second pointer is NULL including the back and forth type casting is just horrible.

Convert the softirq tracepoints to take a single unsigned int argument for the softirq vector number and fix the call sites.

Quoted 4 lines

Well, there was originally a reason for this oddness. The in __do_softirq(), "h - softirq_ve"c computation was not needed outside of the tracepoint handler in the past, but it now seems to be required with the new inlined "kstat_incr_softirqs_this_cpu()".

Dudes, a vector computation is hardly a performance problem in that function and definitely not an excuse for designing such horrible interfaces.

Quoted 5 lines · Thomas Gleixner

On Tue, 19 Oct 2010, Mathieu Desnoyers wrote:

Dudes, a vector computation is hardly a performance problem in that function and definitely not an excuse for designing such horrible interfaces.

Yes, now we can be a bit more liberal. But when these tracepoints were going in, people were watching to make sure they have practically zero impact when tracing was disabled.

Now that people are more use to tracepoints, they are more understanding to have cleaner code over that extra few more lines of machine code in the fast path.

Quoted 7 lines · Steven Rostedt

Quoted 5 lines · Thomas Gleixner

On Tue, 19 Oct 2010, Mathieu Desnoyers wrote:

Dudes, a vector computation is hardly a performance problem in that function and definitely not an excuse for designing such horrible interfaces.

Quoted 7 lines

Yes, now we can be a bit more liberal. But when these tracepoints were going in, people were watching to make sure they have practically zero impact when tracing was disabled.

Now that people are more use to tracepoints, they are more understanding to have cleaner code over that extra few more lines of machine code in the fast path.

The vector computation is compared to the extra tracing induced jumps probably not even measurable. Stop defending horrible coding with handwavy performance and impact arguments.

From the moment markers and tracepoints infrastructures were merged, the

Thanks,

tglx

The vector computation is compared to the extra tracing induced jumps probably not even measurable. Stop defending horrible coding with handwavy performance and impact arguments.

Quoted 1 line · * Thomas Gleixner ([email protected]) wrote:

On Tue, 19 Oct 2010, Steven Rostedt wrote:

as an excuse for adding extra performance impact to kernel code, because when it will be replaced by asm gotos, all that will be left is the performance impact inappropriately justified as insignificant compared to the impact of the old tracepoint scheme.

Let's instead look at some more facts:

#include <linux/interrupt.h>
#include <linux/module.h>

#include <trace/events/irq.h>

static struct softirq_action softirq_vec[NR_SOFTIRQS];

void test(struct softirq_action *h)

{
	trace_softirq_entry(h - softirq_vec);

	h->action(h);
}

Compile this code with GCC 4.5 with and without jump labels (zap the select HAVE_ARCH_JUMP_LABEL line in arch/x86/Kconfig)

So now the !jumplabel case gives us:

../build/kernel/soft.o: file format elf64-x86-64

Disassembly of section .text:

0000000000000000 <test>:

   0:	55                   	push   %rbp
   1:	48 89 e5             	mov    %rsp,%rbp
   4:	41 55                	push   %r13
   6:	49 89 fd             	mov    %rdi,%r13
   9:	49 81 ed 00 00 00 00 	sub    $0x0,%r13
  10:	41 54                	push   %r12
  12:	49 c1 ed 03          	shr    $0x3,%r13
  16:	49 89 fc             	mov    %rdi,%r12
  19:	53                   	push   %rbx
  1a:	48 83 ec 08          	sub    $0x8,%rsp
  1e:	83 3d 00 00 00 00 00 	cmpl   $0x0,0x0(%rip)        # 25 <test+0x25>
  25:	74 4d                	je     74 <test+0x74>
  27:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
  2e:	00 00 
  30:	ff 80 44 e0 ff ff    	incl   -0x1fbc(%rax)
  36:	48 8b 1d 00 00 00 00 	mov    0x0(%rip),%rbx        # 3d <test+0x3d>
  3d:	48 85 db             	test   %rbx,%rbx
  40:	74 13                	je     55 <test+0x55>
  42:	48 8b 7b 08          	mov    0x8(%rbx),%rdi
  46:	44 89 ee             	mov    %r13d,%esi
  49:	ff 13                	callq  *(%rbx)
  4b:	48 83 c3 10          	add    $0x10,%rbx
  4f:	48 83 3b 00          	cmpq   $0x0,(%rbx)
  53:	eb eb                	jmp    40 <test+0x40>
  55:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
  5c:	00 00 
  5e:	ff 88 44 e0 ff ff    	decl   -0x1fbc(%rax)
  64:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
  6b:	a8 08                	test   $0x8,%al
  6d:	74 05                	je     74 <test+0x74>
  6f:	e8 00 00 00 00       	callq  74 <test+0x74>
  74:	4c 89 e7             	mov    %r12,%rdi
  77:	41 ff 14 24          	callq  *(%r12)
  7b:	58                   	pop    %rax
  7c:	5b                   	pop    %rbx
  7d:	41 5c                	pop    %r12
  7f:	41 5d                	pop    %r13

81: c9 leaveq
82: c3 retq

The jumplabel=y case gives:

../build/kernel/soft.o: file format elf64-x86-64

Disassembly of section .text:

0000000000000000 <test>:

   0:	55                   	push   %rbp
   1:	48 89 e5             	mov    %rsp,%rbp
   4:	41 55                	push   %r13
   6:	49 89 fd             	mov    %rdi,%r13
   9:	49 81 ed 00 00 00 00 	sub    $0x0,%r13
  10:	41 54                	push   %r12
  12:	49 c1 ed 03          	shr    $0x3,%r13
  16:	49 89 fc             	mov    %rdi,%r12
  19:	53                   	push   %rbx
  1a:	48 83 ec 08          	sub    $0x8,%rsp
  1e:	e9 00 00 00 00       	jmpq   23 <test+0x23>
  23:	eb 4d                	jmp    72 <test+0x72>
  25:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
  2c:	00 00 
  2e:	ff 80 44 e0 ff ff    	incl   -0x1fbc(%rax)
  34:	48 8b 1d 00 00 00 00 	mov    0x0(%rip),%rbx        # 3b <test+0x3b>
  3b:	48 85 db             	test   %rbx,%rbx
  3e:	74 13                	je     53 <test+0x53>
  40:	48 8b 7b 08          	mov    0x8(%rbx),%rdi
  44:	44 89 ee             	mov    %r13d,%esi
  47:	ff 13                	callq  *(%rbx)
  49:	48 83 c3 10          	add    $0x10,%rbx
  4d:	48 83 3b 00          	cmpq   $0x0,(%rbx)
  51:	eb eb                	jmp    3e <test+0x3e>
  53:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
  5a:	00 00 
  5c:	ff 88 44 e0 ff ff    	decl   -0x1fbc(%rax)
  62:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
  69:	a8 08                	test   $0x8,%al
  6b:	74 05                	je     72 <test+0x72>
  6d:	e8 00 00 00 00       	callq  72 <test+0x72>
  72:	4c 89 e7             	mov    %r12,%rdi
  75:	41 ff 14 24          	callq  *(%r12)
  79:	58                   	pop    %rax
  7a:	5b                   	pop    %rbx
  7b:	41 5c                	pop    %r12
  7d:	41 5d                	pop    %r13

7f: c9 leaveq
80: c3 retq

So that saves _TWO_ bytes of text and replaces:

(quoted diff) +2 -2

-  1e:	83 3d 00 00 00 00 00 	cmpl   $0x0,0x0(%rip)        # 25 <test+0x25>
-  25:	74 4d                	je     74 <test+0x74>
+  1e:	e9 00 00 00 00       	jmpq   23 <test+0x23>
+  23:	eb 4d                	jmp    72 <test+0x72>

So it trades a conditional vs. two jumps ? WTF ??

I thought that jumplabel magic was supposed to get rid of the jump over the tracing code ? In fact it adds another jump. Whatfor ?

Now even worse, when you NOP out the jmpq then your tracepoint is still not enabled. Brilliant !

Did you guys ever look at the assembly output of that insane shite you are advertising with lengthy explanations ?

Obviously _NOT_

Come back when you can show me a clean imlementation of all this crap which reproduces with my jumplabel enabled stock compiler. And please just send me a patch w/o the blurb.

And sane looks like:

jmpq 2f <---- This gets noped out
1:

    mov    %r12,%rdi
    callq  *(%r12)
    [whatever cleanup it takes ]
    leaveq 
    retq   

2f:
[tracing gunk]
jmp 1b

And further I want to see the tracing gunk in a minimal size so the net/core/dev.c deinlining does not happen.

Thanks,

tglx

P.S.: It might be helpful and polite if you'd take off your tracing
blinkers from time to time.

Quoted 8 lines · Thomas Gleixner

So that saves _TWO_ bytes of text and replaces:

(quoted diff) +2 -2

-  1e:	83 3d 00 00 00 00 00 	cmpl   $0x0,0x0(%rip)        # 25 <test+0x25>
-  25:	74 4d                	je     74 <test+0x74>
+  1e:	e9 00 00 00 00       	jmpq   23 <test+0x23>
+  23:	eb 4d                	jmp    72 <test+0x72>

So it trades a conditional vs. two jumps ? WTF ??

Well, the one jmpq is noped out, and the jmp is non conditional. I've

always thought a non conditional jmp was faster than a conditional one,

since there's no need to go into the branch prediction logic. The CPU can simply skip to the code to jump next. Of counse, this pollutes the I$.

So that saves _TWO_ bytes of text and replaces:

(quoted diff) +2 -2

-  1e:	83 3d 00 00 00 00 00 	cmpl   $0x0,0x0(%rip)        # 25<test+0x25>
-  25:	74 4d                	je     74<test+0x74>
+  1e:	e9 00 00 00 00       	jmpq   23<test+0x23>
+  23:	eb 4d                	jmp    72<test+0x72>

So it trades a conditional vs. two jumps ? WTF ??

I thought that jumplabel magic was supposed to get rid of the jump over the tracing code ? In fact it adds another jump. Whatfor ?

Now even worse, when you NOP out the jmpq then your tracepoint is still not enabled. Brilliant !

Did you guys ever look at the assembly output of that insane shite you are advertising with lengthy explanations ?

Obviously _NOT_

Come back when you can show me a clean imlementation of all this crap which reproduces with my jumplabel enabled stock compiler. And please just send me a patch w/o the blurb.

And sane looks like:

jmpq 2f<---- This gets noped out
1:

     mov    %r12,%rdi
     callq  *(%r12)
     [whatever cleanup it takes ]
     leaveq
     retq

2f:
[tracing gunk]
jmp 1b

And further I want to see the tracing gunk in a minimal size so the net/core/dev.c deinlining does not happen.

Thanks,

tglx

P.S.: It might be helpful and polite if you'd take off your tracing
blinkers from time to time.
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Quoted 8 lines · Steven Rostedt

Quoted 7 lines · Thomas Gleixner

So that saves _TWO_ bytes of text and replaces:

(quoted diff) +2 -2

-  1e:	83 3d 00 00 00 00 00 	cmpl   $0x0,0x0(%rip)        # 25 <test+0x25>
-  25:	74 4d                	je     74 <test+0x74>
+  1e:	e9 00 00 00 00       	jmpq   23 <test+0x23>
+  23:	eb 4d                	jmp    72 <test+0x72>

Quoted 3 lines

Quoted 1 line

So it trades a conditional vs. two jumps ? WTF ??

Well, the one jmpq is noped out, and the jmp is non conditional. I've

What are you smoking ?

In case the trace point is enabled the jmpq is there, so it jumps to 23 and jumps from there to 72.

In case the trace point is disabled the jmpq is noped out, so it jumps to 72 directly.

Quoted 2 lines

always thought a non conditional jmp was faster than a conditional one,

I always thought, that at least some of the stuff which comes from tracing folks makes some sense.

Quoted 4 lines

since there's no need to go into the branch prediction logic. The CPU can simply skip to the code to jump next. Of counse, this pollutes the I$.

We might consult Mathieu for further useless blurb on how CPUs work around broken code.

Quoted 5 lines

Quoted 1 line · Steven Rostedt

as an excuse for adding extra performance impact to kernel code, because when it will be replaced by asm gotos, all that will be left is the performance impact inappropriately justified as insignificant compared to the impact of the old tracepoint scheme.

Can you at one point just stop your tracing lectures and look at the facts ?

The impact of a sensible tracepoint design on the code in question before kstat_incr_softirqs_this_cpu() was added would have been a mere _FIVE_ bytes of text. But the original tracepoint code itself is _TWENTY_ bytes of text larger.

So we trade horrible code plus 20 bytes text against 5 bytes of text in the hotpath. And you tell me that these _FIVE_ bytes are impacting performance so much that it's significant.

Now with kstat_incr_softirqs_this_cpu() the impact is zero, it even removes code.

And talking about non impact of disabled trace points. The tracepoint in question which made me look at the code results in deinlining __raise_softirq_irqsoff() in net/dev/core.c. There goes your theory.

So no, you _cannot_ tell what impact a tracepoint has in reality except by looking at the assembly output.

And what scares me way more is the size of a single tracepoint in a code file.

Just adding "trace_softirq_entry(nr);" adds 88 bytes of text. So that's optimized tracing code ?

All it's supposed to do is:

    if (enabled)
	trace_foo(nr);

Replace "if (enabled)" with your favourite code patching jump label whatever magic. The above stupid version takes about 28, but the "optimized" tracing code makes that 88. Brilliant. That's inlining utter shite for no good reason. WTF is it necessary to inline all that gunk ?

Please spare me the "jump label will make this less intrusive" lecture. I'm not interested at all.

Let's instead look at some more facts:

#include <linux/interrupt.h>
#include <linux/module.h>

#include <trace/events/irq.h>

static struct softirq_action softirq_vec[NR_SOFTIRQS];

void test(struct softirq_action *h)

{
	trace_softirq_entry(h - softirq_vec);

	h->action(h);
}

Compile this code with GCC 4.5 with and without jump labels (zap the select HAVE_ARCH_JUMP_LABEL line in arch/x86/Kconfig)

So now the !jumplabel case gives us:

../build/kernel/soft.o: file format elf64-x86-64

Disassembly of section .text:

0000000000000000 <test>:

   0:	55                   	push   %rbp
   1:	48 89 e5             	mov    %rsp,%rbp
   4:	41 55                	push   %r13
   6:	49 89 fd             	mov    %rdi,%r13
   9:	49 81 ed 00 00 00 00 	sub    $0x0,%r13
  10:	41 54                	push   %r12
  12:	49 c1 ed 03          	shr    $0x3,%r13
  16:	49 89 fc             	mov    %rdi,%r12
  19:	53                   	push   %rbx
  1a:	48 83 ec 08          	sub    $0x8,%rsp
  1e:	83 3d 00 00 00 00 00 	cmpl   $0x0,0x0(%rip)        # 25 <test+0x25>
  25:	74 4d                	je     74 <test+0x74>
  27:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
  2e:	00 00 
  30:	ff 80 44 e0 ff ff    	incl   -0x1fbc(%rax)
  36:	48 8b 1d 00 00 00 00 	mov    0x0(%rip),%rbx        # 3d <test+0x3d>
  3d:	48 85 db             	test   %rbx,%rbx
  40:	74 13                	je     55 <test+0x55>
  42:	48 8b 7b 08          	mov    0x8(%rbx),%rdi
  46:	44 89 ee             	mov    %r13d,%esi
  49:	ff 13                	callq  *(%rbx)
  4b:	48 83 c3 10          	add    $0x10,%rbx
  4f:	48 83 3b 00          	cmpq   $0x0,(%rbx)
  53:	eb eb                	jmp    40 <test+0x40>
  55:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
  5c:	00 00 
  5e:	ff 88 44 e0 ff ff    	decl   -0x1fbc(%rax)
  64:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
  6b:	a8 08                	test   $0x8,%al
  6d:	74 05                	je     74 <test+0x74>
  6f:	e8 00 00 00 00       	callq  74 <test+0x74>
  74:	4c 89 e7             	mov    %r12,%rdi
  77:	41 ff 14 24          	callq  *(%r12)
  7b:	58                   	pop    %rax
  7c:	5b                   	pop    %rbx
  7d:	41 5c                	pop    %r12
  7f:	41 5d                	pop    %r13

81: c9 leaveq
82: c3 retq

The jumplabel=y case gives:

../build/kernel/soft.o: file format elf64-x86-64

Disassembly of section .text:

0000000000000000 <test>:

   0:	55                   	push   %rbp
   1:	48 89 e5             	mov    %rsp,%rbp
   4:	41 55                	push   %r13
   6:	49 89 fd             	mov    %rdi,%r13
   9:	49 81 ed 00 00 00 00 	sub    $0x0,%r13
  10:	41 54                	push   %r12
  12:	49 c1 ed 03          	shr    $0x3,%r13
  16:	49 89 fc             	mov    %rdi,%r12
  19:	53                   	push   %rbx
  1a:	48 83 ec 08          	sub    $0x8,%rsp
  1e:	e9 00 00 00 00       	jmpq   23 <test+0x23>
  23:	eb 4d                	jmp    72 <test+0x72>
  25:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
  2c:	00 00 
  2e:	ff 80 44 e0 ff ff    	incl   -0x1fbc(%rax)
  34:	48 8b 1d 00 00 00 00 	mov    0x0(%rip),%rbx        # 3b <test+0x3b>
  3b:	48 85 db             	test   %rbx,%rbx
  3e:	74 13                	je     53 <test+0x53>
  40:	48 8b 7b 08          	mov    0x8(%rbx),%rdi
  44:	44 89 ee             	mov    %r13d,%esi
  47:	ff 13                	callq  *(%rbx)
  49:	48 83 c3 10          	add    $0x10,%rbx
  4d:	48 83 3b 00          	cmpq   $0x0,(%rbx)
  51:	eb eb                	jmp    3e <test+0x3e>
  53:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
  5a:	00 00 
  5c:	ff 88 44 e0 ff ff    	decl   -0x1fbc(%rax)
  62:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
  69:	a8 08                	test   $0x8,%al
  6b:	74 05                	je     72 <test+0x72>
  6d:	e8 00 00 00 00       	callq  72 <test+0x72>
  72:	4c 89 e7             	mov    %r12,%rdi
  75:	41 ff 14 24          	callq  *(%r12)
  79:	58                   	pop    %rax
  7a:	5b                   	pop    %rbx
  7b:	41 5c                	pop    %r12
  7d:	41 5d                	pop    %r13

7f: c9 leaveq
80: c3 retq

So that saves _TWO_ bytes of text and replaces:

(quoted diff) +2 -2

-  1e:	83 3d 00 00 00 00 00 	cmpl   $0x0,0x0(%rip)        # 25 <test+0x25>
-  25:	74 4d                	je     74 <test+0x74>
+  1e:	e9 00 00 00 00       	jmpq   23 <test+0x23>
+  23:	eb 4d                	jmp    72 <test+0x72>

So it trades a conditional vs. two jumps ? WTF ??

I thought that jumplabel magic was supposed to get rid of the jump over the tracing code ? In fact it adds another jump. Whatfor ?

Now even worse, when you NOP out the jmpq then your tracepoint is still not enabled. Brilliant !

Did you guys ever look at the assembly output of that insane shite you are advertising with lengthy explanations ?

Obviously _NOT_

Come back when you can show me a clean imlementation of all this crap which reproduces with my jumplabel enabled stock compiler. And please just send me a patch w/o the blurb.

And sane looks like:

jmpq 2f <---- This gets noped out
1:

    mov    %r12,%rdi
    callq  *(%r12)
    [whatever cleanup it takes ]
    leaveq 
    retq   

2f:
[tracing gunk]
jmp 1b

On 10/19/2010 12:49 PM, Thomas Gleixner wrote:
[...]

Quoted 11 lines

So that saves _TWO_ bytes of text and replaces:

(quoted diff) +2 -2

-  1e:	83 3d 00 00 00 00 00 	cmpl   $0x0,0x0(%rip)        # 25<test+0x25>
-  25:	74 4d                	je     74<test+0x74>
+  1e:	e9 00 00 00 00       	jmpq   23<test+0x23>
+  23:	eb 4d                	jmp    72<test+0x72>

So it trades a conditional vs. two jumps ? WTF ??

I thought that jumplabel magic was supposed to get rid of the jump over the tracing code ? In fact it adds another jump. Whatfor ?

The 'asm goto' construct in GCC-4.5 is deficient in this area.

GCC assumes that all exit paths from an 'asm goto' are equally likely, so the tracing (or dynamic printk etc.) code is assumed to be hot and is emitted inline. Since they are inline like this, there are all these jumps around them and they pollute the I-Cache.

I was looking at fixing it, but I think a true general purpose fix would require enhancing GCC's grammar to allow specifying of the 'likelyness' of each exit path from 'asm goto'.

David Daney

Quoted 25 lines · David Daney

On 10/19/2010 12:49 PM, Thomas Gleixner wrote:
[...]

Quoted 11 lines

So that saves _TWO_ bytes of text and replaces:

(quoted diff) +2 -2

-  1e:	83 3d 00 00 00 00 00 	cmpl   $0x0,0x0(%rip)        # 25<test+0x25>
-  25:	74 4d                	je     74<test+0x74>
+  1e:	e9 00 00 00 00       	jmpq   23<test+0x23>
+  23:	eb 4d                	jmp    72<test+0x72>

So it trades a conditional vs. two jumps ? WTF ??

I thought that jumplabel magic was supposed to get rid of the jump over the tracing code ? In fact it adds another jump. Whatfor ?

The 'asm goto' construct in GCC-4.5 is deficient in this area.

GCC assumes that all exit paths from an 'asm goto' are equally likely, so the tracing (or dynamic printk etc.) code is assumed to be hot and is emitted inline. Since they are inline like this, there are all these jumps around them and they pollute the I-Cache.

I was looking at fixing it, but I think a true general purpose fix would require enhancing GCC's grammar to allow specifying of the 'likelyness' of each exit path from 'asm goto'.

Quoted 2 lines

David Daney

right, the next step is adding support for hot/cold labels, so the tracing code will be annotaed with a 'cold' label. Thus, not adding the 'jmp' above on line '23', and in fact moving the tracing code out-of-line. Maybe I haven't been clear on this.

On Tue, 2010-10-19 at 21:49 +0200, Thomas Gleixner wrote:

Because you do the h - softvec in the tracepoint parameter? I got a different result:

On 10/19/2010 12:49 PM, Thomas Gleixner wrote:
[...]

Quoted 11 lines

So that saves _TWO_ bytes of text and replaces:

(quoted diff) +2 -2

-  1e:	83 3d 00 00 00 00 00 	cmpl   $0x0,0x0(%rip)        # 25<test+0x25>
-  25:	74 4d                	je     74<test+0x74>
+  1e:	e9 00 00 00 00       	jmpq   23<test+0x23>
+  23:	eb 4d                	jmp    72<test+0x72>

So it trades a conditional vs. two jumps ? WTF ??

I thought that jumplabel magic was supposed to get rid of the jump over the tracing code ? In fact it adds another jump. Whatfor ?

The 'asm goto' construct in GCC-4.5 is deficient in this area.

GCC assumes that all exit paths from an 'asm goto' are equally likely, so the tracing (or dynamic printk etc.) code is assumed to be hot and is emitted inline. Since they are inline like this, there are all these jumps around them and they pollute the I-Cache.

I was looking at fixing it, but I think a true general purpose fix would require enhancing GCC's grammar to allow specifying of the 'likelyness' of each exit path from 'asm goto'.

But it seemed that gcc for you inlined the code in the wrong spot. Perhaps it's not a good idea to have the something like h - softirq_vec in the parameter of the tracepoint. Not saying that your change is not worth it. It is, because h - softirq_vec is used by others now too.

Quoted 4 lines · Thomas Gleixner

Quoted 1 line

Quoted 1 line · Steven Rostedt

So it trades a conditional vs. two jumps ? WTF ??

right, so the 'jmpq' on boot on x86 gets patched with 5 byte no-op sequence. So in the disabled case we have no-op followed by a jump around the disabled code.

Quoted 3 lines

I thought that jumplabel magic was supposed to get rid of the jump over the tracing code ? In fact it adds another jump. Whatfor ?

yes, that is the plan. gcc does not yet support hot/cold labels...once it does the second jump will go away and the entire tracepoint code will be moved to a 'cold' section. It's not quite completely optimal yet, but we are getting there.

Quoted 3 lines

Now even worse, when you NOP out the jmpq then your tracepoint is still not enabled. Brilliant !

The 'jmpq' in the enabled case is patched with a jmpq to the body of the tracepoint itself.

Quoted 19 lines

Did you guys ever look at the assembly output of that insane shite you are advertising with lengthy explanations ?

Obviously _NOT_

Come back when you can show me a clean imlementation of all this crap which reproduces with my jumplabel enabled stock compiler. And please just send me a patch w/o the blurb.

And sane looks like:

jmpq 2f <---- This gets noped out
1:

    mov    %r12,%rdi
    callq  *(%r12)
    [whatever cleanup it takes ]
    leaveq 
    retq   

Quoted 4 lines

2f:
[tracing gunk]
jmp 1b

yes, this is what the code should look like when we get support for hot/cold labels. I've discussed this support with gcc folk, and its the next step here. So yes, this is exacatly where we are headed.

Quoted 9 lines · Thomas Gleixner

Quoted 8 lines · Steven Rostedt

Quoted 7 lines · Thomas Gleixner

So that saves _TWO_ bytes of text and replaces:

(quoted diff) +2 -2

-  1e:	83 3d 00 00 00 00 00 	cmpl   $0x0,0x0(%rip)        # 25 <test+0x25>
-  25:	74 4d                	je     74 <test+0x74>
+  1e:	e9 00 00 00 00       	jmpq   23 <test+0x23>
+  23:	eb 4d                	jmp    72 <test+0x72>

Quoted 5 lines

Quoted 3 lines

Quoted 1 line

So it trades a conditional vs. two jumps ? WTF ??

Well, the one jmpq is noped out, and the jmp is non conditional. I've

What are you smoking ?

What? Are you saying that conditional jumps are just as fast as non conditional ones?

Quoted 3 lines

In case the trace point is enabled the jmpq is there, so it jumps to 23 and jumps from there to 72.

No, when we dynamically enable the tracepoint, it will jump to 25, not
23. That's what the goto part is about. We add the do_trace label to the table, and we make it point to that location. If we did it as you say, then tracepoints would never be enabled.

This is not unlike what we do with the function tracer. The original code points to mcount which simply is:

mcount:
retq

And when we enable the callers, we have it jump to a different function.

Quoted 3 lines

In case the trace point is disabled the jmpq is noped out, so it jumps to 72 directly.

That is correct.

Quoted 5 lines

Quoted 2 lines

always thought a non conditional jmp was faster than a conditional one,

I always thought, that at least some of the stuff which comes from tracing folks makes some sense.

Is it still not making sense?

Quoted 7 lines

Quoted 4 lines

since there's no need to go into the branch prediction logic. The CPU can simply skip to the code to jump next. Of counse, this pollutes the I$.

We might consult Mathieu for further useless blurb on how CPUs work around broken code.

The code worked fine before, it just was not very pretty.

But it seemed that gcc for you inlined the code in the wrong spot. Perhaps it's not a good idea to have the something like h - softirq_vec in the parameter of the tracepoint. Not saying that your change is not worth it. It is, because h - softirq_vec is used by others now too.

Quoted 4 lines · Steven Rostedt

On Tue, 2010-10-19 at 21:49 +0200, Thomas Gleixner wrote:

Because you do the h - softvec in the tracepoint parameter? I got a different result:

I guess some serious whacking is due.

The compiler adds two jumps when the parameter changes due to
(h -softvec) instead of (h, softvec) ????

Dude, you can't be serious.

If you would have asked about the compiler version I'm using and told me about the compiler version you are using, then I could take that answer somehow serious.

It still would miss the "Uhhhh, your compiler creates crap code" alert, because that double jump is seriously broken and braindead.

And I tell you more about this. You are going to piss off a lot of users of distro compilers because they will set CC_HAVE_ASM_GOTO happily and create the code I posted. Which will break the tracer no matter what.

So you tracer maniacs happily played with some experimental compiler stuff w/o even testing your crap against something which ships with distros or is the reference 4.5 compiler on kernel.org ?

I prefer you sending a patch to disable this, until it's sorted out, unless you want me to add some really outrageous changelog to the patch I'm going to put into tip tomorrow night, ok ?

Quoted 6 lines · Jason Baron

Quoted 3 lines

Now even worse, when you NOP out the jmpq then your tracepoint is still not enabled. Brilliant !

The 'jmpq' in the enabled case is patched with a jmpq to the body of the tracepoint itself.

Brilliant.

Quoted 6 lines · Steven Rostedt

But it seemed that gcc for you inlined the code in the wrong spot. Perhaps it's not a good idea to have the something like h - softirq_vec in the parameter of the tracepoint. Not saying that your change is not worth it. It is, because h - softirq_vec is used by others now too.

OK, first of all, there are some serious WTFs here:

# define JUMP_LABEL_INITIAL_NOP ".byte 0xe9 \n\t .long 0\n\t"

A jump instruction is one of the worst possible NOPs. Why are we doing this?

The second thing that I found when implementing static_cpu_has() was that it is actually better to encapsulate the asm goto in a small inline which returns bool (true/false) -- gcc will happily optimize out the variable and only see it as a flow of control thing. I would be very curious if that wouldn't make gcc generate better code in cases like that.

gcc 4.5.0 has a bug in that there must be a flowthrough case in the asm goto (you can't have it unconditionally branch one way or the other), so that should be the likely case and accordingly it should be annotated likely() so that gcc doesn't reorder. I suspect in the end one ends up with code like this:

static __always_inline __pure bool __switch_point(...)

{
	asm goto("1: " JUMP_LABEL_INITIAL_NOP
		 /* ... patching stuff */
		: : : : t_jump);
	return false;
t_jump:
	return true;
}

#define SWITCH_POINT(x) unlikely(__switch_point(x))

I *suspect* this will resolve the need for hot/cold labels just fine.

Quoted 10 lines

static __always_inline __pure bool __switch_point(...)

{
	asm goto("1: " JUMP_LABEL_INITIAL_NOP
		 /* ... patching stuff */
		: : : : t_jump);
	return false;
t_jump:
	return true;
}

Quoted 3 lines

#define SWITCH_POINT(x) unlikely(__switch_point(x))

I *suspect* this will resolve the need for hot/cold labels just fine.

Interesting, we could try this.

Quoted 10 lines · H. Peter Anvin

Quoted 6 lines · Steven Rostedt

But it seemed that gcc for you inlined the code in the wrong spot. Perhaps it's not a good idea to have the something like h - softirq_vec in the parameter of the tracepoint. Not saying that your change is not worth it. It is, because h - softirq_vec is used by others now too.

OK, first of all, there are some serious WTFs here:

Quoted 4 lines

# define JUMP_LABEL_INITIAL_NOP ".byte 0xe9 \n\t .long 0\n\t"

A jump instruction is one of the worst possible NOPs. Why are we doing this?

Good question. Safety? Jason?

This is the initial jumps and are converted on boot up to a better nop.

Quoted 23 lines

The second thing that I found when implementing static_cpu_has() was that it is actually better to encapsulate the asm goto in a small inline which returns bool (true/false) -- gcc will happily optimize out the variable and only see it as a flow of control thing. I would be very curious if that wouldn't make gcc generate better code in cases like that.

gcc 4.5.0 has a bug in that there must be a flowthrough case in the asm goto (you can't have it unconditionally branch one way or the other), so that should be the likely case and accordingly it should be annotated likely() so that gcc doesn't reorder. I suspect in the end one ends up with code like this:

static __always_inline __pure bool __switch_point(...)

{
	asm goto("1: " JUMP_LABEL_INITIAL_NOP
		 /* ... patching stuff */
		: : : : t_jump);
	return false;
t_jump:
	return true;
}

Quoted 3 lines

#define SWITCH_POINT(x) unlikely(__switch_point(x))

I *suspect* this will resolve the need for hot/cold labels just fine.

Interesting, we could try this.

hpa just posted code which does the _RIGHT_ _THING_ independent of any compiler madness and you tracer folks just missed it.

Quoted 9 lines · Jason Baron

Quoted 4 lines · Thomas Gleixner

Quoted 1 line

Quoted 1 line · Steven Rostedt

So it trades a conditional vs. two jumps ? WTF ??

right, so the 'jmpq' on boot on x86 gets patched with 5 byte no-op sequence. So in the disabled case we have no-op followed by a jump around the disabled code.

And that's supposed to be useful ? We do _NOT_ want to jump around disabled stuff. The noped out case should fall through into the non traced code. Otherwise that whole jumplabel thing is completely useless.

Quoted 4 lines

Quoted 3 lines

I thought that jumplabel magic was supposed to get rid of the jump over the tracing code ? In fact it adds another jump. Whatfor ?

Quoted 4 lines

yes, that is the plan. gcc does not yet support hot/cold labels...once it does the second jump will go away and the entire tracepoint code will be moved to a 'cold' section. It's not quite completely optimal yet, but we are getting there.

Then do not advertise it as the brilliant solution for all tracing matters.

Quoted 6 lines

Quoted 3 lines

Now even worse, when you NOP out the jmpq then your tracepoint is still not enabled. Brilliant !

The 'jmpq' in the enabled case is patched with a jmpq to the body of the tracepoint itself.

Brilliant.

Quoted 19 lines

Quoted 19 lines

Did you guys ever look at the assembly output of that insane shite you are advertising with lengthy explanations ?

Obviously _NOT_

Come back when you can show me a clean imlementation of all this crap which reproduces with my jumplabel enabled stock compiler. And please just send me a patch w/o the blurb.

And sane looks like:

jmpq 2f <---- This gets noped out
1:

    mov    %r12,%rdi
    callq  *(%r12)
    [whatever cleanup it takes ]
    leaveq 
    retq   

Quoted 8 lines

Quoted 4 lines

2f:
[tracing gunk]
jmp 1b

yes, this is what the code should look like when we get support for hot/cold labels. I've discussed this support with gcc folk, and its the next step here. So yes, this is exacatly where we are headed.

So and at the same time the whole tracing crowd tells me, that this is already a done deal. See previous advertisments from DrTracing. I'm seriously grumpy about this especially in the context of a patch which fixes one of the worst interfaces I've seen in years.

Thanks,

tglx

Quoted 6 lines · Steven Rostedt

But it seemed that gcc for you inlined the code in the wrong spot. Perhaps it's not a good idea to have the something like h - softirq_vec in the parameter of the tracepoint. Not saying that your change is not worth it. It is, because h - softirq_vec is used by others now too.

OK, first of all, there are some serious WTFs here:

# define JUMP_LABEL_INITIAL_NOP ".byte 0xe9 \n\t .long 0\n\t"

A jump instruction is one of the worst possible NOPs. Why are we doing this?

The second thing that I found when implementing static_cpu_has() was that it is actually better to encapsulate the asm goto in a small inline which returns bool (true/false) -- gcc will happily optimize out the variable and only see it as a flow of control thing. I would be very curious if that wouldn't make gcc generate better code in cases like that.

gcc 4.5.0 has a bug in that there must be a flowthrough case in the asm goto (you can't have it unconditionally branch one way or the other), so that should be the likely case and accordingly it should be annotated likely() so that gcc doesn't reorder. I suspect in the end one ends up with code like this:

static __always_inline __pure bool __switch_point(...)

{
	asm goto("1: " JUMP_LABEL_INITIAL_NOP
		 /* ... patching stuff */
		: : : : t_jump);
	return false;
t_jump:
	return true;
}

#define SWITCH_POINT(x) unlikely(__switch_point(x))

I *suspect* this will resolve the need for hot/cold labels just fine.

Quoted 7 lines

OK, first of all, there are some serious WTFs here:

# define JUMP_LABEL_INITIAL_NOP ".byte 0xe9 \n\t .long 0\n\t"

A jump instruction is one of the worst possible NOPs. Why are we doing this?

This code is dynamically patched at boot time (and module load time) with a better nop, just like the function tracer does.

Intel's manual "Intel 64 and IA-32 Architectures Optimization Reference Manual"

http://www.intel.com/Assets/PDF/manual/248966.pdf

Page C-33 (or 577 in the pdf)

"7. Selection of conditional jump instructions should be based on the
recommendation of section Section 3.4.1, “Branch Prediction Optimization,” to improve the predictability of branches. When branches are predicted successfully, the latency of jcc is effectively zero."

So it mentions "jcc", but not jmp. Is there any reason for jmp to have a higher latency than jcc ?

In this manual, the latency of predicted jcc is therefore 0 cycle, and its throughput is 0.5 cycle/insn.

NOP (page C-29) is stated to have a latency of 0.5 to 1 cycle/insn (depending on the exact HW), and throughput of 0.5 cycle/insn.

However, I have not found "jmp" explicitly in this listing.

So if we were executing tracepoints in a maze of jumps, we could argue that instruction throughput is the most important there. However, if we expect the common case to be surrounded by some non-ALU instructions, latency tends to become the most important criterion.

But I feel I might be missing something important that distinguish "jcc" from "jmp".

Quoted 4 lines · Jason Baron

I'm not sure I did, the documentation says that we have nop followed by a jmp:

Review

Quoted 5 lines

(quoted diff) +4 -0

+The new code is a 'nopl' followed by a 'jmp'. Thus:
+
+nopl - 0f 1f 44 00 00 - 5 bytes
+jmp  - eb 3e          - 2 bytes

There is no excuse for needing the second jump here, obviously...

Quoted 2 lines

There is no excuse for needing the second jump here, obviously...

Now the trick is to tell gcc that.

Quoted 8 lines · Mathieu Desnoyers

Quoted 7 lines

OK, first of all, there are some serious WTFs here:

# define JUMP_LABEL_INITIAL_NOP ".byte 0xe9 \n\t .long 0\n\t"

A jump instruction is one of the worst possible NOPs. Why are we doing this?

Quoted 3 lines

This code is dynamically patched at boot time (and module load time) with a better nop, just like the function tracer does.

That's just ridiculous... start out with something sane and you at least have the chance of not having to patch it.

Quoted 5 lines

So if we were executing tracepoints in a maze of jumps, we could argue that instruction throughput is the most important there. However, if we expect the common case to be surrounded by some non-ALU instructions, latency tends to become the most important criterion.

Quoted 2 lines

But I feel I might be missing something important that distinguish "jcc" from "jmp".

NOP has a latency of 0.5-1.0 cycle/insns, *but has no consumers*.

JMP/Jcc does have a consumer -- the IP -- and actually measuring shows that it is much, much worse than NOP and other dummy instructions.

Quoted 3 lines

JMP/Jcc does have a consumer -- the IP -- and actually measuring shows that it is much, much worse than NOP and other dummy instructions.

But how does JMP vs Jcc compare?

Due to not actually having a sane key type the above is not easy to implement, but I tried:

#define _SWITCH_POINT(x)\

({                                                              \
        __label__ jl_enabled;                                   \
        bool ret = true;                                        \
        JUMP_LABEL(x, jl_enabled);                              \
        ret = false;                                            \
jl_enabled:                                                     \

ret; })

#define SWITCH_POINT(x) unlikely(_SWITCH_POINT(x))

#define COND_STMT(key, stmt)                                    \
do {                                                            \
        if (SWITCH_POINT(key)) {                                \
                stmt;                                           \
        }                                                       \

} while (0)

and that's still generating these double jumps.

The key here seems to be to not use the JUMP_LABEL macro as implemented; I have utterly failed to make JUMP_LABEL() do the right thing.

Quoted 20 lines · Peter Zijlstra

Due to not actually having a sane key type the above is not easy to implement, but I tried:

#define _SWITCH_POINT(x)\

({                                                              \
        __label__ jl_enabled;                                   \
        bool ret = true;                                        \
        JUMP_LABEL(x, jl_enabled);                              \
        ret = false;                                            \
jl_enabled:                                                     \

ret; })

#define SWITCH_POINT(x) unlikely(_SWITCH_POINT(x))

#define COND_STMT(key, stmt)                                    \
do {                                                            \
        if (SWITCH_POINT(key)) {                                \
                stmt;                                           \
        }                                                       \

Quoted 5 lines

} while (0)

and that's still generating these double jumps.

I just experimented with it, and the ({...}) construct doesn't work, because it looks like a merged flow of control to gcc.

Replacing the ({ ... }) with an inline does indeed remove the double jumps.

include/linux/jump_label.h +14 -4

index b67cb18..2ff829d 100644
@@ -61,12 +61,22 @@ static inline int jump_label_text_reserved(void
 *start, void *end)
 
 #endif
 
+static __always_inline __pure bool _SWITCH_POINT(void *x)
+{
+       asm goto("# SWITCH_POINT %0\n\t"
+                ".byte 0x66,0x66,0x66,0x66,0x90\n"
+                "1:"
+                : : "i" (x) : : jl_enabled);
+       return false;
+jl_enabled:
+       return true;
+}
+
+#define SWITCH_POINT(x)        unlikely(_SWITCH_POINT(x))
+
 #define COND_STMT(key, stmt)                                   \
 do {                                                           \
-       __label__ jl_enabled;                                   \
-       JUMP_LABEL(key, jl_enabled);                            \
-       if (0) {                                                \
-jl_enabled:                                                    \
+       if (SWITCH_POINT(key)) {                                \
                stmt;                                           \
        }                                                       \

} while (0)

The key here seems to be to not use the JUMP_LABEL macro as implemented; I have utterly failed to make JUMP_LABEL() do the right thing.

Quoted 5 lines · Thomas Gleixner

Quoted 4 lines · Jason Baron

Quoted 3 lines

Now even worse, when you NOP out the jmpq then your tracepoint is still not enabled. Brilliant !

Quoted 4 lines

Quoted 2 lines

The 'jmpq' in the enabled case is patched with a jmpq to the body of the tracepoint itself.

Brilliant.

IOW, We now jump around the jump which jumps around the disabled code.

Quoted 6 lines · Thomas Gleixner

Quoted 5 lines · Thomas Gleixner

Quoted 4 lines · Jason Baron

Quoted 3 lines

Now even worse, when you NOP out the jmpq then your tracepoint is still not enabled. Brilliant !

Quoted 7 lines

Quoted 4 lines

Quoted 2 lines

The 'jmpq' in the enabled case is patched with a jmpq to the body of the tracepoint itself.

Brilliant.

IOW, We now jump around the jump which jumps around the disabled code.

Do you happen to have CONFIG_CC_OPTIMIZE_FOR_SIZE set? If so, then this is a known issue. We even originally had jump label enabled _only_ if CC_OPTIMIZE_FOR_SIZE was not set, but hpa NAK'd it.

http://lkml.org/lkml/2010/9/22/482

http://lkml.org/lkml/2010/9/20/488

http://lkml.org/lkml/2010/9/24/259

-- Steve

Quoted 9 lines · H. Peter Anvin

Quoted 8 lines · Mathieu Desnoyers

Quoted 7 lines

OK, first of all, there are some serious WTFs here:

# define JUMP_LABEL_INITIAL_NOP ".byte 0xe9 \n\t .long 0\n\t"

A jump instruction is one of the worst possible NOPs. Why are we doing this?

Quoted 6 lines

Quoted 3 lines

This code is dynamically patched at boot time (and module load time) with a better nop, just like the function tracer does.

That's just ridiculous... start out with something sane and you at least have the chance of not having to patch it.

Yep we can fix this. Jason?

Quoted 10 lines · Steven Rostedt

Quoted 9 lines · H. Peter Anvin

Quoted 8 lines · Mathieu Desnoyers

Quoted 7 lines

OK, first of all, there are some serious WTFs here:

# define JUMP_LABEL_INITIAL_NOP ".byte 0xe9 \n\t .long 0\n\t"

A jump instruction is one of the worst possible NOPs. Why are we doing this?

Quoted 9 lines

Quoted 6 lines

Quoted 3 lines

This code is dynamically patched at boot time (and module load time) with a better nop, just like the function tracer does.

That's just ridiculous... start out with something sane and you at least have the chance of not having to patch it.

Yep we can fix this. Jason?

sure. The idea of the 'jmp 0' was simply to be an lcd for x86, if there's a better lcd for x86, I'll update it. But note, that since the 'jmp 0' is patched to a better nop at boot, we wouldn't see much gain. And in the boot path we are using 'text_poke_early()', so avoiding that isn't going to improve things much.

I've got a few fixup patches in the queue that I'm going to post first, and then I'll take a look at this change.

Quoted 2 lines · Thomas Gleixner

hpa just posted code which does the _RIGHT_ _THING_ independent of any compiler madness and you tracer folks just missed it.

Thomas,

Can you try this patch and see if it makes the object code better?

-- Steve

include/linux/tracepoint.h +7 -2

index a4a90b6..6264bd3 100644
@@ -144,14 +144,19 @@ static inline void tracepoint_update_probe_range(struct tracepoint *begin,
  */
 #define __DECLARE_TRACE(name, proto, args, data_proto, data_args)	\
 	extern struct tracepoint __tracepoint_##name;			\
-	static inline void trace_##name(proto)				\
+	static __always_inline int __trace_##name(proto)		\
 	{								\
 		JUMP_LABEL(&__tracepoint_##name.state, do_trace);	\
-		return;							\
+		return 0;						\
 do_trace:								\
 			__DO_TRACE(&__tracepoint_##name,		\
 				TP_PROTO(data_proto),			\
 				TP_ARGS(data_args));			\
+			return 1;					\
+	}								\
+	static inline void trace_##name(proto)				\
+	{								\
+		unlikely(__trace_##name(args));				\
 	}								\
 	static inline int						\
 	register_trace_##name(void (*probe)(data_proto), void *data)	\

Quoted 2 lines · Steven Rostedt

On Wed, 2010-10-20 at 00:04 +0200, Thomas Gleixner wrote:

Quoted 6 lines

Quoted 2 lines

hpa just posted code which does the _RIGHT_ _THING_ independent of any compiler madness and you tracer folks just missed it.

Thomas,

Can you try this patch and see if it makes the object code better?

Nope, same result.

Quoted 8 lines · Thomas Gleixner

Quoted 5 lines · Steven Rostedt

Quoted 2 lines · Thomas Gleixner

hpa just posted code which does the _RIGHT_ _THING_ independent of any compiler madness and you tracer folks just missed it.

Quoted 5 lines

Quoted 3 lines

Thomas,

Can you try this patch and see if it makes the object code better?

Nope, same result.

Yeah, I figured. Do you have CC_OPTIMIZE_FOR_SIZE set? And if you do, what happens if you disable it?

sure. The idea of the 'jmp 0' was simply to be an lcd for x86, if there's a better lcd for x86, I'll update it. But note, that since the 'jmp 0' is patched to a better nop at boot, we wouldn't see much gain. And in the boot path we are using 'text_poke_early()', so avoiding that isn't going to improve things much.

Quoted 7 lines · Jason Baron

sure. The idea of the 'jmp 0' was simply to be an lcd for x86, if there's a better lcd for x86, I'll update it. But note, that since the 'jmp 0' is patched to a better nop at boot, we wouldn't see much gain. And in the boot path we are using 'text_poke_early()', so avoiding that isn't going to improve things much.

It's still a completely unnecessary waste of startup time some potentially significant fraction of the time. Startup time matters, especially as the number of tracepoints grow.

Quoted 9 lines · * H. Peter Anvin ([email protected]) wrote:

Quoted 7 lines · Jason Baron

sure. The idea of the 'jmp 0' was simply to be an lcd for x86, if there's a better lcd for x86, I'll update it. But note, that since the 'jmp 0' is patched to a better nop at boot, we wouldn't see much gain. And in the boot path we are using 'text_poke_early()', so avoiding that isn't going to improve things much.