On Mon, 2010-08-23 at 18:41 +0900, Koki Sanagi wrote:
quoted text
> 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@goodmis.org>

-- Steve


--
unsubscribe notice
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/