1 #!/usr/sbin/dtrace -s
   2 /*
   3 * iscsirwlat.d - Report iSCSI Read/Write Latency. Solaris Nevada, DTrace.
   4 *
   5 * This traces iSCSI data I/O events when run on an iSCSI server, and
   6 * produces a report of read/write latency in microseconds.
   7 *
   8 * USAGE: iscsirwlat.d # Hit Ctrl-C to end
   9 *
  10 * FIELDS:
  11 * EVENT Data I/O event (data-send/data-receive)
  12 * REMOTE IP IP address of the client
  13 * COUNT Number of I/O events
  14 * Kbytes Total data Kbytes transferred
  15 *
  16 * NOTE: If you try to sum the read times, they will sometimes add to
  17 * a time longer than the sample time - the reason is that reads can
  18 * occur in parallel, and so suming them together will overcount.
  19 */
  20 
  21 #pragma ident "@(#)iscsirwlat.d 1.3 07/03/28 SMI"
  22 
  23 #pragma D option quiet
  24 
  25 dtrace:::BEGIN
  26 {
  27         printf("Tracing... Hit Ctrl-C to end.\n");
  28 }
  29 
  30 iscsi*:::scsi-command
  31 /args[2]->ic_cdb[0] == 0x08 || args[2]->ic_cdb[0] == 0x28/
  32 {
  33         /*
  34 * self-> variables can't be used, as one thread receives the
  35 * scsi command while another receives the reads.
  36 */
  37         start_read[args[1]->ii_itt, args[1]->ii_initiator] = timestamp;
  38 }
  39 
  40 iscsi*:::scsi-command
  41 /args[2]->ic_cdb[0] == 0x0a || args[2]->ic_cdb[0] == 0x2a/
  42 {
  43         start_write[args[1]->ii_itt, args[1]->ii_initiator] = timestamp;
  44 }
  45 
  46 iscsi*:::data-send
  47 /start_read[args[1]->ii_itt, args[1]->ii_initiator] &&
  48     (args[1]->ii_flags & 0x80)/
  49 {
  50         @read[args[0]->ci_remote] = quantize(timestamp -
  51             start_read[args[1]->ii_itt, args[1]->ii_initiator]);
  52         start_read[args[1]->ii_ttt, args[1]->ii_initiator] = 0;
  53 }
  54 
  55 iscsi*:::scsi-response
  56 /start_write[args[1]->ii_itt, args[1]->ii_initiator]/
  57 {
  58         @write[args[0]->ci_remote] = quantize(timestamp -
  59             start_write[args[1]->ii_itt, args[1]->ii_initiator]);
  60         start_write[args[1]->ii_itt, args[1]->ii_initiator] = 0;
  61 }
  62 
  63 tick-10sec
  64 {
  65         printf("Read Latency (ns),\n");
  66         printa(@read);
  67         printf("Write Latency (ns),\n");
  68         printa(@write);
  69         trunc(@read);
  70         trunc(@write);
  71 }