Commit 0b2ef13a authored by Mike Hibler's avatar Mike Hibler

More tweaks to client-side stats to get a more accurate picture of what

is happening.  Also add a simple perl script to do a little interpretation
of the output stats.
parent 01cb06e9
......@@ -121,6 +121,10 @@ ChunkBuffer_t *ChunkBuffer; /* The cache */
int *ChunkRequestList; /* Randomized chunk request order */
int TotalChunkCount; /* Total number of chunks in file */
#ifdef NEVENTS
int blocksrecv, goodblocksrecv;
#endif
/* XXX imageunzip.c */
extern long long totaledata, totalrdata, totalddata;
extern unsigned long decompblocks, writeridles;
......@@ -162,9 +166,9 @@ usage()
exit(1);
}
void (*DiskIdleCallback)();
void (*DiskStatusCallback)();
static void
WriterIdleCallback(int isidle)
WriterStatusCallback(int isbusy)
{
uint32_t hi, lo;
......@@ -175,7 +179,7 @@ WriterIdleCallback(int isidle)
hi = (totalrdata >> 32);
lo = totalrdata;
}
CLEVENT(1, EV_CLIWRSTATUS, isidle, hi, lo, 0);
CLEVENT((isbusy < 2) ? 1 : 3, EV_CLIWRSTATUS, isbusy, hi, lo, 0);
}
int
......@@ -451,14 +455,14 @@ main(int argc, char **argv)
ClientTraceInit(traceprefix);
TraceStart(tracing);
if (!nothreads)
DiskIdleCallback = WriterIdleCallback;
DiskStatusCallback = WriterStatusCallback;
}
PlayFrisbee();
if (tracing) {
TraceStop();
TraceDump(0);
TraceDump(0, tracing);
}
ImageUnzipQuit();
......@@ -588,7 +592,7 @@ ClientRecvThread(void *arg)
CLEVENT(BackOff ? 1 : (p->msg.block.block==0 ? 3 : 4),
EV_CLIGOTPKT, pstamp.tv_sec, pstamp.tv_usec,
0, 0);
goodblocksrecv, blocksrecv);
#ifdef NEVENTS
needstamp = 1;
#endif
......@@ -990,13 +994,16 @@ GotBlock(Packet_t *p)
static int lastnoroomchunk = -1, lastnoroomblocks, inprogress;
int nfull = 0, nfill = 0;
#ifdef NEVENTS
blocksrecv++;
#endif
#ifndef OLD_SCHOOL
/*
* If we have already processed this chunk, bail now.
*/
if (Chunks[chunk].done) {
assert(Chunks[chunk].seen);
CLEVENT(3, EV_CLIDUPCHUNK, chunk, block, 0, 0);
CLEVENT((block==0)? 3 : 4, EV_CLIDUPCHUNK, chunk, block, 0, 0);
DOSTAT(dupchunk++);
if (debug > 2)
log("Duplicate chunk %d data ignored!", chunk);
......@@ -1054,8 +1061,14 @@ GotBlock(Packet_t *p)
assert(Chunks[dchunk].done == 0);
assert(Chunks[dchunk].seen == 1);
#ifdef NEVENTS
{
int dblocks = BlockMapIsAlloc(&ChunkBuffer[dubious].blockmap, 0, CHUNKSIZE);
goodblocksrecv -= dblocks;
CLEVENT(1, EV_CLIREUSE, chunk, block,
dchunk, 0);
dblocks, dchunk);
}
#endif
Chunks[dchunk].seen = 0;
Chunks[dchunk].lastreq = 0;
lastnoroomchunk = -1;
......@@ -1125,7 +1138,8 @@ GotBlock(Packet_t *p)
bzero(&ChunkBuffer[i].blockmap,
sizeof(ChunkBuffer[i].blockmap));
inprogress++;
CLEVENT(1, EV_CLISCHUNK, chunk, block, inprogress, 0);
CLEVENT(1, EV_CLISCHUNK, chunk, block, inprogress,
goodblocksrecv+1);
}
assert(Chunks[chunk].seen);
......@@ -1144,8 +1158,9 @@ GotBlock(Packet_t *p)
}
ChunkBuffer[i].blockcount--;
memcpy(ChunkBuffer[i].blocks[block].data, p->msg.block.buf, BLOCKSIZE);
#ifdef NEVENTS
goodblocksrecv++;
/*
* If we switched chunks before completing the previous, make a note.
*/
......@@ -1173,7 +1188,8 @@ GotBlock(Packet_t *p)
assert(ChunkBuffer[i].thischunk == chunk);
inprogress--;
CLEVENT(1, EV_CLIECHUNK, chunk, block, inprogress, 0);
CLEVENT(1, EV_CLIECHUNK, chunk, block, inprogress,
goodblocksrecv);
if (debug)
log("Releasing chunk %d to main thread", chunk);
ChunkBuffer[i].state = CHUNK_FULL;
......
......@@ -973,7 +973,7 @@ main(int argc, char **argv)
if (tracing) {
TraceStop();
TraceDump(1);
TraceDump(1, tracing);
}
subtime(&LastReq, &LastReq, &FirstReq);
......
#!/usr/bin/perl
#
# EMULAB-COPYRIGHT
# Copyright (c) 2000-2009 University of Utah and the Flux Group.
# All rights reserved.
#
use Getopt::Std;
sub usage()
{
exit(1);
}
my $optlist = "pi:cT:j";
my $plotem = 0;
my $plotinterval = 500000; # us between data points
my $nextplot = -1;
my ($netfd, $dcfd, $diskfd);
my $cumulative = 0;
my $dojpeg = 0;
my $ptitle;
my $isclient;
my $netstart;
my ($gotevents, $totevents, $starttime, $tracelevel);
my $laststamp;
my $lineno = 0;
my ($c_blocks, $c_blocksize);
my ($c_firstrecv, $c_lastrecv, $c_recvbytes);
my ($c_firstdecomp, $c_lastdecomp, $c_decompbytes);
my ($c_firstwrite, $c_lastwrite, $c_writebytes);
my ($c_prevstamp, $c_prevrbytes, $c_prevdbytes, $c_prevwbytes);
#
# Parse command arguments.
#
%options = ();
if (! getopts($optlist, \%options)) {
usage();
}
if (defined($options{"c"})) {
$cumulative = 1;
$plotinterval = 100000;
}
if (defined($options{"h"})) {
usage();
}
if (defined($options{"i"})) {
$plotinterval = int($options{"i"});
}
if (defined($options{"j"})) {
$dojpeg = 1;
}
if (defined($options{"p"})) {
$plotem = 1;
}
if (defined($options{"T"})) {
$ptitle = $options{"T"};
}
while (@ARGV) {
my $file = shift @ARGV;
processfile($file);
}
#
# Round up a time in seconds to the next plot interval value.
#
sub
plotroundup($)
{
my $val = shift;
$val = int($val * 1000000) + $plotinterval;
$val = int($val / $plotinterval) * $plotinterval;
return $val / 1000000.0;
}
sub
processfile($)
{
my ($file) = @_;
my ($netfile, $dcfile, $diskfile);
if (!open(FD, "$file")) {
printf STDERR "$file: $!\n";
return 1;
}
if ($plotem) {
$netfile = "$ptitle-net.data";
$dcfile = "$ptitle-dcomp.data";
$diskfile = "$ptitle-disk.data";
if (!open($netfd, ">$netfile") || !open($dcfd, ">$dcfile") ||
!open($diskfd, ">$diskfile")) {
printf STDERR "WARNING: can't open a plot file, not generating\n";
$plotem = 0;
} else {
$nextplot = 0;
}
}
$lineno = 0;
while (<FD>) {
chomp;
$lineno++;
# header
if (/(\d+) of (\d+) events, start=(\d+\.\d+), level=(\d+):/) {
if (defined($gotevents)) {
print STDERR "$lineno: two event lines; tracefile has mulitple runs?\n";
exit(1);
}
$gotevents = $1;
$totevents = $2;
$starttime = $3;
$tracelevel = $4;
if ($gotevents != $totevents) {
print STDERR "$lineno: WARNING: only $gotevents of $totevents events recorded; all bets off!\n";
}
next;
}
# client event record
if (/\s+\+(\d+\.\d+): C: (\d+\.\d+\.\d+\.\d+): (.*)/) {
$laststamp = $1;
processclient($1, $2, $3);
next;
}
# server event record
if (/\s+\+(\d+\.\d+): S: (.*)/) {
$laststamp = $1;
processserver($1, $2);
next;
}
print STDERR "Record in unrecognized format:\n $_\n";
}
finishclient($laststamp);
finishserver($laststamp);
close(FD);
if ($plotem) {
#
# Round end of net/decompress activity up to interval boundaries
# so we can show them on the graph
#
my $nstart = plotroundup($c_firstrecv);
my $nstop = plotroundup($c_lastrecv);
my $dstart = plotroundup($c_firstdecomp);
my $dstop = plotroundup($c_lastdecomp);
my $wstart = plotroundup($c_firstwrite);
my $wstop = plotroundup($c_lastwrite);
my $gnpfile = "$ptitle.gnp";
if (!open(PD, ">$gnpfile")) {
printf STDERR "$gnpfile: WARNING: cannot open ($!), not generating\n";
} else {
# XXX
my $ylim = $cumulative ? 40 : 100;
if ($dojpeg) {
print PD
"set terminal jpeg medium\n",
"set output '$ptitle.jpg'\n";
} else {
print PD
"set terminal postscript color\n",
"set output '$ptitle.ps'\n";
}
print PD
"set yrange [0:$ylim]\n",
"set xlabel 'Elapsed time (sec)'\n",
"set ylabel 'Throughput (MB/sec)'\n",
"set key top left\n",
"set title '$ptitle'\n",
"set arrow from $nstart, graph 0 to $nstart, graph 1 nohead lt 1\n",
"set arrow from $nstop, graph 0 to $nstop, graph 1 nohead lt 1\n",
"set arrow from $dstart, graph 0 to $dstart, graph 1 nohead lt 2\n",
"set arrow from $dstop, graph 0 to $dstop, graph 1 nohead lt 2\n",
"set arrow from $wstart, graph 0 to $wstart, graph 1 nohead lt 3\n",
"set arrow from $wstop, graph 0 to $wstop, graph 1 nohead lt 3\n",
"plot '$netfile' title 'net read' with lines, ",
"'$dcfile' title 'decompress' with lines, ",
"'$diskfile' title 'disk write' with lines\n";
close(PD);
}
close($netfd);
close($dcfd);
close($diskfd);
}
}
sub
processclient($$$)
{
my ($stamp, $ip, $msg) = @_;
if (!defined($ptitle)) {
$ptitle = $ip;
}
if ($nextplot >= 0) {
while (($stamp * 1000000) > $nextplot) {
plotclient($nextplot);
$nextplot += $plotinterval;
}
}
if ($msg =~ /^got JOIN reply, blocks=(\d+), blocksize=(\d+)/) {
$c_blocks = $1;
$c_blocksize = $2;
}
if ($msg =~ /^send REQUEST, (\d+)\[(\d+)-(\d+)\]/) {
;
}
if ($msg =~ /^got block, wait=(\d+\.\d+), (\d+) good blocks recv \((\d+) total\)/) {
if ($tracelevel >= 4) {
$c_firstrecv = $stamp
if (!defined($c_firstrecv));
$c_lastrecv = $stamp;
}
$c_recvbytes = $2 * $c_blocksize;
}
if ($msg =~ /^start chunk (\d+), block (\d+), (\d+) chunks in progress \(goodblks=(\d+)\)/) {
if ($tracelevel < 4) {
$c_firstrecv = $stamp
if (!defined($c_firstrecv));
$c_lastrecv = $stamp;
}
$c_recvbytes = $4 * $c_blocksize;
}
if ($msg =~ /^end chunk (\d+), block (\d+), (\d+) chunks in progress \(goodblks=(\d+)\)/) {
$c_recvbytes = $4 * $c_blocksize;
}
if ($msg =~ /^decompressing chunk (\d+), idle=(\d+), \(dblock=(\d+), widle=(\d+)\)/) {
$c_firstdecomp = $stamp
if (!defined($c_firstdecomp));
}
if ($msg =~ /^chunk (\d+) decompressed, (\d+) left, \(dblock=(\d+), widle=(\d+)\)/) {
$c_lastdecomp = $stamp;
}
if ($msg =~ /^decompressed (\d+) bytes total/) {
$c_decompbytes = $1;
}
if ($msg =~ /^writer STARTED, (\d+) bytes written/) {
$c_firstwrite = $stamp
if (!defined($c_firstwrite));
$c_lastwrite = $stamp;
$c_writebytes = $1;
}
if ($msg =~ /^writer RUNNING, (\d+) bytes written/) {
$c_lastwrite = $stamp;
$c_writebytes = $1;
}
if ($msg =~ /^writer IDLE, (\d+) bytes written/) {
$c_lastwrite = $stamp;
$c_writebytes = $1;
}
}
sub
nz($)
{
my ($val) = @_;
return ($val == 0 ? 1 : $val);
}
sub
plotclient($)
{
my ($stamp) = @_;
my ($rbytes, $dbytes, $wbytes, $ilen);
if ($cumulative) {
$rbytes = $c_recvbytes;
$dbytes = $c_decompbytes;
$wbytes = $c_writebytes;
$ilen = $stamp / 1000000;
} else {
$rbytes = $c_recvbytes - $c_prevrbytes;
$dbytes = $c_decompbytes - $c_prevdbytes;
$wbytes = $c_writebytes - $c_prevwbytes;
$ilen = $plotinterval / 1000000;
}
$c_prevrbytes = $c_recvbytes;
$c_prevdbytes = $c_decompbytes;
$c_prevwbytes = $c_writebytes;
printf({$netfd} "%.3f: %.6f\n",
$stamp / 1000000, $rbytes / nz($ilen) / 1000000);
printf({$dcfd} "%.3f: %.6f\n",
$stamp / 1000000, $dbytes / nz($ilen) / 1000000);
printf({$diskfd} "%.3f: %.6f\n",
$stamp / 1000000, $wbytes / nz($ilen) / 1000000);
}
sub
finishclient($)
{
my ($stamp) = @_;
my $etime;
if ($nextplot >= 0) {
while (($stamp * 1000000) > $nextplot) {
plotclient($nextplot);
$nextplot += $plotinterval;
}
}
$etime = $c_lastrecv - $c_firstrecv;
my $rbytes = $c_blocks * $c_blocksize;
printf("Receive: %.2f MB/sec: %d bytes (%d %dK blocks) in %.3f sec (%.3f to %.3f)\n",
$rbytes / nz($etime) / 1000000.0,
$rbytes, $c_blocks, $c_blocksize/1024,
$etime, $c_firstrecv, $c_lastrecv);
$etime = $c_lastdecomp - $c_firstdecomp;
printf("Decompress: %.2f MB/sec: %d->%d bytes in %.3f sec (%.3f to %.3f)\n",
$c_decompbytes / nz($etime) / 1000000.0,
$rbytes, $c_decompbytes, $etime, $c_firstdecomp, $c_lastdecomp);
$etime = $c_lastwrite - $c_firstwrite;
printf("Write: %.2f MB/sec: %d bytes in %.3f sec (%.3f to %.3f)\n",
$c_writebytes / nz($etime) / 1000000.0,
$c_writebytes, $etime, $c_firstwrite, $c_lastwrite);
}
sub
processserver($$)
{
my ($stamp, $msg) = @_;
my $clientip = undef;
if ($msg =~ /(\d+\.\d+\.\d+\.\d+): (.*)/) {
$clientip = $1;
$msg = $2;
}
}
sub
finishserver($)
{
my ($stamp) = @_;
}
exit(0);
......@@ -98,7 +98,7 @@ TraceStop(void)
}
void
TraceDump(int serverrel)
TraceDump(int serverrel, int level)
{
struct event *ptr;
int done = 0;
......@@ -112,10 +112,10 @@ TraceDump(int serverrel)
if (!done) {
done = 1;
fprintf(fd, "%d of %d events, "
"start: %ld.%03ld, level: %d:\n",
"start=%ld.%03ld, level=%d:\n",
evcount > NEVENTS ? NEVENTS : evcount,
evcount, (long)startt.tv_sec,
startt.tv_usec/1000, oevlogging);
startt.tv_usec/1000, level);
/*
* Make all event stamps relative to the
* first event received. This is specifically
......@@ -284,10 +284,10 @@ TraceDump(int serverrel)
break;
case EV_CLIREUSE:
fprintf(fd, "%s: block %lu[%lu], displaces "
"dubious chunk %lu from chunk buffer\n",
"%lu blocks of dubious chunk %lu from chunk buffer\n",
inet_ntoa(ptr->srcip),
ptr->args[0], ptr->args[1],
ptr->args[2]);
ptr->args[2], ptr->args[3]);
break;
case EV_CLIDUBPROMO:
fprintf(fd, "%s: block %lu[%lu], no longer "
......@@ -313,17 +313,17 @@ TraceDump(int serverrel)
break;
case EV_CLISCHUNK:
fprintf(fd, "%s: start chunk %lu, block %lu, "
"%lu chunks in progress\n",
"%lu chunks in progress (goodblks=%lu)\n",
inet_ntoa(ptr->srcip),
ptr->args[0], ptr->args[1],
ptr->args[2]);
ptr->args[2], ptr->args[3]);
break;
case EV_CLIECHUNK:
fprintf(fd, "%s: end chunk %lu, block %lu, "
"%lu chunks in progress\n",
"%lu chunks in progress (goodblks=%lu)\n",
inet_ntoa(ptr->srcip),
ptr->args[0], ptr->args[1],
ptr->args[2]);
ptr->args[2], ptr->args[3]);
break;
case EV_CLILCHUNK:
fprintf(fd, "%s: switched from incomplete "
......@@ -408,26 +408,39 @@ TraceDump(int serverrel)
inet_ntoa(ptr->srcip));
break;
case EV_CLIWRSTATUS:
fprintf(fd, "%s: writer %s",
inet_ntoa(ptr->srcip),
ptr->args[0] ? "IDLE" : "STARTED");
if (ptr->args[0]) {
unsigned long long bytes;
bytes = (unsigned long long)ptr->args[1] << 32;
bytes |= ptr->args[2];
{
unsigned long long bytes;
char *str = "??";
fprintf(fd, ", %llu bytes written",
bytes);
switch (ptr->args[0]) {
case 0:
str = "IDLE";
break;
case 1:
str = "STARTED";
break;
case 2:
str = "RUNNING";
break;
}
fprintf(fd, "\n");
fprintf(fd, "%s: writer %s",
inet_ntoa(ptr->srcip), str);
bytes = (unsigned long long)ptr->args[1] << 32;
bytes |= ptr->args[2];
fprintf(fd, ", %llu bytes written\n",
bytes);
break;
}
case EV_CLIGOTPKT:
stamp.tv_sec = ptr->args[0];
stamp.tv_usec = ptr->args[1];
timersub(&ptr->tstamp, &stamp, &stamp);
fprintf(fd, "%s: got block, wait=%03ld.%03ld\n",
fprintf(fd, "%s: got block, wait=%03ld.%03ld"
", %lu good blocks recv (%lu total)\n",
inet_ntoa(ptr->srcip),
stamp.tv_sec, stamp.tv_usec/1000);
stamp.tv_sec, stamp.tv_usec/1000,
ptr->args[2], ptr->args[3]);
break;
case EV_CLIRTIMO:
stamp.tv_sec = ptr->args[0];
......
......@@ -105,7 +105,7 @@ extern void ClientTraceReinit(char *file);
extern void ServerTraceInit(char *file);
extern void TraceStart(int level);
extern void TraceStop(void);
extern void TraceDump(int mkrel);
extern void TraceDump(int mkrel, int level);
#else
#define EVENT(l, e, ip, a1, a2, a3, a4)
#define CLEVENT(l, e, a1, a2, a3, a4)
......@@ -114,5 +114,5 @@ extern void TraceDump(int mkrel);
#define ServerTraceInit(file)
#define TraceStart(level)
#define TraceStop()
#define TraceDump(mkrel)
#define TraceDump(mkrel, level)
#endif
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment