hints in the coverage log

[Olaf Doschke]

I often refer to the coverage log as a trace log, though by its name it's meant to analyze code coverage, proving/testing, whether all branches of code are covered by test cases of a unit test suite, for example. But it's also a simple log of lines of code executing even profiling execution time, so it's a nice way to discover how code you don't have written yourself but inherited for maintenance works, how it runs.

SET COVERAGE TO coverage.log

That's all you need to put somewhere to start recording every single line of code running. Not the code itself, meta data about the code, procedure/class names and line number, for example.

Create Cursor curCoverage (bExecTime B, cClass C(128), cMethod C(128), iLine I, cFile C(254), iStacklevel I) 
Set Point To '.' 
Append From coverage.log Type CSV

This is how you later can read in all this meta data into a cursor for analysis. VFP itself has an even better tool, the coverage profiler, but it will not give the simple protocoll in the order of code line execution, as the mere data gives, which sometimes is important to find a place in the code doing something wrong, without erroring most probably, giving you no grip on when and from where it is executed. Coverage can reveal triggered calls, like dbc triggers, but also bindevents etc., it doesn't fail to tell you what actually ran, the only lines it won't log are properties set to expressions, unless the expressions call into functions, which appear in the log.

What's missing is a way to put in own lines, like remarks or hints of something you know happens before or after something else, to narrow down the interesting part of the log. You can always end one log and start a specifically named log, but it will become tedious to later have to analyse many short logs. For that problem I had an idea I'll use today:

=EXECSCRIPT("[highlight #FCE94F]hint[/highlight]()"+CHR(13)+"Procedure [highlight #FCE94F]hint[/highlight]()"+CHR(13)+"return")

or even

=EXECSCRIPT("[highlight #FCE94F]hint[/highlight]()"+CHR(13)+"Procedure [highlight #FCE94F]hint[/highlight]()"+CHR(13)+"Messagebox('[highlight #FCE94F]hint[/highlight]')")

This will show up in the log this way:
[pre] 0.000071,,0000j18p00b3,1,c:\users\...\appdata\local\temp\0000j18p00b3.fxp,2
0.000022,,[highlight #FCE94F]hint[/highlight],3,c:\users\...\appdata\local\temp\0000j18p00b3.fxp,3[/pre]

Execscripts generates a temp prg file, compiles and runs the fxp with a cryptic name, but what is most important, you find your hint keyword within the logs meta data, so you can smuggle your own keywords into the log and mark places of interest, places to make a cut. This way you can have a single longer coverage.log and still find sections of interest in it, especially, if you look for several sections and even won't know how to get there without an experienced user of the software you try to analyse. With the messagebox variant you can also see whether code runs before or after certain other events and remember visually what happend before and after a certain message was shown. Instead of "hint" you can have anything here, just the procedure name has to be a valid procedure name. And though that doesn't allow you to log anything into the coverage log, it even could contain data, as long as you assemble a valid procedure name, ie for numeric output prefix it with an underline, and it becomes a valid procedure name, in general:

=EXECSCRIPT("hint_&cInfo()"+CHR(13)+"Procedure hint_&cInfo()"+CHR(13)+"Messagebox('message for &cInfo')")

The main idea here is to generate procedure names on the fly, as they will be put into the coverage log. The procedure has to be called and has to have one line of code at least, eg just the return, to appear in the log with its name.

Bye, Olaf.

 

[Mike Lewis]

This is very ingenious, Olaf. Thanks for sharing it.

One point to watch out for:

The coverage log can generate huge volumes of data, especially if you don't limit the logging to a small part of the program. If you use something like [tt]Create Cursor curCoverage .... Append From coverage.log Type CSV[/tt], the cursor can quickly exceed the 2 GB limit. This is also true if you use the built-in profiler, as that generates its own internal cursor.

You need to be careful to specify the smallest possible scope for the coverage, while still making it big enough to provide the required information. I use [tt]SET COVERAGE TO <filename> ADDITIVE[/tt] and [tt]SET COVERAGE TO[/tt] respectively to mark the start and end of the scope, but you can also do it in the debugger with the Coverage dialogue.

Of course, this does not detract from your very useful tip, Olaf.

Mike

__________________________________
Mike Lewis (Edinburgh, Scotland)

Visual FoxPro articles, tips and downloads

 

[Olaf Doschke]

The usual coverage logging sessions I do for minutes have a few MB file size, you can comfortably record quite long sessions in the typical interactive application, unless you have a very frequent timer doing a lot of code even at the usual wait time. Then it pays to keep that off the log by changing the Timer() event code. Overall your mileage of course can vary a lot, if you log something like a data migration tool running data transformations as fast as it can and without a pause the log obviously can grow much faster.

The warning should be taken serious, but you will have your own experience very soon. I would not suggest using this in production environment, unless you want to find out a detail working closely with an end user in a test phase. I always let this be configurable, so the logging can be turned off without needing an EXE version without the command. Whatever suits you, a txt file with the log file name to be set from outside, an INI entry, a config.dbf record...

It's also good to know, what really is logged here. The script EXECSCRIPT writes out and executes is this:

hint()
PROCEDURE hint()
return && or a Messagebox()

What becomes part of the log is the EXECSCRIPT line, of course, then line no 1 of the script - the call into the procedure - which logs with the fxp name you can't decide, as EXECSCRIPT generates it randomly and the third line getting into the log is the wanted one, the FXPs line 3, which has the RETURN or MESSAGEBOX inside the hint() procedure (or whatever you call it). You can do more, but obviously this won't add to the purpose of having your hint in the coverage log. You also can't do any shorter, if you leave out this line, the procedure name won't appear in the coverage log. The procedure has to have a line of code to be logged. An empty procedure can also be called, but since no line of it runs it wouldn't be logged at all, that's also a reason the coverage log does not log events, which have no developer code and thus only execute native behaviour. For that Foxpro offers event tracking - another topic, though.

It's a bit unfortunate you have three log lines for the one hint, but this is minimum waste in comparison to the rest of the log. To keep a log shorter, once you know which parts of code are interesting, you can always suspend logging via [tt]SET COVERAGE TO[/tt] without specifying the log file name and then continue logging with [tt]SET COVERAGE TO coverage.log ADDITIVE[/tt]. Besides that, you can of course also specify different names for different purposes, but that's typically only happening in a stage the code is not a black box to you anymore. Also notice, this can really also be done within an EXE. The class/method/procedure/function names also are available when building the EXE without debug info, so this can also be used to "debug" at runtime on systems you can't add in a Foxpro installation, but due to the file growth has to be done with caution. You should at least restart the log when the exe starts, which happens anyway, if you don't use the ADDITIVE clause. When interested in long term logging you may keep backups, todays disc space would allow that, given the usual daily session doesn't let the coverage outgrow, but the main reason to not add this just for the precaution of being able to see what happened at some time is not the file size of the log, but the performance degradation due to writing out some bytes per line of code executing. It's running astonishing fast on todays systems, considering that.

Bye, Olaf.