High-resolution timestamps in SmartInspect

If you are a .NET, Java or Delphi developer, make sure to take a look at our advanced logging tool SmartInspect.

Last week I was working on adding high-resolution timestamp support to the SmartInspect libraries and the SmartInspect Console. One limit of SmartInspect (and I think most other logging tools) is that the timestamp resolution is just too coarse-grained. SmartInspect provides several time related features in the Console like showing the elapsed time between multiple log entries or the time offset to the start of the log. These features are already quite useful in the current version, but with the standard resolution provided by the system time functions, it can happen that a lot of log entries appear to have the same timestamp and this obviously reduces the value of these features.

The standard resolution in Windows happens to be 10-55ms (depending on the Windows version) and beginning with the next SmartInspect version, SmartInspect will offer a microsecond resolution. Yep, that’s right, an improvement with a factor of 10000 and more! We made high-resolution timestamps optional (we added a new property to the SmartInspect class for this) but it is enabled by default. There are some performance related issues on the .NET side which need to be considered in high-performance scenarios (only noticeable when using the non-I/O memory protocol though), but overall we are very satisfied with the runtime performance. Here’s a screenshot which shows the new functionality (also note the time difference, time offset and time span properties in the Details toolbox on the left):

High-resolution timestamps in SmartInspect

This entry was posted in SmartInspect. Bookmark the permalink. Post a comment or leave a trackback: Trackback URL.

7 Comments

  1. Posted April 26, 2007 at 9:20 pm | Permalink

    Nice feature, but I should warn that the QueryPerformanceCounter has a few problems…

    http://support.microsoft.com/kb/274323

    and

    http://blogs.msdn.com/oldnewthing/archive/2005/09/02/459952.aspx

    So, it can leap foward, and on multiprocessor systems it has potential other problems, see http://blogs.msdn.com/oldnewthing/archive/2005/09/02/459952.aspx#459991

    so, while you’ll get sharper numbers, GetTickCount will get you consant results.. :)

    perhaps looking at the multimedia timers?

    Kind regards

  2. Posted April 27, 2007 at 7:24 am | Permalink

    Thanks for the comment, Davy. The problem with the multimedia timers is their maximum resolution of 1ms. This is unfortunately not a lot better than the resolution provided by the standard system timers.

    I’ve read about the leaping forward problem before. It is unfortunate but not that problematic if the time occasionally advances by a second or two on some hardware under certain circumstances. What’s indeed more problematic are the multi-processor related problems. I’ve spent the last hours reading articles/documentation about this issue and although the QPC function tries to do its best, it seems that hardware related bugs can still cause some problems here. Microsoft recommends to call QPC from a single thread which is ideally configured to run on a single processor only:

    http://msdn2.microsoft.com/en-us/library/bb173458.aspx

    This is unfortunately not an option for us since we can not change the threading behavior of the host application just for a logging library. However, small jumps in time related to multi-processor synchronization problems/bugs are acceptable to a certain degree but obviously not if these jumps are backwards. But a simple work-around like comparing the return value of QPC with the previous counter value could at least guarantee that the time cannot go backwards.

    But I’ve found another problem in the meantime. It is related to CPUs with varying frequencies like found in most modern notebooks. With these kinds of processors it can happen that the QPC return values can get totally inaccurate. Internally, on some systems QPC can use the RDTSC instruction which increments a counter on every CPU clock cycle. If the underlying hardware uses some mechanisms to adjust the CPU frequency dynamically depending on the machine load (like Intel’s SpeedStep technology), it can happen that QPC and QPF can produce wrong results:

    http://www.codinghorror.com/blog/archives/000460.html
    http://www.gamedev.net/reference/programming/features/timing/

    I haven’t seen this myself while testing, but it’s plausible. What’s interesting is that I’ve also found references stating that QPC and QPF can understand and handle SpeedStep and similar technologies under some circumstances. However, even if this is true, this whole discussion makes QPC obviously a less reliable option. What I will test is to improve my existing code by adding some detection code which can fall back to the standard system timers (or maybe the multimedia timers) when such a problem is found.

    With all the found problems, we will probably disable high-resolution timestamp support by default and add more documentation to our manual. We already added some topics about this new feature, but I think it’s a good idea to add more details about the impacts and potential problems of high-resolution timestamps and the QPC usage.

  3. Posted April 28, 2007 at 10:06 am | Permalink

    Hi Tobias Gurock,

    indeed, the speedstepping I forgot to mention, because I couldn’t find a reference to that problem…

    I use a small program to see what the leaps are and detect if they are to large to be normal… (I’m not sure where I got this program from..)

    The advantage with the multimedia timers is that while the GetTickCount will indeed also return milliseconds, the steps of that API are sometimes in the range of 30ms.. While the multimedia timer provide a lot smaller steps…

    Good luck with the project,
    Davy Landman

  4. Posted April 28, 2007 at 7:31 pm | Permalink

    There are even more problems related to QPC (clock synchronization and deviation over time). I’ve found an interesting article from the MSDN Magazine:

    http://msdn.microsoft.com/msdnmag/issues/04/03/HighResolutionTimer/

    We decided to disable high-resolution timestamps by default and declare it as ‘developer-only’ feature, i.e. intended for use during development and not on production systems. It’s still a very nice feature, but the problems unfortunately make it unsuitable for production usage.

    Multimedia timers look indeed more interesting now, but I’ve read about performance problems if you use the maximum possible resolution (about 1ms). The default resolution of the multimedia timers is about 5ms on Windows 2000 and later whereas the standard system timers can provide 15ms (and even 10ms on Windows NT). On older Windows versions, the difference between multimedia and standard timers is more noticeable though. It’s probably a good idea to think about adding an additional option in the future for using multimedia timers.

  5. Roland Bengtsson
    Posted May 4, 2007 at 5:37 am | Permalink

    Can this new feature be tested on the trial version of SmartInspect 2.1.1.6106?

  6. Posted May 4, 2007 at 10:50 am | Permalink

    Hi Roland,

    We need to do some further testing before we can release this feature to the public. But this new feature will definitely be integrated into the next minor version (SmartInspect 2.2).

  7. Posted January 23, 2008 at 4:50 pm | Permalink

    Cool…

One Trackback

  1. […] high-resolution timestamps in both the SmartInspect Console and the SmartInspect libraries (Tobias talked about this before). For more information about the new version, please refer to our What’s New […]

Post a Comment

Your email is never published nor shared.