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] [Commented] (LOG4J2-467) Thread name caching in async logger incompatible with use of Thread.setName()
Date Sat, 04 Jan 2014 07:42:52 GMT

    [ https://issues.apache.org/jira/browse/LOG4J2-467?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13862236#comment-13862236

Remko Popma commented on LOG4J2-467:

Performance test result update:

The numbers I reported in the [comment above|https://issues.apache.org/jira/browse/LOG4J2-467?focusedCommentId=13862126&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-13862126]
are all results for the CACHED thread name scenario. Here they are again:

(1 thread) : throughput: 4,407,972 ops/sec.
(2 threads): throughput: 2,717,954 ops/sec.
(4 threads): throughput: 1,616,480 ops/sec.

(1 thread) : throughput: 4,124,748 ops/sec.
(2 threads): throughput: 1,928,624 ops/sec.
(4 threads): throughput: 3,006,960 ops/sec.

(1 thread) : throughput: 4,987,891 ops/sec.
(2 threads): throughput: 1,933,868 ops/sec.
(4 threads): throughput: 3,222,753 ops/sec.

(1 thread) : throughput: 4,670,605 ops/sec.
(2 threads): throughput: 2,215,214 ops/sec. 
(4 threads): throughput: 1,154,320 ops/sec. 

I've re-run the tests with the updated PerfTestDriver and the -DAsyncLogger.ThreadNameStrategy=UNCACHED

(1 thread) : throughput: 3,429,421 ops/sec.
(2 threads): throughput: 1,688,868 ops/sec.
(4 threads): throughput: 2,207,599 ops/sec.

(1 thread) : throughput: 4,684,796 ops/sec.
(2 threads): throughput: 1,232,496 ops/sec.
(4 threads): throughput: 2,906,195 ops/sec.

(1 thread) : throughput: 3,404,258 ops/sec.
(2 threads): throughput: 1,821,020 ops/sec.
(4 threads): throughput: 4,254,485 ops/sec.

(All on Windows 7 (64bit) with JDK1.7.0_45, 2-core Intel i5-3317u CPU @1.70Ghz with hyperthreading
switched on (4 virtual cores)).

Discounting the 4-thread tests (too much variance) I get these averages (in million ops/sec):
| |Cached|Uncached|
|1 thread|4.5|3.8|
|2 thread|2.2|1.6|

 I will re-run the tests on a Unix box with more cores next week (should have less variance).

> 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
>            Assignee: Remko Popma
>             Fix For: 2.0-rc1
>         Attachments: PerfTestDriver.java, 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

This message was sent by Atlassian JIRA

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

View raw message