[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)
