Subject: [PATCH 0/5] tracing/events: add tracepoint to TCP/IP stack and netdev layer

From: Koki Sanagi <[email-masked]>
Date: Mon, 18 Jan 2010 17:26:25 +0900

These patch-set adds some tracepoints to the TCP/IP stack and netdev layer.

As described below,
http://marc.info/?l=linux-netdev&m=126096487212459&w=2
dev_hard_start_xmit and netif_receive_skb are important location to add
tracepoints. Because driver depends on an machine environment, we usually
check this point when solving network problem. But these two points are lack of
infrotmation that what packets are passed, So I add other tracepoints to know
what packets are passed and to give some merits.

Added tracepoints are at transmit/receive entry of TCP, UDP, RAW, IPv4, driver
and Qdisc. And tracepoints to output information to make connection
between these entry tracepoints are also added.

These tracepoints give some merits.
For example, they enable us to measure packet latency.
By using tcpdump, we can analyze what packets are passed, but we cannot analyze
how long it takes to pass through network layer(In other words, latency of TCP
layer, IP layer and Qdisc). 
Packet latency is very useful information to solve a network bad performance or
bad reaction network application, packet latency is very useful information.

As an other use case, unlike a tcpdump, they are recorded in ftrace buffer
without IO burden. Only when you need, output recorded information.
I mean, they are fit to run always.

Details of added tracepoint are below.

skb_clone               chase the cloned skb
senddata_copy_skb       copy userdata to skb for transmit

netdev_start_xmit       entry of driver's transmit function.
netdev_receive_skb      entry of netstack(receive).
dev_queue_xmit          entry of Qdisc.	

ip_queue_xmit           entry of IP layer(TCP transmit)
ip_push_pending_frames  entry of IP layer(UDP transmit)
ip_output               entry of IP layer(RAW transmit)
ip_frag_queue           aggregate fragmented packet
ip_frag_reasm           reasemble fragmented packet
ip_rcv                  entry of IP layer(receive)

tcp_sendmsg             entry of TCP layer(transmit)
tcp_sendpage            entry of TCP layer(transmit)
tcp_push_pending_frames all data(tcp_sendmsg have) have copied to skb
tcp_v4_rcv              entry of TCP layer(receive)

udp_sendmsg             entry of UDP layer(transmit)
udp_sendpage            entry of UDP layer(transmit)
udp_push_pending_frames all data(udp_sendmsg have) have copied to skb
udp_rcv                 entry of UDP layer(receive).

raw_sendmsg             entry of RAW layer(transmit).
raw_rcv                 entry of RAW layer(receive).

Outputs are below.

TCP send
         netperf-2513  [000]  2603.586818: tcp_sendmsg: sk=f644eac0 len=5000
         netperf-2513  [000]  2603.586818: senddata_copy_skb: sk=f644eac0 skbaddr=f7159800 len=1416
         netperf-2513  [000]  2603.586820: senddata_copy_skb: sk=f644eac0 skbaddr=f7159500 len=1448
         netperf-2513  [000]  2603.586821: senddata_copy_skb: sk=f644eac0 skbaddr=f7158d80 len=1448
         netperf-2513  [000]  2603.586822: senddata_copy_skb: sk=f644eac0 skbaddr=f7159c80 len=688
         netperf-2513  [000]  2603.586822: tcp_push_pending_frames: sk=f644eac0 sport=54875 dport=51707
            tail-2514  [001]  2603.587577: skb_clone: original=f7159800 clone=f71598b4
            tail-2514  [001]  2603.587578: ip_queue_xmit: skbaddr=f71598b4 saddr=192.168.100.5 daddr=192.168.100.2
            tail-2514  [001]  2603.587579: ip_output: skbaddr=f71598b4 saddr=192.168.100.5 daddr=192.168.100.2
            tail-2514  [001]  2603.587579: dev_queue_xmit: dev=eth10 skbaddr=f71598b4 len=1514
            tail-2514  [001]  2603.587580: netdev_start_xmit: dev=eth10 skbaddr=f71598b4 len=1514
            tail-2514  [001]  2603.587628: skb_clone: original=f7159500 clone=f71595b4
            tail-2514  [001]  2603.587629: ip_queue_xmit: skbaddr=f71595b4 saddr=192.168.100.5 daddr=192.168.100.2
            tail-2514  [001]  2603.587630: ip_output: skbaddr=f71595b4 saddr=192.168.100.5 daddr=192.168.100.2
            tail-2514  [001]  2603.587631: dev_queue_xmit: dev=eth10 skbaddr=f71595b4 len=1514
            tail-2514  [001]  2603.587632: netdev_start_xmit: dev=eth10 skbaddr=f71595b4 len=1514
            tail-2514  [001]  2603.587632: skb_clone: original=f7158d80 clone=f7158e34
            tail-2514  [001]  2603.587633: ip_queue_xmit: skbaddr=f7158e34 saddr=192.168.100.5 daddr=192.168.100.2
            tail-2514  [001]  2603.587634: ip_output: skbaddr=f7158e34 saddr=192.168.100.5 daddr=192.168.100.2
            tail-2514  [001]  2603.587635: dev_queue_xmit: dev=eth10 skbaddr=f7158e34 len=1514
            tail-2514  [001]  2603.587635: netdev_start_xmit: dev=eth10 skbaddr=f7158e34 len=1514
            tail-2514  [001]  2603.587685: skb_clone: original=f7159c80 clone=f7159d34
            tail-2514  [001]  2603.587685: ip_queue_xmit: skbaddr=f7159d34 saddr=192.168.100.5 daddr=192.168.100.2
            tail-2514  [001]  2603.587687: ip_output: skbaddr=f7159d34 saddr=192.168.100.5 daddr=192.168.100.2
            tail-2514  [001]  2603.587687: dev_queue_xmit: dev=eth10 skbaddr=f7159d34 len=1514
            tail-2514  [001]  2603.587688: netdev_start_xmit: dev=eth10 skbaddr=f7159d34 len=1514

TCP recv
          <idle>-0     [001]  3499.386601: netdev_receive_skb: dev=eth10 skbaddr=f4a88480 len=1500
          <idle>-0     [001]  3499.386602: ip_rcv: skbaddr=f4a88480 saddr=192.168.100.2 daddr=192.168.100.5
          <idle>-0     [001]  3499.386604: tcp_v4_rcv: skbaddr=f4a88480 sport=51035 dport=34474
          <idle>-0     [000]  3499.386619: netdev_receive_skb: dev=eth10 skbaddr=f3c75300 len=1500
          <idle>-0     [000]  3499.386619: ip_rcv: skbaddr=f3c75300 saddr=192.168.100.2 daddr=192.168.100.5
          <idle>-0     [000]  3499.386622: tcp_v4_rcv: skbaddr=f3c75300 sport=51035 dport=34474
       netserver-2519  [000]  3499.386626: skb_copy_datagram_iovec: skbaddr=f4a88480 len=1448
       netserver-2519  [000]  3499.386628: skb_copy_datagram_iovec: skbaddr=f3c75300 len=1448

UDP send
         netperf-2506  [001]  2309.073460: udp_sendmsg: sk=f662e6c0 len=5000
         netperf-2506  [001]  2309.073466: senddata_copy_skb: sk=f662e6c0 skbaddr=f5f65780 len=1472
         netperf-2506  [001]  2309.073467: senddata_copy_skb: sk=f662e6c0 skbaddr=f5f65000 len=1480
         netperf-2506  [001]  2309.073468: senddata_copy_skb: sk=f662e6c0 skbaddr=f3decf00 len=1480
         netperf-2506  [001]  2309.073469: senddata_copy_skb: sk=f662e6c0 skbaddr=f4802840 len=568
         netperf-2506  [001]  2309.073470: udp_push_pending_frames: sk=f662e6c0 sport=42679 dport=47640
         netperf-2506  [001]  2309.073470: ip_push_pending_frames: skbaddr=f5f65780 saddr=192.168.100.5 daddr=192.168.100.2
         netperf-2506  [001]  2309.073471: ip_output: skbaddr=f5f65780 saddr=192.168.100.5 daddr=192.168.100.2
         netperf-2506  [001]  2309.073472: dev_queue_xmit: dev=eth10 skbaddr=f5f65780 len=1514
         netperf-2506  [001]  2309.073473: dev_queue_xmit: dev=eth10 skbaddr=f5f65000 len=1514
         netperf-2506  [001]  2309.073474: dev_queue_xmit: dev=eth10 skbaddr=f3decf00 len=1514
         netperf-2506  [001]  2309.073474: dev_queue_xmit: dev=eth10 skbaddr=f4802840 len=602
          <idle>-0     [001]  2309.073615: netdev_start_xmit: dev=eth10 skbaddr=f5f65780 len=1514
          <idle>-0     [001]  2309.073616: netdev_start_xmit: dev=eth10 skbaddr=f5f65000 len=1514
          <idle>-0     [000]  2309.073633: netdev_start_xmit: dev=eth10 skbaddr=f3decf00 len=1514
          <idle>-0     [000]  2309.073633: netdev_start_xmit: dev=eth10 skbaddr=f4802840 len=602

UDP recv
          <idle>-0     [001]  3671.663678: netdev_receive_skb: dev=eth10 skbaddr=f5f72d80 len=1500
          <idle>-0     [001]  3671.663678: ip_rcv: skbaddr=f5f72d80 saddr=192.168.100.2 daddr=192.168.100.5
          <idle>-0     [001]  3671.663680: ip_frag_queue: skbaddr=f5f72d80 prev=(null)
          <idle>-0     [001]  3671.663681: netdev_receive_skb: dev=eth10 skbaddr=f5f6aa80 len=1500
          <idle>-0     [001]  3671.663681: ip_rcv: skbaddr=f5f6aa80 saddr=192.168.100.2 daddr=192.168.100.5
          <idle>-0     [001]  3671.663681: ip_frag_queue: skbaddr=f5f6aa80 prev=f5f72d80
          <idle>-0     [000]  3671.663702: netdev_receive_skb: dev=eth10 skbaddr=f4800840 len=1500
          <idle>-0     [000]  3671.663703: ip_rcv: skbaddr=f4800840 saddr=192.168.100.2 daddr=192.168.100.5
          <idle>-0     [000]  3671.663703: ip_frag_queue: skbaddr=f4800840 prev=f5f6aa80
          <idle>-0     [000]  3671.663704: netdev_receive_skb: dev=eth10 skbaddr=f4a88b40 len=588
          <idle>-0     [000]  3671.663705: ip_rcv: skbaddr=f4a88b40 saddr=192.168.100.2 daddr=192.168.100.5
          <idle>-0     [000]  3671.663705: ip_frag_queue: skbaddr=f4a88b40 prev=f4800840
          <idle>-0     [000]  3671.663706: skb_clone: original=f4a88b40 clone=f5fff480
          <idle>-0     [000]  3671.663707: kfree_skb: skbaddr=f5f72d80 protocol=2048 location=c0715f1a
          <idle>-0     [000]  3671.663707: ip_frag_reasm: head=f4a88b40 len=1480
          <idle>-0     [000]  3671.663711: udp_rcv: skbaddr=f4a88b40 sport=57915 dport=37634
       netserver-2525  [000]  3671.663718: skb_copy_datagram_iovec: skbaddr=f4a88b40 len=5000
       netserver-2525  [000]  3671.663718: skb_copy_datagram_iovec: skbaddr=f5f6aa80 len=1480
       netserver-2525  [000]  3671.663719: skb_copy_datagram_iovec: skbaddr=f4800840 len=1480
       netserver-2525  [000]  3671.663719: skb_copy_datagram_iovec: skbaddr=f5fff480 len=568

RAW send
            send-2431  [001]  1813.799957: raw_sendmsg: sk=f4a37200 len=1500
            send-2431  [001]  1813.799959: senddata_copy_skb: sk=f4a37200 skbaddr=f3dec180 len=1500
            send-2431  [001]  1813.799960: ip_output: skbaddr=f3dec180 saddr=192.168.100.5 daddr=192.168.100.2
            send-2431  [001]  1813.799960: dev_queue_xmit: dev=eth10 skbaddr=f3dec180 len=1514
            send-2431  [001]  1813.799961: netdev_start_xmit: dev=eth10 skbaddr=f3dec180 len=1514

RAW recv
          <idle>-0     [000]  2052.858947: netdev_receive_skb: dev=eth1 skbaddr=f5f66000 len=1500
          <idle>-0     [000]  2052.858947: ip_rcv: skbaddr=f5f66000 saddr=192.168.101.2 daddr=192.168.101.5
          <idle>-0     [000]  2052.858951: skb_clone: original=f5f66000 clone=f3e43cc0
          <idle>-0     [000]  2052.858952: raw_rcv: skbaddr=f3e43cc0 len=1476
            recv-2499  [001]  2052.858970: skb_copy_datagram_iovec: skbaddr=f3e43cc0 len=1500

Best Regards,
Koki Sanagi <[email-masked]>