Why do events logged by the ReportEvent function show up in the wrong order in the Event Viewer?


A customer observed that when their service logs multiple events in rapid succession, they sometimes show up out of order in Event Viewer. Specifically, the order of events that all occur within the same second are sometimes mis-ordered relative to each other. Is this expected?

Events in the event viewer are timestamped only to one-second resolution. The EVENT­LOG­RECORD structure reports time in UNIX format, namely, seconds since January 1, 1970.

Experimentation suggested that the Event Viewer sorts events by timestamp, but it does not use a stable sort, so multiple events that occur within the same second end up in an unpredictable order.

Not much you can do about it, but at least now you know that you're not hallucinating.

Comments (18)
  1. Brian_EE says:

    One could keep a global counter and use the RawData to log the counter value on each call to ReportEvent. Or, you know, put that all in a wrapper class.

  2. anonymouscommenter says:

    So that 32-bit DWORD is going to wrap around in 2038…. EVENTLOGRECORDEX?

  3. SimonRev says:

    Actually since it is a DWORD you should get an extra 68 years or so before you have problems.  The 2038 problem has to do with using a signed 32 bit integer to represent time.

  4. anonymouscommenter says:

    >> Experimentation suggested that the Event Viewer sorts events by timestamp, but it does not use a stable sort, so multiple events that occur within the same second end up in an unpredictable order.

    Actually, Event Viewer doesn't initially sort the events at all (at least not on Windows 7); they are merely quasi-sorted (similar to what one gets from most database engines when you execute "select * from tblFoo" – the records are almost, but not quite, sorted by the primary key).  This behavior can be very deceptive if you're not aware of it.

  5. anonymouscommenter says:

    Had to depend on the quazi-sort on multiple occasions. The event sorting is wrong wrong wrong. Don't use the system clock here. Use an incrementing 8 byte integer.

  6. alegr1 says:

    THe event viewer is one of the lamest programs included with Windows.

    I think its programmers haven't heard of stable sort. C qsort is not a stable sort.

  7. anonymouscommenter says:

    I think the standard way to make quicksort (which is how qsort is usually implemented) stable, is to compare the items, and then if they are equal, compare their indices.  That is very easy to do with qsort in the comparison routine.  If you don't want a stable sort (for example, because you know that all the items are different), there is no reason for the standard to impose the overhead of making the comparison stable.

  8. anonymouscommenter says:

    > THe event viewer is one of the lamest programs included with Windows.

    It's quite annoying how the window freezes for 5-20 seconds even on high-end machines when you first open it.

  9. anonymouscommenter says:

    So the problem wouldn't occur if you used a low-level event dump utility that just reported events in log order? Why does Event Viewer sort the records anyway? (The View menu doesn't show any particular sort order applied, so I would expect no sorting.)

  10. anonymouscommenter says:

    @ender

    At least it doesn't freeze the cursor like the Task Scheduler snap-in does.

  11. Pyjong says:

    Is EventRecordId of any use here? Seems pretty sequential to me.

  12. anonymouscommenter says:

    @Pyjong: That won’t help much either, as they use an unstable sort on timestamp.

    With a stable sort on EventRecordId and Timestamp, one could obviously fix it, but they prefer to use a quite slow, unstable sort.

  13. Dave Bacher says:

    The EVTX logs contain this:

     <Keywords>0x2000000000000000</Keywords>

     <TimeCreated SystemTime="2015-06-01T06:09:11.492377800Z" />

     <EventRecordID>804</EventRecordID>

     <Correlation />

     <Execution ProcessID="38512" ThreadID="49496" />

     <Channel>Microsoft-Windows-Kernel-PnP/Configuration</Channel>

     <Computer>Surface3</Computer>

    So it appears that it is only an issue for the NT through XP Event Log API, and not the newer log.  As a couple people have indicated, the Record ID is sequential — sorting by date/time has always been a bad idea to get a sequential list, because the clock on Windows < XP is not stable.

    (Note: it's not necessarily stable on newer versions of Windows, either — however, I'm talking instability due to the OS itself versus instability due to the user and/or network adjusting the clock.)

    From a security standpoint — for the security logs at least, you want to find the range of record ID's you need and pull everything in the middle.  You don't want an attacker to "disappear" because they changed the system clock.  Just saying.

  14. alegr1 says:

    @Martin Bonner:

    std::sort is stable.

  15. anonymouscommenter says:

    @enderyes, it is very slow, not only the first opening, but also any redraw takes much longer time than one would expect. Windows 95 on 486 with ISA VGA card were slightly faster. But it was fast on Windows XP, so it was probably rewritten (to .NET ? ).

  16. GregM says:

    @alegr1 std::stable_sort is stable.  std::sort is not.

  17. anonymouscommenter says:

    Yeah, the event viewer since Vista is awful, regardless of computer speed. It's like it's doing a spin loop to wait a certain amount of time or something.

  18. ahmd says:

    Honest suggestion, based on my personal experience dealing with Windows Event Log in a Win32 service. DO NOT use it! It is seriously flawed. Here are major reasons to abandon it:

    1. It is unreliable. Besides the point of the original question, it will stop logging events right before the system begins shutting down. (And that's when you might **really** need them logged!) This happens because you're technically relying on another service for logging and when shut-down event is broadcast Microsoft logging server may unload before your service does.

    2. As I said above, it relies on another Microsoft service to function and that is an added unnecessary complexity. I've witnessed systems where something went wrong with the Microsoft logging service, that took down my service's logger with it.

    3. The built-in Microsoft Event Viewer is atrocious! Seriously. It's slow, inconvenient to read, hard to navigate, there's no decent search, filters, etc. Don't get me started…

    So what shall one do instead? Easy. Write your own text logger, put it in a class and then reuse it in your other applications. Very easy and reliable solution. You'll remember this later if you waste countless hours trying to see why your Windows Event Log messages are totally out of order or are completely missing…

Comments are closed.

Skip to main content