logging-log4net-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From <piers.willi...@gmail.com>
Subject Re: All threads blocked while logging
Date Tue, 21 Oct 2014 13:46:55 GMT
I'll gladly defer to an expert here, but it's my understanding that the pattern that log4net
is currently using within Logger.CallAppenders() does indeed have the problem described in
the link you sent. 
I'd imagine you'd have to abort a lot of threads for this relatively small race to occur frequently
however.




Successfully managing the semantics around atomic lock hold/release in the face of thread
aborts is a bit of a minefield actually, especially as the low-level details (what op codes
the JITer spits out on what architectures) do actually matter. Anyway, my understanding is
it was realized that the typical locking pattern (and that used by log4net):




EnterLock()

try{




}finally{


ReleaseLock()

}




had a race condition in that the thread could be killed (for various reasons) prior to the
try block being entered*. In CLR 4 Microsoft introduced some additional approaches to lock
acquisition to remove this, so for example





var x = new object();

lock(x){

// something within lock

}




…now compiles down to something quite different to what it did before, using the Monitor.TryEnter()
overloads:





var x = new object();

bool wasHeld;

try{

	Monitor.TryEnter(x, out wasHeld);

	// do stuff

}finally{

	if(wasHeld)

Monitor.Exit(x);

}




see http://www.danielmoth.com/Blog/NET-4-MonitorEnter-Replaced-By-MonitorEnter.aspx

Unfortunately the TryEnter(ref bool) type overloads were never implemented for ReaderWriterLockSlim
(vote here https://connect.microsoft.com/VisualStudio/feedback/details/612135/readerwriterlockslim-tryenter-methods-with-ref-bool-locktaken).
So even if log4net's ReaderWriterLock wrapper were to be re-written in this style, it's going
to have to mess about with critical sections etc … to achieve the same thing, and then still
just hope that the implementation is 'right’. Nasty.




I'd have to say, however, that having to abort threads is generally a bad place to be in (good
excerpt from C# in a nutshell here : http://www.albahari.com/threading/part4.aspx#_Aborting_Threads
). I don't know exactly what you're attempting to do, but if possible I'd have thought you
would benefit from either:


Passing a cancellation token into long-running synchronous code, and just check it from time
to time


Refactor to use an async structure (like Task), and allow the framework to deal with the mopup
if you cancel the token





In the meantime, you might want to just consider recycling your process periodically.




( * depending on what the JIT actually spits out of course. See http://joeduffyblog.com/2007/01/29/monitorenter-thread-aborts-and-orphaned-locks/
for some gory details on this)

--

Piers, longtime log4net lurker





From: Calin Pavel
Sent: ‎Friday‎, ‎October‎ ‎17‎, ‎2014 ‎5‎:‎55‎ ‎PM
To: log4net-user@logging.apache.org





Hello everybody, 

I do have an .NET application (Windows Service) that collects data from a lot of sources (DBs,
log files, machines event logs, ...) and uses Log4Net to log details of the actions / execution.
 As expected, I'm using a high number of threads to collect data, threads that are writing
logs in some files (RollingFileAppenderer).

Lately it happens that the entire application is BLOCKED because all threads were trying to
acquire a read lock, like in the stack trace:
000000001ac3d998 00000000774715fa [HelperMethodFrame: 000000001ac3d998] System.Threading.Thread.SleepInternal(Int32)
000000001ac3da90 000007fef747b5e9 System.Threading.Thread.Sleep(Int32)
000000001ac3dac0 000007fef5fb9631 System.Threading.ReaderWriterLockSlim.EnterMyLockSpin()
000000001ac3db90 000007fef5cd297e System.Threading.ReaderWriterLockSlim.TryEnterReadLockCore(TimeoutTracker)
000000001ac3dbf0 000007fef5cd28fa System.Threading.ReaderWriterLockSlim.TryEnterReadLock(TimeoutTracker)
000000001ac3dc40 000007fe98fb4efd log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent)
000000001ac3dcc0 000007fe98fb4907 log4net.Repository.Hierarchy.Logger.Log(System.Type, log4net.Core.Level,
System.Object, System.Exception)
000000001ac3dd30 000007fe98fb47f9 log4net.Core.LogImpl.Info(System.Object)  
....

Did you encountered this before or did anybody else reported similar problems?

May be it's important to mention:
- I'm using Log4Net 1.2.13, .NET 4.5 on Windows 2008 R2
- that my threads have a timeout, and if they do not finish the job in the given interval
they are aborted. 

In relation with this, I found a possible explanation of application hanging here: http://chabster.blogspot.ro/2013/07/a-story-of-orphaned-readerwriterlockslim.html

Could it be that the acquire of read lock in Logger.CallAppenderers method to generate our
problems?

Thank you in advance, 
Calin Pavel
Mime
View raw message