Tracing Linux Networking with DTrace on Oracle Linux

March 7, 2018 | 6 minute read
Text Size 100%:

In this post from Alan Maguire, he shows how to use DTrace to inspect common network-related system calls. DTrace is a powerful tracing tool for understanding user and kernel processes.

We've been steadily adding DTrace support for networking in Oracle Linux. Let's see how we can use these probes to better understand network behaviour. Let's do a quick tour to see what sort of support is available for dynamic tracing the network stack.

Before diving into the details though, it's worth asking why use DTrace at all? Don't we have enough tools in the networking space? The reasons I use it are:

  • DTrace is open-ended while being production-safe. So in other words if I want to find something out, there's usually a way of doing it, and most importantly I can do that without panic'ing a system. The hard part of course is forming those questions into queries that DTrace understands. I hope the next few blog posts will provide some useful hints on how to do so.
  • DTrace allows me to reach across multiple subsystems, e.g. how effectively are interrupts being coalesced when receiving packets? Which locks are hot on the network receive path? In cloud environments especially, it's critical to be able to connect the dots from network behaviour to other subsystems and abstractions. People love to blame "the network". DTrace allows us to see where the costs are really incurred.

Socket layer: syscall provider - available since UEK2

As on other operating systems, the syscall provider is avaiable and we can trace network-related system calls - sendto, sendmsg, sendmmsg, recvfrom, recvmsg, recvmmsg.

Here's a simple example - trace bytes sent on a per-executable basis. Hit Ctrl+C when you're done collecting info.

Copied to Clipboard
Error: Could not Copy
Copied to Clipboard
Error: Could not Copy
# dtrace -n 'syscall::sendto:entry { @c[execname] = sum(arg2); }'
dtrace: description 'syscall::sendto:entry ' matched 1 probe
^C
 
  DNS Resolver #6                                                  65
  ping                                                            192
  Socket Thread                                                  2006
  vpnagentd                                                      3872


This is what we call a DTrace one-liner. Let's examine it piece-by-piece.

  • The -n option says we are directly specifying our probes rather than using a DTrace script (if we wanted to do that, we would use "dtrace -s <scriptname>").
  • The probe is a 4-element description, with each element separated by a ":". The first element is the provider - the DTrace subsystem which we are using. In this case it is "syscall". The second is the module, which is relevant for other DTrace providers but not here (for Linux it is always "vmlinux", so we can leave it blank). The third is the function - in the case of the syscall provider, that's the system call name. And finally we have the probe name. For each system call there are two probes, entry and return, corresponding to system call request/completion.
  • Next is the action,contained in the curly brackets. DTrace code takes the form "probe /predicate/ { action }". In this case we have no predicate, but if we did it would determine if the body was executed or not. Next let's describe the action.
  • Here we are using an aggregation variable "c" - the aggregation is signified by the "@" symbol. Aggregations can specify multiple keys in between the square brackets, and the associated values for the various sets of keys are computed using one of the aggregating functions sum(), count(), avg() etc.  Aggregations are collected efficientl in-kernel. Here we are sum()ing arg2 - the third argument to sendto(), which if you look at the manual page you will see is the size.

 

So to summarize, our one-liner says "show me the sum total of bytes sent via sendto() system calls, and collect the sums for each program name" ("execname" is a built in variable that references the current process executable name).

Now of course these are requests, and some may fail.  Again note that the probe we used was syscall::sendto:entry.  There is also a corresponding syscall::sendto:return. A common pattern in DTrace is to measure how long it takes from :entry to :return.

 

Layer 4 (Transport layer): TCP, UDP providers - available since UEK4QU5

In Linux – as in Solaris – we have transport-level providers for TCP and UDP. These trace transmit/receive events, and for TCP we also trace TCP state machine transitions and connection establishment milestones.

Copied to Clipboard
Error: Could not Copy
Copied to Clipboard
Error: Could not Copy
# dtrace -l -P udp
   ID   PROVIDER            MODULE                          FUNCTION NAME
 1836        udp           vmlinux                      udp_send_skb send
 1838        udp           vmlinux                       udp_recvmsg receive
 1840        udp           vmlinux                 udp_queue_rcv_skb receive
 1868        udp           vmlinux                   udp_v6_send_skb send
 1869        udp           vmlinux                     udpv6_recvmsg receive
 1871        udp           vmlinux               udpv6_queue_rcv_skb receive
 
# dtrace -l -P tcp
   ID   PROVIDER            MODULE                          FUNCTION NAME
 1818        tcp           vmlinux                     tcp_set_state state-change
 1819        tcp           vmlinux                  tcp_conn_request state-change
 1820        tcp           vmlinux                tcp_finish_connect connect-established
 1821        tcp           vmlinux             tcp_rcv_state_process accept-established
 1822        tcp           vmlinux             tcp_rcv_state_process connect-refused
 1823        tcp           vmlinux                  tcp_transmit_skb send
 1824        tcp           vmlinux                  tcp_transmit_skb connect-request
 1825        tcp           vmlinux                       tcp_connect state-change
 1826        tcp           vmlinux                   tcp_v4_send_ack send
 1827        tcp           vmlinux                 tcp_v4_send_reset send
 1828        tcp           vmlinux                 tcp_v4_send_reset accept-refused
 1829        tcp           vmlinux                tcp_v4_send_synack send
 1830        tcp           vmlinux                        tcp_v4_rcv receive
 1831        tcp           vmlinux                     tcp_time_wait state-change
 1882        tcp           vmlinux              tcp_v6_send_response send
 1883        tcp           vmlinux              tcp_v6_send_response accept-refused
 1884        tcp           vmlinux                tcp_v6_send_synack send
 1885        tcp           vmlinux                        tcp_v6_rcv receive

 

Here's a quick example - what systems (remote IP) are we refusing connections to, and which ports are they trying to connect to?

Copied to Clipboard
Error: Could not Copy
Copied to Clipboard
Error: Could not Copy
# dtrace -n 'tcp:::accept-refused { @c[args[2]->ip_daddr, args[4]->tcp_sport] = count(); }'
dtrace: description 'tcp:::accept-refused ' matched 2 probes
^C
 
  127.0.0.1                                              7                1


I telnet'ed port 7 locally in another window to generate this. Port 7 was closed so we see 1 connection being refused. The TCP, UDP and IP providers are all static-defined tracing (SDT) providers. The idea of these is that rather than trying to write probes that sit on ever-changing function entry or return to gather information from data structures that are also changing, we define a set of events of interest, and each place in the code that these events occur we place a static probe. So for example we can see that the tcp:::send probe is in tcp_v4_send_reset, tcp_v4_send_ack, etc. Importantly, these probes also define stable translators which take the OS-specific structures and translate them into stable arguments that DTrace consumers can rely on.  To see the relevant deinifitions for Oracle Linux, you can look in /usr/lib64/dtrace/4.1/tcp.d, udp.d, ip.d.

 

For the most part we have preserved compatibility with Solaris. If there's something missing you really need, let us know! Here's how the various arguments look. We use args[0] instead of arg0 to let DTrace know we're trying to access the stable, translated argument. The raw arguments are still available via arg0, arg1 etc.

Copied to Clipboard
Error: Could not Copy
Copied to Clipboard
Error: Could not Copy
args[0] - pktinfo_t * [packet information]
args[1] - csinfo_t * [ connection information]
args[2] - ipinfo_t * [IP protocol information]
args[3] - tcpsinfo_t * for TCP, udpsinfo_t * for UDP [TCP/UDP state information]
args[4] - tcpinfo_t * for TCP, udpinfo_t * for UDP [TCP/UDP header information]


Layer 3 (IP provider) - available since UEK4QU4

The IP provider traces send, receive, and inbound/outbound drops.

Copied to Clipboard
Error: Could not Copy
Copied to Clipboard
Error: Could not Copy
# dtrace -l -P ip
   ID   PROVIDER            MODULE                          FUNCTION NAME
 1839         ip           vmlinux                     ip_rcv_finish drop-in
 1840         ip           vmlinux                  ip_local_deliver receive
 1841         ip           vmlinux                            ip_rcv drop-in
 1842         ip           vmlinux                  __ip_append_data drop-out
 1843         ip           vmlinux                 __ip_local_out_sk send
 1844         ip           vmlinux                    ip_append_page drop-out
 1845         ip           vmlinux                       ip_send_skb drop-out
 1861         ip           vmlinux                       raw_sendmsg send
 1878         ip           vmlinux        __ip6_flush_pending_frames drop-out
 1879         ip           vmlinux                          ip6_xmit send
 1880         ip           vmlinux                          ip6_xmit drop-out
 1881         ip           vmlinux                ip6_finish_output2 drop-out
 1882         ip           vmlinux                 __ip6_append_data drop-out
 1883         ip           vmlinux                       ip6_forward drop-out
 1884         ip           vmlinux                        ip6_output drop-out
 1885         ip           vmlinux                      ip6_send_skb drop-out
 1886         ip           vmlinux                  ip6_input_finish drop-in
 1887         ip           vmlinux                          ipv6_rcv drop-in
 1888         ip           vmlinux                         ip6_input receive
 1895         ip           vmlinux                    ndisc_send_skb send
 1900         ip           vmlinux                     rawv6_sendmsg send
 1903         ip           vmlinux                      mld_sendpack send
 1904         ip           vmlinux                      mld_sendpack drop-out
 1905         ip           vmlinux                        igmp6_send send
 1906         ip           vmlinux                        igmp6_send drop-out
 1923         ip           vmlinux                __ip6_local_out_sk send


For IP the arguments are

Copied to Clipboard
Error: Could not Copy
Copied to Clipboard
Error: Could not Copy
args[0] - pktinfo_t * [packet information]
args[1] - csinfo_t * [connection information]
args[2] - ipinfo_t * [IP protocol information]
args[3] - ifinfo_t * [IP interface info]
args[4] - ipv4info_t * [IPv6 header info if IPv6 packet]
args[5] - ipv6info_t * [IPv6 header info if IPv6 packet]

 

Other

DTrace on Oracle Linux includes a perf provider, which traces perf events. And of course function boundary tracing (fbt) is available too. Here's an example of using function boundary tracing to get counts of socket buffer (struct sk_buff) allocation sizes. sk_buff is the key structure for network data, and here we're examining the counts in each power-of-two bucket 0-1, 1-2, 2-4, etc - this is the quantize() aggregating action. We see for example that the majority were in the 2048-4096 range.

Copied to Clipboard
Error: Could not Copy
Copied to Clipboard
Error: Could not Copy
# dtrace -n 'fbt::__alloc_skb:entry { @size = quantize(arg0); }'
dtrace: description 'fbt::__alloc_skb:entry ' matched 1 probe
^C
           value  ------------- Distribution ------------- count    
              -1 |                                         0        
               0 |                                         80       
               1 |                                         3        
               2 |                                         0        
               4 |                                         137      
               8 |                                         988      
              16 |@@                                       5719     
              32 |@@@@@                                    10977    
              64 |                                         779      
             128 |@@@                                      6805     
             256 |@@@@@@@@@@@                              25462    
             512 |                                         508      
            1024 |@@                                       5108     
            2048 |@@@@@@@@@@@@@@@@                         39011    
            4096 |                                         8        
            8192 |                                         0        
           16384 |                                         16       
           32768 |                                         0


We'll describe some more examples using fbt and perf providers in a future blog post!

Alan Maguire

Oracle Chatbot
Disconnected