Web Request Rate Analysis with R

During performance testing it's easy to find raw data relating to the response time of a web service or RPC. This information is typically recorded in log files like the server access log or in some form or another in the load-generating client logs. Response time statistics are an important operational parameter but need to be qualified with the request rate to give context to the metric. I use a simple R script generate request rate graphs from Apache JMeter output (.jtl files) but the concept can easily be extended to any format which includes timestamped entries, preferably labelled somehow to distinguish one service type from another.

The basis of the request rate calculation is calculating and inverting the inter-arrival time of requests. If the generation of requests is independent then the request generator follows a Poisson Process and inter-arrival times will follow an exponential distribution. Generally requests directed at a web site will not be entirely independent as a user will be guided by the site navigation constraints, but the approximation lends itself to modelling of the service using queueing theory. One of the simplest of such models is shown below, an M/M/1 queue, which models the queue length in a system having a single server, where arrivals are determined by a Poisson Process and job service times have an exponential distribution.

Moving on with less esoteric endevours, each request from the Jmeter client is recorded as a separate XML element an a jtl file. Request parameters are recorded as attributes on the element. The attributes we are interested in are ts (epoch timestamp) and lb (service label). The shell command below turns the jtl file into a format that R can read into a dataframe. This includes adding column headers to save us having to define these within the R script. These shell commands are the part you would change if importing data from another source.

	# Write column headers to data file
	$echo "t lt ts s lb rc rm tn dt by" >$DATAFILE
	# Extract values in quotes
	$sed -n '/^<httpSample/{s/[^"]*\("[^"]*"\)[^"]*/\1 /gp}'$JTLFILE >> $DATAFILE
	# Data file looks something like this...
	$head$DATAFILE
	t lt ts s lb rc rm tn dt by
	"319" "319" "1348598679755" "true" "service-M" "200" "OK" "Thread Group 1-1" "text" "2918"
	"2167" "2159" "1348598680583" "true" "service-J" "200" "OK" "Thread Group 1-1" "text" "2853"
	"22" "22" "1348598683251" "true" "service-A" "200" "OK" "Thread Group 1-1" "text" "6114"
	"31" "31" "1348598685752" "true" "service-M" "200" "OK" "Thread Group 1-2" "text" "2918"
	"192" "186" "1348598686284" "true" "service-J" "200" "OK" "Thread Group 1-2" "text" "2853"
	"24" "24" "1348598686977" "true" "service-A" "200" "OK" "Thread Group 1-2" "text" "6114"
	"4999" "4999" "1348598683774" "true" "service-E" "200" "OK" "Thread Group 1-1" "text" "10869"
	"190" "190" "1348598689274" "true" "service-E" "200" "OK" "Thread Group 1-1" "text" "9893"
	"9" "9" "1348598689965" "true" "service-B" "200" "OK" "Thread Group 1-1" "text" "6520"

view raw jtl2dat.sh hosted with ❤ by GitHub

Now we run the data file generated above through the R script below. The script begins by loading the data into a dataframe and sorting based on timestamp. We can't take for granted that log entries generated in a buffered multi-threaded environment will be chronologically interleaved. We then iterate over the dataframe, calculating the inter-arrival time between each request and its predecessor. This value is added as a new column v to the dataframe. We then invert and scale the inter-arrival times and plot over time to give us the overall request rate per minute. We then filter the data on service labels and perform the same exercise to get a service-specific request rate breakdown. We have used a locally weighted smoothing function, adjusting the span factor to suit our granularity requirements.

	#!/usr/bin/env Rscript
	#
	# Usage: $0 <datafile>
	#
	# Expected data file format: t lt ts s lb rc rm tn dt by
	#
	myspan = 0.1
	myargs <- commandArgs(TRUE)
	file <- myargs[1]
	d <- read.table (file, header=TRUE)
	## Order by timestamp so we can get meaningful iats
	d <- d[order(d$ts),]
	# Inter-arrival time
	v = numeric (length(d$ts))
	v[1] = 1
	for (i in 2:length(d$ts)) { v[i] = d$ts[i] - d$ts[i-1] + 1 }
	d$v <- v
	# Main Plot
	image = paste(file, ".png", sep="")
	png (image, width=960, height=480)
	tsmin = min (d$ts)
	ymax=1000*60*(1/mean(d$v)+1/sd(d$v))
	palette <- rainbow (nlevels(d$lb)+1)
	d.lo <- loess (d$v ~ d$ts, span=myspan)
	# Total
	plot ((d$ts-tsmin)/1000, 1000*60/predict(d.lo, d$ts), type="l", ylab="req/min", xlab="seconds", main="Request Rate", col=palette[1], ylim=c(0,ymax))
	legend("topright", c("total", levels(d$lb)), col=palette, lty=1, cex=0.75)
	# Labels
	pindex = 2;
	palette <- rainbow (nlevels(d$lb))
	for (label in levels(d$lb))
	{
	print (label)
	a <- subset(d, lb==label)
	v = numeric (length(a$ts))
	v[1] = 1
	for (i in 2:length(a$ts)) { v[i] = a$ts[i] - a$ts[i-1] + 1 }
	a$v <- v
	a.lo <- loess (a$v ~ a$ts, span=myspan)
	lines ((a$ts-tsmin)/1000, 1000*60/predict(a.lo, a$ts), col=palette[pindex])
	rm(a)
	rm(v)
	pindex = pindex+1
	}
	grid()
	dev.off()
	print (paste("Request rate plot written to file", image))

view raw reqrate.R hosted with ❤ by GitHub

A sample graph is shown below. For this test run we used a rate-controlled request generator with a small ramp, accounting for the initial rise and bounded oscillation for each service. Below that is a density plot of the inter-arrival time for this sample data, showing that it does indeed look exponential, as postulated by the Poisson process model.