Time is relative in Log4View

When two logging events both have a time stamp of 2010-1-1 10:20:30,456, does that mean that both events happened at the same time?

Not necessarily. It depends on some factors:

  • The location, where the events happened and their time zone.
  • The current daylight saving settings in the country.
  • The logging framework, which can use Universal or local time.
  • The accuracy of the clock in the computer, which generated the event.
  • The precision of the time’s storage format.
  • The precision of the time’s display format.

Log4View 2011.1 tries to address all this aspects and has added some extra settings and time representations.

Log4View stores the message time in a DateTimeOffset structure, which preserves the time zone and the daylight savings settings. If the log data is sent in log4net XML format, this is no problem, because the XML layout presents the time with the time zone information. However, the original log4j XML format stores times as ticks without any time zone information. For this and other cases, where no time zone information comes with the log data, you can set the time zone in the receiver settings.

By default, Log4View shows the message time in the time zone, where it was stored. Thus, a message with the time stamp 10:00:00+01 (CET) will be shown as “10:00:00”. This is what normally is expected when dealing with just time zone.

However, when you are working with log files or streams from different time zones, things become more complicated. As long as you don’t change the sort order, all messages in a message window are sorted by their UTC time. Thus it can happen, that a message with timestamp 10:20:00+01 is shown before a message with timestamp 10:00:00+00, because the later message was actually created 40 minutes after the first message.

Another issue is computer clocks, which are not in sync. This can be quite disturbing when you want to compare log output from different machines. To correct this, you can specify a time offset when configuring a log receiver. This offset will be applied to every message from this receiver.

Dealing with all that time zones and offsets can be quite confusing and that’s why Log4View has different time representations. For this example, we assume that we are viewing a log message with timestamp 12:14:40,000+02 (IDT, Jerusalem) in summer in Munich, Germany (CET) with an offset of 650 ms to compensate the slow Jerusalem computer’s clock:

  • Time: The time as local time where it was created with the offset applied: 12:14:40,650
  • Local Time: The time converted to current local time with offset applied: 11:14:40,650
  • Universal Time: The time converted to UTC with offset applied: 10:14:40,650
  • Original Time: The time as it was stored without offset: 12:14:40,000

All time representations can be shown as extra columns in the message view by right-clicking a columns header, selecting the column chooser from the context menu and dragging the respective columns to the desired location.

Precision Matters

By default, Log4View shows all times with a resolution of milliseconds. This is enough, especially when considering, that the resolution of the normal log4net or NLog timestamp is approx. 10 milliseconds. However, when using your own time source, you can create timestamps with a resolution of microseconds.

You can increase the time resolution of Log4View to microseconds by entering “HH:mm:ss,ffffff” into the Time Format field in the Log4View settings.

Advertisements

2 Responses to Time is relative in Log4View

  1. Shlomi says:

    Thanks for your great work!

    Just a little remark:
    “Log4View stores the message time in a DateTimeOffset structure, which preserves the time zone and the daylight savings settings.”

    DateTimeOffset doesn’t preserves the daylight saving settings, quoted from your MSDN link:
    “Although a DateTimeOffset value includes an offset, it is not a fully time zone-aware data structure. While an offset from UTC is one characteristic of a time zone, it does not unambiguously identify a time zone. Not only do multiple time zones share the same offset from UTC, but the offset of a single time zone changes if it observes daylight saving time. This means that, as soon as a DateTimeOffset value is disassociated from its time zone, it can no longer be unambiguously linked back to its original time zone.”.

    • Ulrich says:

      Shlomi, you are right, I was a bit unclear on this point. The DateTimeoffset structure actually preserves just the offset, which is the aggregate of timezone and daylight savings settings.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google+ photo

You are commenting using your Google+ account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s

%d bloggers like this: