logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Remko Popma (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (LOG4J2-467) Thread name caching in async logger incompatible with use of Thread.setName()
Date Fri, 03 Jan 2014 09:48:51 GMT

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

Remko Popma updated LOG4J2-467:
-------------------------------

    Attachment: PerfTestDriver.java

Gary, I've tested the performance difference like you asked. I used the existing benchmark
test that I used to generate the performance numbers for Async Loggers: org.apache.logging.log4j.core.async.perftest.*
I modified the PerfTestDriver class to comment out all tests except for "Loggers all async",
and tested for 1, 2 and 4 threads. Here are the results:

{code}
Cached thread name (AsyncLogger line 203: info.cachedThreadName)
1 thread : throughput: 4,380,953 ops/sec. (avg of 5 runs)
2 threads: throughput: 2,481,713 ops/sec. (avg of 5 runs)
4 threads: throughput: 5,712,182 ops/sec. (avg of 3 runs)

Thread.currentThread().getName() (AsyncLogger line 202)
1 thread : throughput: 3,762,280 ops/sec. (avg of 5 runs)
2 threads: throughput: 2,805,796 ops/sec. (avg of 5 runs)
4 threads: throughput: 2,193,664 ops/sec. (avg of 3 runs)
{code}

I conclude that caching the thread name gives a significant performance benefit.

I attached the PerfTestDriver class so you can run the tests yourself to verify these results
if you want. Each run takes about 30 minutes. To toggle between Thread.currentThread().getName()
and the cached thread name, you need to modify AsyncLogger and recompile.

> Thread name caching in async logger incompatible with use of Thread.setName()
> -----------------------------------------------------------------------------
>
>                 Key: LOG4J2-467
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-467
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Core
>    Affects Versions: 2.0-beta9
>         Environment: Debian Squeeze amd64
> OpenJDK 7u25
>            Reporter: Anthony Baldocchi
>         Attachments: PerfTestDriver.java
>
>
> AsyncLogger caches a thread's name in a thread-local info variable.  I make use of a
thread pool where the submitted Runnables call Thread.setName() at the beginning of their
task and the thread name is included in the log message.  For an example of this behavior,
see org.jboss.netty.util.ThreadRenamingRunnable in Netty 3.x.  With the cached thread name,
the log messages will contain whatever name the thread had when it logged for the first time
and so long as the thread doesn't terminate (such as in a core pool thread), all log messages
involving this thread will be erroneous.  If Thread.getName has a significant performance
impact for async logging, I would be satisfied if this behavior were configurable, perhaps
on a per-logger basis, so that the penalty only needs to be taken by users who make use of
Thread.setName()



--
This message was sent by Atlassian JIRA
(v6.1.5#6160)

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message