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
Oracle L
Trackbacks
Comments