You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4cxx-user@logging.apache.org by BUNBURY Myles <My...@alcatel-lucent.com> on 2007/09/28 23:27:25 UTC

Log4cxx wilting under heavy load

Log4cxx seems to wilt when under heavy load.

With the syslog appender enabled, the application cores when under heavy load.

When using a RollingFileAppender with an XMLLayout layout, my output file gets garbled:

<<<snip>>>

<log4j:event logger="Gateway.AuthenticationServices/ANS_AuthenticationService.cpp" timestamp="1191005220721" level="INFO" thread="0x61eb3b90">
<log4j:message><![CDATA[No username/password token or SAML assertion to process.]]></log4j:message>
</log4j:event>
<log4j:event logger="Gateway.MediationPipeline/MED_PipelineMessage.cpp" timestamp="1191005220721" level="INFO" thread="0x61eb3b90">
<log4j:message><![CDATA[No session policy set for user/group .]]></log4j:message>
</log4j:event>
<log4j:event logger="Gateway.MediationPipeline/MED_PipelineMessage.cpp" timestamp="1191005220721" level="DEBUG" thread="0x61eb3b90">
<log4j:message><![CDATA[Using session #2 with session policy DefaultPolicy.]]></log4j:message>
</log4j:event>
<log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp" timestamp="1191005220729" level="WARN" thread="0x5ecaeb90">
<log4j:message><![CDATA[Concurrent session limit reached. Transaction is rejected.]]></log4j:message>
</log4j:event>
<log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp" timestamp="1191005220729" level="ERROR" thread="0x5ecaeb90">
<log4j:message><![CDATA[User session rejected - have exceeded the maximum number of concurrent sessions based on the current license (0 concurrent sessions allowed)]]></log4j:message>
</log4j:event>
¦«    "          ´T#
ýÍÊ^˜ÌÊ^Ä        °Ñ"
ôÌÊ^µ	‡·<T#
ÜÑ"
            XÍÊ^       <T#
ÜÑ"
À4‡·    dÐÊ^ÍÊ^§c    ´T#
    ð‡·°Ñ"
@ÍÊ^1ֆ· T#
¸Ñ"
            XÍÊ^           ôO ÔÑ"
        |ó³            hÍÊ^
   Þ$z  XÍÊ^p÷³ xÍÊ^/&L4#
z  ¸ÍÊ^Z;'°Ñ"
    ¸ÍÊ^ü(H4#
ðÍÊ^¸ÍÊ^13 Ì€ðÍÊ^ðÍÊ^            
   
   Þ$z  ÏÊ^ÄydÐÊ^ðÍÊ^    ðÍÊ^ ÏÊ^PÏÊ^XÏÊ^h         ·‹·    1191‘À‹·20729&ô €¼ÏÊ^(ÎÊ^®Ý‹· €È €—ÎÊ^H€¼ÏÊ^H €@ €   ô5  À€       €À€   ¼ÏÊ^xÎÊ^  €   Ðõ‹··‹·ôO À€   ˆÎÊ^@ €‹‚&   ·‹·      X~—·¨ÎÊ^5
´ dÐÊ^Þ$¸ÎÊ^ H&    çÎÊ^ÏÊ^^¥!øÎÊ^°#
ÏÊ^§c %  ôèÎÊ^ðÆ0ÐÊ^'ÏÊ^øÎÊ^ÙÃ'ÏÊ^'ÏÊ^(ÏÊ^žÇ'ÏÊ^'ÏÊ^SÏÊ^ͦ!\sA
dÐÊ^(ÏÊ^%LRÏÊ^´ÏÊ^XÏÊ^ÖÇRÏÊ^SÏÊ^RÏÊ^¶0 \sA
kÏÊ^XÏÊ^¶&$HsA
dÐÊ^ÈÏÊ^¦«0ÐÊ^Þ$xÏÊ^íÃHÐÊ^ÿÿÿÿˆÏÊ^ÄHÐÊ^l4¸ÏÊ^6ÉHÐÊ^    ó   ôO l4z  ÈÏÊ^e4 HÐÊ^dÐÊ^ÈÏÊ^uÉHÐÊ^Þ$ˆÐÊ^@š!HÐÊ^l4  HÒÊ^ÑÊ^ÿÿÿÿ‘â³ Z;'°Ñ" j  8ÐÊ^ü(0x5ecaeb90Ê^13 4€pÐÊ^pÐÊ^    Þ$z  HÐÊ^Í&ä6%
        4ÐÊ^4ÐÊ^    ˆÐÊ^
*à6%
LÐÊ^LÐÊ^    Üí#
Ì€˜ÐÊ^<log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp" timestamp="1191005220729" level="WARN" thread="0x600b0b90">
<log4j:message><![CDATA[Concurrent session limit reached. Transaction is rejected.]]></log4j:message>
</log4j:event>
<log4j:event logger="Gateway.MediationPipeline/MED_PipelineMessage.cpp" timestamp="1191005220729" level="INFO" thread="0x5ecaeb90">
<log4j:message><![CDATA[Auth'ed user hitting dend. Transaction is rejected.]]></log4j:message>
</log4j:event>
<log4j:event logger="Gateway.MediationPipeline/MED_PipelineMessage.cpp" timestamp="1191005220729" level="INFO" thread="0x5ecaeb90">
<log4j:message><![CDATA[Auth'ed user hitting deny-all ws]]></log4j:message>
</log4j:event>
<log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp" timestamp="1191005220729" level="ERROR" thread="0x600b0b90">
<log4j:message><![CDATA[User session rejected - have exceeded the maximum number of concurrent sessions based on the current license (0 concurrent sessions allowed)]]></log4j:message>
</log4j:event>

<<<snip>>>

This output was generated with ~150 threads throwing out error messages in rapid succession.

I have not noted these problems when treading lightly on the system.

At this point I'm suspicious that log4cxx is overflowing some sort of output buffer that's fills up due to the volume. I don't believe it is a multithreading issue as I serialized the logging calls in my code with a mutex and did not note any change.

Has anyone else noted something similiar?

How is log4cxx supposed to behave when the logging volume exceeds its capacity to output those events?

RE: Log4cxx wilting under heavy load

Posted by BUNBURY Myles <My...@alcatel-lucent.com>.
> -----Original Message-----
> From: Curt Arnold [mailto:carnold@apache.org] 
> Sent: Friday, September 28, 2007 6:11 PM
> To: Log4CXX User
> Subject: Re: Log4cxx wilting under heavy load
> 
> 
> On Sep 28, 2007, at 4:27 PM, BUNBURY Myles wrote:
> 
> > Log4cxx seems to wilt when under heavy load.
> >
> > With the syslog appender enabled, the application cores when under  
> > heavy load.
> >
> > When using a RollingFileAppender with an XMLLayout layout, my  
> > output file gets garbled:
> >
> > <<<snip>>>
> >
> > <log4j:event logger="Gateway.AuthenticationServices/ 
> > ANS_AuthenticationService.cpp" timestamp="1191005220721"  
> > level="INFO" thread="0x61eb3b90">
> > <log4j:message><![CDATA[No username/password token or SAML  
> > assertion to process.]]></log4j:message>
> > </log4j:event>
> > <log4j:event logger="Gateway.MediationPipeline/ 
> > MED_PipelineMessage.cpp" timestamp="1191005220721" level="INFO"  
> > thread="0x61eb3b90">
> > <log4j:message><![CDATA[No session policy set for user/group .]]></ 
> > log4j:message>
> > </log4j:event>
> > <log4j:event logger="Gateway.MediationPipeline/ 
> > MED_PipelineMessage.cpp" timestamp="1191005220721" level="DEBUG"  
> > thread="0x61eb3b90">
> > <log4j:message><![CDATA[Using session #2 with session policy  
> > DefaultPolicy.]]></log4j:message>
> > </log4j:event>
> > <log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp"  
> > timestamp="1191005220729" level="WARN" thread="0x5ecaeb90">
> > <log4j:message><![CDATA[Concurrent session limit reached.  
> > Transaction is rejected.]]></log4j:message>
> > </log4j:event>
> > <log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp"  
> > timestamp="1191005220729" level="ERROR" thread="0x5ecaeb90">
> > <log4j:message><![CDATA[User session rejected - have exceeded the  
> > maximum number of concurrent sessions based on the current license  
> > (0 concurrent sessions allowed)]]></log4j:message>
> > </log4j:event>
> > ¦«    "          ´T#
> > ýÍÊ^˜ÌÊ^Ä        °Ñ"
> > ôÌÊ^µ   ‡·<T#
> > ÜÑ"
> >             XÍÊ^       <T#
> > ÜÑ"
> > À4‡·    dÐÊ^ÍÊ^§c    ´T#
> >     ð‡·°Ñ"
> > @ÍÊ^1Ö†· T#
> > ¸Ñ"
> >             XÍÊ^           ôO ÔÑ"
> >         |ó³            hÍÊ^
> >    Þ$z  XÍÊ^p÷³ xÍÊ^/&L4#
> > z  ¸ÍÊ^Z;'°Ñ"
> >     ¸ÍÊ^ü(H4#
> > ðÍÊ^¸ÍÊ^13 Ì€ðÍÊ^ðÍÊ^
> >
> >    Þ$z  ÏÊ^ÄydÐÊ^ðÍÊ^    ðÍÊ^  
> > ÏÊ^PÏÊ^XÏÊ^h         ·‹·     
> > 1191‘À‹·20729&ô €¼ÏÊ^(ÎÊ^®Ý‹· €È  
> > €—ÎÊ^H€¼ÏÊ^H €@ €   ô5  À 
> > €       €À€   ¼ÏÊ^xÎÊ^  €    
> > Ðõ‹··‹·ôO À€   ˆÎÊ^@ €‹‚&    
> > ·‹·      X~—·¨ÎÊ^5
> > ´ dÐÊ^Þ$¸ÎÊ^ H&    çÎÊ^ÏÊ^^¥!øÎÊ^°#
> > ÏÊ^§c %   
> > ôèÎÊ^ðÆ0ÐÊ^'ÏÊ^øÎÊ^ÙÃ'ÏÊ^'ÏÊ^ 
> > (ÏÊ^žÇ'ÏÊ^'ÏÊ^SÏÊ^ͦ!\sA
> > dÐÊ^(ÏÊ^%LRÏÊ^´ÏÊ^XÏÊ^ÖÇRÏÊ^SÏÊ^RÏÊ^¶0 \sA
> > kÏÊ^XÏÊ^¶&$HsA
> > dÐÊ^ÈÏÊ^¦«0ÐÊ^Þ 
> > $xÏÊ^íÃHÐÊ^ÿÿÿÿˆÏÊ^ÄHÐÊ^l4¸ÏÊ^6ÉHÐÊ^   
> >   ó   ôO l4z  ÈÏÊ^e4 HÐÊ^dÐÊ^ÈÏÊ^uÉHÐÊ^Þ 
> > $ˆÐÊ^@š!HÐÊ^l4  HÒÊ^ÑÊ^ÿÿÿÿ‘â³ Z;'°Ñ"  
> > j  8ÐÊ^ü(0x5ecaeb90Ê^13 4€pÐÊ^pÐÊ^    Þ$z   
> > HÐÊ^Í&ä6%
> >         4ÐÊ^4ÐÊ^    ˆÐÊ^
> > *à6%
> > LÐÊ^LÐÊ^    Üí#
> > Ì€˜ÐÊ^<log4j:event logger="Gateway.SessionInfra/ 
> > SI_SessionManager.cpp" timestamp="1191005220729" level="WARN"  
> > thread="0x600b0b90">
> > <log4j:message><![CDATA[Concurrent session limit reached.  
> > Transaction is rejected.]]></log4j:message>
> > </log4j:event>
> > <log4j:event logger="Gateway.MediationPipeline/ 
> > MED_PipelineMessage.cpp" timestamp="1191005220729" level="INFO"  
> > thread="0x5ecaeb90">
> > <log4j:message><![CDATA[Auth'ed user hitting dend. Transaction is  
> > rejected.]]></log4j:message>
> > </log4j:event>
> > <log4j:event logger="Gateway.MediationPipeline/ 
> > MED_PipelineMessage.cpp" timestamp="1191005220729" level="INFO"  
> > thread="0x5ecaeb90">
> > <log4j:message><![CDATA[Auth'ed user hitting deny-all ws]]></ 
> > log4j:message>
> > </log4j:event>
> > <log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp"  
> > timestamp="1191005220729" level="ERROR" thread="0x600b0b90">
> > <log4j:message><![CDATA[User session rejected - have exceeded the  
> > maximum number of concurrent sessions based on the current license  
> > (0 concurrent sessions allowed)]]></log4j:message>
> > </log4j:event>
> >
> > <<<snip>>>
> >
> > This output was generated with ~150 threads throwing out error  
> > messages in rapid succession.
> >
> > I have not noted these problems when treading lightly on the system.
> >
> > At this point I'm suspicious that log4cxx is overflowing some sort  
> > of output buffer that's fills up due to the volume. I don't 
> believe  
> > it is a multithreading issue as I serialized the logging calls in  
> > my code with a mutex and did not note any change.
> >
> > Has anyone else noted something similiar?
> >
> > How is log4cxx supposed to behave when the logging volume exceeds  
> > its capacity to output those events?
> >
> 
> There was a similar symptoms reported in https://issues.apache.org/ 
> jira/browse/LOGCXX-186.  That ended up being due to attempting to  
> configure log4cxx simultaneously on multiple threads.  I assume that  
> is not the case with you, but could you confirm that the problem  
> persists if you configure and attempt a logging request prior to  
> launching threads (assuming that your app is the one launching the  
> threads).
> 
> If that is not the case, then the previous bug report might be  
> instructive to try to identify and fix the problem.  The problems  
> might be related, but perhaps not.  I would focus on trying to  
> identify the one that is most significant to you and then see if any  
> resolution fixed the other.
> 
> I would suggest:
> 
> 1. Make sure that you are using the most current SVN HEAD.
> 
> 2. Making sure that configuration and some initial log 
> requests occur  
> before threads are launched.  (previously mentioned).
> 
> 3. Wrap the failing appender in the soon to be committed rewrite of  
> AsyncAppender (if not in the next hour or so, at least by mid-day  
> tomorrow).  AsyncAppender has been badly flawed.  I'm just about the  
> commit a port of the log4j 1.2.14 AsyncAppender (which replaced an  
> earlier log4j implementation that was badly flawed too).  
> That should  
> have the affect of bringing all appends on the underlying appender  
> down to a common thread.  Plus it would be a great stress 
> test of all  
> my new code (thanks for volunteering for testing).
> 
> 4. Simplify, simplify.  There are a couple of places that corruption  
> may be occurring.  It could be an Appender problem, a Layout 
> problem,  
> a CharsetEncoder problem, a CharsetDecoder problem or some  
> combination.  Trying to isolate the problem makes resolution a lot  
> easier.
>      a) Setting LOG4CXX_LOGCHAR_IS_UTF8 would replace an conversion  
> between the local code page and UTF-8 with a straight copy.   
> Eliminating a lot of complexity and potential source of problems.
>      b) Replace the layout (if there is one) with something 
> simpler.   
> First try simplifying the pattern as much as possible like %m%n.
>      c) See if the problem occurs with the simpler appenders  
> (FileAppender instead of RollingFileAppender) or other unrelated  
> appenders.
> 
> 5. Attempt to recreate the problem in a sample app that you can  
> attach to a bug report.  Please specify all specifics of the  
> configurations (operating system, compiler, type and number of  
> processors, etc) that have been tested and whether they fail  
> consistently, have not been observed to fail or somewhere in between.
> 
> 6. If you are running on a x86 Unix, valgrind could be useful to  
> identify potential problems.  I used the helgrind tool in earlier  
> versions of valgrind (its been broken for a while, so had to 
> build it  
> from source) to identify potential race conditions.  Other tools  
> might be useful to identify the problem.



Firstly, the relevant portions of the log4cxx.properties file might be a useful reference:

---
log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.File=${WSG_HOME}/grizzlyGW.log
log4j.appender.file.MaxFileSize=10000KB
log4j.appender.file.MaxBackupIndex=10
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{ISO8601} %5p [%c] (%F:%L) %t: %m%n

log4j.appender.XMLFile=org.apache.log4j.RollingFileAppender
log4j.appender.XMLFile.File=${WSG_HOME}/grizzlyGW.xml
log4j.appender.XMLFile.MaxFileSize=10000KB
log4j.appender.XMLFile.MaxBackupIndex=10
log4j.appender.XMLFile.layout=org.apache.log4j.xml.XMLLayout

log4j.appender.file2=org.apache.log4j.FileAppender
log4j.appender.file2.File=${WSG_HOME}/grizzlyGW2.log
log4j.appender.file2.layout=org.apache.log4j.PatternLayout
log4j.appender.file2.layout.ConversionPattern=%m%n

log4j.appender.XMLFileGateway=org.apache.log4j.RollingFileAppender
log4j.appender.XMLFileGateway.File=${WSG_HOME}/grizzlyGW2.xml
log4j.appender.XMLFileGateway.MaxFileSize=10000KB
log4j.appender.XMLFileGateway.MaxBackupIndex=10
log4j.appender.XMLFileGateway.layout=org.apache.log4j.xml.XMLLayout

log4j.rootLogger=off, XMLFile
log4j.logger.Gateway=warn, file2
---

The following were all done without syncronizing log messages as I mentioned trying before. The log4cxx code was based on revision #572744, with the modifications I mentioned in LOGCXX-191 (pre-"official" fix). As the modifications relate to the syslog appender, and are relatively minor, I doubt that they are influencing the results outlined below since syslog is not involved in my tests.

I tried forcing a log message in the same thread that configured the logging system, immediately after the configuration was done and before any threads started pounding away. I did not note any change in behaviour, so I went back to what I had before.


I simplified things down to a FileAppender appender with a PatternLayout layout set to '%m%n':
log4j.rootLogger=off
log4j.logger.Gateway=debug, file2

The corrupt output was not visible in the log.


I readded the XMLFile appender to the root logger:
log4j.rootLogger=off, XMLFile
log4j.logger.Gateway=debug, file2

The corrupt output was visible in both the XML and plaintext logs.


I removed the simplified plaintext appender:
log4j.rootLogger=off, XMLFile
log4j.logger.Gateway=debug

The corrupt output was not visible in the log.


I removed the simplified plaintext appender:
log4j.rootLogger=off, XMLFile
log4j.logger.Gateway=debug, XMLFileGateway

The corrupt output was visible in both XML logs.


At this point, I'm starting to think it's got something to do with either having multiple appenders on the go, or simply something bad in the XML layout that garbles things for subsequent appenders.


I tried two plaintext appenders. I reduced the 'file' appender to a simple FileAppender with a pattern layout of '%m%n':
log4j.rootLogger=off, file
log4j.logger.Gateway=debug, file2

The corrupt output was visible in both plaintext logs.


At this point, it seems to me that the verdict is in: there's a bug that corrupts data when multiple appenders (regardless of type) are present.


For amusement, I tried combining appenders on a single logger:
log4j.rootLogger=off, file, file2
log4j.logger.Gateway=debug

The corrupt output was not visible in the logs.


For more amusement, I tried combining appenders on a single logger other than the root logger:
log4j.rootLogger=off
log4j.logger.Gateway=debug, file, file2

The corrupt output was not visible in the logs.


Since I'm guessing the 'OFF' level isn't used all that commonly, I tried enabling the root logger with the appenders on separate loggers:
log4j.rootLogger=info, file
log4j.logger.Gateway=debug, file2

The corrupt output was visible in both plaintext logs.


These extra tests confim my ealier verdict as to the cause.

I will open a bug based on this information. I will post the bug number to the user group when I have it. Further information on this problem will be logged there.

Next steps:
-Verify that the problem still exists in a clean copy of SVN-HEAD. (I expect it does.)
-Determine whether the core dumps I experienced when using the syslog appender are related to this same issue.


---
 
Myles Bunbury, P.Eng., BASc.
Software Development Engineering Specialist 
Web Services Internal Venture
Alcatel-Lucent
 
Phone: (613) 784-4325
Fax: (613) 784-8944
Web: www.alcatel-lucent.com

RE: Log4cxx wilting under heavy load

Posted by BUNBURY Myles <My...@alcatel-lucent.com>.
This issue has been recorded as bug #LOGCXX-194.



> -----Original Message-----
> From: BUNBURY Myles 
> Sent: Monday, October 01, 2007 12:05 PM
> To: Log4CXX User
> Subject: RE: Log4cxx wilting under heavy load
> 
> > -----Original Message-----
> > From: Curt Arnold [mailto:carnold@apache.org] 
> > Sent: Friday, September 28, 2007 6:11 PM
> > To: Log4CXX User
> > Subject: Re: Log4cxx wilting under heavy load
> > 
> > 
> > On Sep 28, 2007, at 4:27 PM, BUNBURY Myles wrote:
> > 
> > > Log4cxx seems to wilt when under heavy load.
> > >
> > > With the syslog appender enabled, the application cores 
> when under  
> > > heavy load.
> > >
> > > When using a RollingFileAppender with an XMLLayout layout, my  
> > > output file gets garbled:
> > >
> > > <<<snip>>>
> > >
> > > <log4j:event logger="Gateway.AuthenticationServices/ 
> > > ANS_AuthenticationService.cpp" timestamp="1191005220721"  
> > > level="INFO" thread="0x61eb3b90">
> > > <log4j:message><![CDATA[No username/password token or SAML  
> > > assertion to process.]]></log4j:message>
> > > </log4j:event>
> > > <log4j:event logger="Gateway.MediationPipeline/ 
> > > MED_PipelineMessage.cpp" timestamp="1191005220721" level="INFO"  
> > > thread="0x61eb3b90">
> > > <log4j:message><![CDATA[No session policy set for 
> user/group .]]></ 
> > > log4j:message>
> > > </log4j:event>
> > > <log4j:event logger="Gateway.MediationPipeline/ 
> > > MED_PipelineMessage.cpp" timestamp="1191005220721" level="DEBUG"  
> > > thread="0x61eb3b90">
> > > <log4j:message><![CDATA[Using session #2 with session policy  
> > > DefaultPolicy.]]></log4j:message>
> > > </log4j:event>
> > > <log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp"  
> > > timestamp="1191005220729" level="WARN" thread="0x5ecaeb90">
> > > <log4j:message><![CDATA[Concurrent session limit reached.  
> > > Transaction is rejected.]]></log4j:message>
> > > </log4j:event>
> > > <log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp"  
> > > timestamp="1191005220729" level="ERROR" thread="0x5ecaeb90">
> > > <log4j:message><![CDATA[User session rejected - have 
> exceeded the  
> > > maximum number of concurrent sessions based on the 
> current license  
> > > (0 concurrent sessions allowed)]]></log4j:message>
> > > </log4j:event>
> > > ¦«    "          ´T#
> > > ýÍÊ^˜ÌÊ^Ä        °Ñ"
> > > ôÌÊ^µ   ‡·<T#
> > > ÜÑ"
> > >             XÍÊ^       <T#
> > > ÜÑ"
> > > À4‡·    dÐÊ^ÍÊ^§c    ´T#
> > >     ð‡·°Ñ"
> > > @ÍÊ^1Ö†· T#
> > > ¸Ñ"
> > >             XÍÊ^           ôO ÔÑ"
> > >         |ó³            hÍÊ^
> > >    Þ$z  XÍÊ^p÷³ xÍÊ^/&L4#
> > > z  ¸ÍÊ^Z;'°Ñ"
> > >     ¸ÍÊ^ü(H4#
> > > ðÍÊ^¸ÍÊ^13 Ì€ðÍÊ^ðÍÊ^
> > >
> > >    Þ$z  ÏÊ^ÄydÐÊ^ðÍÊ^    ðÍÊ^  
> > > ÏÊ^PÏÊ^XÏÊ^h         ·‹·     
> > > 1191‘À‹·20729&ô €¼ÏÊ^(ÎÊ^®Ý‹· €È  
> > > €—ÎÊ^H€¼ÏÊ^H €@ €   ô5  À 
> > > €       €À€   ¼ÏÊ^xÎÊ^  €    
> > > Ðõ‹··‹·ôO À€   ˆÎÊ^@ €‹‚&    
> > > ·‹·      X~—·¨ÎÊ^5
> > > ´ dÐÊ^Þ$¸ÎÊ^ H&    çÎÊ^ÏÊ^^¥!øÎÊ^°#
> > > ÏÊ^§c %   
> > > ôèÎÊ^ðÆ0ÐÊ^'ÏÊ^øÎÊ^ÙÃ'ÏÊ^'ÏÊ^ 
> > > (ÏÊ^žÇ'ÏÊ^'ÏÊ^SÏÊ^ͦ!\sA
> > > dÐÊ^(ÏÊ^%LRÏÊ^´ÏÊ^XÏÊ^ÖÇRÏÊ^SÏÊ^RÏÊ^¶0 \sA
> > > kÏÊ^XÏÊ^¶&$HsA
> > > dÐÊ^ÈÏÊ^¦«0ÐÊ^Þ 
> > > $xÏÊ^íÃHÐÊ^ÿÿÿÿˆÏÊ^ÄHÐÊ^l4¸ÏÊ^6ÉHÐÊ^   
> > >   ó   ôO l4z  ÈÏÊ^e4 HÐÊ^dÐÊ^ÈÏÊ^uÉHÐÊ^Þ 
> > > $ˆÐÊ^@š!HÐÊ^l4  HÒÊ^ÑÊ^ÿÿÿÿ‘â³ Z;'°Ñ"  
> > > j  8ÐÊ^ü(0x5ecaeb90Ê^13 4€pÐÊ^pÐÊ^    Þ$z   
> > > HÐÊ^Í&ä6%
> > >         4ÐÊ^4ÐÊ^    ˆÐÊ^
> > > *à6%
> > > LÐÊ^LÐÊ^    Üí#
> > > Ì€˜ÐÊ^<log4j:event logger="Gateway.SessionInfra/ 
> > > SI_SessionManager.cpp" timestamp="1191005220729" level="WARN"  
> > > thread="0x600b0b90">
> > > <log4j:message><![CDATA[Concurrent session limit reached.  
> > > Transaction is rejected.]]></log4j:message>
> > > </log4j:event>
> > > <log4j:event logger="Gateway.MediationPipeline/ 
> > > MED_PipelineMessage.cpp" timestamp="1191005220729" level="INFO"  
> > > thread="0x5ecaeb90">
> > > <log4j:message><![CDATA[Auth'ed user hitting dend. 
> Transaction is  
> > > rejected.]]></log4j:message>
> > > </log4j:event>
> > > <log4j:event logger="Gateway.MediationPipeline/ 
> > > MED_PipelineMessage.cpp" timestamp="1191005220729" level="INFO"  
> > > thread="0x5ecaeb90">
> > > <log4j:message><![CDATA[Auth'ed user hitting deny-all ws]]></ 
> > > log4j:message>
> > > </log4j:event>
> > > <log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp"  
> > > timestamp="1191005220729" level="ERROR" thread="0x600b0b90">
> > > <log4j:message><![CDATA[User session rejected - have 
> exceeded the  
> > > maximum number of concurrent sessions based on the 
> current license  
> > > (0 concurrent sessions allowed)]]></log4j:message>
> > > </log4j:event>
> > >
> > > <<<snip>>>
> > >
> > > This output was generated with ~150 threads throwing out error  
> > > messages in rapid succession.
> > >
> > > I have not noted these problems when treading lightly on 
> the system.
> > >
> > > At this point I'm suspicious that log4cxx is overflowing 
> some sort  
> > > of output buffer that's fills up due to the volume. I don't 
> > believe  
> > > it is a multithreading issue as I serialized the logging 
> calls in  
> > > my code with a mutex and did not note any change.
> > >
> > > Has anyone else noted something similiar?
> > >
> > > How is log4cxx supposed to behave when the logging volume 
> exceeds  
> > > its capacity to output those events?
> > >
> > 
> > There was a similar symptoms reported in https://issues.apache.org/ 
> > jira/browse/LOGCXX-186.  That ended up being due to attempting to  
> > configure log4cxx simultaneously on multiple threads.  I 
> assume that  
> > is not the case with you, but could you confirm that the problem  
> > persists if you configure and attempt a logging request prior to  
> > launching threads (assuming that your app is the one launching the  
> > threads).
> > 
> > If that is not the case, then the previous bug report might be  
> > instructive to try to identify and fix the problem.  The problems  
> > might be related, but perhaps not.  I would focus on trying to  
> > identify the one that is most significant to you and then 
> see if any  
> > resolution fixed the other.
> > 
> > I would suggest:
> > 
> > 1. Make sure that you are using the most current SVN HEAD.
> > 
> > 2. Making sure that configuration and some initial log 
> > requests occur  
> > before threads are launched.  (previously mentioned).
> > 
> > 3. Wrap the failing appender in the soon to be committed 
> rewrite of  
> > AsyncAppender (if not in the next hour or so, at least by mid-day  
> > tomorrow).  AsyncAppender has been badly flawed.  I'm just 
> about the  
> > commit a port of the log4j 1.2.14 AsyncAppender (which replaced an  
> > earlier log4j implementation that was badly flawed too).  
> > That should  
> > have the affect of bringing all appends on the underlying appender  
> > down to a common thread.  Plus it would be a great stress 
> > test of all  
> > my new code (thanks for volunteering for testing).
> > 
> > 4. Simplify, simplify.  There are a couple of places that 
> corruption  
> > may be occurring.  It could be an Appender problem, a Layout 
> > problem,  
> > a CharsetEncoder problem, a CharsetDecoder problem or some  
> > combination.  Trying to isolate the problem makes resolution a lot  
> > easier.
> >      a) Setting LOG4CXX_LOGCHAR_IS_UTF8 would replace an 
> conversion  
> > between the local code page and UTF-8 with a straight copy.   
> > Eliminating a lot of complexity and potential source of problems.
> >      b) Replace the layout (if there is one) with something 
> > simpler.   
> > First try simplifying the pattern as much as possible like %m%n.
> >      c) See if the problem occurs with the simpler appenders  
> > (FileAppender instead of RollingFileAppender) or other unrelated  
> > appenders.
> > 
> > 5. Attempt to recreate the problem in a sample app that you can  
> > attach to a bug report.  Please specify all specifics of the  
> > configurations (operating system, compiler, type and number of  
> > processors, etc) that have been tested and whether they fail  
> > consistently, have not been observed to fail or somewhere 
> in between.
> > 
> > 6. If you are running on a x86 Unix, valgrind could be useful to  
> > identify potential problems.  I used the helgrind tool in earlier  
> > versions of valgrind (its been broken for a while, so had to 
> > build it  
> > from source) to identify potential race conditions.  Other tools  
> > might be useful to identify the problem.
> 
> 
> 
> Firstly, the relevant portions of the log4cxx.properties file 
> might be a useful reference:
> 
> ---
> log4j.appender.file=org.apache.log4j.RollingFileAppender
> log4j.appender.file.File=${WSG_HOME}/grizzlyGW.log
> log4j.appender.file.MaxFileSize=10000KB
> log4j.appender.file.MaxBackupIndex=10
> log4j.appender.file.layout=org.apache.log4j.PatternLayout
> log4j.appender.file.layout.ConversionPattern=%d{ISO8601} %5p 
> [%c] (%F:%L) %t: %m%n
> 
> log4j.appender.XMLFile=org.apache.log4j.RollingFileAppender
> log4j.appender.XMLFile.File=${WSG_HOME}/grizzlyGW.xml
> log4j.appender.XMLFile.MaxFileSize=10000KB
> log4j.appender.XMLFile.MaxBackupIndex=10
> log4j.appender.XMLFile.layout=org.apache.log4j.xml.XMLLayout
> 
> log4j.appender.file2=org.apache.log4j.FileAppender
> log4j.appender.file2.File=${WSG_HOME}/grizzlyGW2.log
> log4j.appender.file2.layout=org.apache.log4j.PatternLayout
> log4j.appender.file2.layout.ConversionPattern=%m%n
> 
> log4j.appender.XMLFileGateway=org.apache.log4j.RollingFileAppender
> log4j.appender.XMLFileGateway.File=${WSG_HOME}/grizzlyGW2.xml
> log4j.appender.XMLFileGateway.MaxFileSize=10000KB
> log4j.appender.XMLFileGateway.MaxBackupIndex=10
> log4j.appender.XMLFileGateway.layout=org.apache.log4j.xml.XMLLayout
> 
> log4j.rootLogger=off, XMLFile
> log4j.logger.Gateway=warn, file2
> ---
> 
> The following were all done without syncronizing log messages 
> as I mentioned trying before. The log4cxx code was based on 
> revision #572744, with the modifications I mentioned in 
> LOGCXX-191 (pre-"official" fix). As the modifications relate 
> to the syslog appender, and are relatively minor, I doubt 
> that they are influencing the results outlined below since 
> syslog is not involved in my tests.
> 
> I tried forcing a log message in the same thread that 
> configured the logging system, immediately after the 
> configuration was done and before any threads started 
> pounding away. I did not note any change in behaviour, so I 
> went back to what I had before.
> 
> 
> I simplified things down to a FileAppender appender with a 
> PatternLayout layout set to '%m%n':
> log4j.rootLogger=off
> log4j.logger.Gateway=debug, file2
> 
> The corrupt output was not visible in the log.
> 
> 
> I readded the XMLFile appender to the root logger:
> log4j.rootLogger=off, XMLFile
> log4j.logger.Gateway=debug, file2
> 
> The corrupt output was visible in both the XML and plaintext logs.
> 
> 
> I removed the simplified plaintext appender:
> log4j.rootLogger=off, XMLFile
> log4j.logger.Gateway=debug
> 
> The corrupt output was not visible in the log.
> 
> 
> I removed the simplified plaintext appender:
> log4j.rootLogger=off, XMLFile
> log4j.logger.Gateway=debug, XMLFileGateway
> 
> The corrupt output was visible in both XML logs.
> 
> 
> At this point, I'm starting to think it's got something to do 
> with either having multiple appenders on the go, or simply 
> something bad in the XML layout that garbles things for 
> subsequent appenders.
> 
> 
> I tried two plaintext appenders. I reduced the 'file' 
> appender to a simple FileAppender with a pattern layout of '%m%n':
> log4j.rootLogger=off, file
> log4j.logger.Gateway=debug, file2
> 
> The corrupt output was visible in both plaintext logs.
> 
> 
> At this point, it seems to me that the verdict is in: there's 
> a bug that corrupts data when multiple appenders (regardless 
> of type) are present.
> 
> 
> For amusement, I tried combining appenders on a single logger:
> log4j.rootLogger=off, file, file2
> log4j.logger.Gateway=debug
> 
> The corrupt output was not visible in the logs.
> 
> 
> For more amusement, I tried combining appenders on a single 
> logger other than the root logger:
> log4j.rootLogger=off
> log4j.logger.Gateway=debug, file, file2
> 
> The corrupt output was not visible in the logs.
> 
> 
> Since I'm guessing the 'OFF' level isn't used all that 
> commonly, I tried enabling the root logger with the appenders 
> on separate loggers:
> log4j.rootLogger=info, file
> log4j.logger.Gateway=debug, file2
> 
> The corrupt output was visible in both plaintext logs.
> 
> 
> These extra tests confim my ealier verdict as to the cause.
> 
> I will open a bug based on this information. I will post the 
> bug number to the user group when I have it. Further 
> information on this problem will be logged there.
> 
> Next steps:
> -Verify that the problem still exists in a clean copy of 
> SVN-HEAD. (I expect it does.)
> -Determine whether the core dumps I experienced when using 
> the syslog appender are related to this same issue.
> 
> 
> ---
>  
> Myles Bunbury, P.Eng., BASc.
> Software Development Engineering Specialist 
> Web Services Internal Venture
> Alcatel-Lucent
>  
> Phone: (613) 784-4325
> Fax: (613) 784-8944
> Web: www.alcatel-lucent.com

Re: Log4cxx wilting under heavy load

Posted by Curt Arnold <ca...@apache.org>.
On Sep 28, 2007, at 4:27 PM, BUNBURY Myles wrote:

> Log4cxx seems to wilt when under heavy load.
>
> With the syslog appender enabled, the application cores when under  
> heavy load.
>
> When using a RollingFileAppender with an XMLLayout layout, my  
> output file gets garbled:
>
> <<<snip>>>
>
> <log4j:event logger="Gateway.AuthenticationServices/ 
> ANS_AuthenticationService.cpp" timestamp="1191005220721"  
> level="INFO" thread="0x61eb3b90">
> <log4j:message><![CDATA[No username/password token or SAML  
> assertion to process.]]></log4j:message>
> </log4j:event>
> <log4j:event logger="Gateway.MediationPipeline/ 
> MED_PipelineMessage.cpp" timestamp="1191005220721" level="INFO"  
> thread="0x61eb3b90">
> <log4j:message><![CDATA[No session policy set for user/group .]]></ 
> log4j:message>
> </log4j:event>
> <log4j:event logger="Gateway.MediationPipeline/ 
> MED_PipelineMessage.cpp" timestamp="1191005220721" level="DEBUG"  
> thread="0x61eb3b90">
> <log4j:message><![CDATA[Using session #2 with session policy  
> DefaultPolicy.]]></log4j:message>
> </log4j:event>
> <log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp"  
> timestamp="1191005220729" level="WARN" thread="0x5ecaeb90">
> <log4j:message><![CDATA[Concurrent session limit reached.  
> Transaction is rejected.]]></log4j:message>
> </log4j:event>
> <log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp"  
> timestamp="1191005220729" level="ERROR" thread="0x5ecaeb90">
> <log4j:message><![CDATA[User session rejected - have exceeded the  
> maximum number of concurrent sessions based on the current license  
> (0 concurrent sessions allowed)]]></log4j:message>
> </log4j:event>
> ¦«    "          ´T#
> ýÍÊ^˜ÌÊ^Ä        °Ñ"
> ôÌÊ^µ   ‡·<T#
> ÜÑ"
>             XÍÊ^       <T#
> ÜÑ"
> À4‡·    dÐÊ^ÍÊ^§c    ´T#
>     ð‡·°Ñ"
> @ÍÊ^1Ö†· T#
> ¸Ñ"
>             XÍÊ^           ôO ÔÑ"
>         |ó³            hÍÊ^
>    Þ$z  XÍÊ^p÷³ xÍÊ^/&L4#
> z  ¸ÍÊ^Z;'°Ñ"
>     ¸ÍÊ^ü(H4#
> ðÍÊ^¸ÍÊ^13 Ì€ðÍÊ^ðÍÊ^
>
>    Þ$z  ÏÊ^ÄydÐÊ^ðÍÊ^    ðÍÊ^  
> ÏÊ^PÏÊ^XÏÊ^h         ·‹·     
> 1191‘À‹·20729&ô €¼ÏÊ^(ÎÊ^®Ý‹· €È  
> €—ÎÊ^H€¼ÏÊ^H €@ €   ô5  À 
> €       €À€   ¼ÏÊ^xÎÊ^  €    
> Ðõ‹··‹·ôO À€   ˆÎÊ^@ €‹‚&    
> ·‹·      X~—·¨ÎÊ^5
> ´ dÐÊ^Þ$¸ÎÊ^ H&    çÎÊ^ÏÊ^^¥!øÎÊ^°#
> ÏÊ^§c %   
> ôèÎÊ^ðÆ0ÐÊ^'ÏÊ^øÎÊ^ÙÃ'ÏÊ^'ÏÊ^ 
> (ÏÊ^žÇ'ÏÊ^'ÏÊ^SÏÊ^ͦ!\sA
> dÐÊ^(ÏÊ^%LRÏÊ^´ÏÊ^XÏÊ^ÖÇRÏÊ^SÏÊ^RÏÊ^¶0 \sA
> kÏÊ^XÏÊ^¶&$HsA
> dÐÊ^ÈÏÊ^¦«0ÐÊ^Þ 
> $xÏÊ^íÃHÐÊ^ÿÿÿÿˆÏÊ^ÄHÐÊ^l4¸ÏÊ^6ÉHÐÊ^   
>   ó   ôO l4z  ÈÏÊ^e4 HÐÊ^dÐÊ^ÈÏÊ^uÉHÐÊ^Þ 
> $ˆÐÊ^@š!HÐÊ^l4  HÒÊ^ÑÊ^ÿÿÿÿ‘â³ Z;'°Ñ"  
> j  8ÐÊ^ü(0x5ecaeb90Ê^13 4€pÐÊ^pÐÊ^    Þ$z   
> HÐÊ^Í&ä6%
>         4ÐÊ^4ÐÊ^    ˆÐÊ^
> *à6%
> LÐÊ^LÐÊ^    Üí#
> Ì€˜ÐÊ^<log4j:event logger="Gateway.SessionInfra/ 
> SI_SessionManager.cpp" timestamp="1191005220729" level="WARN"  
> thread="0x600b0b90">
> <log4j:message><![CDATA[Concurrent session limit reached.  
> Transaction is rejected.]]></log4j:message>
> </log4j:event>
> <log4j:event logger="Gateway.MediationPipeline/ 
> MED_PipelineMessage.cpp" timestamp="1191005220729" level="INFO"  
> thread="0x5ecaeb90">
> <log4j:message><![CDATA[Auth'ed user hitting dend. Transaction is  
> rejected.]]></log4j:message>
> </log4j:event>
> <log4j:event logger="Gateway.MediationPipeline/ 
> MED_PipelineMessage.cpp" timestamp="1191005220729" level="INFO"  
> thread="0x5ecaeb90">
> <log4j:message><![CDATA[Auth'ed user hitting deny-all ws]]></ 
> log4j:message>
> </log4j:event>
> <log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp"  
> timestamp="1191005220729" level="ERROR" thread="0x600b0b90">
> <log4j:message><![CDATA[User session rejected - have exceeded the  
> maximum number of concurrent sessions based on the current license  
> (0 concurrent sessions allowed)]]></log4j:message>
> </log4j:event>
>
> <<<snip>>>
>
> This output was generated with ~150 threads throwing out error  
> messages in rapid succession.
>
> I have not noted these problems when treading lightly on the system.
>
> At this point I'm suspicious that log4cxx is overflowing some sort  
> of output buffer that's fills up due to the volume. I don't believe  
> it is a multithreading issue as I serialized the logging calls in  
> my code with a mutex and did not note any change.
>
> Has anyone else noted something similiar?
>
> How is log4cxx supposed to behave when the logging volume exceeds  
> its capacity to output those events?
>

There was a similar symptoms reported in https://issues.apache.org/ 
jira/browse/LOGCXX-186.  That ended up being due to attempting to  
configure log4cxx simultaneously on multiple threads.  I assume that  
is not the case with you, but could you confirm that the problem  
persists if you configure and attempt a logging request prior to  
launching threads (assuming that your app is the one launching the  
threads).

If that is not the case, then the previous bug report might be  
instructive to try to identify and fix the problem.  The problems  
might be related, but perhaps not.  I would focus on trying to  
identify the one that is most significant to you and then see if any  
resolution fixed the other.

I would suggest:

1. Make sure that you are using the most current SVN HEAD.

2. Making sure that configuration and some initial log requests occur  
before threads are launched.  (previously mentioned).

3. Wrap the failing appender in the soon to be committed rewrite of  
AsyncAppender (if not in the next hour or so, at least by mid-day  
tomorrow).  AsyncAppender has been badly flawed.  I'm just about the  
commit a port of the log4j 1.2.14 AsyncAppender (which replaced an  
earlier log4j implementation that was badly flawed too).  That should  
have the affect of bringing all appends on the underlying appender  
down to a common thread.  Plus it would be a great stress test of all  
my new code (thanks for volunteering for testing).

4. Simplify, simplify.  There are a couple of places that corruption  
may be occurring.  It could be an Appender problem, a Layout problem,  
a CharsetEncoder problem, a CharsetDecoder problem or some  
combination.  Trying to isolate the problem makes resolution a lot  
easier.
     a) Setting LOG4CXX_LOGCHAR_IS_UTF8 would replace an conversion  
between the local code page and UTF-8 with a straight copy.   
Eliminating a lot of complexity and potential source of problems.
     b) Replace the layout (if there is one) with something simpler.   
First try simplifying the pattern as much as possible like %m%n.
     c) See if the problem occurs with the simpler appenders  
(FileAppender instead of RollingFileAppender) or other unrelated  
appenders.

5. Attempt to recreate the problem in a sample app that you can  
attach to a bug report.  Please specify all specifics of the  
configurations (operating system, compiler, type and number of  
processors, etc) that have been tested and whether they fail  
consistently, have not been observed to fail or somewhere in between.

6. If you are running on a x86 Unix, valgrind could be useful to  
identify potential problems.  I used the helgrind tool in earlier  
versions of valgrind (its been broken for a while, so had to build it  
from source) to identify potential race conditions.  Other tools  
might be useful to identify the problem.

Re: Log4cxx wilting under heavy load

Posted by Curt Arnold <ca...@apache.org>.
AsyncAppender rewrite is now committed in rev 580512, see message on  
log4cxx-dev.  Would appreciate any feedback since you seem to have a  
ready built stress test.  You may want to experiment with set  
blocking=false which will not block the threads making the logging  
request if the buffer becomes full but at the cost of dropped  
messages (which are summarized with a count of the messages dropped  
and the message from the initial logging request at the highest level).