I was working with a client this week who had quite a few entries for slow pages in his server.log file. I decided to see if I could write a quick report based on the log and came up with the following. Ignore the butt-ugly HTML I used:
<cfset filename = "C:\Documents and Settings\Raymond Camden\Desktop\doc\server.log">
<cffile action="read" file="#filename#" variable="buffer">
<cfset fileData = structNew()> <cfloop index=”line” list=”#buffer#” delimiters=”#chr(10)#”> <cfif findNoCase(“exceeding the 45 second warning limit”, line)> <cfset template = rereplace(line, “.?processing template: (.?), completed.”, “\1”)> <cfset time = rereplace(line, “.?completed in ([0-9,]?) seconds,.”, “\1”)> <cfset time = replace(time, “,”, “”, “all”)> <cfif not structKeyExists(fileData, template)> <cfset fileData[template] = structNew()> <cfset fileData[template].hitCount = 0> <cfset fileData[template].total = 0> <cfset fileData[template].max = 0> </cfif> <cfset fileData[template].hitCount = fileData[template].hitCount + 1> <cfset fileData[template].total = fileData[template].total + time> <cfif time gt fileData[template].max> <cfset fileData[template].max = time> </cfif> </cfif> </cfloop>
<cfdocument format=”pdf”> <cfoutput><h2>#structCount(fileData)# Total File</h2></cfoutput>
<table width=”100%” cellpadding=”10” border=”1”> <tr> <th>Template</th> <th>Times in Log</th> <th>Avg Execution Time</th> <th>Max Execution Time</th> </tr> <cfloop item=”temp” collection=”#fileData#”> <cfset average = fileData[temp].total / fileData[temp].hitcount> <cfif average gt 200> <cfset style = “color: red”> <cfelse> <cfset style = ““> </cfif> <cfoutput> <tr style=”#style#”> <td><b>#temp#</b></td> <td>#fileData[temp].hitCount#</td> <td>#numberFormat(average,”9.99”)#</td> <td>#fileData[temp].max#</td> </tr> </cfoutput> </cfloop> </table> </cfdocument> </code>
Obviously the hard coded file name would need to be changed, and it is going to be super slow on a large file. All I’m doing is sucking in the file and using some regex on the lines. One very important note. Notice this line:
<cfif findNoCase("exceeding the 45 second warning limit", line)>
Notice the use of 45. That was the setting on his server. You could probably get away with just looking for “second warning limit”, or you could switch to a reFindNoCase and replace the 45 with [0-9]+.
Either way, run this and you get a nice report of the files that were logged as being slow. Files taking more than 200 ms on average will be flagged. You could also switch the structure to a query, do QofQ, and then sort by most slowest page.
Starfish has data like this, but only works on currently executing code, while this code will work on your log file. I’ve pinged Scott to see if this could be added to his uber cool Flex-based log reader application.