Best way to log time taken by service callout or any other policy

[#1]

I know we can probably set start time in a previous javascript policy and calculate the difference in the next one. But is there a better way?

[mdunker · Accepted solution]

If you are using this for debugging purposes, I find it handy to be able to drop a preexisting policy into the flow in several places, rather than having to create a new one each time.

I have used the following JS policy:

var lastLoggedTime = context.getVariable("lastTimestamp");
var nowTime = context.getVariable("system.timestamp");


context.setVariable("lastTimestamp", nowTime);


if (lastLoggedTime !== null) {
  var deltaTime = nowTime - lastLoggedTime;
  context.setVariable("lastElapsed", deltaTime);
}

You can drop this same policy multiple times in the code wherever you'd like, and it will calculate the delta time since the last time the policy was run in the same call. If you want to syslog, you can use the lastElapsed variable.

[#3]

If you are using trace enabled - then the trace should have it. But in general the system.timestamp with assign message polices around the service callout policy can solve it. You can use assign message instead to Javascript to capture the start time.

[DChiesa]

I can't think of a better way.

[mdunker · Accepted solution]

If you are using this for debugging purposes, I find it handy to be able to drop a preexisting policy into the flow in several places, rather than having to create a new one each time.

I have used the following JS policy:

var lastLoggedTime = context.getVariable("lastTimestamp");
var nowTime = context.getVariable("system.timestamp");


context.setVariable("lastTimestamp", nowTime);


if (lastLoggedTime !== null) {
  var deltaTime = nowTime - lastLoggedTime;
  context.setVariable("lastElapsed", deltaTime);
}

You can drop this same policy multiple times in the code wherever you'd like, and it will calculate the delta time since the last time the policy was run in the same call. If you want to syslog, you can use the lastElapsed variable.

[#6]

@Mike Dunker, is it a good idea to log that variable to analytics and then build a custom report with that as metric? Or will it have an adverse impact on analytics performance?

[mdunker]

@Sandeep Murusupalli

Adding a few additional variables to analytics shouldn't cause a performance issue. I would do it if the information is important to you on an ongoing basis. I generally wouldn't use analytics as a generic logging mechanism, though. Don't litter analytics with debugging data -- you wouldn't want to create a whole bunch of one-off variable names for logging elapsed times. Creating a variable or two that you reuse, though (authCalloutMsec or calloutMsec, for example) should be fine and might be very useful.

[Former Community Member]

Hi @jaskaran.rm what is the intended use of this? Is it to merely log this time for all transactions in run-time or is it to just determine during development what time each policy takes? If its the later then the trace tool can give you that information. (See attached image). If it's the former, then the approach suggested by @Mike Dunker should work.screen-shot-2015-06-01-at-25257-pm.png

[#9]

Hi @jaskaran.rm , As suggested above by the team we can use tracetool (manual) to capture the timestamps or you can log programatically by capturing timestamps and logging to logs or analytics if you want to maintain history or check the timestamps for past transactions.

One advantage of using message logging is that you can have that in the postclientflow so that it gets executed after the response is sent to the client .

Check this http://apigee.com/docs/api-services/content/flow-configurations#understandingflows-postclientflow

There is another way to get the timestamps using the debug session API

Check this http://apigee.com/docs/api/debug-sessions

Basically , you don't need to start the trace but you can get the same output in json or xml using the API . So you can write scripts to capture what ever you want and run for what ever time you want .

This can be helpful in cases where you want to capture the policy times for some 30 min in your performance environment but you don't want to make changes to your code .

[#10 · Accepted solution]

With the latest release every policy exposes a variable with name

apigee.metrics.policy.<policy name>.timeTaken

The value is the the time taken by the policy in nano-seconds.

[#11]

Awesome. Thanks @sriki77

[#12]

@Anil Sagar @sriki77

capture.png

Its <proxy name> or <policy name> ??

In documentation its <api_proxy_name>

Doc Ref: Variable Reference

[jonesfloyd]

Docs are fixed. Thanks for pointing it out!

[#14]

Also can we access this variable at any point in the complete flow??

[amol_deshmukh]

I used "apigee.metrics.policy.{policyName}.timeTaken" in my proxy and I think its not giving time taken by the Rest call in ServiceCallout . Its just giving response time taken by only Service Callout policy.

can somebody please confirm this?

I am getting Around 139537ns using above flow variable and when i trace the call the Its showing the time taken by whole service callout as 600ms .