Results from the *single-read-2* test

Adam Lyon, August 8, 2005

# Introduction

A SAM test was performed to determine the rate of file deliveries
possible on a test CAF system.

###### R Session

R is an open source statistical analysis software package that allows
for very easy analysis of data in databases and text files. I wrote a
\"notebook\" style package that allows one to use R from within
Microsoft Word. Below is the notebook providing all of the code and
results for this document.

####### Connect to R and initialize

Connect to R running locally on my laptop.

\<R0\> #connect port 6101 timeout 20

R is using work directory
/Users/adam/work/projects/cdfSamTests/single-read-2

Set up graphics

\<R1\> library(lattice)

\<R2\> trellis.par.set(col.whitebg())

\<R3\> fontsize = trellis.par.get(\"fontsize\"); fontsize\$text=16 ;
fontsize\$points=6 ; trellis.par.set(\"fontsize\", fontsize)

I have a helper function that makes putting graphics into Word easy.

\<R4\> mp

function (plotExpr, file, height = 7, width = 7, res = 72 \* 3)\
{\
bitmap(file, \"pngalpha\", height = height, width = width,\
res = res, pointsize = 10)\
r = eval(plotExpr)\
if (class(r) == \"trellis\")\
print(r)\
invisible(dev.off())\
}\
\<environment: namespace:RemoteRSOAP\>

####### Running job output

Doug\'s python script loops over getting the next file, waiting thirty
seconds to simulate processing, and then releasing the file. A log file
records the time of the get next file, the duration of the command, the
pnfs name of the file, and the time and duration of the release file
command.

Let\'s read this information into R.

\<R5\> d = read.table(\"out.log\", header=T)

\<R6\> d\[1:5,\]

job segment getDate getTime getDur fileNum\
1 2369 1 2005-08-05 17:26:41 49.421 1\
2 2369 1 2005-08-05 17:27:45 30.085 2\
3 2369 1 2005-08-05 17:28:30 1.097 3\
4 2369 1 2005-08-05 17:28:47 11.090 4\
5 2369 1 2005-08-05 17:29:13 1.082 5\
pnfs\
1
dcap://cdfdca3.fnal.gov:25159/pnfs/fnal.gov/usr/cdfen/filesets/GJ/GJ23/GJ2360/GJ2360.0/xd025f02.0260bhd0\
2
dcap://cdfdca3.fnal.gov:25159/pnfs/fnal.gov/usr/cdfen/filesets/GJ/GJ23/GJ2365/GJ2365.0/xd025f02.0580bhd0\
3
dcap://cdfdca3.fnal.gov:25159/pnfs/fnal.gov/usr/cdfen/filesets/GJ/GJ23/GJ2368/GJ2368.0/xd025f02.03b7bhd0\
4
dcap://cdfdca3.fnal.gov:25159/pnfs/fnal.gov/usr/cdfen/filesets/GJ/GJ23/GJ2377/GJ2377.0/xd02601e.0068bhd0\
5
dcap://cdfdca3.fnal.gov:25159/pnfs/fnal.gov/usr/cdfen/filesets/GJ/GJ23/GJ2383/GJ2383.0/xd026042.0145bhd0\
relDate relTime relDur\
1 2005-08-05 17:27:45 0.232\
2 2005-08-05 17:28:30 0.101\
3 2005-08-05 17:28:47 0.110\
4 2005-08-05 17:29:13 0.118\
5 2005-08-05 17:29:29 0.124

Convert dates and times into POSIX times that R can deal with\...

\<R7\> d\$getDateTime = paste(d\$getDate, d\$getTime)

\<R8\> d\$relDateTime = paste(d\$relDate, d\$relTime)

\<R9\> d\$getPTime = as.POSIXct( strptime( d\$getDateTime, \"%Y-%m-%d
%H:%M:%S\" ) )

\<R10\> d\$relPTime = as.POSIXct( strptime( d\$relDateTime, \"%Y-%m-%d
%H:%M:%S\" ) )

We can make the delivery time from the get time plus the duration

\<R11\> d\$delPTime = d\$getPTime + d\$getDur

What is the range of the test?

\<R12\> testEdges = c(min(d\$getPTime), max(d\$relPTime, na.rm=T)) ;
testEdges

\[1\] \"2005-08-05 17:26:41 CDT\" \"2005-08-06 03:01:20 CDT\"

\<R13\> testTime = diff(testEdges) ; testTime

Time difference of 9.5775 hours

\<R14\> prettyEdges = c(testEdges\[1\]-60\*60, testEdges\[2\]+60\*60)

######## Basics

How many files deliveries were attempted?

\<R15\> nrow(d)

\[1\] 2000

How many failed on the get end?

\<R16\> sum(is.na(d\$getDur))

\[1\] 0

How many failed on the release end?

\<R17\> sum(is.na(d\$relDur))

\[1\] 0

Merge job and segment numbers

\<R18\> d\$jobseg = paste(d\$job, d\$segment)

What were the jobs and segments?

\<R19\> d\$jobseg\[ is.na(d\$relDur) \]

character(0)

\<R20\> #var successfulDeliveries = nrow(d)

2000

All files were delivered!

Look up the maximum file number for each job and segment.

\<R22\> largestFNum = tapply(d\$fileNum, d\$jobseg, max)

How many did not get all 40 files?

\<R23\> length( largestFNum\[ largestFNum \< 2000 \] )

\[1\] 0

######## File delivery rate

\<R24\> fileRatePerDay = nrow(d)/(as.numeric(testTime))\*24;
fileRatePerDay

\[1\] 5011.746

In a perfect world, what should be the mean wait time?

\<R25\> filesPerSeg = nrow(d) / length(unique(d\$jobseg)) ; filesPerSeg

\[1\] 2000

Assume that every segment runs the entire length of the test. Therefore
(in minutes),

\<R26\> meanWaitTime = as.numeric(testTime)\*60 / filesPerSeg ;
meanWaitTime

\[1\] 0.287325

How many seconds per file?

\<R27\> secondsPerFile = as.numeric(testTime)\*60\*60 / nrow(d) ;
secondsPerFile

\[1\] 17.2395

######## Number of segments running

Let\'s plot how many segments were running at a given time.

A segment turns on when it does its first \"get next file\". It turns
off when it does its last release.

How many segments are there?

\<R28\> length( unique( d\$jobseg) )

\[1\] 1

So we have a record of all 1 segments. Good!

Segment starts when the first file is requested

\<R29\> segStart = data.frame( time=d\$getPTime\[d\$fileNum==1\], adj=1
)

\<R30\> segEnd = data.frame( time=d\$relPTime\[d\$fileNum==2000\],
adj=-1 )

\<R31\> segs = rbind(segStart, segEnd)

\<R32\> segs = segs\[ order(segs\$time), \]

\<R33\> segs\$count = cumsum(segs\$adj)

\<R34\> segs\[1:2,\]

time adj count\
1 2005-08-05 17:26:41 1 1\
11 2005-08-06 03:01:20 -1 0

\<R35\> mp(\
xyplot( segs\$count \~ segs\$time, type=\"s\",\
main=\"Number of running segments\",\
xlab=\"Time of day\",\
ylab=\"# running segments\",\
scales=list(x=list(tick.number=6, cex=0.6)),\
xlim=prettyEdges ),\
\"nsegs.png\", h=4, w=6 )\
#with graphics nsegs.png timeout 120

######## Number of gets and deliveries

Let\'s count up how many get file requests and deliveries there were per
hour

\<R36\> getsPerHourCuts = cut( d\$getPTime, \"hours\" )

\<R37\> delsPerHourCuts = cut( d\$delPTime, \"hours\" )

\<R38\> getsPerHour = tabulate(getsPerHourCuts)

\<R39\> delsPerHour = tabulate(delsPerHourCuts)

\<R40\> mp(\
xyplot( getsPerHour \~ as.POSIXct(levels(getsPerHourCuts)),\
main=\"Get file requests\",\
xlab=\"Time of day of request\",\
ylab=\"# per hour\", type=\"s\", xlim=prettyEdges,\
scales=list(x=list(tick.number=6, cex=0.6))\
),\
\"getsPerHour.png\", h=4, w=6\
)\
#with graphics getsPerHour.png timeout 60

\<R41\> mp(\
xyplot( delsPerHour \~ as.POSIXct(levels(delsPerHourCuts)),\
main=\"File deliveries\",\
xlab=\"Time of day of delivery\", xlim=prettyEdges,\
ylab=\"# per hour\", type=\"s\",\
scales=list(x=list(tick.number=6, cex=0.6))\
),\
\"delsPerHour.png\", h=4, w=6\
)\
#with graphics delsPerHour.png timeout 60

Let\'s just get a cumulative plot of when deliveries occurred.

\<R43\> deliveries = data.frame( time=d\$delPTime, adj=1 )

\<R44\> deliveries = deliveries\[ order(deliveries\$time), \]

\<R45\> deliveries\$count = cumsum(deliveries\$adj)

\<R46\> nrow(deliveries)

\[1\] 2000

\<R47\> deliveries\[39270:39281,\]

time adj count\
NA \<NA\> NA NA\
NA.1 \<NA\> NA NA\
NA.2 \<NA\> NA NA\
NA.3 \<NA\> NA NA\
NA.4 \<NA\> NA NA\
NA.5 \<NA\> NA NA\
NA.6 \<NA\> NA NA\
NA.7 \<NA\> NA NA\
NA.8 \<NA\> NA NA\
NA.9 \<NA\> NA NA\
NA.10 \<NA\> NA NA\
NA.11 \<NA\> NA NA

\<R48\> mp(\
xyplot( deliveries\$count \~ deliveries\$time, type=\"p\",\
main=\"Cumulative number of deliveries\",\
xlab=\"Time of day\",\
ylab=\"Cumulative number of deliveries\",\
scales=list(x=list(tick.number=6, cex=0.6)),\
xlim=prettyEdges ),\
\"ndel.png\", h=4, w=6 )\
#with graphics ndel.png timeout 120

What do the wait times look like?

\<R49\> mp(\
xyplot( getDur \~ getPTime, data=d,\
main=\"File delivery waits\",\
xlab=\"Time of day of request\", xlim=prettyEdges,\
ylab=\"Wait time (seconds)\",\
scales=list(x=list(tick.number=6, cex=0.6))\
),\
\"getWaits.png\", h=4, w=6\
)\
#with graphics getWaits.png timeout 60

\<R50\> mp(\
xyplot( getDur \~ delPTime, data=d,\
main=\"File delivery waits\",\
xlab=\"Time of day of delivery\", xlim=prettyEdges,\
ylab=\"Wait time (seconds)\",\
scales=list(x=list(tick.number=6, cex=0.6))\
),\
\"delWaits.png\", h=4, w=6\
)\
#with graphics delWaits.png timeout 60

These plots make the outliers really stand out and hard to see the mean
wait times. Let\'s try to plot those\...

\<R51\> mp(\
bwplot( getsPerHourCuts \~ getDur, data=d,\
main=\"File delivery waits\",\
xlab=\"Wait time (seconds)\", ylab=\"Time of day of request\"\
),\
\"waitsPerHourBw.png\", h=4, w=6\
)\
#with graphics waitsPerHourBw.png timeout 60

Again, the outliers dominate the plot. Let\'s just plot medians and how
many are over an hour\...

\<R52\> waitMedians = tapply(d\$getDur, getsPerHourCuts, median)

\<R53\> waitMeans = tapply(d\$getDur, getsPerHourCuts, mean)

\<R54\> nOverHour = tapply(d\$getDur \>= 4, getsPerHourCuts, sum)

\<R55\> percOverHour = nOverHour / getsPerHour \* 100

\<R56\> nOverHalfHour = tapply(d\$getDur \>= 3, getsPerHourCuts, sum)

\<R57\> percOverHalfHour = nOverHalfHour / getsPerHour \* 100

\<R58\> nUnderMinute = tapply(d\$getDur \< 1, getsPerHourCuts, sum)

\<R59\> percUnderMinute = nUnderMinute / getsPerHour \* 100

Let\'s plot these things

\<R60\> mp(\
xyplot( waitMedians \~ as.POSIXct(names(waitMedians)), type=\"s\",\
main=\"Median wait time\", xlab=\"Time of day of request\",\
ylab=\"Median wait time (seconds)\",\
ylim=c(0, max(waitMeans)\*1.2),\
scales=list(x=list(tick.number=6, cex=0.6))\
),\
\"medians.png\", h=4, w=6)\
#with graphics medians.png timeout 60

\<R61\> mp(\
xyplot( waitMeans \~ as.POSIXct(names(waitMeans)), type=\"s\",\
main=\"Mean wait time\", xlab=\"Time of day of request\",\
ylab=\"Mean wait time (minutes)\",\
ylim=c(0, max(waitMeans)\*1.2),\
scales=list(x=list(tick.number=6, cex=0.6))\
),\
\"means.png\", h=4, w=6)\
#with graphics means.png timeout 60

\<R62\> mp(\
xyplot( percOverHour \~ as.POSIXct(names(percOverHour)), type=\"s\",\
main=\"Percent long wait times\", xlab=\"Time of day of request\",\
ylab=\"% with wait time \>= 4 seconds\",\
scales=list(x=list(tick.number=6, cex=0.6))\
),\
\"overHour.png\", h=4, w=6)\
#with graphics overHour.png timeout 60

\<R63\> mp(\
xyplot( percOverHalfHour \~ as.POSIXct(names(percOverHalfHour)),
type=\"s\",\
main=\"Percent long wait times\", xlab=\"Time of day of request\",\
ylab=\"% with wait time \>= 3 seconds\",\
scales=list(x=list(tick.number=6, cex=0.6))\
),\
\"overHalfHour.png\", h=4, w=6)\
#with graphics overHalfHour.png timeout 60

Look for short wait times.

\<R64\> mp(\
xyplot( percUnderMinute \~ as.POSIXct(names(percUnderMinute)),
type=\"s\",\
main=\"Percent short wait times\", xlab=\"Time of day of request\",\
ylab=\"% with wait time \< 1 second\",\
scales=list(tick.number=6, cex=0.6)\
),\
\"underMinute.png\", h=4, w=6)\
#with graphics underMinute.png timeout 60

######## Look at number of open requests

Let\'s look at the number of instantaneous requests that are open at any
given time.

Get next file requests\...

\<R65\> gnf = data.frame( time=d\$getPTime, adj=1 )

File deliveries (request fulfilled)

\<R66\> gnc = data.frame( time=d\$delPTime, adj=-1 )

Join them,

\<R67\> gn = rbind(gnf, gnc)

Sort by time,

\<R68\> gn = gn\[ order(gn\$time), \]

Do a running count of \# of unfulfilled get next file requests

\<R69\> gn\$count = cumsum(gn\$adj)

\<R70\> gn\[1:10,\]

time adj count\
1 2005-08-05 17:26:41 1 1\
11000 2005-08-05 17:27:30 -1 0\
2 2005-08-05 17:27:45 1 1\
2100 2005-08-05 17:28:15 -1 0\
3 2005-08-05 17:28:30 1 1\
3100 2005-08-05 17:28:31 -1 0\
4 2005-08-05 17:28:47 1 1\
4100 2005-08-05 17:28:58 -1 0\
5 2005-08-05 17:29:13 1 1\
5100 2005-08-05 17:29:14 -1 0

\<R71\> summary(gn\$count)

Min. 1st Qu. Median Mean 3rd Qu. Max.\
0.0 0.0 0.5 0.5 1.0 1.0

Plot it\...

\<R72\> mp(\
xyplot( gn\$count \~ gn\$time, type=\"l\",\
main=\"Pending get next file requests\",\
xlab=\"Time of day\",\
ylab=\"Instantaneous \# of unfulfilled requests\",\
scales=list(x=list(tick.number=6, cex=0.6)),\
xlim=prettyEdges, pex=0.1 ),\
\"unfulfilled.png\", h=4, w=6 )\
#with graphics unfulfilled.png timeout 240