Frequently Asked Questions

Nov 21, 2019 - 01:08pm

 [F] Frequently Asked Questions  / Operational Questions  / Macros and Templates  /

Interpreting Macro Timestamp (macro execution) Logs

Rate This FAQ
Rating: **** (based on 3 votes)

Created On: 6 Aug 2007 12:01 pm
Last Edited: 6 Nov 2008 3:55 pm

Question Email This Printer Friendly

I ran a timestamp log to try and find what macro is slowing my server down, but I am not sure how to interpret it.

Answer

A timestamp log allows you to determine how long it takes a WCTL macro or WCJS function to execute; you can also discover out how often it executes. Start by visiting the Control Panel and putting a check in the box for "Log macro execution times". Note that this logging takes time and will impact performance, so use this feature with caution on a production site and switch back to a less intensive level of logging when your analysis is complete.

When our developers do a log analysis, the first thing they do is grep out the lines with " CGI " in them. Then they strip off the prefix for each line up to and including the "Millisecs=". Next, sort them by milliseconds.

Once you have the sorted list, start looking at the slowest requests, using the tail of the CGI line to find it in the full log. Then you can use the IP address to search backwards and find the start of the request, and pull all the lines into a separate file for analysis.

Ex "390488602 MacroMsecsJs mySpecialMacro 0 t=14337638"
means as follows:

390488602 -- system ticks (milliseconds) when the call started
MacroMsecsJs -- a JS routine was called
mySpecialMacro -- the name of the routine
0 -- the number of milliseconds this routine and all nested routines
took, wall clock
t=14337638 -- thread ID was 14337638. You can use the thread ID to
untangle interleaved requests