[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <1283212210.3656.84.camel@gandalf.stny.rr.com>
Date: Mon, 30 Aug 2010 19:50:10 -0400
From: Steven Rostedt <rostedt@...dmis.org>
To: Koki Sanagi <sanagi.koki@...fujitsu.com>
Cc: netdev@...r.kernel.org, linux-kernel@...r.kernel.org,
davem@...emloft.net, kaneshige.kenji@...fujitsu.com,
izumi.taku@...fujitsu.com, kosaki.motohiro@...fujitsu.com,
nhorman@...driver.com, laijs@...fujitsu.com,
scott.a.mcmillan@...el.com, eric.dumazet@...il.com,
fweisbec@...il.com, mathieu.desnoyers@...ymtl.ca
Subject: Re: [PATCH v4 0/5] netdev: show a process of packets
On Mon, 2010-08-23 at 18:41 +0900, Koki Sanagi wrote:
> 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.
>
The entire series:
Acked-by: Steven Rostedt <rostedt@...dmis.org>
-- Steve
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists