[prev in list] [next in list] [prev in thread] [next in thread]
List: log4net-user
Subject: =?utf-8?Q?Re:_All_threads_blocked_while_logging?=
From: <piers.williams () gmail ! com>
Date: 2014-10-21 13:46:55
Message-ID: 54466f0e.8165460a.6a87.10e5 () mx ! google ! com
[Download RAW message or body]
[Attachment #2 (text/plain)]
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
[Attachment #3 (text/html)]
<html>
<head>
<meta name="generator" content="Windows Mail 17.5.9600.20605">
<style data-externalstyle="true"><!--
p.MsoListParagraph, li.MsoListParagraph, div.MsoListParagraph {
margin-top:0in;
margin-right:0in;
margin-bottom:0in;
margin-left:.5in;
margin-bottom:.0001pt;
}
p.MsoNormal, li.MsoNormal, div.MsoNormal {
margin:0in;
margin-bottom:.0001pt;
}
p.MsoListParagraphCxSpFirst, li.MsoListParagraphCxSpFirst, \
div.MsoListParagraphCxSpFirst, p.MsoListParagraphCxSpMiddle, \
li.MsoListParagraphCxSpMiddle, div.MsoListParagraphCxSpMiddle, \
p.MsoListParagraphCxSpLast, li.MsoListParagraphCxSpLast, div.MsoListParagraphCxSpLast \
{ margin-top:0in;
margin-right:0in;
margin-bottom:0in;
margin-left:.5in;
margin-bottom:.0001pt;
line-height:115%;
}
--></style></head>
<body dir="ltr">
<div data-externalstyle="false" dir="ltr" style="font-family: 'Calibri', 'Segoe UI', \
'Meiryo', 'Microsoft YaHei UI', 'Microsoft JhengHei UI', 'Malgun Gothic', \
'sans-serif';font-size:12pt;"> <div>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. \
<div style='color: rgb(0, 0, 0); font-family: "Color Emoji", "Calibri", "Segoe UI", \
"Meiryo", "Microsoft YaHei UI", "Microsoft JhengHei UI", "Malgun Gothic", \
"sans-serif"; font-size: 16px;'>I'd imagine you'd have to abort a <em>lot of \
threads</em> for this relatively small race to occur frequently \
however.</div></div><div><br></div><div data-signatureblock="true">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):</div><div><br></div><div>EnterLock()</div><div>try{</div><div><br></div><div>}finally{</div><blockquote \
class="defaultFont" style="margin-top: 0px; margin-right: 0px; margin-bottom: 0px;" \
dir="ltr"><div>ReleaseLock()</div></blockquote><div>}</div><div><br></div><div>had a \
race condition in that the thread could be killed (for various reasons) <strong>prior \
to the try block being entered</strong>*. In CLR 4 Microsoft introduced some \
additional approaches to lock acquisition to remove this, so for \
example</div><div><br></div><div><p><font color="#0000ff" face="Consolas" \
size="2"><font color="#0000ff" face="Consolas" size="2"><font color="#0000ff" \
face="Consolas" size="2">var</font></font></font><font face="Consolas" size="2"><font \
face="Consolas" size="2"> x = </font></font><font color="#0000ff" face="Consolas" \
size="2"><font color="#0000ff" face="Consolas" size="2"><font color="#0000ff" \
face="Consolas" size="2">new</font></font></font><font face="Consolas" size="2"><font \
face="Consolas" size="2"> </font></font><font color="#0000ff" face="Consolas" \
size="2"><font color="#0000ff" face="Consolas" size="2"><font color="#0000ff" \
face="Consolas" size="2">object</font></font></font><font face="Consolas" \
size="2"><font face="Consolas" size="2">();</font></font></p><font face="Consolas" \
size="2"><font face="Consolas" size="2"> </font></font><font color="#0000ff" \
face="Consolas" size="2"><font color="#0000ff" face="Consolas" size="2"><font \
color="#0000ff" face="Consolas" size="2"></font></font></font><p><font \
color="#0000ff" face="Consolas" size="2"><font color="#0000ff" face="Consolas" \
size="2"><font color="#0000ff" face="Consolas" \
size="2">lock</font></font></font><font face="Consolas" size="2"><font \
face="Consolas" size="2">(x){</font></font></p><font face="Consolas" size="2"><font \
face="Consolas" size="2"> </font></font><p style="margin-right: 0px;" dir="ltr"><font \
color="#008000" face="Consolas" size="2"><font color="#008000" face="Consolas" \
size="2"><font color="#008000" face="Consolas" size="2">// something within \
lock</font></font></font></p><font color="#008000" face="Consolas" size="2"><font \
color="#008000" face="Consolas" size="2"><font color="#008000" face="Consolas" \
size="2"> </font></font></font><font face="Consolas" size="2"><font face="Consolas" \
size="2"><p>}</p></font></font></div><div><br></div><div>…now compiles down to \
something quite different to what it did before, using the Monitor.TryEnter() \
overloads:</div><div><br></div><div><p><font color="#0000ff" face="Consolas" \
size="2"><font color="#0000ff" face="Consolas" size="2"><font color="#0000ff" \
face="Consolas" size="2">var</font></font></font><font face="Consolas" size="2"><font \
face="Consolas" size="2"> x = </font></font><font color="#0000ff" face="Consolas" \
size="2"><font color="#0000ff" face="Consolas" size="2"><font color="#0000ff" \
face="Consolas" size="2">new</font></font></font><font face="Consolas" size="2"><font \
face="Consolas" size="2"> </font></font><font color="#0000ff" face="Consolas" \
size="2"><font color="#0000ff" face="Consolas" size="2"><font color="#0000ff" \
face="Consolas" size="2">object</font></font></font><font face="Consolas" \
size="2"><font face="Consolas" size="2">();</font></font></p><font face="Consolas" \
size="2"><font face="Consolas" size="2"> </font></font><font color="#0000ff" \
face="Consolas" size="2"><font color="#0000ff" face="Consolas" size="2"><font \
color="#0000ff" face="Consolas" size="2"></font></font></font><p><font \
color="#0000ff" face="Consolas" size="2"><font color="#0000ff" face="Consolas" \
size="2"><font color="#0000ff" face="Consolas" \
size="2">bool</font></font></font><font face="Consolas" size="2"><font \
face="Consolas" size="2"> wasHeld;</font></font></p><font face="Consolas" \
size="2"><font face="Consolas" size="2"> </font></font><font color="#0000ff" \
face="Consolas" size="2"><font color="#0000ff" face="Consolas" size="2"><font \
color="#0000ff" face="Consolas" size="2"></font></font></font><p><font \
color="#0000ff" face="Consolas" size="2"><font color="#0000ff" face="Consolas" \
size="2"><font color="#0000ff" face="Consolas" size="2">try</font></font></font><font \
face="Consolas" size="2"><font face="Consolas" size="2">{</font></font></p><font \
face="Consolas" size="2"><font face="Consolas" size="2"> </font></font><p><font \
face="Consolas" size="2"><font face="Consolas" size="2"> Monitor.TryEnter(x, \
</font></font><font color="#0000ff" face="Consolas" size="2"><font color="#0000ff" \
face="Consolas" size="2"><font color="#0000ff" face="Consolas" \
size="2">out</font></font></font><font face="Consolas" size="2"><font face="Consolas" \
size="2"> wasHeld);</font></font></p><font face="Consolas" size="2"><font \
face="Consolas" size="2"> </font></font><p><font face="Consolas" size="2"><font \
face="Consolas" size="2"> </font></font><font color="#008000" face="Consolas" \
size="2"><font color="#008000" face="Consolas" size="2"><font color="#008000" \
face="Consolas" size="2">// do stuff</font></font></font></p><font color="#008000" \
face="Consolas" size="2"><font color="#008000" face="Consolas" size="2"><font \
color="#008000" face="Consolas" size="2"> </font></font></font><font face="Consolas" \
size="2"><font face="Consolas" size="2"></font></font><p><font face="Consolas" \
size="2"><font face="Consolas" size="2">}</font></font><font color="#0000ff" \
face="Consolas" size="2"><font color="#0000ff" face="Consolas" size="2"><font \
color="#0000ff" face="Consolas" size="2">finally</font></font></font><font \
face="Consolas" size="2"><font face="Consolas" size="2">{</font></font></p><font \
face="Consolas" size="2"><font face="Consolas" size="2"> </font></font><p><font \
face="Consolas" size="2"><font face="Consolas" size="2"> </font></font><font \
color="#0000ff" face="Consolas" size="2"><font color="#0000ff" face="Consolas" \
size="2"><font color="#0000ff" face="Consolas" size="2">if</font></font></font><font \
face="Consolas" size="2"><font face="Consolas" \
size="2">(wasHeld)</font></font></p><font face="Consolas" size="2"><font \
face="Consolas" size="2"> <p> Monitor.Exit(x);</p>
<p>}</p><p><br></p><p>see <a \
href="http://www.danielmoth.com/Blog/NET-4-MonitorEnter-Replaced-By-MonitorEnter.aspx" \
target="_parent">http://www.danielmoth.com/Blog/NET-4-MonitorEnter-Replaced-By-MonitorEnter.aspx</a></p></font></font></div><div>Unfortunately \
the TryEnter(ref bool) type overloads were <strong>never implemented </strong>for \
ReaderWriterLockSlim (vote here <a \
href="https://connect.microsoft.com/VisualStudio/feedback/details/612135/readerwriterlockslim-tryenter-methods-with-ref-bool-locktaken" \
target="_parent">https://connect.microsoft.com/VisualStudio/feedback/details/612135/readerwriterlockslim-tryenter-methods-with-ref-bool-locktaken</a>). \
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.</div><div><br></div><div>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 : <a href="http://www.albahari.com/threading/part4.aspx#_Aborting_Threads" \
target="_parent">http://www.albahari.com/threading/part4.aspx#_Aborting_Threads</a> \
). I don't know exactly what you're attempting to do, but if possible I'd have \
thought you would benefit from either:</div><div><ul style="padding-top: 0px; \
padding-bottom: 0px; margin-top: 0px; margin-bottom: 0px; list-style-type: disc;"><li \
style='color: rgb(0, 0, 0); font-family: "Color Emoji", "Calibri", "Segoe UI", \
"Meiryo", "Microsoft YaHei UI", "Microsoft JhengHei UI", "Malgun Gothic", \
"sans-serif"; font-size: 16px;'><div>Passing a cancellation token into long-running \
synchronous code, and just check it from time to time</div></li><li style='color: \
rgb(0, 0, 0); font-family: "Color Emoji", "Calibri", "Segoe UI", "Meiryo", "Microsoft \
YaHei UI", "Microsoft JhengHei UI", "Malgun Gothic", "sans-serif"; font-size: \
16px;'><div>Refactor to use an async structure (like Task), and allow the framework \
to deal with the mopup if you cancel the token</div></li></ul></div><div \
style='color: rgb(0, 0, 0); font-family: "Color Emoji", "Calibri", "Segoe UI", \
"Meiryo", "Microsoft YaHei UI", "Microsoft JhengHei UI", "Malgun Gothic", \
"sans-serif"; font-size: 16px;'><br></div><div style='color: rgb(0, 0, 0); \
font-family: "Color Emoji", "Calibri", "Segoe UI", "Meiryo", "Microsoft YaHei UI", \
"Microsoft JhengHei UI", "Malgun Gothic", "sans-serif"; font-size: 16px;'>In the \
meantime, you might want to just consider recycling your process \
periodically.</div><div style='color: rgb(0, 0, 0); font-family: "Color Emoji", \
"Calibri", "Segoe UI", "Meiryo", "Microsoft YaHei UI", "Microsoft JhengHei UI", \
"Malgun Gothic", "sans-serif"; font-size: 16px;'><br></div><div><font \
style="font-size: 10pt;">( * depending on what the JIT actually spits out of \
course. See </font><a \
href="http://joeduffyblog.com/2007/01/29/monitorenter-thread-aborts-and-orphaned-locks/" \
target="_parent"><font style="font-size: \
10pt;">http://joeduffyblog.com/2007/01/29/monitorenter-thread-aborts-and-orphaned-locks/</font></a><font \
style="font-size: 10pt;"> for some gory details on this)</font></div><div><font \
size="2">--</font></div><div><font size="2" style="font-size: 12pt;">Piers, longtime \
log4net lurker</font></div><div><br></div><div style="padding-top: 5px; \
border-top-color: rgb(229, 229, 229); border-top-width: 1px; border-top-style: \
solid;"><div><font face=" 'Calibri', 'Segoe UI', 'Meiryo', 'Microsoft YaHei UI', \
'Microsoft JhengHei UI', 'Malgun Gothic', 'sans-serif'" style='line-height: 15pt; \
letter-spacing: 0.02em; font-family: "Calibri", "Segoe UI", "Meiryo", "Microsoft \
YaHei UI", "Microsoft JhengHei UI", "Malgun Gothic", "sans-serif"; font-size: \
12pt;'><b>From:</b> <a href="mailto:calin.pavel@codemart.ro" \
target="_parent">Calin Pavel</a><br><b>Sent:</b> Friday, October \
17, 2014 5:55 PM<br><b>To:</b> <a \
href="mailto:log4net-user@logging.apache.org" \
target="_parent">log4net-user@logging.apache.org</a></font></div></div><div><br></div><div \
dir=""> <div class="moz-text-html" lang="x-western"> Hello everybody, <br>
<br>
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).<br>
<br>
Lately it happens that the entire application is BLOCKED because
all threads were trying to acquire a read lock, like in the stack
trace:<br>
<small>000000001ac3d998 00000000774715fa [HelperMethodFrame:
000000001ac3d998] System.Threading.Thread.SleepInternal(Int32)<br>
000000001ac3da90 000007fef747b5e9
System.Threading.Thread.Sleep(Int32)<br>
000000001ac3dac0 000007fef5fb9631
System.Threading.ReaderWriterLockSlim.EnterMyLockSpin()<br>
000000001ac3db90 000007fef5cd297e
System.Threading.ReaderWriterLockSlim.TryEnterReadLockCore(TimeoutTracker)<br>
000000001ac3dbf0 000007fef5cd28fa
System.Threading.ReaderWriterLockSlim.TryEnterReadLock(TimeoutTracker)<br>
000000001ac3dc40 000007fe98fb4efd
log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent)<br>
000000001ac3dcc0 000007fe98fb4907
log4net.Repository.Hierarchy.Logger.Log(System.Type,
log4net.Core.Level, System.Object, System.Exception)<br>
000000001ac3dd30 000007fe98fb47f9
log4net.Core.LogImpl.Info(System.Object)</small> <br>
....<br>
<br>
Did you encountered this before or did anybody else reported
similar problems?<br>
<br>
May be it's important to mention:<br>
- I'm using Log4Net 1.2.13, .NET 4.5 on Windows 2008 R2<br>
- that my threads have a timeout, and if they do not finish the
job in the given interval they are aborted. <br>
<br>
In relation with this, I found a possible explanation of
application hanging here: <a \
href="http://chabster.blogspot.ro/2013/07/a-story-of-orphaned-readerwriterlockslim.html" \
target="_parent">http://chabster.blogspot.ro/2013/07/a-story-of-orphaned-readerwriterlockslim.html</a><br>
<br>
Could it be that the acquire of read lock in
Logger.CallAppenderers method to generate our problems?<br>
<br>
Thank you in advance, <br>
Calin Pavel<br>
</div>
</div>
</div>
</body>
</html>
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic