iSCSI DTrace provider

I recently tried out the new iSCSI Target Server DTrace provider which Adam wrote (which should be included in Solaris sometime soon). It provides observability of iSCSI traffic from the the server's perspective. This is great news if you have an iSCSI Solaris server, or are planning to have one.

In this entry I'll post a few screenshots of the iSCSI provider in action, both one-liners and scripts.

one-liners

I'll start by listing the probes - which may convey a sense of what is possible to trace. Look down the "NAME" column,
# dtrace -ln 'iscsi\*:::'
   ID    PROVIDER            MODULE                          FUNCTION NAME
11696 iscsi100653         iscsitgtd                 send_async_logout async-send
11697 iscsi100653         iscsitgtd                   send_async_scsi async-send
11698 iscsi100653         iscsitgtd                  handle_scsi_data data-receive
11699 iscsi100653         iscsitgtd              iscsi_conn_data_rqst data-request
11700 iscsi100653         iscsitgtd                   send_datain_pdu data-send
11701 iscsi100653         iscsitgtd            iscsi_handle_login_pkt login-command
11702 iscsi100653         iscsitgtd                 send_login_reject login-response
11703 iscsi100653         iscsitgtd            iscsi_handle_login_pkt login-response
11704 iscsi100653         iscsitgtd                 handle_logout_msg logout-command
11705 iscsi100653         iscsitgtd                        conn_state logout-response
11706 iscsi100653         iscsitgtd                   handle_noop_cmd nop-receive
11707 iscsi100653         iscsitgtd                    iscsi_conn_pkt nop-send
11708 iscsi100653         iscsitgtd                   handle_scsi_cmd scsi-command
11709 iscsi100653         iscsitgtd                     send_scsi_rsp scsi-response
11710 iscsi100653         iscsitgtd                   handle_task_mgt task-command
11711 iscsi100653         iscsitgtd                    iscsi_conn_pkt task-response
11712 iscsi100653         iscsitgtd                   handle_text_msg text-command
11713 iscsi100653         iscsitgtd                   handle_text_msg text-response
The easiest one-liner would be to frequency count iSCSI operations,
# dtrace -n 'iscsi\*::: { @[probename] = count(); }'
dtrace: description 'iscsi\*::: ' matched 18 probes
\^C

  nop-receive                                                       3
  nop-send                                                          3
  data-receive                                                     55
  data-request                                                     55
  scsi-response                                                   103
  scsi-command                                                    342
  data-send                                                      2865
The above output shows that the iSCSI server is doing more send operations (2865 data-sends), than receive (55 data-receives).

Now to see who is using this iSCSI server, by frequency counting remote IP addresses,

# dtrace -n 'iscsi\*::: { @[args[0]->ci_remote] = count(); }'
dtrace: description 'iscsi\*::: ' matched 18 probes
\^C

  192.168.1.109                                                  1338
The above shows that 192.168.1.108 triggered 1338 iSCSI operations - which may have been sends, receives, nops, etc. Breaking down further is just a little more DTrace,
# dtrace -qn 'iscsi\*::: { @[args[0]->ci_remote, probename] = count(); } 
  END { printa("%32s %18s %@16d\\n", @); }'
\^C
                   192.168.1.109        nop-receive                2
                   192.168.1.109           nop-send                2
                   192.168.1.109       data-receive               16
                   192.168.1.109       data-request               16
                   192.168.1.109      scsi-response               43
                   192.168.1.109       scsi-command              253
                   192.168.1.109          data-send             2619
Great, while a simple one-liner - it quickly identifies who is connecting and what operations they are doing. Some performance wins are about locating and eliminating unnecessary work, which one-liners such as this help identify.

Now for printing payload bytes by iSCSI operation,

# dtrace -n 'iscsi\*::: { @[probename] = sum(args[1]->ii_datalen); }'
dtrace: description 'iscsi\*::: ' matched 18 probes
\^C

  data-request                                                      0
  scsi-response                                                     0
  data-receive                                                  99328
  scsi-command                                                 140800
  data-send                                                  20672512
The above one-liner prints total bytes by operation, which does lose some data - what was the count by operation, average, min, max? DTrace can answer all of these seperately, or provide a summary as a distribution plot. Here I've used quantize for a power of 2 plot,
# dtrace -n 'iscsi\*::: { @[probename] = quantize(args[2]->ii_datalen); }'
dtrace: description 'iscsi\*::: ' matched 18 probes
\^C

  data-request                                      
           value  ------------- Distribution ------------- count    
              -1 |                                         0        
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 12       
               1 |                                         0        

  scsi-response                                     
           value  ------------- Distribution ------------- count    
              -1 |                                         0        
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 55       
               1 |                                         0        

  data-receive                                      
           value  ------------- Distribution ------------- count    
             512 |                                         0        
            1024 |@@@@@@@                                  2        
            2048 |                                         0        
            4096 |@@@@@@@@@@@@@                            4        
            8192 |@@@@@@@@@@@@@@@@@@@@                     6        
           16384 |                                         0        

  scsi-command                                      
           value  ------------- Distribution ------------- count    
              -1 |                                         0        
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@         209      
               1 |                                         0        
               2 |                                         0        
               4 |                                         0        
               8 |                                         0        
              16 |                                         0        
              32 |                                         0        
              64 |                                         0        
             128 |                                         0        
             256 |                                         0        
             512 |@@@                                      18       
            1024 |@@                                       10       
            2048 |@@                                       11       
            4096 |@                                        4        
            8192 |@@                                       12       
           16384 |                                         0        

  data-send                                         
           value  ------------- Distribution ------------- count    
             256 |                                         0        
             512 |                                         1        
            1024 |                                         16       
            2048 |                                         21       
            4096 |                                         28       
            8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  2559     
           16384 |                                         0        
The plots above show that for the data-send operation, the payload size was usually in the 8 to 16 Kbyte bucket.

scripts

Apart from one-lines, DTrace allows powerful scripts to be contstructed. I've put a few on the SolarisInternals DTrace Topics: iSCSI page.

Here I'll post my favourite so far - a script which measures read/write latency (or "response time") in nanoseconds,

# ./iscsirwlat.d 
Tracing... Hit Ctrl-C to end.
\^C
Read Latency (ns),

  192.168.1.109                                     
           value  ------------- Distribution ------------- count    
           32768 |                                         0        
           65536 |@@@                                      27       
          131072 |@@                                       17       
          262144 |                                         4        
          524288 |@@@@                                     39       
         1048576 |@@@                                      32       
         2097152 |@@@@@@@@@@@@@@@@@                        164      
         4194304 |@                                        11       
         8388608 |@                                        5        
        16777216 |@                                        10       
        33554432 |@                                        7        
        67108864 |@                                        5        
       134217728 |@@@@@                                    46       
       268435456 |@                                        14       
       536870912 |                                         0        

Write Latency (ns),

  192.168.1.109                                     
           value  ------------- Distribution ------------- count    
           32768 |                                         0        
           65536 |@@                                       14       
          131072 |@@                                       16       
          262144 |@@@                                      20       
          524288 |@@@                                      20       
         1048576 |@@@@@                                    33       
         2097152 |@                                        5        
         4194304 |                                         0        
         8388608 |                                         2        
        16777216 |@                                        10       
        33554432 |@@@                                      18       
        67108864 |@@@@@                                    33       
       134217728 |@@@@@@@@@@@@@                            93       
       268435456 |@@                                       12       
       536870912 |                                         0        
The script is on the DTrace Topics page. It is a glimpse of things to come; how many of those were synchronous requests (which may hurt application performance) versus asynchronous flushing or read ahead (which may not hurt performance)? More DTrace is needed - which will probably include running DTrace on the client side as well...
Comments:

Post a Comment:
Comments are closed for this entry.
About

Brendan Gregg, Fishworks engineer

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today