New Dtrace book $9.99

April 9th, 2011

UPDATE: the book sale was only a couple of days and is over now and back to the regular price last I checked

———————————————————-

New Dtrace book $9.99
http://www.informit.com/deals/

As a fan of Active Session History (ASH) I’ve always wanted a version of ASH for operating systems. Operating systems, especially UNIX/Linux and the ilk have generally had ways of generating the basic info such as what process is active at a certain time slice but getting more detailed information was less than obvious if it was possible at all. Now dtrace changes all that.

Let’s take an example. What if I wanted to see all the communication and timings between and NFS client and an NFS server? What happens when I do:

dd if=/dev/zero of=foo bs=8k count=1

On an NFS mounted file system?
First thing we could do is get the timings,size and file being accessed

#!/usr/sbin/dtrace -s
#pragma D option quiet
dtrace:::BEGIN
{
      printf("%-16s %-18s %2s %-8s %6s %s\n", "TIME(us)",
          "CLIENT", "OP", "OFFSET", "BYTES", "PATHNAME");
}

nfsv3:::op-read-start
{
      rtime[args[1]->noi_xid] = timestamp;
      roffset[args[1]->noi_xid] =  args[2]->offset / 1024;
      rsize[args[1]->noi_xid] =  args[2]->count;
      rname[args[1]->noi_xid] =  args[1]->noi_curpath;
}

nfsv3:::op-read-done
/   rtime[args[1]->noi_xid] /
{
      printf("%-16d %-18s %2s %-8d %6d %s\n", (timestamp - rtime[args[1]->noi_xid])/ 1000,
          args[0]->ci_remote, "R",
          roffset[args[1]->noi_xid] ,
          rsize[args[1]->noi_xid] ,
          args[1]->noi_curpath);
}

nfsv3:::op-write-start
{
      wtime[args[1]->noi_xid] = timestamp;
      woffset[args[1]->noi_xid] =  args[2]->offset / 1024;
      wsize[args[1]->noi_xid] =  args[2]->count;
      wname[args[1]->noi_xid] =  args[1]->noi_curpath;
}

nfsv3:::op-write-done
/   wtime[args[1]->noi_xid] /
{
      printf("%-16d %-18s %2s %-8d %6d %s\n", (timestamp - wtime[args[1]->noi_xid]) / 1000,
          args[0]->ci_remote, "W",
          woffset[args[1]->noi_xid] ,
          wsize[args[1]->noi_xid] ,
          args[1]->noi_curpath);
}

Now if I run the above dtrace, and then kick off the dd, I get some dtrace output like

TIME(us)         CLIENT             OP OFFSET    BYTES PATHNAME
1079             172.16.100.194      W 0          8192 /domain0/group0/vdb1/datafile/u01/oracle/oradata/orcl/foo

The above data says that it took 1ms (or 1079us) to finish the nfs write operation.
The “dd” command reports 58ms (ie 5800us)

[oracle@kylelinux orcl]$ dd if=/dev/zero of=foo bs=8k count=1
1+0 records in
1+0 records out
8192 bytes (8.2 kB) copied, 0.005861 seconds, 140 kB/s

Where did all the extra time come from? One area is the TCP/IP layer above the NFS.
We can also trace that. Here is a detailed trace of the “dd” at the TCP/IP level:

    delta      send     recd       seq/ack  seq/ack flags
                    <-- 120          2436     4870 ACK|PUSH|
      198       124 -->              4870     2556 ACK|PUSH|
      514           <-- 0            2556     4994 ACK|
       33           <-- 120          2556     4994 ACK|PUSH|
       37       124 -->              4994     2676 ACK|PUSH|
      280           <-- 116          2676     5118 ACK|PUSH|
       39       116 -->              5118     2792 ACK|PUSH|
      208           <-- 116          2792     5234 ACK|PUSH|
       42       116 -->              5234     2908 ACK|PUSH|
      264           <-- 120          2908     5350 ACK|PUSH|
       59       124 -->              5350     3028 ACK|PUSH|
      224           <-- 152          3028     5474 ACK|PUSH|
      771       148 -->              5474     3180 ACK|PUSH|
      430           <-- 1448         3180     5622 ACK|
      111           <-- 1448         4628     5622 ACK|
      138           <-- 1448         6076     5622 ACK|
      332           <-- 1448         7524     5622 ACK|
      105           <-- 1448         8972     5622 ACK|
       94           <-- 1088          420     5622 ACK|PUSH|
      615       164 -->              5622     1508 ACK|PUSH|
      225           <-- 116          1508     5786 ACK|PUSH|
       57       116 -->              5786     1624 ACK|PUSH|
    39863           <-- 0            1624     5902 ACK|

(notice that the last ACK seems to me to be a lazy ack as it happens well after dd says it is finished)
How would I get that info? It gets a little more complex, but here is the Dtrace script for the TCP level:

#!/usr/sbin/dtrace -s
#pragma D option quiet
#pragma D option defaultargs
#pragma D option dynvarsize=64m

inline int TICKS=$1;
inline string ADDR=$$2;

dtrace:::BEGIN
{
       TIMER = ( TICKS != NULL ) ?  TICKS : 1 ;
       ticks = TIMER;
       TITLE = 10;
       title = 0;
       walltime=timestamp;
       printf("starting up ...\n");
}

tcp:::send,
tcp:::receive
/   title == 0
/
{
      printf("%9s %8s %6s %8s %8s %8s \n",
        "delta"    ,
        "cid"    ,
        "pid"    ,
        "send" ,
        "recd"  ,
        "flags"
      );
        title=TITLE;
}

tcp:::send
/     ( args[2]->ip_daddr == ADDR || ADDR == NULL )
    && curpsinfo->pr_psargs == "/usr/lib/nfs/nfsd"
/
{
    nfs[args[1]->cs_cid]=1; /* this is an NFS thread */
    delta= timestamp-walltime;
    walltime=timestamp;
    flags="";
    flags= strjoin((( args[4]->tcp_flags & TH_FIN ) ? "FIN|" : ""),flags);
    flags= strjoin((( args[4]->tcp_flags & TH_SYN ) ? "SYN|" : ""),flags);
    flags= strjoin((( args[4]->tcp_flags & TH_RST ) ? "RST|" : ""),flags);
    flags= strjoin((( args[4]->tcp_flags & TH_PUSH ) ? "PUSH|" : ""),flags);
    flags= strjoin((( args[4]->tcp_flags & TH_ACK ) ? "ACK|" : ""),flags);
    flags= strjoin((( args[4]->tcp_flags & TH_URG ) ? "URG|" : ""),flags);
    flags= strjoin((( args[4]->tcp_flags & TH_ECE ) ? "ECE|" : ""),flags);
    flags= strjoin((( args[4]->tcp_flags & TH_CWR ) ? "CWR|" : ""),flags);
    flags= strjoin((( args[4]->tcp_flags == 0 ) ? "null " : ""),flags);

    printf("%9d %8d %6d %8d --> %8s %8d %8d %s \n",
        delta/1000,
        args[1]->cs_cid  % 100000,
        args[1]->cs_pid ,
        args[2]->ip_plength - args[4]->tcp_offset,
        "",
        args[4]->tcp_seq % 10000,
        args[4]->tcp_ack % 10000,
        flags
      );
    flag=0;
    title--;
}

tcp:::receive
/ ( args[2]->ip_saddr == ADDR || ADDR == NULL )
    && nfs[args[1]->cs_cid]
/
{
      delta=timestamp-walltime;
      walltime=timestamp;
      flags="";
      flags= strjoin((( args[4]->tcp_flags & TH_FIN ) ? "FIN|" : ""),flags);
      flags= strjoin((( args[4]->tcp_flags & TH_SYN ) ? "SYN|" : ""),flags);
      flags= strjoin((( args[4]->tcp_flags & TH_RST ) ? "RST|" : ""),flags);
      flags= strjoin((( args[4]->tcp_flags & TH_PUSH ) ? "PUSH|" : ""),flags);
      flags= strjoin((( args[4]->tcp_flags & TH_ACK ) ? "ACK|" : ""),flags);
      flags= strjoin((( args[4]->tcp_flags & TH_URG ) ? "URG|" : ""),flags);
      flags= strjoin((( args[4]->tcp_flags & TH_ECE ) ? "ECE|" : ""),flags);
      flags= strjoin((( args[4]->tcp_flags & TH_CWR ) ? "CWR|" : ""),flags);
      flags= strjoin((( args[4]->tcp_flags == 0 ) ? "null " : ""),flags);
      printf("%9d %8d %6d %8s <-- %-8d %8d %8d %s \n",         delta/1000,         args[1]->cs_cid  % 100000,
        args[1]->cs_pid ,
        "",
        args[2]->ip_plength - args[4]->tcp_offset,
        args[4]->tcp_seq % 10000,
        args[4]->tcp_ack % 10000,
        flags
      );
    flag=0;
    title--;
}

Now I can run

sudo nfs_details.d 1 172.16.100.194

To get the above output.
The above output can get pretty overwhelming, so what about outputting the summaries every second?

#!/usr/sbin/dtrace -s
#pragma D option defaultargs
#pragma D option dynvarsize=64m
#pragma D option quiet
inline int TICKS=$1;
inline string ADDR=$$2;

dtrace:::BEGIN
{
       TIMER = ( TICKS != NULL ) ?  TICKS : 1 ;
       ticks = TIMER;
       TITLE = 10;
       title = 0;
       start = 1;
}

/* ***** begin initialization */
/*
    curpsinfo->pr_psargs == "/usr/lib/nfs/nfsd"
    or could have done
    execname == "nfsd"
*/
tcp:::send
/   (args[2]->ip_daddr == ADDR || ADDR == NULL )&&
    curpsinfo->pr_psargs == "/usr/lib/nfs/nfsd"
/
{
    printf("execname %s\n",execname);
    nfs[args[1]->cs_cid]=1; /* this is an NFS thread */
    @send_tot_sz[args[2]->ip_daddr] =  sum( args[2]->ip_plength - args[4]->tcp_offset);
    @send_tot_ct[args[2]->ip_daddr] =  count();
}

tcp:::receive, tcp:::send
/ ( args[2]->ip_saddr == ADDR || ADDR == NULL )
    && nfs[args[1]->cs_cid]
    && start == 1
/
{
       start =0;
       recd_small_tm_beg[args[1]->cs_cid] = 0;
       recd_small_tm_beg[args[1]->cs_cid] = 0;
       recd_small_ct[args[1]->cs_cid]=0;
       recd_small_sz[args[1]->cs_cid]=0;

       recd_big_tm_beg[args[1]->cs_cid] = 0;
       recd_big_tm_beg[args[1]->cs_cid] = 0;
       recd_big_ct[args[1]->cs_cid]=0;
       recd_big_sz[args[1]->cs_cid]=0;

       send_big_tm_beg[args[1]->cs_cid] = 0;
       send_big_tm_beg[args[1]->cs_cid] = 0;
       send_big_ct[args[1]->cs_cid]=0;
       send_big_sz[args[1]->cs_cid]=0;

       send_small_tm_beg[args[1]->cs_cid] = 0;
       send_small_tm_beg[args[1]->cs_cid] = 0;
       send_small_ct[args[1]->cs_cid]=0;
       send_small_sz[args[1]->cs_cid]=0;
}
/* ***** end initialization */

/* ***************** BEG _OUT_  big RTT  TIME ****************** */
tcp:::send
/     (args[2]->ip_daddr == ADDR || ADDR == NULL )
    && curpsinfo->pr_psargs == "/usr/lib/nfs/nfsd"
    && (args[2]->ip_plength - args[4]->tcp_offset) > 300
/
{
    send_big_unacked[args[1]->cs_cid] = 1;
    send_big_sq[args[1]->cs_cid] = args[4]->tcp_seq;

    send_big_tm_beg[args[1]->cs_cid] =
      send_big_tm_beg[args[1]->cs_cid] == 0
    ? timestamp : send_big_tm_beg[args[1]->cs_cid] ;

    send_big_tm_end[args[1]->cs_cid] = timestamp;

    send_big_sz[args[1]->cs_cid] += (args[2]->ip_plength - args[4]->tcp_offset);
    send_big_ct[args[1]->cs_cid] ++;
}
tcp:::receive
/ ( args[2]->ip_saddr == ADDR || ADDR == NULL )
    && send_big_unacked[args[1]->cs_cid] == 1
    && nfs[args[1]->cs_cid]
    && (args[2]->ip_plength - args[4]->tcp_offset)  >= 0
/
{
/* kyle
   just take out sequence check
   response seems to be lazy on last ACK , ie slower
   process that asked for data
    && args[4]->tcp_ack > send_big_sq[args[1]->cs_cid]

   if we want to use a beginning and ending sequence :
    recd_sq_beg[args[1]->cs_cid] =
       recd_sq_beg[args[1]->cs_cid] == 0
      ? args[4]->tcp_seq : recd_sq_beg[args[1]->cs_cid] ;

        printf("receive > 0 %d size %d  end %d\n",
              timestamp - send_big_tm_end[args[1]->cs_cid] ,
             (args[2]->ip_plength - args[4]->tcp_offset) ,
              timestamp - send_big_tm_beg[args[1]->cs_cid]
              );

*/
        @rtt_big_tm_beg[args[2]->ip_saddr] =  avg(timestamp - send_big_tm_beg[args[1]->cs_cid]);
        @rtt_big_tm_end[args[2]->ip_saddr] =  avg(timestamp - send_big_tm_end[args[1]->cs_cid]);
        @rtt_big_sz[args[2]->ip_saddr] =  avg(send_big_sz[args[1]->cs_cid]);
        @rtt_big_ct[args[2]->ip_saddr] =  avg(send_big_ct[args[1]->cs_cid]);
        @rtt_big_tot_ct[args[2]->ip_saddr] =  count();

        send_big_sq[args[1]->cs_cid] = 0;
        send_big_unacked[args[1]->cs_cid] = 0;
        send_big_tm_end[args[1]->cs_cid] = 0;
        send_big_tm_beg[args[1]->cs_cid] = 0;
        send_big_sz[args[1]->cs_cid] = 0;
        send_big_ct[args[1]->cs_cid] = 0;
}
tcp:::receive
/ ( args[2]->ip_saddr == ADDR || ADDR == NULL )
    && send_big_unacked[args[1]->cs_cid] == 1
    && args[4]->tcp_ack > send_big_sq[args[1]->cs_cid]
    && nfs[args[1]->cs_cid]
    && (args[2]->ip_plength - args[4]->tcp_offset)  < 0 / {         send_big_sq[args[1]->cs_cid] = 0;
        send_big_unacked[args[1]->cs_cid] = 0;
        send_big_tm_end[args[1]->cs_cid] = 0;
        send_big_tm_beg[args[1]->cs_cid] = 0;
        send_big_sz[args[1]->cs_cid] = 0;
        send_big_ct[args[1]->cs_cid] = 0;
}
 /* ***************** END  _OUT_ big RTT  TIME ****************** */

 /* ***************** BEGIN _OUT_  small RTT  TIME ****************** */
tcp:::send
/     (args[2]->ip_daddr == ADDR || ADDR == NULL )
    && curpsinfo->pr_psargs == "/usr/lib/nfs/nfsd"
    && (args[2]->ip_plength - args[4]->tcp_offset) > 0
    && (args[2]->ip_plength - args[4]->tcp_offset) <= 300 / {     send_small_unacked[args[1]->cs_cid] = 1;
    send_small_sq[args[1]->cs_cid] = args[4]->tcp_seq;

    send_small_tm_beg[args[1]->cs_cid] =
      send_small_tm_beg[args[1]->cs_cid] == 0
    ? timestamp : send_small_tm_beg[args[1]->cs_cid] ;

    send_small_tm_end[args[1]->cs_cid] = timestamp;

    send_small_sz[args[1]->cs_cid] += args[2]->ip_plength - args[4]->tcp_offset;
    send_small_ct[args[1]->cs_cid] ++;
}

/*
    && args[4]->tcp_ack > send_small_sq[args[1]->cs_cid]
*/
tcp:::receive
/ ( args[2]->ip_saddr == ADDR || ADDR == NULL )
    && send_small_unacked[args[1]->cs_cid] == 1
    && nfs[args[1]->cs_cid]
    && (args[2]->ip_plength - args[4]->tcp_offset) >   0
/
{
        @rtt_small_tm_beg[args[2]->ip_saddr] =  avg(timestamp - send_small_tm_beg[args[1]->cs_cid]);
        @rtt_small_tm_end[args[2]->ip_saddr] =  avg(timestamp - send_small_tm_end[args[1]->cs_cid]);
        @rtt_small_sz[args[2]->ip_saddr] =  avg(send_small_sz[args[1]->cs_cid]);
        @rtt_small_ct[args[2]->ip_saddr] =  avg(send_small_ct[args[1]->cs_cid]);

        send_small_sq[args[1]->cs_cid] = 0;
        send_small_unacked[args[1]->cs_cid] = 0;
        send_small_tm_end[args[1]->cs_cid] = 0;
        send_small_tm_beg[args[1]->cs_cid] = 0;
        send_small_sz[args[1]->cs_cid] =0;
        send_small_ct[args[1]->cs_cid] =0;
}
tcp:::receive
/ ( args[2]->ip_saddr == ADDR || ADDR == NULL )
    && send_small_unacked[args[1]->cs_cid] == 1
    && args[4]->tcp_ack > send_small_sq[args[1]->cs_cid]
    && nfs[args[1]->cs_cid]
    && (args[2]->ip_plength - args[4]->tcp_offset) ==   0
/
{
        send_small_sq[args[1]->cs_cid] = 0;
        send_small_unacked[args[1]->cs_cid] = 0;
        send_small_tm_end[args[1]->cs_cid] = 0;
        send_small_tm_beg[args[1]->cs_cid] = 0;
        send_small_sz[args[1]->cs_cid] =0;
        send_small_ct[args[1]->cs_cid] =0;
}
 /* ***************** END  _OUT_ small RTT  TIME ****************** */

/* ***************** START _IN_ SMALL RESPONSE TIME ****************** */
tcp:::receive
/ ( args[2]->ip_saddr == ADDR || ADDR == NULL )
    && nfs[args[1]->cs_cid]
    && (args[2]->ip_plength - args[4]->tcp_offset) >   0
    && (args[2]->ip_plength - args[4]->tcp_offset) <= 300 / {        recd_small_unacked[args[1]->cs_cid] = 1;

       recd_small_tm_beg[args[1]->cs_cid] =
          recd_small_tm_beg[args[1]->cs_cid] == 0
        ? timestamp : recd_small_tm_beg[args[1]->cs_cid] ;

       recd_small_sq_end[args[1]->cs_cid] = args[4]->tcp_seq;
       recd_small_tm_end[args[1]->cs_cid] = timestamp;

       @recd_tot_sz[args[2]->ip_saddr] = sum(args[2]->ip_plength - args[4]->tcp_offset);
       @recd_tot_ct[args[2]->ip_saddr] = count();

       recd_small_sz[args[1]->cs_cid] += args[2]->ip_plength - args[4]->tcp_offset;
       recd_small_ct[args[1]->cs_cid] ++;

}
/*
    && args[4]->tcp_ack > recd_small_sq_end[args[1]->cs_cid]
*/
tcp:::send
/      (args[2]->ip_daddr == ADDR || ADDR == NULL )
    && curpsinfo->pr_psargs == "/usr/lib/nfs/nfsd"
    && recd_small_unacked[args[1]->cs_cid] == 1
    && (args[2]->ip_plength - args[4]->tcp_offset) >   0
/
{
/*
        printf("send > 0 beg %d size %d end %d \n",
                            timestamp - recd_small_tm_beg[args[1]->cs_cid],
                           (args[2]->ip_plength - args[4]->tcp_offset) ,
                            timestamp - recd_small_tm_end[args[1]->cs_cid]
                            );
*/
        @resp_small_tm_beg[args[2]->ip_daddr] =  avg(timestamp - recd_small_tm_beg[args[1]->cs_cid]);
        @resp_small_tm_end[args[2]->ip_daddr] =  avg(timestamp - recd_small_tm_end[args[1]->cs_cid]);
        @resp_small_sz[args[2]->ip_daddr] =  avg(recd_small_sz[args[1]->cs_cid]);
        @resp_small_ct[args[2]->ip_daddr] =  avg(recd_small_ct[args[1]->cs_cid]);
             recd_small_tm_beg[args[1]->cs_cid] = 0;
             recd_small_tm_end[args[1]->cs_cid] = 0;
             recd_small_sq_end[args[1]->cs_cid] = 0;
             recd_small_ct[args[1]->cs_cid]  =0;
             recd_small_sz[args[1]->cs_cid]  =0;
             recd_small_unacked[args[1]->cs_cid] = 0;
}
/*
    && args[4]->tcp_ack > recd_small_sq_end[args[1]->cs_cid]
*/
tcp:::send
/      (args[2]->ip_daddr == ADDR || ADDR == NULL )
    && curpsinfo->pr_psargs == "/usr/lib/nfs/nfsd"
    && recd_small_unacked[args[1]->cs_cid] == 1
    && (args[2]->ip_plength - args[4]->tcp_offset) ==   0
/
{
             recd_small_tm_beg[args[1]->cs_cid] = 0;
             recd_small_tm_end[args[1]->cs_cid] = 0;
             recd_small_sq_end[args[1]->cs_cid] = 0;
             recd_small_ct[args[1]->cs_cid]  =0;
             recd_small_sz[args[1]->cs_cid]  =0;
             recd_small_unacked[args[1]->cs_cid] = 0;
}
/* ***************** end _IN_ SMALL RESPONSE TIME ****************** */
/* ****** BIG _IN_ RESP ******************* */
tcp:::receive
/ ( args[2]->ip_saddr == ADDR || ADDR == NULL )
    && nfs[args[1]->cs_cid]
    && (args[2]->ip_plength - args[4]->tcp_offset) >  300
/
{
       recd_big_unacked[args[1]->cs_cid] = 1;

       recd_big_tm_beg[args[1]->cs_cid] =
          recd_big_tm_beg[args[1]->cs_cid] == 0
        ? timestamp : recd_big_tm_beg[args[1]->cs_cid] ;

       recd_big_sq_end[args[1]->cs_cid] = args[4]->tcp_seq;
       recd_big_tm_end[args[1]->cs_cid] = timestamp;

       @recd_tot_sz[args[2]->ip_saddr] = sum(args[2]->ip_plength - args[4]->tcp_offset);
       @recd_tot_ct[args[2]->ip_saddr] = count();

       recd_big_sz[args[1]->cs_cid] += args[2]->ip_plength - args[4]->tcp_offset;
       recd_big_ct[args[1]->cs_cid] ++;

}
/*
    && args[4]->tcp_ack > recd_big_sq_end[args[1]->cs_cid]
*/
tcp:::send
/      (args[2]->ip_daddr == ADDR || ADDR == NULL )
    && curpsinfo->pr_psargs == "/usr/lib/nfs/nfsd"
    && recd_big_unacked[args[1]->cs_cid] == 1
/
{
        @resp_big_tm_beg[args[2]->ip_daddr] =  avg(timestamp - recd_big_tm_beg[args[1]->cs_cid]);
        @resp_big_tm_end[args[2]->ip_daddr] =  avg(timestamp - recd_big_tm_end[args[1]->cs_cid]);
        @resp_big_sz[args[2]->ip_daddr] =  avg(recd_big_sz[args[1]->cs_cid]);
        @resp_big_ct[args[2]->ip_daddr] =  avg(recd_big_ct[args[1]->cs_cid]);
        @resp_big_tot_ct[args[2]->ip_daddr] =  count();
             recd_big_tm_beg[args[1]->cs_cid] = 0;
             recd_big_tm_end[args[1]->cs_cid] = 0;
             recd_big_sq_end[args[1]->cs_cid] = 0;
             recd_big_ct[args[1]->cs_cid]  =0;
             recd_big_sz[args[1]->cs_cid]  =0;
             recd_big_unacked[args[1]->cs_cid] = 0;
}
/* ***************** END _IN_ RESPONSE TIME ****************** */

profile:::tick-1sec
/ ticks > 0 /
{ ticks--; }

profile:::tick-1sec
/ title == 0 /
{
        printf("%-15s %8s %8s %8s %8s %8s %8s %8s %8s %8s %8s  \n",
                                                   "client",
                                                   "out_rtt",
                                                   "in_resp",
                                                   "in_bytes",
                                                   "in_cnt",
                                                   "i_avg_sz",
                                                   "i_avg_tm",
                                                   "o_bytes_",
                                                   "out_cnt",
                                                   "o_avg_sz",
                                                   "o_avg_tm"
                                            );
        title=TITLE;
}

profile:::tick-1sec
/ ticks == 0 /
{
/*
*/

        normalize(@recd_tot_ct,TIMER);
        normalize(@send_tot_ct,TIMER);
        normalize(@recd_tot_sz,(TIMER) );
        normalize(@send_tot_sz,(TIMER) );
        normalize(@resp_small_tm_beg,1000);
        normalize(@resp_small_tm_end,1000);
        normalize(@rtt_small_tm_beg,1000);
        normalize(@rtt_small_tm_end,1000);
        normalize(@resp_big_tm_beg,1000);
        normalize(@rtt_big_tm_beg,1000);
        normalize(@resp_big_tm_end,1000);
        normalize(@rtt_big_tm_end,1000);
  /*                    1   2    3    4    5     6   7    8    9   10    */
        printa("%-15s %@8d %@8d %@8d %@8d %@8d %@8d %@8d %@8d %@8d %@8d  \n",
                                                   @rtt_small_tm_end,
                                                   @resp_small_tm_end,
                                                   @recd_tot_sz,
                                                   @recd_tot_ct,
                                                   @resp_big_sz,
                                                   @resp_big_tm_beg,
                                                   @send_tot_sz,
                                                   @rtt_big_sz,
                                                   @send_tot_ct,
                                                   @rtt_big_tm_beg
                                                   );

                                                   trunc(@rtt_big_tot_ct);
                                                   trunc(@resp_big_tot_ct);

                                                   trunc(@send_tot_sz);
                                                   trunc(@recd_tot_sz);
                                                   trunc(@send_tot_ct);
                                                   trunc(@recd_tot_ct);

                                                   trunc(@resp_small_tm_beg);
                                                   trunc(@resp_small_tm_end);
                                                   trunc(@resp_small_sz);
                                                   trunc(@resp_small_ct);
                                                   trunc(@resp_big_tm_beg);
                                                   trunc(@resp_big_tm_end);
                                                   trunc(@resp_big_sz);
                                                   trunc(@resp_big_ct);

                                                   trunc(@rtt_small_tm_beg);
                                                   trunc(@rtt_small_tm_end);
                                                   trunc(@rtt_small_sz);
                                                   trunc(@rtt_small_ct);
                                                   trunc(@rtt_big_tm_beg);
                                                   trunc(@rtt_big_tm_end);
                                                   trunc(@rtt_big_sz);
                                                   trunc(@rtt_big_ct);
        title--;
        ticks = TIMER;
}

Now if I run the above dtrace, and re-run my dd I get the following dtrace output:

client           out_rtt  in_resp in_bytes   in_cnt i_avg_sz i_avg_tm o_bytes_  out_cnt o_avg_sz o_avg_tm
172.16.100.194       764     1968     9188       13     8328     4873     1032        0        8        0

this is telling me that my
round trips were 764us
server response to incoming requests is 1968us
I had 9068 incoming bytes
I had 12 incoming packages
the average size of packages above 300 bytes was 8328
the average time to response to packets above 300 bytes was 4837us
and my dd command (in this case) reported 5.8ms or (5800us)
so I’m getting at most the dd response time for the TCP response time to the 8K packet


Uncategorized


6 − one =