Wiki code for CEC 2006 Demo

Hide Line numbers
1: =CEC 2006 Demo
2: 
3: At the CEC 2006 conference in San Francisco, Bryan Cantrill and Brendan Gregg demonstrated a prototype DTrace tcp provider - part of a planned collection of DTrace network providers. The following documents the demonstrations that were performed (expanded a little further, and updated to match provider developments). These are actual screenshots from DTrace (command line output).
4: 
5: Last Update: 16-Oct-2006
6: 
7: {{toc start=2 depth=3 numbered=false scope=page /}}
8: 
9: ==Intro
10: 
11: A few weeks ago, a proposed design for a DTrace Network provider was posted [[here>>Community Group dtrace.NetworkProvider]] on OpenSolaris, and then discussed on [[dtrace-discuss>>http://mail.opensolaris.org/mailman/listinfo/dtrace-discuss]]. This design has been improved from the DTrace discuss feedback and from discoveries made when attempting to implement these providers. Last week we began putting together a prototype tcp provider (based on SDT tracing) to see how these ideas will work. This provider was first demonstrated at the CEC 2006 conference.
12: 
13: ==Network Utilisation
14: 
15: Lets begin with the basics. How do we measure network utilisation? That is suprisingly hard given that your network is a key resource, and while CPUs have numerous tools for per-CPU and per-process performance observability - there is little by default in Solaris for per-NIC and per-connection observabality.
16: 
17: Kstat solves many per-NIC observability questions, as first shown (and shown well) by the SE Toolkit. netstat -i, a Kstat consumer, only throws out packet counts - which have some value, but we really want bytes as well. Among other things, bytes allows us to calculate a per-NIC utilisation metric. [[nicstat>>http://www.brendangregg.com/k9toolkit.html#nicstat]], an open source tool available in both Perl and C, does this:
18: 
19: {{{
20: # **./nicstat -i e1000g0 1**
21:     Time     Int   rKB/s   wKB/s   rPk/s   wPk/s    rAvs    wAvs   **%Util**    Sat
22: 13:46:08 e1000g0   77.43   19.89   59.65   24.26  1329.3   839.7    **0.08**   0.00
23: 13:46:09 e1000g0  1387.7   387.9  1837.2  1337.5   773.4   297.0    **1.45**   0.00
24: 13:46:10 e1000g0  1396.1   350.5  1734.3  1188.5   824.3   302.0    **1.43**   0.00
25: 13:46:11 e1000g0   129.6   42.62   213.2   171.5   622.7   254.5    **0.14**   0.00
26: 13:46:12 e1000g0   196.1   66.27   279.2   219.8   719.1   308.7    **0.21**   0.00
27: 13:46:13 e1000g0   155.7   54.13   240.6   193.1   662.5   287.1    **0.17**   0.00
28: 13:46:14 e1000g0   122.8   58.01   229.7   201.0   547.6   295.6    **0.15**   0.00
29: ^C
30: }}}
31: 
32: Ok, we see some network traffic (%Util around 1%) in this example output. If you have multiple interfaces, nicstat prints a line for each.
33: 
34: nicstat uses Kstat, and such on-going statistics are (and should) be maintained by Kstat. MIB provides similar info for SNMP. So by-NIC observability has a number of solutions, depending on what interests you.
35: 
36: There aren’t many options for by-connection observability. We can capture and examine packets using tools such as snoop, however the overheads of promiscuous tracing can have double digit percentage perfmance costs (depending on the interface and workload). In which case, you won’t want to run snoop much in production, and even if you do - the performance impact casts doubt on any derived performance metrics.
37: 
38: With DTrace we can safely explore the potential of per-connection and per-packet tracing, armed with the rich programming functionality that DTrace provides.
39: 
40: ==DTrace Scripts (D Scripts)
41: 
42: ===DTT/Net/tcpsnoop
43: 
44:  The following is tcpsnoop from the [[DTraceToolkit>>Community Group dtrace.dtracetoolkit]],
45: 
46: {{{
47: # **./tcpsnoop**
48:   **UID    PID LADDR           LPORT DR RADDR           RPORT  SIZE CMD**
49:     0    418 192.168.1.185      79 <- 192.168.1.109   55036    54 inetd
50:     0    418 192.168.1.185      79 -> 192.168.1.109   55036    54 inetd
51:     0    418 192.168.1.185      79 <- 192.168.1.109   55036    54 inetd
52:     0   3265 192.168.1.185      79 -> 192.168.1.109   55036   423 in.fingerd
53:     0   3265 192.168.1.185      79 <- 192.168.1.109   55036    54 in.fingerd
54:     0   3265 192.168.1.185      79 -> 192.168.1.109   55036    54 in.fingerd
55:     0   3265 192.168.1.185      79 <- 192.168.1.109   55036    54 in.fingerd
56:     0   3265 192.168.1.185      79 <- 192.168.1.109   55036    54 in.fingerd
57:     0   3265 192.168.1.185      79 -> 192.168.1.109   55036    54 in.fingerd
58: ^C
59: }}}
60: 
61: This output shows an inbound finger connection, and shows when the connection was passed from inetd to in.fingerd. This tool was designed to show a line for each ethernet frame, along with IP addresses, TCP ports and process details. tcpsnoop was written by Brendan Gregg in July 2005, after studying the public OpenSolaris code since its release in June 2005. It uses the DTrace fbt provider (function boundary tracing), which has an unstable interface whose probes and arguments change as the kernel changes; and since it’s release, tcpsnoop has indeed needed a few updates to keep up with Solaris 10 updates.
62: 
63: So, since DTrace exists (Dec 2004), and the fbt provider exists, and OpenSolaris provides public code access (June 2005) ~-- customers already have all the components needed to solve such observability needs, should they have the skills and time to do it and patience to get it right. tcpsnoop is an example of this - and it is a giant observabaility win that this is at all possible.
64: 
65: However writing tcpsnoop required reading through thousands of lines of kernel TCP/IP C code, something that most customers are unlikely to have the time or skills to do (especially time), nor maintain as the kernel changes. Such network observability is important and should be available to all Solaris users, in a simple and stable manner. This is a key need that the stable networking providers will fulfill.
66: 
67: ===tcpaccept1.d
68: 
69: The following is the first demonstration of the prototype tcp provider,
70: 
71: {{{
72: # ./tcpaccept1.d
73: dtrace: script ’./tcpaccept1.d’ matched 1 probe
74: ^C
75: 192.168.1.107                                         79                1
76: fe80::214:4fff:fe3b:76c8                              79                1
77: 192.168.1.107                                        513                2
78: 192.168.1.109                                         22                2
79: 192.168.1.109                                         79                3
80: 192.168.1.109                                         80                8
81: }}}
82: 
83: This counts inbound TCP connections ("accepts") by IP address and TCP port number. The output shows 8 connections to port 80 (HTTP) from 192.168.1.109, and 1 connection to port 79 (finger) from fe80::214:4fff:fe3b:76c8 - an IPv6 connection. Great!
84: 
85: Also great is the source code,
86: 
87: {{{
88: #!/usr/sbin/dtrace -s
89: 
90: tcp:::accept-established {
91:         @num[args[1]->ip_saddr, args[2]->tcp_dport] = count();
92: }
93: }}}
94: 
95: The tcp:::accept-established probe fires for inbound TCP connections. The values that we aggregated on are:
96: 
97: * args[1]->ip_saddr - IP address as a string (both IPv4 and IPv6). args[1] is an IP observability structure, and is available for some of the TCP probes (those at the IP interface); it contains addresses, version and payload length. Full and raw IP header details must be fetched from the ip provider.
98: * args[2]->tcp_dport - TCP destination port address. args[2] is a structure that contains the TCP header details, including a pointer to the raw structure. As with args[1], args[2] is only available for probes where the TCP header is (and should) be available - such as TCP send and receive.
99: 
100: ===tcpaccept2.d
101: 
102: {{{
103: # ./tcpaccept2.d 
104: dtrace: script ’./tcpaccept2.d’ matched 1 probe 
105: Tracing... Hit Ctrl-C to end.
106: ^C
107:    HOSTNAME                   PORT        COUNT
108:    marlin6                    finger          1
109:    bass                       login           2
110:    marlin                     ssh             2
111:    marlin                     telnet          2
112:    marlin                     finger          3
113: }}}
114: 
115: Fantastic! Rather than print out IP addresses and port numbers, tcpaccept2.d prints out hostnames and service names. This was achieved by adding new format operators to the DTrace printf and printa functions, as can be seen in the below source of tcpaccept2.d.
116: 
117: {{{
118: #!/usr/sbin/dtrace -qs
119: 
120: dtrace:::BEGIN
121: {
122:         printf("Tracing... Hit Ctrl-C to end.\n");
123: }
124: 
125: tcp:::accept-established
126: {
127:         @num[args[1]->ip_saddr, args[2]->tcp_dport] = count();
128: }
129: 
130: dtrace:::END
131: {
132:         printf("   %-26s %-8s %8s\n", "HOSTNAME", "PORT", "COUNT");
133:         printa("   %-26I %-8P %@8d\n", @num);
134: }
135: }}}
136: 
137: The %I will lookup and print a hostname, and %P a service name. This is an observability feature should it be desired - some people may prefer to keep the IP addresses and port numbers as they were.
138: 
139: ===tcpio1.d
140: 
141: {{{
142: # ./tcpio1.d
143: dtrace: script ’./tcpio1.d’ matched 5 probes
144: CPU     ID                    FUNCTION:NAME
145:   0  47016            tcp_rput_data:receive   192.168.1.109:53816  ->    192.168.1.185:23
146:   0  46929               tcp_send_data:send   192.168.1.185:23     ->    192.168.1.109:53816
147:   0  47017         tcp_conn_request:receive   192.168.1.109:37879  ->    192.168.1.185:79
148:   0  46929               tcp_send_data:send   192.168.1.185:79     ->    192.168.1.109:37879
149:   0  47016            tcp_rput_data:receive   192.168.1.109:37879  ->    192.168.1.185:79
150:   0  47016            tcp_rput_data:receive   192.168.1.109:37879  ->    192.168.1.185:79
151:   0  46929               tcp_send_data:send   192.168.1.185:79     ->    192.168.1.109:37879
152:   0  46929               tcp_send_data:send   192.168.1.185:79     ->    192.168.1.109:37879
153:   0  47016            tcp_rput_data:receive   192.168.1.109:37879  ->    192.168.1.185:79
154:   0  46929               tcp_send_data:send   192.168.1.185:79     ->    192.168.1.109:37879
155:   0  47016            tcp_rput_data:receive   192.168.1.109:37879  ->    192.168.1.185:79
156:   0  47016            tcp_rput_data:receive   192.168.1.109:37879  ->    192.168.1.185:79
157:   0  46929               tcp_send_data:send   192.168.1.185:79     ->    192.168.1.109:37879
158: ^C
159: }}}
160: 
161: The above output shows the tcpio1.d script snooping an inbound finger connection. By examining the IP addresses and direction of packets, we can see where the initial TCP SYN/SYN-ACK/ACK 3-way handshake would be. The output is fairly raw, it contains the DTrace default fields - this demonstration is more about the source of the D-script tcpio1.d,
162: 
163: {{{
164: #!/usr/sbin/dtrace -s
165: 
166: tcp:::send,
167: tcp:::receive
168: {
169:         printf("%15s:%-5d  ->  %15s:%-5d",
170:             args[1]->ip_saddr, args[2]->tcp_sport,
171:             args[1]->ip_daddr, args[2]->tcp_dport);
172: }
173: }}}
174: 
175:  This could not get any easier. For TCP send and receive packets, print out the source IP address and source TCP port, and the destination IP address and destination IP port.
176: 
177: The next demonstration spends a few more lines in our D-script to improve the output.
178: 
179: ===tcpio2.d
180: 
181: {{{
182: # ./tcpio2.d
183:            LADDR:PORT                 RADDR:PORT   BYTES FLAGS
184:    192.168.1.185:79     <-    192.168.1.109:56145      0 (SYN)
185:    192.168.1.185:79     ->    192.168.1.109:56145      0 (SYN|ACK)
186:    192.168.1.185:79     <-    192.168.1.109:56145      0 (ACK)
187:    192.168.1.185:79     <-    192.168.1.109:56145      2 (PUSH|ACK)
188:    192.168.1.185:79     ->    192.168.1.109:56145      0 (ACK)
189:    192.168.1.185:79     ->    192.168.1.109:56145    126 (PUSH|ACK)
190:    192.168.1.185:79     <-    192.168.1.109:56145      0 (ACK)
191:    192.168.1.185:79     ->    192.168.1.109:56145      0 (FIN|ACK)
192:    192.168.1.185:79     <-    192.168.1.109:56145      0 (ACK)
193:    192.168.1.185:79     <-    192.168.1.109:56145      0 (FIN|ACK)
194:    192.168.1.185:79     ->    192.168.1.109:56145      0 (ACK)
195: ^C
196: }}}
197: 
198: The tcpio2.d script prints headers, TCP payload bytes and TCP flags. Now we can clearly see where the TCP SYN/SYN-ACK/ACK handshake is, right down to the final FINs. Rather than always having the source address on the left and the destination on the right, we now print the local address on the left (LADDR) and the remote address on the right (RADDR); the arrow changes so that we know which direction the packet travelled.
199: 
200: The script for tcpio2.d did get a little longer, but it is still fairly straightforward,
201: 
202: {{{
203: #!/usr/sbin/dtrace -s
204: 
205: #pragma D option quiet
206: #pragma D option switchrate=10hz
207: 
208: dtrace:::BEGIN
209: {
210:         printf(" %15s:%-5s      %15s:%-5s %6s %s\n",
211:             "LADDR", "PORT", "RADDR", "PORT", "BYTES", "FLAGS");
212: }
213: 
214: tcp:::send
215: {
216:         this->length = args[1]->ip_plength - args[2]->tcp_offset;
217:         printf(" %15s:%-5d  ->  %15s:%-5d %6d (",
218:             args[1]->ip_saddr, args[2]->tcp_sport,
219:             args[1]->ip_daddr, args[2]->tcp_dport, this->length);
220: }
221: 
222: tcp:::receive
223: {
224:         this->length = args[1]->ip_plength - args[2]->tcp_offset;
225:         printf(" %15s:%-5d  <-  %15s:%-5d %6d (",
226:             args[1]->ip_daddr, args[2]->tcp_dport,
227:             args[1]->ip_saddr, args[2]->tcp_sport, this->length);
228: }
229: 
230: tcp:::send,
231: tcp:::receive
232: {
233:         printf("%s", args[2]->tcp_flags & TH_FIN ? "FIN|" : "");
234:         printf("%s", args[2]->tcp_flags & TH_SYN ? "SYN|" : "");
235:         printf("%s", args[2]->tcp_flags & TH_RST ? "RST|" : "");
236:         printf("%s", args[2]->tcp_flags & TH_PUSH ? "PUSH|" : "");
237:         printf("%s", args[2]->tcp_flags & TH_ACK ? "ACK|" : "");
238:         printf("%s", args[2]->tcp_flags & TH_URG ? "URG|" : "");
239:         printf("%s", args[2]->tcp_flags & TH_ECE ? "ECE|" : "");
240:         printf("%s", args[2]->tcp_flags & TH_CWR ? "CWR|" : "");
241:         printf("%s", args[2]->tcp_flags == 0 ? "null " : "");
242:         printf("\b)\n");
243: }
244: }}}
245: 
246: The last section prints out each of the flags as a string, if they are set. Note that we can directly match args[2]->tcp_flags using bitwise and with meaningful TCP flag names - TH_FIN, TH_SYN, etc (TH is transport header).
247: 
248: This also allows us to match TCP traffic with particular flags in a DTrace predicate, so that scripts could identify and measure different TCP events.
249: 
250: ===tcpio2x.d
251: 
252: Now the tcpio2.d script is made a little wider, so that IPv6 addresses look neat and tidy,
253: 
254: {{{
255: # ./tcpio2x.d
256: C                     LADDR:PORT                           RADDR:PORT   BYTES FLAGS
257: 0    fe80::214:4fff:fe2a:64:79     <-   fe80::214:4fff:fe3b:76c8:61706      0 (SYN)
258: 0    fe80::214:4fff:fe2a:64:79     ->   fe80::214:4fff:fe3b:76c8:61706      0 (SYN|ACK)
259: 0    fe80::214:4fff:fe2a:64:79     <-   fe80::214:4fff:fe3b:76c8:61706      0 (ACK)
260: 0    fe80::214:4fff:fe2a:64:79     <-   fe80::214:4fff:fe3b:76c8:61706      2 (PUSH|ACK)
261: 0    fe80::214:4fff:fe2a:64:79     ->   fe80::214:4fff:fe3b:76c8:61706      0 (ACK)
262: 0    fe80::214:4fff:fe2a:64:79     ->   fe80::214:4fff:fe3b:76c8:61706    126 (PUSH|ACK)
263: 0    fe80::214:4fff:fe2a:64:79     <-   fe80::214:4fff:fe3b:76c8:61706      0 (ACK)
264: 0    fe80::214:4fff:fe2a:64:79     ->   fe80::214:4fff:fe3b:76c8:61706      0 (FIN|ACK)
265: 0    fe80::214:4fff:fe2a:64:79     <-   fe80::214:4fff:fe3b:76c8:61706      0 (ACK)
266: 0    fe80::214:4fff:fe2a:64:79     <-   fe80::214:4fff:fe3b:76c8:61706      0 (FIN|ACK)
267: 0    fe80::214:4fff:fe2a:64:79     ->   fe80::214:4fff:fe3b:76c8:61706      0 (ACK)
268: ^C
269: }}}
270: 
271: Perhaps more exciting is the ability to examine loopback traffic,
272: 
273: {{{
274: # ./tcpio2x.d
275: C                     LADDR:PORT                           RADDR:PORT   BYTES FLAGS
276: 0                 127.0.0.1:47335  ->                  127.0.0.1:79         0 (SYN)
277: 0                 127.0.0.1:79     <-                  127.0.0.1:47335      0 (SYN)
278: 0                 127.0.0.1:79     ->                  127.0.0.1:47335      0 (SYN|ACK)
279: 0                 127.0.0.1:47335  <-                  127.0.0.1:79         0 (SYN|ACK)
280: 0                 127.0.0.1:47335  ->                  127.0.0.1:79         0 (ACK)
281: 0                 127.0.0.1:79     <-                  127.0.0.1:47335      0 (ACK)
282: 0                 127.0.0.1:79     ->                  127.0.0.1:47335      0 (FIN|ACK)
283: 0                 127.0.0.1:47335  <-                  127.0.0.1:79         0 (FIN|ACK)
284: 0                 127.0.0.1:47335  ->                  127.0.0.1:79         0 (ACK)
285: 0                 127.0.0.1:79     <-                  127.0.0.1:47335      0 (ACK)
286: 0                 127.0.0.1:47335  ->                  127.0.0.1:79         0 (FIN|ACK)
287: 0                 127.0.0.1:79     <-                  127.0.0.1:47335      0 (FIN|ACK)
288: 0                 127.0.0.1:79     ->                  127.0.0.1:47335      0 (ACK)
289: 0                 127.0.0.1:47335  <-                  127.0.0.1:79         0 (ACK)
290: 
291: 0                       ::1:51380  ->                        ::1:79         0 (SYN)
292: 0                       ::1:79     <-                        ::1:51380      0 (SYN)
293: 0                       ::1:79     ->                        ::1:51380      0 (SYN|ACK)
294: 0                       ::1:51380  <-                        ::1:79         0 (SYN|ACK)
295: 0                       ::1:51380  ->                        ::1:79         0 (ACK)
296: 0                       ::1:79     <-                        ::1:51380      0 (ACK)
297: 0                       ::1:79     ->                        ::1:51380      0 (FIN|ACK)
298: 0                       ::1:51380  <-                        ::1:79         0 (FIN|ACK)
299: 0                       ::1:51380  ->                        ::1:79         0 (ACK)
300: 0                       ::1:79     <-                        ::1:51380      0 (ACK)
301: 0                       ::1:51380  ->                        ::1:79         0 (FIN|ACK)
302: 0                       ::1:79     <-                        ::1:51380      0 (FIN|ACK)
303: 0                       ::1:79     ->                        ::1:51380      0 (ACK)
304: 0                       ::1:51380  <-                        ::1:79         0 (ACK)
305: ^C
306: }}}
307: 
308: The traffic appears duplicated - this is because the source and destination are on the same host, localhost, and we can trace both the send and the receive of the same packet.
309: 
310: So far this is sufficient to see which loopback connections are being made, what the destination ports are, and the rate of connections; however note that the BYTES column is always zero. Due to performance reasons, once loopback connections are established their data transfers bypass costly TCP code (the session becomes "fused"), and the regular tcp:::send and tcp:::receive probes don’t fire. It is still possible to trace this traffic, and we plan to do so, we just haven’t added the probes yet.
311: 
312: The first column in the previous output is the CPU id. For DTrace reasons, when tracing events as they occur - the output can become shuffled as data is collected from each CPU in turn. So a CPU column is handy to have - if you are on a multi-CPU server, and you are printing events as they occur, and you expect them to appear in the correct order. A different tactic can be to print out a timestamp, and use a tool to post-process and sort the output.
313: 
314: ===The Probes
315: 
316: So far we have seen probes with intuitive names - accept-established, send, receive. The entire list of probenames so far is as follows,
317: 
318: {{{
319: # dtrace -lP tcp | awk ’{ print $5 }’ | sort -u
320: NAME
321: accept-established
322: accept-refused
323: connect-established
324: connect-refused
325: connect-request
326: receive
327: send
328: state-bound
329: state-close-wait
330: state-closed
331: state-closing
332: state-established
333: state-fin-wait1
334: state-fin-wait2
335: state-idle
336: state-last-ack
337: state-listen
338: state-syn-received
339: state-syn-sent
340: state-time-wait
341: }}}
342: 
343: The accept-* probes are high-level events for inbound traffic; connect- probes are similar events for outbound traffic. send and receive are for all TCP traffic, including ACKs and exotic port scans. The state-* probes allow us to trace state changes in tcp by connection.
344: 
345: This collection of probes opens the door to a huge number of tracing possibilities. More probes have been imagined, however due to concerns for maintainability of the tcp code these may not be implemented. At the very least, send and receive allows all traffic to be examined.
346: 
347: ===One-Liners
348: 
349: Another way to appreciate a provider is to see what one-liners are possible. Here is a collection that now work with this prototype tcp provider:
350: 
351: {{{
352: DTrace Network Providers One-Liners
353: ~-----------------------------------
354: 
355: # Watch inbound TCP connections by remote address,
356: **dtrace -n ’tcp:::accept-established { trace(args[1]->ip_saddr); }’**
357: 
358: # Inbound TCP connections by remote address summary,
359: **dtrace -n ’tcp:::accept-established { @addr[args[1]->ip_saddr] = count(); }’**
360: 
361: # Inbound TCP connections by destination port summary,
362: **dtrace -n ’tcp:::accept-established { @port[args[2]->tcp_dport] = count(); }’**
363: 
364: # Outbound TCP connections by destination port summary,
365: **dtrace -n ’tcp:::connect-established { @port[args[2]->tcp_dport] = count(); }’**
366: 
367: # Inbound TCP refused connections by destination port summary (port scan?),
368: **dtrace -n ’tcp:::accept-refused { @port[args[2]->tcp_dport] = count(); }’**
369: 
370: # Outbound TCP refused connections by destination port summary,
371: **dtrace -n ’tcp:::connect-refused { @port[args[2]->tcp_dport] = count(); }’**
372: 
373: # Inbound TCP packets by remote address summary,
374: **dtrace -n ’tcp:::receive { @addr[args[1]->ip_saddr] = count(); }’**
375: 
376: # Outbound TCP packets by remote address summary,
377: **dtrace -n ’tcp:::send { @addr[args[1]->ip_daddr] = count(); }’**
378: 
379: # Inbound TCP packets by destination port summary,
380: **dtrace -n ’tcp:::receive { @port[args[2]->tcp_dport] = count(); }’**
381: 
382: # Outbound TCP packets by destination port summary,
383: **dtrace -n ’tcp:::send { @port[args[2]->tcp_dport] = count(); }’**
384: 
385: # sent TCP bytes summary,
386: **dtrace -n ’tcp:::send { @b = sum(args[1]->ip_plength - args[2]->tcp_offset); }’**
387: 
388: # TCP events by type summary,
389: **dtrace -n ’tcp::: { @event[probename] = count(); }’**
390: }}}
391: 
392: For this short demonstration we won’t each one by one - but from the descriptions and code we can get a feeling for what is possible.
393: 
394: ===tcpbytes1.d
395: 
396: Back to the scripts. Here we create summaries of by-byte traffic,
397: 
398: {{{
399: # ./tcpbytes1.d
400: dtrace: script ’./tcpbytes1.d’ matched 5 probes
401: ^C
402: 
403:   192.168.1.107                                        513               87
404:   fe80::214:4fff:fe3b:76c8                              79              128
405:   192.168.1.109                                         79              256
406:   192.168.1.109                                         22             9128
407:   192.168.1.109                                        514         21380483
408: }}}
409: 
410: The tcpbytes1.d script adds sent and received bytes, by IP address and by destination port. Here we can see that 192.168.1.109 transferred 9128 bytes to port 22 on our server. The source to tcpbytes1.d is as follows,
411: 
412: {{{
413: #!/usr/sbin/dtrace -s
414: 
415: tcp:::receive
416: {
417:         @bytes[args[1]->ip_saddr, args[2]->tcp_dport] =
418:             sum(args[1]->ip_plength - args[2]->tcp_offset);
419: }
420: 
421: tcp:::send
422: {
423:         @bytes[args[1]->ip_daddr, args[2]->tcp_sport] =
424:             sum(args[1]->ip_plength - args[2]->tcp_offset);
425: }
426: }}}
427: 
428: The bytes are found by adding the payload length from the IP observability info structure (args[1] - which is based on the IP header), and then subtracting the TCP header length (args[2]->tcp_offset - from the TCP header). Both these values return a byte count for convienence, whereas the RFCs specify that these would be the number of 32-bit words (of course, the raw TCP header will be made available if people want it; args[2] provides a endian-correct processed form for convienence).
429: 
430: ===unprepared - TCP byte size
431: 
432: About this point in the demonstration, someone in the audience asked Brendan if the size in bytes of the TCP I/O could be quantized. Yes - that’s a great idea! Brendan ran the following while Bryan generated some test traffic,
433: 
434: {{{
435: # dtrace -n ’tcp:::send { @q = quantize(args[1]->ip_plength - args[2]->tcp_offset); }’
436: ^C
437: 
438:            value  ~------------- Distribution ~------------- count
439:               -1 |                                         0
440:                0 |@@@@@                                    227
441:                1 |@                                        24
442:                2 |                                         4
443:                4 |                                         0
444:                8 |                                         1
445:               16 |                                         1
446:               32 |                                         6
447:               64 |                                         1
448:              128 |                                         0
449:              256 |                                         2
450:              512 |                                         2
451:             1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@       1501
452:             2048 |                                         0
453: }}}
454: 
455: To start with, lets feed the byte size into a single quantize. We’ll do sent traffic, adding a receive probe as well would be no problem. The above one-liner does quantizes by byte size, and we can see that our TCP traffic is in the 0 byte to 2047 byte range (which we can assume is bounded by MTU). There is a large spike in the 1024 to 2047 byte bucket, which sounds like a data transfer from someone..
456: 
457: By adding keys to our aggregate, we can find out who the IP addresses are that are receiving bytes from us, and what port they are receiving from,
458: 
459: {{{
460: # dtrace -n ’tcp:::send { @q[args[1]->ip_daddr, args[2]->tcp_sport] =
461:      quantize(args[1]->ip_plength - args[2]->tcp_offset); }’
462: dtrace: description ’tcp:::send ’ matched 2 probes
463: ^C
464: 
465:   192.168.1.107                                         79
466:            value  ~------------- Distribution ~------------- count
467:               -1 |                                         0
468:                0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@         4
469:                1 |                                         0
470:                2 |                                         0
471:                4 |                                         0
472:                8 |                                         0
473:               16 |                                         0
474:               32 |                                         0
475:               64 |                                         0
476:              128 |@@@@@@@@                                 1
477:              256 |                                         0
478: 
479:   192.168.1.109                                         22
480:            value  ~------------- Distribution ~------------- count
481:               -1 |                                         0
482:                0 |@@                                       5
483:                1 |                                         0
484:                2 |                                         0
485:                4 |                                         0
486:                8 |                                         0
487:               16 |                                         1
488:               32 |@@@@@@@@@@@@@@@@@                        38
489:               64 |@@@@@@@@@@@@@@@@@                        37
490:              128 |                                         1
491:              256 |@@                                       4
492:              512 |                                         1
493:             1024 |                                         0
494: 
495:   192.168.1.109                                        514
496:            value  ~------------- Distribution ~------------- count
497:               -1 |                                         0
498:                0 |                                         5
499:                1 |                                         2
500:                2 |                                         1
501:                4 |                                         0
502:                8 |                                         0
503:               16 |                                         1
504:               32 |                                         1
505:               64 |                                         0
506:              128 |                                         0
507:              256 |                                         0
508:              512 |                                         0
509:             1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1499
510:             2048 |                                         0
511: }}}
512: 
513: Superb! This immediatly shows that our spike of large packets (this time 1499 packets in the 1024 to 2047 byte bucket) belongs to 192.168.1.109 connecting to port 514. Port 22 (ssh) from the same host is responsible for some medium sized traffic - mostly 32 to 128 bytes in size; and most of the TCP traffic to port 79 wil zero sized (ACKs).
514: 
515: Now if only we could remember who 192.168.1.109 was, and what port 514 was for...
516: 
517: {{{
518: # dtrace -qn ’tcp:::send { @q[args[1]->ip_daddr, args[2]->tcp_sport] = 
519:     quantize(args[1]->ip_plength - args[2]->tcp_offset); } END { printa("   %-32I %21P %@d", @q); }’
520: ^C
521:    marlin                                           shell
522:            value  ~------------- Distribution ~------------- count
523:               -1 |                                         0
524:                0 |                                         5
525:                1 |                                         3
526:                2 |                                         1
527:                4 |                                         0
528:                8 |                                         0
529:               16 |                                         1
530:               32 |                                         1
531:               64 |                                         0
532:              128 |                                         0
533:              256 |                                         0
534:              512 |                                         0
535:             1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1499
536:             2048 |                                         0
537: }}}
538: 
539: We are now using the enhanced printf format characters to fetch the hostname and service name - so it was marlin connecting to our shell port, probably doing an rcp. (We need to run DTrace on marlin to check).
540: 
541: ===tcpbytes2.d
542: 
543: Back to the scripts we brought to the demonstration; this one is tcpbytes2.d,
544: 
545: {{{
546: # ./tcpbytes2.d
547: 
548:    HOST                                      BYTES/s
549:    192.168.1.109                            21210735
550: 
551:    HOST                                      BYTES/s
552:    192.168.1.109                            16511328
553: 
554:    HOST                                      BYTES/s
555:    192.168.1.109                            26249638
556: 
557:    HOST                                      BYTES/s
558:    192.168.1.107                                  54
559: 
560:    HOST                                      BYTES/s
561:    192.168.1.109                                 418
562: 
563:    HOST                                      BYTES/s
564:    fe80::214:4fff:fe3b:76c8                      209
565: 
566:    HOST                                      BYTES/s
567: ^C
568: }}}
569: 
570: Per second, tcpbytes2.d prints a report of TCP payload byte transfers by IP address. In the output we can see that 192.168.1.109 began transferring at around 20 Mbytes/sec. The source was,
571: 
572: {{{
573: #!/usr/sbin/dtrace -s
574: 
575: #pragma D option quiet
576: 
577: tcp:::receive
578: {
579:         @bytes[args[1]->ip_saddr, args[2]->tcp_dport] =
580:             sum(args[1]->ip_plength - args[2]->tcp_offset);
581: }
582: 
583: tcp:::send
584: {
585:         @bytes[args[1]->ip_daddr, args[2]->tcp_sport] =
586:             sum(args[1]->ip_plength - args[2]->tcp_offset);
587: }
588: 
589: profile:::tick-1sec
590: {
591:         printf("\n   %-32s %16s\n", "HOST", "BYTES/s");
592:         printa("   %-32s %@16d\n", @bytes);
593:         trunc(@bytes);
594: }
595: }}}
596: 
597: This can be customised as desired, and provides a quick summary of who is transferring data to our host.
598: 
599: ===tcpnmap.d
600: 
601: Since the tcp provider allows us to easily match on TCP flags - it will be possible to write numerous tools that use this capability to look for certain packets. Here is a demonstration that is more about the D-script that it is about practicality. Long term defense against port scans includes the installation of NIDS (Network Intrusion Detection Systems); for example, snort.
602: 
603: The [[nmap>>http://insecure.org/nmap/index.html]] port scanner is a popular and powerful security tool for host vulnerability and remote identification analysis. By using flags, various exotic scans can be performed, including Xmas and null scans. The tcpnmap.d tool examines these flags to find traffic that is //possible// scan evets - however (as with the connect() scan) they may also be normal traffic. The differentiator (left to the user) is the volume of these suspicious events.
604: 
605: {{{
606: # ./tcpnmap.d
607: Tracing for possible nmap scans... Hit Ctrl-C to end.
608: ^C
609: Possible scan events,
610: 
611:    TYPE                     HOST                            COUNT
612:    TCP_null_scan            192.168.1.109                     208
613:    TCP_Xmas_scan            192.168.1.109                     304
614:    TCP_connect()_scan       192.168.1.109                     388
615: }}}
616: 
617: Here all our scan types had counts of more than 100, which (for this 10 second sample), is evidence of scanning.
618: 
619: The tcpnmap.d script was,
620: 
621: {{{
622: #!/usr/sbin/dtrace -s
623: 
624: #pragma D option quiet
625: 
626: dtrace:::BEGIN
627: {
628:         printf("Tracing for possible nmap scans... Hit Ctrl-C to end.\n");
629: }
630: 
631: tcp:::accept-refused
632: {
633:         @num["TCP_connect()_scan", args[1]->ip_daddr] = count();
634: }
635: 
636: tcp:::receive
637: /args[2]->tcp_flags == 0/
638: {
639:         @num["TCP_null_scan", args[1]->ip_saddr] = count();
640: }
641: 
642: tcp:::receive
643: /args[2]->tcp_flags == (TH_URG|TH_PUSH|TH_FIN)/
644: {
645:         @num["TCP_Xmas_scan", args[1]->ip_saddr] = count();
646: }
647: 
648: dtrace:::END
649: {
650:         printf("Possible scan events,\n\n");
651:         printf("   %-24s %-28s %8s\n", "TYPE", "HOST", "COUNT");
652:         printa("   %-24s %-28s %@8d\n", @num);
653: }
654: }}}
655: 
656: Null and Xmas scans were identified by matching on the TCP flags. Connect scans were matched simply by examining accept-refused events - an inbound SYN to a closed port. This means that we will see the connect() scans to closed ports, however we will miss them to open ones. Wait! We can in fact measure connect() scans to open ports by checking if accept-established events were immediatly closed with a RST - which is what nmap does. In fact, I just verified it by using the tcpio2.d script! Hey - this is really cool - sorry, I didn’t do this at CEC, but check this out:
657: 
658: **nmap connect() to an open port**
659: 
660: {{{
661: # ./tcpio2.d
662:            LADDR:PORT                 RADDR:PORT   BYTES FLAGS
663:    192.168.1.185:22     <-    192.168.1.109:60631      0 (SYN)
664:    192.168.1.185:22     ->    192.168.1.109:60631      0 (SYN|ACK)
665:    192.168.1.185:22     <-    192.168.1.109:60631      0 (ACK)
666:    192.168.1.185:22     <-    192.168.1.109:60631      0 (RST)
667: }}}
668: 
669: **nmap connect() to a closed port**
670: 
671: {{{
672: # ./tcpio2.d
673:            LADDR:PORT                 RADDR:PORT   BYTES FLAGS
674:    192.168.1.185:26     <-    192.168.1.109:47113      0 (SYN)
675:    192.168.1.185:26     ->    192.168.1.109:47113      0 (RST|ACK)
676: }}}
677: 
678: **nmap TCP Xmas to an open port**
679: 
680: {{{
681: # ./tcpio2.d
682:            LADDR:PORT                 RADDR:PORT   BYTES FLAGS
683:    192.168.1.185:22     <-    192.168.1.109:43968      0 (FIN|PUSH|URG)
684: }}}
685: 
686: **nmap TCP Xmas to a closed port**
687: 
688: {{{
689: # ./tcpio2.d
690:            LADDR:PORT                 RADDR:PORT   BYTES FLAGS
691:    192.168.1.185:26     <-    192.168.1.109:33466      0 (FIN|PUSH|URG)
692: }}}
693: 
694: **nmap TCP Null to an open port**
695: 
696: {{{
697: # ./tcpio2.d
698:            LADDR:PORT                 RADDR:PORT   BYTES FLAGS
699:    192.168.1.185:22     <-    192.168.1.109:53034      0 (null)
700: }}}
701: 
702: **nmap TCP Null to a closed port**
703: 
704: {{{
705: # ./tcpio2.d
706:            LADDR:PORT                 RADDR:PORT   BYTES FLAGS
707:    192.168.1.185:26     <-    192.168.1.109:61054      0 (null)
708: }}}
709: 
710: **nmap TCP Stealth to an open port**
711: 
712: {{{
713: # ./tcpio2.d
714:            LADDR:PORT                 RADDR:PORT   BYTES FLAGS
715:    192.168.1.185:22     <-    192.168.1.109:39438      0 (SYN)
716:    192.168.1.185:22     ->    192.168.1.109:39438      0 (SYN|ACK)
717:    192.168.1.185:22     <-    192.168.1.109:39438      0 (RST)
718: }}}
719: 
720: **nmap TCP Stealth to a closed port**
721: 
722: {{{
723: # ./tcpio2.d
724:            LADDR:PORT                 RADDR:PORT   BYTES FLAGS
725:    192.168.1.185:26     <-    192.168.1.109:57433      0 (SYN)
726:    192.168.1.185:26     ->    192.168.1.109:57433      0 (RST|ACK)
727: }}}
728: 
729: Very, very cool. Bryan commented that this script needs to be used at Universities when teaching TCP - you can probably see why!
730: 
731: Note that Solaris doesn’t respond to null or Xmas scans ~-- good Solaris! :-)
732: 
733: ===tcpstate.d
734: 
735: A TCP connection changes between well defined states (see RFC 793), which are highly useful to observe. The following script simply prints out when a state has changed, including the previous and the new state,
736: 
737: {{{
738: # ./tcpstate.d
739: C   PREV                    NEW
740: 0   state-established    -> state-idle
741: 0   state-idle           -> state-bound
742: 0   state-bound          -> state-syn-sent
743: 0   state-syn-sent       -> state-established
744: 0   state-established    -> state-close-wait
745: 0   state-close-wait     -> state-last-ack
746: 0   state-last-ack       -> state-closed
747: ^C
748: }}}
749: 
750: And the script was,
751: 
752: {{{
753: #!/usr/sbin/dtrace -s
754: 
755: #pragma D option quiet
756: 
757: dtrace:::BEGIN
758: {
759:         printf("%s   %-20s    %-20s\n", "C", "PREV", "NEW");
760: }
761: 
762: tcp:::state-bound,
763: tcp:::state-close-wait,
764: tcp:::state-closed,
765: tcp:::state-closing,
766: tcp:::state-established,
767: tcp:::state-fin-wait1,
768: tcp:::state-fin-wait2,
769: tcp:::state-idle,
770: tcp:::state-last-ack,
771: tcp:::state-listen,
772: tcp:::state-syn-received,
773: tcp:::state-syn-sent,
774: tcp:::state-time-wait
775: {
776:         printf("%d   %-20s -> %-20s\n", cpu, args[2]->ts_prevstr, probename);
777: }
778: }}}
779: 
780: All TCP probes as arg0 provide a connection-ID, similar to a process-ID, so that we can uniquely identify TCP connections. If we can (it may not make sense for all contexts), we will make it available as the variable cid. Apart from the old and new states, these state probes will also provide the cid. They will not, however, provide IP or TCP header information - such as IP addresses or ports - as such header information is not in a stable state when these probes fire. Not a great problem - the cid will allow us to associate IP and TCP header details to the state events, by caching them when they are available.
781: 
782: About cids: If we had a system with sudden CPU load, and suspected a runaway process, we are of the mentality to go hunting for the PID responsible. What about a server that has network load? We need a similar mechanism to refer to established network connections, so that tools can be written to associate cid data and present it. The kernel already has such a mechanism, the struct conn_s *, and we plan to make the cid be an integer form of that pointer (it’s unique, it’s valid for the session, and it works for both TCP and UDP). Perhaps years form now we will take for granted a wide range of by-cid tools (powered by DTrace) for network connection observability, just as we currently have a range of by-pid tools (powered by procfs).. (either that or I invent my own filesystem - /connfs ;-) - Brendan)
783: 
784: These state probes should allow some really amazing scripts to be written - watch this space!
785: 
786: ===tcpconnlat.d
787: 
788: The tcp provider gives us the means to measure numerous new and useful latency metrics. To begin with, there is latency incurred for the TCP 3-way handshake to complete for outbound connections. The tcpconnlat.d script measures this.
789: 
790: {{{
791: # ./tcpconnlat.d
792: dtrace: script ’./tcpconnlat.d’ matched 2 probes
793: ^C
794: 
795:   Connect Latency (ns)                                192.168.1.109
796:            value  ~------------- Distribution ~------------- count
797:            65536 |                                         0
798:           131072 |@@@@@@@@@@@@@@@@@@@@@@@@                 3
799:           262144 |@@@@@@@@@@@@@@@@                         2
800:           524288 |                                         0
801: 
802:   Connect Latency (ns)                                72.5.124.61
803:            value  ~------------- Distribution ~------------- count
804:          4194304 |                                         0
805:          8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@           3
806:         16777216 |@@@@@@@@@@                               1
807:         33554432 |                                         0
808: }}}
809: 
810: 192.168.1.109 is a host on the same subnet, 72.5.124.61 is www.sun.com. This measures an outbound SYN to the final ACK in the 3 way handshake. So a nearby host was connecting in less than 0.3 ms, while www.sun.com was connecting in around 10 ms. This latency includes network hop latency, and the time for the remote kernel to create a new TCP session and reply.
811: 
812: This example is much more interesting than what we could do at the CEC conference, where we only had two laptops and a crossover cable!
813: 
814: The source for tcpconnlat.d is,
815: 
816: {{{
817: #!/usr/sbin/dtrace -s
818: 
819: tcp:::connect-request
820: {
821:         start[arg0] = timestamp;
822: }
823: 
824: tcp:::connect-established
825: /start[arg0]/
826: {
827:         @latency["Connect Latency (ns)", args[1]->ip_daddr] =
828:             quantize(timestamp - start[arg0]);
829:         start[arg0] = 0;
830: }
831: }}}
832: 
833: ===tcp1stbyte.d
834: 
835: Another useful latency metric is the time from when an outbound connection is established to the when first application data arrives - which we can call "1st byte latency". The tcp1stbyte.d script measures this,
836: 
837: {{{
838: # ./tcp1stbyte.d
839: dtrace: script ’./tcp1stbyte.d’ matched 4 probes
840: ^C
841: 
842:   1st Byte Latency (ns)                               192.168.1.109
843:            value  ~------------- Distribution ~------------- count
844:          8388608 |                                         0
845:         16777216 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
846:         33554432 |@@@@@@@@@@@@@                            1
847:         67108864 |                                         0
848: 
849:   1st Byte Latency (ns)                               72.5.124.61
850:            value  ~------------- Distribution ~------------- count
851:          8388608 |                                         0
852:         16777216 |@@@@@@                                   1
853:         33554432 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@       6
854:         67108864 |                                         0
855: }}}
856: 
857: This is the time for the first TCP data byte to be received, and includes both network latency and application latency. Now www.sun.com is mostly in the 32 to 64 ms bucket, and these times are much larger. We would usually expect this application latency to be large, as it is the time for the application to be scheduled, read the request, process it and respond - which is likely to be much slower than a streamlined kernel TCP handshake.
858: 
859: The source for tcp1stbyte.d is,
860: 
861: {{{
862: #!/usr/sbin/dtrace -s
863: 
864: tcp:::connect-established
865: {
866:         start[arg0] = timestamp;
867: }
868: 
869: tcp:::receive
870: /start[arg0] && (args[1]->ip_plength - args[2]->tcp_offset) > 0/
871: {
872:         @latency["1st Byte Latency (ns)", args[1]->ip_saddr] =
873:             quantize(timestamp - start[arg0]);
874:         start[arg0] = 0;
875: }
876: }}}
877: 
878: ==Conclusion
879: 
880: Hopefully these short demonstrations of this prototype tcp provider will help convey what we are trying to achieve. This is by no means a certain addition to Solaris, and there are many challenges ahead, including:
881: 
882: * Extensive testing. Test that every packet is matched correctly, including those with exotic flags.
883: * Minimising the kernel code changes, and reworking the probes and arguments if needed for maintainability.
884: * Gaining the support of the kernel engineers and the customers. If enough people (especially customers) want this, it can happen. Let us know on [[dtrace-discuss>>http://mail.opensolaris.org/mailman/listinfo/dtrace-discuss]].
885: 
886: ==Questions
887: 
888: **Q: Where can I get a BFU archive so I can help by testing this?**
889: **A:** We’ll put something together and post on DTrace-discuss.
OpenSolaris

Top Menu

Wiki code for CEC 2006 Demo

Search

Collectives

Community Group

Project

User Group

Subsites

Community Group dtrace Pages
