Results from the *read-15-2* test

Adam Lyon, August 12, 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/read-15-2

Set up graphics

\<R1\> library(lattice)

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

\<R2\> 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.

\<R3\> 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 2373 1 2005-08-11 23:24:40 230.222 1\
2 2373 1 2005-08-11 23:28:45 469.180 2\
3 2373 1 2005-08-11 23:36:49 99.157 3\
4 2373 1 2005-08-11 23:38:44 1299.454 4\
5 2373 1 2005-08-12 00:00:38 260.169 5\
pnfs\
1
dcap://cdfdca3.fnal.gov:25163/pnfs/fnal.gov/usr/cdfen/filesets/GJ/GJ26/GJ2657/GJ2657.0/xd0260f7.0350bhd0\
2
dcap://cdfdca3.fnal.gov:25163/pnfs/fnal.gov/usr/cdfen/filesets/GJ/GJ27/GJ2717/GJ2717.0/xd02610e.0055bhd0\
3
dcap://cdfdca3.fnal.gov:25163/pnfs/fnal.gov/usr/cdfen/filesets/GJ/GJ27/GJ2773/GJ2773.0/xd0260aa.00f0bhd0\
4
dcap://cdfdca3.fnal.gov:25163/pnfs/fnal.gov/usr/cdfen/filesets/GJ/GJ22/GJ2270/GJ2270.0/xd025a3f.0062bhd0\
5
dcap://cdfdca3.fnal.gov:25163/pnfs/fnal.gov/usr/cdfen/filesets/GJ/GJ22/GJ2270/GJ2270.0/xd025b54.03ebbhd0\
relDate relTime relDur\
1 2005-08-11 23:28:45 0.196\
2 2005-08-11 23:36:49 0.078\
3 2005-08-11 23:38:44 0.124\
4 2005-08-12 00:00:38 0.126\
5 2005-08-12 00:05:13 0.093

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

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

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

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

\<R7\> 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

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

What is the range of the test?

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

\[1\] \"2005-08-11 22:54:05 CDT\" \"2005-08-12 08:55:43 CDT\"

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

Time difference of 10.02722 hours

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

######## Basics

How many files deliveries were attempted?

\<R12\> nrow(d)

\[1\] 39347

How many failed on the get end?

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

\[1\] 0

How many failed on the release end?

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

\[1\] 0

Merge job and segment numbers

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

What were the jobs and segments?

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

character(0)

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

39347

How come this isn\'t 40,000?

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

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

How many did not get all 40 files?

\<R19\> length( largestFNum\[ largestFNum \< 40 \] )

\[1\] 195

Hmmm.

\<R20\> notDone = largestFNum\[ largestFNum \< 40 \]

\<R21\> notDone\[1:3\]

2373 4 2373 46 2373 47\
39 35 21

Will have to look these up!

######## File delivery rate

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

\[1\] 94176.43

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

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

\[1\] 39.347

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

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

\[1\] 15.29045

How many seconds per file?

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

\[1\] 0.917427

######## 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?

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

\[1\] 1000

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

Segment starts when the first file is requested

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

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

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

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

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

\<R32\> segs\[1:10,\]

time adj count\
19 2005-08-11 22:54:05 1 1\
679 2005-08-11 22:54:52 1 2\
16 2005-08-11 22:55:00 1 3\
59 2005-08-11 22:55:02 1 4\
39 2005-08-11 22:55:03 1 5\
899 2005-08-11 22:55:04 1 6\
236 2005-08-11 22:55:12 1 7\
939 2005-08-11 22:55:12 1 8\
676 2005-08-11 22:55:25 1 9\
896 2005-08-11 22:55:30 1 10

\<R33\> 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

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

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

\<R36\> getsPerHour = tabulate(getsPerHourCuts)

\<R37\> delsPerHour = tabulate(delsPerHourCuts)

\<R38\> 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

\<R39\> 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.

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

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

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

\<R43\> nrow(deliveries)

\[1\] 39347

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

time adj count\
33321 2005-08-12 08:53:09 1 39270\
31695 2005-08-12 08:53:11 1 39271\
33212 2005-08-12 08:53:13 1 39272\
31039 2005-08-12 08:53:15 1 39273\
32554 2005-08-12 08:53:15 1 39274\
29319 2005-08-12 08:53:16 1 39275\
35612 2005-08-12 08:53:18 1 39276\
28534 2005-08-12 08:53:19 1 39277\
35498 2005-08-12 08:53:20 1 39278\
30264 2005-08-12 08:53:21 1 39279\
30147 2005-08-12 08:53:21 1 39280\
32445 2005-08-12 08:53:22 1 39281

\<R45\> 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?

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

\<R47\> mp(\
xyplot( getDur/60/60 \~ delPTime, data=d,\
main=\"File delivery waits\",\
xlab=\"Time of day of delivery\", xlim=prettyEdges,\
ylab=\"Wait time (hours)\",\
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\...

\<R48\> mp(\
bwplot( getsPerHourCuts \~ getDur/60/60, data=d,\
main=\"File delivery waits\",\
xlab=\"Wait time (hours)\", 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\...

\<R49\> waitMedians = tapply(d\$getDur/60, getsPerHourCuts, median)

\<R50\> waitMeans = tapply(d\$getDur/60, getsPerHourCuts, mean)

\<R51\> nOverHour = tapply(d\$getDur/60/60 \>= 1, getsPerHourCuts, sum)

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

\<R53\> nOverHalfHour = tapply(d\$getDur/60/60 \>= 0.5, getsPerHourCuts,
sum)

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

\<R55\> nUnderMinute = tapply(d\$getDur/60 \< 1, getsPerHourCuts, sum)

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

Let\'s plot these things

\<R57\> mp(\
xyplot( waitMedians \~ as.POSIXct(names(waitMedians)), type=\"s\",\
main=\"Median wait time\", xlab=\"Time of day of request\",\
ylab=\"Median wait time (minutes)\",\
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

\<R58\> 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

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

\<R60\> mp(\
xyplot( percOverHalfHour \~ as.POSIXct(names(percOverHalfHour)),
type=\"s\",\
main=\"Percent long wait times\", xlab=\"Time of day of request\",\
ylab=\"% with wait time \>= 30 Minutes\",\
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.

\<R61\> 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 Minute\",\
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\...

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

File deliveries (request fulfilled)

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

Join them,

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

Sort by time,

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

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

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

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

time adj count\
718 2005-08-11 22:54:05 1 1\
26770 2005-08-11 22:54:52 1 2\
598 2005-08-11 22:55:00 1 3\
2307 2005-08-11 22:55:02 1 4\
1512 2005-08-11 22:55:03 1 5\
35323 2005-08-11 22:55:04 1 6\
9288 2005-08-11 22:55:12 1 7\
36883 2005-08-11 22:55:12 1 8\
26652 2005-08-11 22:55:25 1 9\
35203 2005-08-11 22:55:30 1 10

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

Min. 1st Qu. Median Mean 3rd Qu. Max.\
0 795 947 835 957 975

Plot it\...

\<R69\> mp(\
xyplot( gn\$count \~ gn\$time, type=\"p\",\
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

I think this just shows the affect of the request wait time being longer
than the request rate.