What do you log in your desktop applications to improve stability?

Question

I've started using SmartInspect in my Delphi applications because my users were running into bugs/problems I couldn't reproduce on my machine. When I have a general idea of the problem I'll monitor the application in a few specific places to confirm what is or is not working.

When the bug doesn't have an obvious cause, I feel lost. I don't know where to start logging in order to narrow down the problem. Are there common techniques or best practices for using a logger?

SmartInspect seems to be quite powerful, but I don't know quite what to log or how to organise my logs so the data is meaningful and useful for catching bugs.

NOTE: I'm using SmartInspect but I assume the answers should be suitable for any logging package.

Bathulda

This is a Java idiom, but try { ... } catch (Exception ex) {} removes "crashes" ... (I kid, I kid) – Ainsworth

@pst In Delphi, try except will handle exceptions, but there are some possibilities in Delphi to log all exceptions, not only un-handled ones. – Quinones

as a sidenote: when you are going to do logging anyway, then it is very wise to log (anonymous) usage statistics. That helps you to get a better grasp of what your users actually are you doing with your application. – Nourishing

@Jeroen: That sounds like a good idea! I have been wondering how much my app is actually used. :) – Bathulda

Answer 1

Here are some guidelines I tried to implement in my own OpenSource logging unit, but it's fairly generic, and as you state, it should be suitable for any logging package:

• Make several levels (we use sets) of logging, to tune the logging information needed;
• Log all exceptions, even the handled one with a try...except block - and add an exception classes list not worth logging (e.g. EConvertError) - e.g. our unit is able to log all exceptions via a global exception "hook" (no try..except to add in your code), and handle a list of exception classes to be ignored;
• Log all "fatal" errors, like database connection issues, or wrong SQL syntax - should be done though "log all exceptions" previous item;
• For such exceptions, log the stack trace to know about the calling context;
• Be able to log all SQL statements, or database access;
• Add a generic User Interface logging, to know which main functions of the software the User did trigger (e.g. for every toolbar button or menu items): it's very common that the user said 'I have this on my screen/report, but I didn't do anything'... and when you see the log, you will discover that the "anything" was done. ;)
• Monitor the main methods of your application, and associated parameters;
• Logging is an evolving feature: use those general rules above, then tune your logging from experiment, according to your debugging needs.

Quinones

+ for logging exceptions, that's fairly important. Not sure about call stack because I personally don't like shipping exe's built with stack frames. – Excursus

@Cosmin: I've wondered about this. So how do you determine the source code route that led to the exception? – Pronator

@Brian, if you can somehow identify stack frames (ie: function return pointers on stack), you can look them up in the compiler generated MAP file and get the name of the method, unit and line number. Unfortunately the key here is having stack frames: while they help put line numbers on errors, they also help hackers understand your assembler and make runtime execution slightly slower. – Excursus

@Brian Take a look at the OpenSource unit source code I link to, and this blog article. You'll find out how we were intercepting all exceptions (even with Delphi 5 which did not provide any global hooking function), and how we use the .map file to retrieve the source code lines and make a stack trace. – Quinones

@Cosmin You don't need to "ship exe with stack frames" in all cases. You can guess from the stack frame about line numbers. It's not perfect (you got false positives), but it works. See how we implemented it in TSynLog.AddStackTrace. – Quinones

Answer 2

For UI-driven applications here are the main things I instrument first:

1. ActionManager or ActionList's events when an action executes (gives me a user clicked here then here then here list).

2. Unhandled Exceptions with tracebacks using JCL debug go right in my main log, whereas if I was using MadExcept or EurekaLog, exceptions have their own log.

3. Background thread starts, stops and significant history events

4. Warnings, errors, API function failures, file access failures, handled (caught) exceptions.

Merovingian

Answer 3

Current memory usage can be useful for long running processes to see if there are memory leaks (which could lead to an out of memory error some day).

Wo

You should better use the full debug mode of FastMM4 which is far more advanced and reliable than using Total Allocated Memory counters... – Quinones

@A.Bouchez FastMM4 will only take its own managed memory into account – Wo

Which other kind of memory would be managed outside FastMM4 in Delphi? GDI handles or OleStr are global, and won't appear as memory, but as resource. In all cases, your link will return PagefileUsage value, i.e. "The current space allocated for the pagefile, in bytes. Those pages may or may not be in memory", according to MSDN. So this will return the spanning pagefile bytes, not the current total allocated memory. The full debug mode of FastMM4 is very reliable to track memory leaks, NOT this value. – Quinones

@A.Bouchez: memory used by DLLs in the process space, see #5470699 – Wo

Some of this memory is shared, other is hidden in Microsoft's internals... Memory leaks will be more surely discovered in your Delphi code, from the wrapper which uses this external memory: if one of your class instance (e.g. TFont) is not released, FastMM4 will notify it in full debugg mode, and you'll find out that the associated Windows / DLLs memory leak (e.g. the GDI handle for a TFont). I saw you removed your (wrong) link - perhaps worth saying that ProcessExplorer is the right tool for monitoring resources. – Quinones