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

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

Remko Popma edited comment on LOG4J2-467 at 1/4/14 7:50 AM:
------------------------------------------------------------

Gary, after rebooting my windows laptop I'm getting different numbers. 

{panel:title=Update |borderStyle=dashed|borderColor=#ccc|titleBGColor=#F7D6C1|bgColor=#FFFFCE}
I made a mistake running these tests. These results are all for the CACHED thread name scenario.
Results for the UNCACHED scenario are in [this comment below|https://issues.apache.org/jira/browse/LOG4J2-467?focusedCommentId=13862236&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-13862236]

{panel}

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

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

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

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

CACHED still has an advantage over UNCACHED, but there seems to be a lot of variance between
runs. Especially the 4-thread results have too much variance to be useful. (This may be because
my laptop only has 4 virtual cores, and occasionally running OS tasks skew the results.)

I'll try running the performance test on a Unix box early next week.


was (Author: remkop@yahoo.com):
Gary, after rebooting my windows laptop I'm getting different numbers. 

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

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

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

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

CACHED still has an advantage over UNCACHED, but there seems to be a lot of variance between
runs. Especially the 4-thread results have too much variance to be useful. (This may be because
my laptop only has 4 virtual cores, and occasionally running OS tasks skew the results.)

I'll try running the performance test on a Unix box early next week.

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