DebugTrace log analyser (WinBatch Script Exchange)

[cssyphus]

I have a few scripts that are both (a) background apps, and (b) more than 5,000 lines of (mostly uncommented) code. Debugging can take a long time, especially when something is merely slowing it down (for example, when clicking the tray icon might be taking ~ 10 seconds to open the PopMenu).

Standard solution: the DebugTrace() command creates a log file showing each line executed and the return value of the line.

I use these heavily, and find myself poring over the logfiles, looking for (a) ERROR SUPPRESSED messages or (b) anomalies in the (tickcount) number beside each line.  The ERROR SUPPRESSED messages are easily found with a simple search, but the tickcount was largely unhelpful... so I finally wrote wrote this basic log analyser. 

The attached app reads each line of the debugTrace log and compares each tickcount to the one preceeding it. When there is a jump larger than _maxTicks (you specify that number at top of file - 1000 ticks is roughly one second), the line is copied to an output report.  It can take quite a while to run (I just ran it on a logfile with 3.5M lines and it took about 20 mins), but it immediately identified the line that was causing the slowdown in my app.

My primary app is a background app that manages my work day, with 105 udfs and a while @TRUE loop with 178 GoSubs. I generally add, fix or improve around 10 features per week - so problems crop up pretty frequently. On this app, I have debugTrace running all the time. When the logfile reaches a certain size (120Mb), I rename it and debugTrace automagically starts a new one. I retain the last 5 log files, and this allows me to troubleshoot my ever-expanding app with relative ease. Now, with the aid of this log analyser, I can finally monitor the tickcount values to find the slow-downs.

Sharing with y'all. The script is relatively basic, and easily tweaked so please fine-tune it to work best for you.

USAGE NOTES:

a. Options most people will want to modify are at top, under label ;RUN OPTIONS. Those options are:
b. `_fn=` assignment - Before running, point this var to your logfile
c. `_maxTicks=` - This is the maximum allowed execution time for a line of code before it is logged in the output report (1000 ticks ~~ 1 sec, default is 1300)
d. `_displayProgress` - While running, a pop-up box is displayed with the line number being analysed. You can hide this with _displayProgress = 0
e. `_progressIndicatorOnMon2` - The script checks if you have > 1 monitor. If so, _progressIndicatorOnMon2 (0 or 1, @FALSE or @TRUE) will control where that progress indicator is located
f. Around line 60 is an IF block that you can uncomment for testing, causing the script to stop at that point (15,000 lines, <30 secs) and display the report
g. The script also watches for a "haltanalyse.txt" file to appear in the script directory - if found, it halts at that point and displays the report.

Note: Each found error is stored in an array, with each future error being tested against that array so as to not display the same error a gazillion times (i.e. if your script has looped 10,000 times). However, if there is a difference in the tickcount value, the error will be reported for each time where the tickcount is different. This helps with locating sudden jumps, or steady increases in the time that line of code is taking to process. (BTW, why would one want to log 10,000 repetitions of a loop? Isn't one rep enough? No... because sometimes a sub-routine is only called every so-many minutes (thousands of loops), or some routines are not called at all unless a certain condition happens... but each time through the loop the code gets fully logged. So, if you have a couple of errors and one error is seen each time the app loops, but another error only happens every 13,000th loop, one doesn't want the second error being drowned in a plethora of reports of the first error... so that has been somewhat mitigated.)

[td]

Haven't had a chance to try the script yet but the concept is an interesting and useful one. Thanks for sharing it.