Total time taken by a request?

Not applicable

Is there a variable that exposes the total time taken by a request? I was trying to use response.header.x-apigee-serverprocessingtime but i dont seem to get any content from it.

Note: Im looking for something that i can use w/o doing any calculations. If this doesnt exist there i no answer 🙂

Note: a javascript calculation is not what im looking for - I know how to do that.

Solved Solved
2 19 2,740
1 ACCEPTED SOLUTION

Not applicable

You are correct in that duration is populated in the response and NOT available as a flow variable. The Duration header captures timings from processing that is beyond what you see in the flow steps in your proxy definition. As such, it would be misleading to expose Duration in flow - I suppose we could document the Duration as a changing value through the lifecycle of the message processing with a "partialDuration" value. This would be a feature request you can make through the support team.

Given your current need for a partial duration and to use this value in logging you will need to create two javascript policies using two variables. Your first step in proxy preflow would record the current time in milliseconds in a variable "mpStart" and at the completion of the proxy request post flow as late as possible run have a second JSC callout to calculate the mpPartialDuration. This is the typical solution. Overall latency add would typically be sub millisecond in a production org.

Your logging policy could then include one or both of these variables. Note you would also need to add the second JSC policy to any Fault handling so that you could capture the duration values if you need them in log entries for exceptions.

View solution in original post

19 REPLIES 19

Not applicable

The response includes a header "Duration" which is the total time taken to handle the request within the MessageProcessor:

Access-Control-Allow-Headers → origin, x-requested-with, accept, authorization, authorization2, X-Client-Session-ID, Content-Type
Access-Control-Allow-Methods → GET, PUT, POST, DELETE, OPTIONS
Access-Control-Allow-Origin → *
Access-Control-Max-Age → 86400
Connection → keep-alive
Content-Length → 773
Content-Type → application/json; charset=utf-8
Date → Fri, 14 Aug 2015 14:29:32 GMT
Duration → 346 ms

Let me try this. Will get back to you soon.

@David Allen

Im trying to pull this in a message logging policy - and set an easy to parse key:value pair like this:

elapsedTime:{response.header.Duration}

This was giving me an empty. So i went ahead and plopped a javascript policy down on the response post-process and i did this:

var headerElapsedTime = context.getVariable("response.header.duration"); context.setVariable("headerElapsedTime", headerElapsedTime);

I get an empty for the response.header.duration - and ig et an empty for my flow variable.

Is there a total duration value i can pull from "PostClientFlow" ? This would represent total processing time at the gateway level - and is really all I am after. It seems like it is WAY too hard to get this right now...

@Benjamin Goldman @David Allen - Even i am trying to do the same (log elapsed time when it reaches edge and when edge sens reply). But, when i use following javascript i end up getting negative value in response.

var requestTimestamp = context.getVariable("client.received.end.timestamp");

var responseTimestamp = context.getVariable("client.sent.start.timestamp");

var duration = (responseTimestamp - requestTimestamp);

context.setVariable("duration",duration);

What is the workaround for the same?

Thanks in advance. 🙂

@Alok Kumar Singh can @David Allen I ended up... well... compromising. I HATE COMPROMISING 🙂 But I did it.

there are a lot of problems with variable scope that you need to work around, etc. In the end, its not even an accurate time taken designation - which is REALLY annoying. Why? because all of this is still taking place inside the message processor - so you are ignoring time spent in the router...

We ended up doing something pretty brain dead and stupid:

logging once at the start of the proxy pre-flow

logging once at the end of the target pre-flow

running a javascript code block to calculate time spent at target (system.timestamp MINUS target.sent.start.timetamp) as the first policy on target post-flow

Then immediately logging this out in the same target post-flow

then finally in the PostClientFlow (the special one that doesnt show up in the editor) we logged out again.

I had to sacrifice accuracy and precision to get my 4 data points - but it seems to have resolved our customer issues internally.

There is absolutely nothing proprietary here - so feel free to use it to figure out for yourself why your variables arnt scoped correctly. Note: this is why your math wasnt working 🙂

logging-basic.zip

Not applicable

You are correct in that duration is populated in the response and NOT available as a flow variable. The Duration header captures timings from processing that is beyond what you see in the flow steps in your proxy definition. As such, it would be misleading to expose Duration in flow - I suppose we could document the Duration as a changing value through the lifecycle of the message processing with a "partialDuration" value. This would be a feature request you can make through the support team.

Given your current need for a partial duration and to use this value in logging you will need to create two javascript policies using two variables. Your first step in proxy preflow would record the current time in milliseconds in a variable "mpStart" and at the completion of the proxy request post flow as late as possible run have a second JSC callout to calculate the mpPartialDuration. This is the typical solution. Overall latency add would typically be sub millisecond in a production org.

Your logging policy could then include one or both of these variables. Note you would also need to add the second JSC policy to any Fault handling so that you could capture the duration values if you need them in log entries for exceptions.

Thanks David. This is exactly what I ended up doing. Its a bit disappointing to have to add yet another policy here to capture what I think of as baseline log data for a request/response flow - but it works. In the end - the challenge im going to face is having to apply this to *every single proxy* in all of our internal organizations - and make sure that all of our participants understand that w/o these policies in place they wont be able to ask for logs from our operations group, etc.

We have some features in the works which would ease your pain somewhat - stay tuned for that.

In the meantime you can look at using the dependency management maven plugin - creating a single initializeLogging and finalizeLogging flow fragment that could be used in every proxy. At least then you have one bit to manage.

More info on the maven plugin at: https://github.com/apigee/proxy-dependency-maven-plugin

I may write something up on this as a blog post for others with a similar challenge.

I should note - i NEED to output a duration in MS - so im doing SORT OF what you said above. I am unfortunately now needing to wrap the Apigee log output in yet another layer to perform transformations to get what I want before sending them to my enterprise backend log system. All of this could go away if we could put javascript policies in the post response flow.

"We have some features in the works which would ease your pain somewhat - stay tuned for that." - Is the feature out yet?

OR is this still the best way?

Ditto @ the prior ask. Do we have a better way to do this now?

Not applicable

@Benjamin Goldman - Thanks a lot. Eventually I also ended up doing same thing using 2 javascripts one at start of proxy preflow and attaching the second one at each fault handling fragment and finally at response postflow. And finally getting the math right -:P in post client flow. Wish there was flow variable for duration.

I spent a LOT of time pissing and moaning at the product manager about this and other things we see as problems - but apparently we are the only shop seeing it as unacceptable....

any updates so far ?

I believe you are asking, has Google delivered an enhancement that provides the "current total elapsed time" of the request? 
As far as I know an enhancement request was never filed for this feature. And, I don't know of any enhancement that was made, independently, that would provide a "running total" of elapsed time of the request, within a flow variable. 

Still today the best way to get that number is to do the arithmetic yourself. 

var start = context.getVariable('client.received.start.timestamp'),
    end = context.getVariable('system.timestamp'),
    delta = Math.floor(end - start);
context.setVariable('current-time-elapsed', delta);

The explanation: The "client.received.start.timestamp" is the moment when the Apigee proxy received the first byte of a request from the client.  The "system.timestamp" is the current time.  Subtracting them gives you current elapsed time.

Thanks u @dchiesa1 , this will help 🙂

I'm trying to use this on PostClientFlow, but isn't working. Should this be it used on another flow ?

In my company we don't set the elapse, but the transaction start and end times, using these variables in the Post Client Flow.

 

"start_time_unix_nano": {client.received.start.timestamp}000000
"end_time_unix_nano": {client.sent.end.timestamp}000000

 

It is probably better than system.timestamp when it's not a problem to process it in the post client flow. 

As you can read here, A PostClientFlow can include the following policies:

Therefore, if you need to do operations via javascript, you will have to use what Dino suggested in the Response Post Flow. That's why he uses system.timestamp, as the variable client.sent.end.timestamp is not set yet.