Detailed response times with TrafficScript

Response time is an important metric for any service. According to recent research, users are likely to abandon a website if it takes longer than four seconds to load (BBC News article). So what do you do if you want to track down a response time problem, if you want to test the time impact of a new feature or if you just want to find out which parts of your service take the most time?

In many situations, your traffic manager is the best place to gather this information, especially if it's pulling information from multiple sources for each request. This article shows how you can use sys.time.highres() (new in ZXTM 4.1) to record timing information when processing requests.

sys.time.highres() returns the (fractional) number of seconds since midnight on 1970-01-01. Looking at the increase in this value after an operation, you can see how much time has passed:

$start = sys.time.highres();
http.request.get( "http://example.com/" );
log.info( "Fetched example.com in " . ( sys.time.highres() - $start ) . " seconds" );

Since you can attach start times (or any other data) to connections using connection.data.set(), a timing interval's beginning and end need not be in the same rule, or even in rules of the same type. Here's an example that puts a time into the access log, if your log format includes %{responseTime}d (as it stands, it should give you a number slightly higher than the backend response time, %T).

# Request rule
connection.data.set( "start", string.sprintf( "%f", sys.time.highres() ) );

# Response rule
$start = toDouble( connection.data.get( "start" ) );
if( ! $start ) break;
connection.data.set( "responseTime", string.sprintf( "%f", sys.time.highres() - $start ) );

Because connection.data.set() and connection.data.get() work with strings rather than numbers, we must use string.sprintf() when setting (to set e.g. 1166095503.988931 and not 1.1661e+09) and toDouble() when getting.

Of course, you don't have to put the time into the event log or the access log. You could http.request.post() it somewhere, or insert it into the response itself or a response header, as in this replacement response rule:

$start = toDouble( connection.data.get( "start" ) );
if( ! $start ) break;
http.setResponseHeader( "X-Response-Time", string.sprintf( "%f seconds", sys.time.highres() - $start ) );

You can see this in action from Firefox using the Live HTTP Headers extension.

For detailed information about these and other functions, see the TrafficScript Manual.

Chris Boyle [Zeus Dev Team] 19 December 2006