In the last few days I've been trying to find the reason for a slowness in one very specific case in a software. It looks like it crashes and since it includes many try/catch with (...) it certainly captures the fact, but contrary to what it is expected to do, this one does not get logged! In any event, I wanted to prove that the area where we first were looking was not affected, and sure enough it was not. The problem is somewhere else. However, to prove that I needed to have a way to log milli-seconds because things happen very fast and a 1 second decimation is definitively not enough.

This company makes use of log4cplus to log all the info in log files, rotate log files, etc. This is great, except that they are using version 1.0.2, in other words, a VERY OLD VERSION.

The log4cplus documentation clearly spells out the method to print out the milli-seconds in your time stamp:

%D{%m/%d/%Y %H:%M:%S.%q}

As you can see, the trick is to use the %q format. However, somehow, under MS-Windows and version 1.0.2 of the library, it crashes. Most certainly because the wcsftime() function doesn't like it and returns something wrong in the buffer.

The solution is simple though, you can double the % character so that way the format for the wcsftime() does not try to interpret the q format. Instead, it returns %q which is then replaced by log4cplus as expected. So the correct format is as follow:

%D{%m/%d/%Y %H:%M:%S.%%q}

Only difference: the double % before the q.

Note that the documentation says %s in several places for seconds, strftime() clearly takes %S (capital S). Although maybe it works either way.