[jira] [Commented] (LOG4J2-2391) Investigate ThrowableProxy performance

2018-08-23 Thread ASF GitHub Bot (JIRA)


[ 
https://issues.apache.org/jira/browse/LOG4J2-2391?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16590929#comment-16590929
 ] 

ASF GitHub Bot commented on LOG4J2-2391:


Github user cakofony commented on the issue:

https://github.com/apache/logging-log4j2/pull/212
  
I like `ThrowableProxyRenderer`though I don't think `ThrowableProxyCache` 
is quite right. The initialization logic includes a cache to avoid loading the 
same class many times, but that's an optimization.

Maybe `ThrowableProxyInitialization`? I'm open to suggestions. Renaming it 
in the future shouldn't be dangerous since it's package private.

Apologies for the slow reply, this week has been busier than usual!


> Investigate ThrowableProxy performance
> --
>
> Key: LOG4J2-2391
> URL: https://issues.apache.org/jira/browse/LOG4J2-2391
> Project: Log4j 2
>  Issue Type: Task
>Affects Versions: 2.11.1
>Reporter: Carter Kozak
>Assignee: Carter Kozak
>Priority: Major
>
> I've noticed when applications get into a state where they log more 
> exceptions than usual (e.g. network connectivity issues) thread dumps contain 
> many threads working inside of ThrowableProxy, loading classes.
> A simple jmh benchmark of a pattern layout writing to disk with a message and 
> throwable appears to write about 160,000 events/second using a throwable, and 
> 2,000 events/second using ThrowableProxy.
> I will investigate to understand where the substantial difference is coming 
> from, and clean up the benchmarks to add to the log4j2 benchmarking module.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)


[GitHub] logging-log4j2 issue #212: [LOG4J2-2391] Refactor as much logic as possible ...

2018-08-23 Thread cakofony
Github user cakofony commented on the issue:

https://github.com/apache/logging-log4j2/pull/212
  
I like `ThrowableProxyRenderer`though I don't think `ThrowableProxyCache` 
is quite right. The initialization logic includes a cache to avoid loading the 
same class many times, but that's an optimization.

Maybe `ThrowableProxyInitialization`? I'm open to suggestions. Renaming it 
in the future shouldn't be dangerous since it's package private.

Apologies for the slow reply, this week has been busier than usual!


---


[jira] [Commented] (LOGCXX-500) Logging in Timing-Critical Applications

2018-08-23 Thread JIRA


[ 
https://issues.apache.org/jira/browse/LOGCXX-500?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16590584#comment-16590584
 ] 

Thorsten Schöning commented on LOGCXX-500:
--

Great work, only one compile time issue in my environment left: std::atomic. 
Want to port that to APR as well or should it depend on the configure option?

> Logging in Timing-Critical Applications
> ---
>
> Key: LOGCXX-500
> URL: https://issues.apache.org/jira/browse/LOGCXX-500
> Project: Log4cxx
>  Issue Type: Improvement
>  Components: Core
>Affects Versions: 0.10.0
>Reporter: Thorsten Schöning
>Priority: Minor
> Attachments: config.xml, main.cpp, non_blocking.diff, 
> non_blocking_wo_debian_control.diff
>
>
> The following has been arrived on the mailing list, providing it here as well 
> mainly to additionally collect the given patches etc.:
> {quote}Hello All,
> I'd like to share some experience as well as some patches with regard 
> to using log4cxx in timing-critical application. First few words about 
> our requirements: it's a service which must generate some network 
> packets with up to hundred of microseconds precision. Thus, it's very 
> important to have predictable code timing. One can argue that log4cxx 
> is not very well suited for such applications, but surprisingly it 
> works pretty well after some light tuning.
> So, what were the issues?
> Basically from library user's point of view they looked the same: one 
> of a sudden logging done with LOG4CXX_DEBUG() macro could take 
> unexpectedly long time to complete. For example the same trace which 
> takes several μs for 99% of the time would take hundreds microseconds 
> and even few milliseconds sometimes. After further investigation this 
> has been traced down to few of the root-causes:
> 1. Asyns logger (which we have been using of course) has internal queue 
> to pass log entries to background disk-writer thread. This queue is 
> mutex-protected which might seem fine unless you think a little bit 
> more about it. First of all, someone calling LOG4CXX_DEBUG() to simply 
> put something into the log might not expect to be blocked inside 
> waiting for a mutex at all. Second point is that, although there were 
> measures taken to minimize time disk-thread holds that lock, 
> OS-schedulers often work in a way that thread which is blocked on a 
> mutex gets de-scheduled. With normal OS-scheduler quantum that means 
> that the logging thread can be preempted for milliseconds.
> 2. There are some mutexes protecting internal states of both loggers 
> and appenders. This means that two separate threads calling 
> LOG4CXX_DEBUG() can block each other. Even if they are using different 
> loggers they would block on appender! This has the same consequences 
> for execution timing and the performance as described above.
> 3. std::stringstream class constructor has some internal locks on it's 
> own. Unfortunately each MessageBuffer has it's own instance of this 
> class. And also unfortunately MessageBuffer is created inside 
> LOG4CXX_DEBUG() macro. There is optimization to not create stringstream 
> for logging simple strings, but as soon as your log statement has 
> single '<<' operator it's created.
> 4. Dynamic memory allocations. Unfortunately there are still quite few 
> of them even though memory pool is used in some other places. Thus, 
> hidden calls to new and malloc induce unpredictable delays.
> So, what we did to mitigate these problems?
> 1. Natural solution for this issue was to use atomic queue. There are 
> few of them available, but we made use of boost::lockfree::queue as it 
> can serve as a drop-in replacement allowing us to keep all present 
> functionality.
> 2. After looking more into the code it has appeared that two concurrent 
> calls to LOG4CXX_DEBUG() from within different threads are not harmful 
> because internal structures of logger and appender are not being 
> changed there. What only really requires protection is concurrency 
> between logging and configuring. Thus, we came to a solution - 
> read-write locks where logging calls act as readers and 
> configuration/exiting calls are writers. With such approach multiple 
> threads calling LOG4CXX_DEBUG() became free of any contention.
> 3. This problem also has one simple solution - make one static 
> std::stringstream object per thread using std::thread_local. 
> Unfortunately we found one drawback - thread_local memory is not 
> released if thread is not detached or joined. As there is some code 
> which does neither of this we made static stringstream a xml file 
> configuration option. Also, there could be an issue with using multiple 
> MessageBuffer instances from within single thread, but LOG4CXX_DEBUG() 
> is not doing that.
> 4. At this time we didn't do anything to address 

[GitHub] logging-log4cxx pull request #6: Made all changes related to non-blocking be...

2018-08-23 Thread asfgit
Github user asfgit closed the pull request at:

https://github.com/apache/logging-log4cxx/pull/6


---


[jira] [Commented] (LOG4J2-2417) NullPointerException without any `requestContext` attributes

2018-08-23 Thread Ralph Goers (JIRA)


[ 
https://issues.apache.org/jira/browse/LOG4J2-2417?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16590351#comment-16590351
 ] 

Ralph Goers commented on LOG4J2-2417:
-

Thanks, I added a version. Yes, this is the correct place to create a bug 
report and yes, this is a bug.

> NullPointerException without any `requestContext` attributes
> 
>
> Key: LOG4J2-2417
> URL: https://issues.apache.org/jira/browse/LOG4J2-2417
> Project: Log4j 2
>  Issue Type: Bug
>  Components: Log4j-Audit
>Affects Versions: Log4j-Audit 1.0.0
>Reporter: Andrei Ivanov
>Priority: Minor
>
> The Log4j-Audit project page indicates this as the place to file tickets, but 
> I don't see the 1.0.0 version for it.
> Investigating the use of the project, I started with a basic `catalog.json`, 
> with just an event and 2 attributes, both with {{requestContext = false}}.
> {noformat}
> java.lang.NullPointerException
>   at 
> org.apache.logging.log4j.audit.LogEventFactory.validateContextConstraint(LogEventFactory.java:385)
>   at 
> org.apache.logging.log4j.audit.LogEventFactory.validateContextConstraints(LogEventFactory.java:380)
>   at 
> org.apache.logging.log4j.audit.LogEventFactory.access$400(LogEventFactory.java:57)
>   at 
> org.apache.logging.log4j.audit.LogEventFactory$AuditProxy.invoke(LogEventFactory.java:263)
> {noformat}
> As far as I understand, request context attributes are not required.
> ??While usage of a RequestContext is not required, the use of one should be 
> considered a best practice.??



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)


[jira] [Assigned] (LOG4J2-2417) NullPointerException without any `requestContext` attributes

2018-08-23 Thread Ralph Goers (JIRA)


 [ 
https://issues.apache.org/jira/browse/LOG4J2-2417?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Ralph Goers reassigned LOG4J2-2417:
---

Assignee: Ralph Goers

> NullPointerException without any `requestContext` attributes
> 
>
> Key: LOG4J2-2417
> URL: https://issues.apache.org/jira/browse/LOG4J2-2417
> Project: Log4j 2
>  Issue Type: Bug
>  Components: Log4j-Audit
>Affects Versions: Log4j-Audit 1.0.0
>Reporter: Andrei Ivanov
>Assignee: Ralph Goers
>Priority: Minor
>
> The Log4j-Audit project page indicates this as the place to file tickets, but 
> I don't see the 1.0.0 version for it.
> Investigating the use of the project, I started with a basic `catalog.json`, 
> with just an event and 2 attributes, both with {{requestContext = false}}.
> {noformat}
> java.lang.NullPointerException
>   at 
> org.apache.logging.log4j.audit.LogEventFactory.validateContextConstraint(LogEventFactory.java:385)
>   at 
> org.apache.logging.log4j.audit.LogEventFactory.validateContextConstraints(LogEventFactory.java:380)
>   at 
> org.apache.logging.log4j.audit.LogEventFactory.access$400(LogEventFactory.java:57)
>   at 
> org.apache.logging.log4j.audit.LogEventFactory$AuditProxy.invoke(LogEventFactory.java:263)
> {noformat}
> As far as I understand, request context attributes are not required.
> ??While usage of a RequestContext is not required, the use of one should be 
> considered a best practice.??



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)


[jira] [Updated] (LOG4J2-2417) NullPointerException without any `requestContext` attributes

2018-08-23 Thread Ralph Goers (JIRA)


 [ 
https://issues.apache.org/jira/browse/LOG4J2-2417?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Ralph Goers updated LOG4J2-2417:

Affects Version/s: Log4j-Audit 1.0.0

> NullPointerException without any `requestContext` attributes
> 
>
> Key: LOG4J2-2417
> URL: https://issues.apache.org/jira/browse/LOG4J2-2417
> Project: Log4j 2
>  Issue Type: Bug
>  Components: Log4j-Audit
>Affects Versions: Log4j-Audit 1.0.0
>Reporter: Andrei Ivanov
>Priority: Minor
>
> The Log4j-Audit project page indicates this as the place to file tickets, but 
> I don't see the 1.0.0 version for it.
> Investigating the use of the project, I started with a basic `catalog.json`, 
> with just an event and 2 attributes, both with {{requestContext = false}}.
> {noformat}
> java.lang.NullPointerException
>   at 
> org.apache.logging.log4j.audit.LogEventFactory.validateContextConstraint(LogEventFactory.java:385)
>   at 
> org.apache.logging.log4j.audit.LogEventFactory.validateContextConstraints(LogEventFactory.java:380)
>   at 
> org.apache.logging.log4j.audit.LogEventFactory.access$400(LogEventFactory.java:57)
>   at 
> org.apache.logging.log4j.audit.LogEventFactory$AuditProxy.invoke(LogEventFactory.java:263)
> {noformat}
> As far as I understand, request context attributes are not required.
> ??While usage of a RequestContext is not required, the use of one should be 
> considered a best practice.??



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)


[jira] [Commented] (LOGCXX-500) Logging in Timing-Critical Applications

2018-08-23 Thread Denys Smolianiuk (JIRA)


[ 
https://issues.apache.org/jira/browse/LOGCXX-500?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16590335#comment-16590335
 ] 

Denys Smolianiuk commented on LOGCXX-500:
-

Submitted new PR with such change. Existing Windows projects should build as if 
this option is disabled.

Thanks,

Denys Smolianiuk

 

> Logging in Timing-Critical Applications
> ---
>
> Key: LOGCXX-500
> URL: https://issues.apache.org/jira/browse/LOGCXX-500
> Project: Log4cxx
>  Issue Type: Improvement
>  Components: Core
>Affects Versions: 0.10.0
>Reporter: Thorsten Schöning
>Priority: Minor
> Attachments: config.xml, main.cpp, non_blocking.diff, 
> non_blocking_wo_debian_control.diff
>
>
> The following has been arrived on the mailing list, providing it here as well 
> mainly to additionally collect the given patches etc.:
> {quote}Hello All,
> I'd like to share some experience as well as some patches with regard 
> to using log4cxx in timing-critical application. First few words about 
> our requirements: it's a service which must generate some network 
> packets with up to hundred of microseconds precision. Thus, it's very 
> important to have predictable code timing. One can argue that log4cxx 
> is not very well suited for such applications, but surprisingly it 
> works pretty well after some light tuning.
> So, what were the issues?
> Basically from library user's point of view they looked the same: one 
> of a sudden logging done with LOG4CXX_DEBUG() macro could take 
> unexpectedly long time to complete. For example the same trace which 
> takes several μs for 99% of the time would take hundreds microseconds 
> and even few milliseconds sometimes. After further investigation this 
> has been traced down to few of the root-causes:
> 1. Asyns logger (which we have been using of course) has internal queue 
> to pass log entries to background disk-writer thread. This queue is 
> mutex-protected which might seem fine unless you think a little bit 
> more about it. First of all, someone calling LOG4CXX_DEBUG() to simply 
> put something into the log might not expect to be blocked inside 
> waiting for a mutex at all. Second point is that, although there were 
> measures taken to minimize time disk-thread holds that lock, 
> OS-schedulers often work in a way that thread which is blocked on a 
> mutex gets de-scheduled. With normal OS-scheduler quantum that means 
> that the logging thread can be preempted for milliseconds.
> 2. There are some mutexes protecting internal states of both loggers 
> and appenders. This means that two separate threads calling 
> LOG4CXX_DEBUG() can block each other. Even if they are using different 
> loggers they would block on appender! This has the same consequences 
> for execution timing and the performance as described above.
> 3. std::stringstream class constructor has some internal locks on it's 
> own. Unfortunately each MessageBuffer has it's own instance of this 
> class. And also unfortunately MessageBuffer is created inside 
> LOG4CXX_DEBUG() macro. There is optimization to not create stringstream 
> for logging simple strings, but as soon as your log statement has 
> single '<<' operator it's created.
> 4. Dynamic memory allocations. Unfortunately there are still quite few 
> of them even though memory pool is used in some other places. Thus, 
> hidden calls to new and malloc induce unpredictable delays.
> So, what we did to mitigate these problems?
> 1. Natural solution for this issue was to use atomic queue. There are 
> few of them available, but we made use of boost::lockfree::queue as it 
> can serve as a drop-in replacement allowing us to keep all present 
> functionality.
> 2. After looking more into the code it has appeared that two concurrent 
> calls to LOG4CXX_DEBUG() from within different threads are not harmful 
> because internal structures of logger and appender are not being 
> changed there. What only really requires protection is concurrency 
> between logging and configuring. Thus, we came to a solution - 
> read-write locks where logging calls act as readers and 
> configuration/exiting calls are writers. With such approach multiple 
> threads calling LOG4CXX_DEBUG() became free of any contention.
> 3. This problem also has one simple solution - make one static 
> std::stringstream object per thread using std::thread_local. 
> Unfortunately we found one drawback - thread_local memory is not 
> released if thread is not detached or joined. As there is some code 
> which does neither of this we made static stringstream a xml file 
> configuration option. Also, there could be an issue with using multiple 
> MessageBuffer instances from within single thread, but LOG4CXX_DEBUG() 
> is not doing that.
> 4. At this time we didn't do anything to address dynamic memory 
> 

[GitHub] logging-log4cxx pull request #6: Made all changes related to non-blocking be...

2018-08-23 Thread DenysSmolianiuk
GitHub user DenysSmolianiuk opened a pull request:

https://github.com/apache/logging-log4cxx/pull/6

Made all changes related to non-blocking behaviour configurable with …

…--enable-non-blocking=yes option

You can merge this pull request into a Git repository by running:

$ git pull https://github.com/DenysSmolianiuk/logging-log4cxx LOGCXX-500

Alternatively you can review and apply these changes as the patch at:

https://github.com/apache/logging-log4cxx/pull/6.patch

To close this pull request, make a commit to your master/trunk branch
with (at least) the following in the commit message:

This closes #6


commit 72701c84efd1f4a96a90bb4eec63abbbce497c69
Author: Denys Smolianiuk 
Date:   2018-08-23T13:26:13Z

Made all changes related to non-blocking behaviour configurable with 
--enable-non-blocking=yes option




---


[jira] [Resolved] (LOG4J2-2418) NullPointerException when closing never used RollingRandomAccessFileAppender

2018-08-23 Thread Gary Gregory (JIRA)


 [ 
https://issues.apache.org/jira/browse/LOG4J2-2418?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Gary Gregory resolved LOG4J2-2418.
--
   Resolution: Fixed
Fix Version/s: 2.11.2
   3.0.0

Committed to branch {{release-2.x}} and {{master}}. Please verify and close 
this ticket.

> NullPointerException when closing never used RollingRandomAccessFileAppender
> 
>
> Key: LOG4J2-2418
> URL: https://issues.apache.org/jira/browse/LOG4J2-2418
> Project: Log4j 2
>  Issue Type: Bug
>  Components: Appenders
>Affects Versions: 2.10.0, 2.11.1
>Reporter: Jonas Rutishauser
>Priority: Major
> Fix For: 3.0.0, 2.11.2
>
>
> If a {{RollingRandomAccessFileAppender}} is configured using the 
> {{DirectWriteRolloverStrategy}} and there is no log event which is passed to 
> this appender there will be a {{NullPointerException}} when the configuration 
> is stoped.
> {code:java}
> java.lang.NullPointerException
> at 
> org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.closeOutputStream(RollingRandomAccessFileManager.java:168)
> at 
> org.apache.logging.log4j.core.appender.OutputStreamManager.releaseSub(OutputStreamManager.java:136)
> at 
> org.apache.logging.log4j.core.appender.rolling.RollingFileManager.releaseSub(RollingFileManager.java:266)
> at 
> org.apache.logging.log4j.core.appender.AbstractManager.stop(AbstractManager.java:86)
> at 
> org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.stop(AbstractOutputStreamAppender.java:142)
> at 
> org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.stop(RollingRandomAccessFileAppender.java:223)
> at 
> org.apache.logging.log4j.core.config.AbstractConfiguration.stop(AbstractConfiguration.java:360)
> at 
> org.apache.logging.log4j.core.AbstractLifeCycle.stop(AbstractLifeCycle.java:136)
> at 
> org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:552)
> at 
> org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:619)
> at 
> org.apache.logging.log4j.core.LoggerContext.setConfigLocation(LoggerContext.java:605)
> at 
> org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.locateContext(ClassLoaderContextSelector.java:157)
> at 
> org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:70)
> at 
> org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:228)
> at 
> org.apache.logging.log4j.core.config.Configurator.initialize(Configurator.java:158)
> at 
> org.apache.logging.log4j.core.config.Configurator.initialize(Configurator.java:131)
> at 
> org.apache.logging.log4j.core.config.Configurator.initialize(Configurator.java:101)
> at 
> org.apache.logging.log4j.junit.LoggerContextRule$1.evaluate(LoggerContextRule.java:120)
> at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> [...]
> {code}
> To reproduce the issue a config may be created wich does not use this 
> appender:
> {code:xml}
> 
>  
>   
>immediateFlush="false">
>
>
>   
>  
>  
>   
>
>   
>  
> 
> {code}



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)


[jira] [Created] (LOG4J2-2418) NullPointerException when closing never used RollingRandomAccessFileAppender

2018-08-23 Thread Jonas Rutishauser (JIRA)
Jonas Rutishauser created LOG4J2-2418:
-

 Summary: NullPointerException when closing never used 
RollingRandomAccessFileAppender
 Key: LOG4J2-2418
 URL: https://issues.apache.org/jira/browse/LOG4J2-2418
 Project: Log4j 2
  Issue Type: Bug
  Components: Appenders
Affects Versions: 2.11.1, 2.10.0
Reporter: Jonas Rutishauser


If a {{RollingRandomAccessFileAppender}} is configured using the 
{{DirectWriteRolloverStrategy}} and there is no log event which is passed to 
this appender there will be a {{NullPointerException}} when the configuration 
is stoped.

{code:java}
java.lang.NullPointerException
at 
org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.closeOutputStream(RollingRandomAccessFileManager.java:168)
at 
org.apache.logging.log4j.core.appender.OutputStreamManager.releaseSub(OutputStreamManager.java:136)
at 
org.apache.logging.log4j.core.appender.rolling.RollingFileManager.releaseSub(RollingFileManager.java:266)
at 
org.apache.logging.log4j.core.appender.AbstractManager.stop(AbstractManager.java:86)
at 
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.stop(AbstractOutputStreamAppender.java:142)
at 
org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.stop(RollingRandomAccessFileAppender.java:223)
at 
org.apache.logging.log4j.core.config.AbstractConfiguration.stop(AbstractConfiguration.java:360)
at 
org.apache.logging.log4j.core.AbstractLifeCycle.stop(AbstractLifeCycle.java:136)
at 
org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:552)
at 
org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:619)
at 
org.apache.logging.log4j.core.LoggerContext.setConfigLocation(LoggerContext.java:605)
at 
org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.locateContext(ClassLoaderContextSelector.java:157)
at 
org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:70)
at 
org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:228)
at 
org.apache.logging.log4j.core.config.Configurator.initialize(Configurator.java:158)
at 
org.apache.logging.log4j.core.config.Configurator.initialize(Configurator.java:131)
at 
org.apache.logging.log4j.core.config.Configurator.initialize(Configurator.java:101)
at 
org.apache.logging.log4j.junit.LoggerContextRule$1.evaluate(LoggerContextRule.java:120)
at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[...]
{code}

To reproduce the issue a config may be created wich does not use this appender:
{code:xml}

 
  
  
   
   
  
 
 
  
   
  
 

{code}



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)