Computing Time Deltas with PowerQueries

With the edition of Powerqueires to Scalyr, we can now compute the delta of time between various events. This could be useful in simply computing the latency of a request, measuring the time delta of one event to another, or in a distributed environment where multiple systems are communicating, and measuring latency is important.

In this example, we will be working with AWS Lambda logs to demo this technique. This is because they have a distinct start event, end event, and also logs the actual latency, so we can reconcile this against the actual latency.

What we will be doing.
1. Identifying a start event
2. Identifying an end event
3. Write a PowerQuery to join the two searches
4. Compute the delta

Prereqs:
1. Scalyr Account
2. A start and stop pattern with timestamps

Let’s start with data.
1. Login to your Scalyr account and identify a start event. In the case of Lambda logs, when a request is started, there is an identifying pattern

START RequestId: xxxxx

2. Now lets identify an end event. Once a lambda has finished, lambda logs the end of the event.

END RequestId: xxxxx

3. Now let’s get the start event in a PowerQuery.

Input:

 

("START Request") && $logfile == '/aws/lambda/scalyr-test'
|columns RequestId, timestamp

//if you are not already parsing requestid, then you can use the parse function to extract it from the message field. 

// |parse from message ".*RequestId: $RequestId$"

Output:

timestamp	message
Jan 30 · 12:15:14.622 AM	START RequestId: 162342c7-5050-4f6f-971f-876453ab6f35 Version: 10

4. Now let’s get the end event in a PowerQuery.

Input:

("END Request") && $logfile == '/aws/lambda/scalyr-test'
|columns RequestId, timestamp

//if you are not already parsing requestid, then you can use the parse function to extract it from the message field. 

// |parse from message ".*RequestId: $RequestId$"

Output:

timestamp	message
Jan 30 · 12:21:41.129 AM	END RequestId: 162342c7-5050-4f6f-971f-876453ab6f35

5. Now let’s join these two together.
The join syntax is simple.

|join
     query1 = (foo),
     query2 = (bar)
on
     id

Let’s add our two PQs

Input:

 

|join 
     start = (
          ("START Request") && $logfile == '/aws/lambda/scalyr-test'
          |columns RequestId, timestamp
     ),
     end = (
          ("END Request") && $logfile == '/aws/lambda/scalyr-test'
          |columns RequestId, timestamp
     )
on
     RequestId 

Output:

RequestId	start.timestamp	end.timestamp
162342c7-5050-4f6f-971f-876453ab6f35	Jan 30 · 12:15:14.622 AM	Jan 30 · 12:21:41.129 AM

Now that we have the two in one row, we can compute the difference.

Input:

|join 
     start = (
          ("START Request") && $logfile == '/aws/lambda/scalyr-test'
          |columns RequestId, timestamp
     ),
     end = (
          ("END Request") && $logfile == '/aws/lambda/scalyr-test'
          |columns RequestId, timestamp
     )
on
     RequestId 
|let delta_microsec = (end.timestamp - start.timestamp)/1000000000/60

//note we are converting milliseconds to minutes by dividing the differnce by 1B 60 

RequestId	start.timestamp	end.timestamp	delta_min
162342c7-5050-4f6f-971f-876453ab6f35	Jan 30 · 12:15:14.622 AM	Jan 30 · 12:21:41.129 AM	6.44

The response took 6.44 minutes.

Aws reports on this information already, so lets test this value.

Input:

|join 
     start = (
          ("START Request") && $logfile == '/aws/lambda/scalyr-test'
          |columns RequestId, timestamp
     ),
     end = (
          ("END Request") && $logfile == '/aws/lambda/scalyr-test'
          |columns RequestId, timestamp
     ),
     report = (
          ("REPORT Request") && $logfile == '/aws/lambda/scalyr-test'
          |columns RequestId, Duration
          |let duration = Duration/1000/60 
     )
on
     RequestId 
|let delta_min = (end.timestamp - start.timestamp)/1000000000/60
|columns RequestId, start.timestamp, end.timestamp, duration, delta_min
//note we are converting milliseconds to minutes by dividing by 1B and 60 

Output:

RequestId	start.timestamp	end.timestamp	delta_min	duration
162342c7-5050-4f6f-971f-876453ab6f35	Jan 30 · 12:15:14.622 AM	Jan 30 · 12:21:41.129 AM	6.44	6.43

We can see we are <1% off what AWS is internally computing.