Unix script to calculate response time from log file, start and end on separate lines

My unix scripting got more complex this week. I wanted to get the response times from the log file. The log file writes a time stamped line out at the start of the transaction and a separate times stamped line at the end of the transaction. Similar to the format below but with other junk on lines in between as well as intermixing of threads:

2012-09-28 13:08:31,243 INFO [pool-2-thread-9]: XXFilterApiCall — start
2012-09-28 13:08:31,968 INFO [pool-2-thread-9]: XXFilterApiCall — end
2012-09-28 13:08:39,805 INFO [pool-2-thread-2]: XXFilterApiCall — start
2012-09-28 13:08:40,499 INFO [pool-2-thread-2]: XXFilterApiCall — end
2012-09-28 13:08:44,984 INFO [pool-2-thread-5]: XXFilterApiCall — start
2012-09-28 13:08:45,698 INFO [pool-2-thread-5]: XXFilterApiCall — end

This is how I did it..

I needed to list the contents of the log cat mylog.log
Pull out the lines of interest using grep apiuser | grep XXFilterApiCall
Take the second column and convert of milliseconds and print out other columns {split($2,Arr,":|,"); print Ar[1]*3600000+Arr[2]*60000+Arr[3]*1000+Arr[4],$4,$8}
Sort into time the new second and first columns we are calculating results fit the correct thread
Next load those results into an awk array awk '{time[NR] = $1;thread[NR] = $2;marker[NR] = $3}
Loop through even numbers of the array so that you can get the start time from the preceding element and calculate response time, max etc END {for (i=2; i <= length(time); i=i+2) {rt=time[i]-time[i-1];sum+=rt;if (rtmax) max=rt;print thread[i],marker[i],rt}
Finally print it all out print "SLA :",sla*2/length(time); print "Avg: ",sum/(length(time)/2); print "Max: ",max; print "Count: ",(length(time)/2)}'

So you should get output similar to
SLA : 0.06
Avg: 234.567
Max: 789.432
Count: 123

The code will not work if the time stamp crosses midnight and there must be a complete entry for every transaction so good for a performance test where transaction complete but not so great if you take a snapshot of a production log.

Here is the whole command

cat mylog.log | grep apiuser | grep XXFilterApiCall | \awk '{split($2,Arr,":|,"); print Ar[1]*3600000+Arr[2]*60000+Arr[3]*1000+Arr[4],$4,$8}' | sort -k2,2 -k1,1n | \awk '{time[NR] = $1;thread[NR] = $2;marker[NR] = $3} END {for (i=2; i <= length(time); i=i+2) {rt=time[i]-time[i-1];sum+=rt;if (rtmax) max=rt;print thread[i],marker[i],rt} print "SLA :",sla*2/length(time); print "Avg: ",sum/(length(time)/2); print "Max: ",max; print "Count: ",(length(time)/2)}'


Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s