[jira] [Commented] (LOG4J2-2391) Investigate ThrowableProxy performance
[ 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 ...
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
[ 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...
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
[ 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
[ 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
[ 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
[ 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...
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
[ 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
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)