CODEWITHSUNDEEP
c#log4net
jeff
jeff

Reputation: 3327

is it possible log4net writes things out of order in a multithreaded app

I have a multithreaded C# app for which we use common.logging/log4net. while the logs read reasonably as one would expect, the timestamps can be pretty far off. I'm questioning if I can trust what I see, in terms of order of operations.

In this case I'm tracking memory and resetting my ConsumerUI. In the T09:27 entry I have lots of memory, in the next entry, T04:27 I don't. But you'll notice the T04 timestamp precedes the prior log entry by like 5 hours.

I've added diagnostic code to see if the log statements are truly out of order they are not. A timestamp arrives that is simply wrong.

What is going on here?

enter image description here

enter image description here

Upvotes: 1

Views: 390

Answers (2)

PhillipH
PhillipH

Reputation: 6222

Yes. All logging is Async. Its up to the log reader to correllate a coherent time sequence from the log files written. If this wasnt the case, logging would impost a hideous syncblock on an otherwise multithreaded application.

Upvotes: 2

Tim
Tim

Reputation: 2912

Depending on your log target configuration, the order of logged operations may be very far off. Typically for DB, file, or other expensive IO logging targets, a buffering Async wrapper is used, which will write to the IO target in batches, depending on usage. So it is fairly common to have the order that they get flushed not match the order that they were logged.

We always order our logs by the dateLoggedUTC (our field for that date) in order to really understand the order of operations.

Upvotes: 0

Related Questions