James asks:
I am currently trying to solve a problem where our third party vendor's web services are very slow, our pages that invoke the web services are appearing in our log files as slow files.
What would be the best way to capture slow response time, to prove that it's not us that is causing the slow pages? I hear ColdFusion 8's monitor adds a significant performance hit, so I was thinking there might be a better way.
My thoughts are
1) Get the time before and after the web service invocation then figure out the difference then log the time. OR
2) Place a try/catch around the invocation and set a timeout, if the timeout has exceeded then log it and try again without the timeout OR
3) Apache log files???
I think you have a few good suggestions already, so let's look at them.
Your first idea is probably the best. I whipped up a quick web service that had this simple method in it:
<cffunction name="slowascrap" access="remote" returnType="string">
<cfset sleep(6000)>
<cfreturn now()>
</cffunction>
I first created a template that wrapped the call to the web service with getTickCounts:
<cfset ws = createObject("webservice", "http://localhost/test.cfc?wsdl")>
<cfset counter = getTickCount()>
<cfset res = ws.slowascrap()>
<cfset duration = getTickCount() - counter>
<cflog file="slowws" text="duration of web service call: #duration# ms">
<cfoutput>result is #res#</cfoutput>
This will log the execution time of every call to the web service. If the time is consistently 6000+ ms and your page itself executes in 6100ms or so, then it is pretty evident that the web service is taking up the majority of your page execution time.
Your second suggestion was a bit confusing. I'm not quite sure why you would set a time limit, but then repeat the call again. I assumed (and I could be wrong!) that you didn't really want to repeat it. Here is an example that gives the web service two seconds to run, and if it doesn't complete simply says that the service is not available.
<cftry>
<cfinvoke webservice="http://localhost/test.cfc?wsdl" method="slowascrap" returnvariable="res" timeout="2">
<cfoutput>result is #res#</cfoutput>
<cfcatch>
Service is not available.
</cfcatch>
</cftry>
Lastly - not quite sure what you would use the Apache log files for. Since the web service is a third party solution you can't check their files. My quick scan of the Apache docs for the access logs do not show a 'duration to generate' report. I would, however, recommend the ColdFusion Administrator setting to log slow pages. This is found in the Logging Settings page.
Archived Comments
4) Which is a takeoff on #1. You need to capture two time components:
a) OnRequestStart to OnRequestEnd
b) On start of web service invocation to end of web service invocation.
The log both times in a record (same record if possible)
Crunch the data – see where the time is being spent.
Your example – assumes the page executes in 100ms – it needs to be measured. No assumptions!
You could use onRequestStart/End. You could also just put another getTickCount pair on top and at the bottom of the CFM. If that total is N and the inner is M then your page minus the ws is just N-M. :)
If you want to abstract it even more then just build yourself a custom tag which generates a tick count in its start and end tag. Then have the end tag log the difference along with some additional information.
Ray, interesting title for a blog post. ;)
How dare you insensate that I used a titillating title. ;)
I read it for the title, no other reason.