You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by Leon Finker <le...@gmail.com> on 2017/02/16 03:37:19 UTC
Async logging and thread name
Hi,
Is there any thread name caching going on with log4j2 (doesn't matter sync/async)? If I have a thread pool of tasks and call Thread.currentThread().setName (with unique id) in the beginning of the task execution, I sometimes see reuse of previous thread name in the log statements. Id is UUID, so it's definitely unique. And if I do System.out on the current thread name after setting it, I do see the new name as expected. But in log statements the thread name is from the previous set. The pattern layout is: [%date{DEFAULT}{UTC}Z][%level][%thread:%tid][%c{3}] %message%n
log4j:2.7
Any ideas what could be causing the thread name reuse?
Thank you
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Async logging and thread name
Posted by Matt Sicker <bo...@gmail.com>.
Only thing I can think of offhand is an issue with ReusableLogEventFactory.
I don't see anything in the 2.8 changelog fixing anything related. Could
you try disabling GC-free mode? <
https://logging.apache.org/log4j/2.x/manual/garbagefree.html>
I'm sure Remko will have some ideas when he's online. :)
On 15 February 2017 at 21:37, Leon Finker <le...@gmail.com> wrote:
> Hi,
>
> Is there any thread name caching going on with log4j2 (doesn't matter
> sync/async)? If I have a thread pool of tasks and call
> Thread.currentThread().setName (with unique id) in the beginning of the
> task execution, I sometimes see reuse of previous thread name in the log
> statements. Id is UUID, so it's definitely unique. And if I do System.out
> on the current thread name after setting it, I do see the new name as
> expected. But in log statements the thread name is from the previous set.
> The pattern layout is: [%date{DEFAULT}{UTC}Z][%level][%thread:%tid][%c{3}]
> %message%n
>
> log4j:2.7
>
> Any ideas what could be causing the thread name reuse?
>
> Thank you
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
>
--
Matt Sicker <bo...@gmail.com>
Re: Async logging and thread name
Posted by Leon Finker <le...@gmail.com>.
Hi Remko/Matt,
Yes the AsyncLogger.ThreadNameStrategy=UNCACHED solved it.
Thank you
On 2017-02-15 23:21 (-0500), Remko Popma <re...@gmail.com> wrote:
> Hi Leon,
>
> Yes by default the thread name is cached.
> There is a system property to switch that off: see https://github.com/apache/logging-log4j2/blob/master/log4j-core/src/main/java/org/apache/logging/log4j/core/async/ThreadNameCachingStrategy.java
>
> The reason for the caching is that every call to get the current thread's name creates a new String object, which I found impacted performance measurably.
>
> Why Thread is implemented to store its name in a char[] array and create a new String on each query I don't know. May have to do with interaction with native code.
>
> Remko
>
> Sent from my iPhone
>
> > On Feb 16, 2017, at 4:37, Leon Finker <le...@gmail.com> wrote:
> >
> > Hi,
> >
> > Is there any thread name caching going on with log4j2 (doesn't matter sync/async)? If I have a thread pool of tasks and call Thread.currentThread().setName (with unique id) in the beginning of the task execution, I sometimes see reuse of previous thread name in the log statements. Id is UUID, so it's definitely unique. And if I do System.out on the current thread name after setting it, I do see the new name as expected. But in log statements the thread name is from the previous set. The pattern layout is: [%date{DEFAULT}{UTC}Z][%level][%thread:%tid][%c{3}] %message%n
> >
> > log4j:2.7
> >
> > Any ideas what could be causing the thread name reuse?
> >
> > Thank you
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> > For additional commands, e-mail: log4j-dev-help@logging.apache.org
> >
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Async logging and thread name
Posted by Matt Sicker <bo...@gmail.com>.
The usual reason for using char[] instead of String is so you can overwrite
it in heap without having to wait for garbage collection and is only used
for security reasons (e.g., a password). I'm going to guess legacy reasons
for the char[], but native code could make sense, too.
On 15 February 2017 at 22:21, Remko Popma <re...@gmail.com> wrote:
> Hi Leon,
>
> Yes by default the thread name is cached.
> There is a system property to switch that off: see
> https://github.com/apache/logging-log4j2/blob/master/
> log4j-core/src/main/java/org/apache/logging/log4j/core/async/
> ThreadNameCachingStrategy.java
>
> The reason for the caching is that every call to get the current thread's
> name creates a new String object, which I found impacted performance
> measurably.
>
> Why Thread is implemented to store its name in a char[] array and create a
> new String on each query I don't know. May have to do with interaction with
> native code.
>
> Remko
>
> Sent from my iPhone
>
> On Feb 16, 2017, at 4:37, Leon Finker <le...@gmail.com> wrote:
>
> Hi,
>
> Is there any thread name caching going on with log4j2 (doesn't matter
> sync/async)? If I have a thread pool of tasks and call
> Thread.currentThread().setName (with unique id) in the beginning of the
> task execution, I sometimes see reuse of previous thread name in the log
> statements. Id is UUID, so it's definitely unique. And if I do System.out
> on the current thread name after setting it, I do see the new name as
> expected. But in log statements the thread name is from the previous set.
> The pattern layout is: [%date{DEFAULT}{UTC}Z][%level][%thread:%tid][%c{3}]
> %message%n
>
> log4j:2.7
>
> Any ideas what could be causing the thread name reuse?
>
> Thank you
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
>
--
Matt Sicker <bo...@gmail.com>
Re: Async logging and thread name
Posted by Remko Popma <re...@gmail.com>.
Hi Leon,
Yes by default the thread name is cached.
There is a system property to switch that off: see https://github.com/apache/logging-log4j2/blob/master/log4j-core/src/main/java/org/apache/logging/log4j/core/async/ThreadNameCachingStrategy.java
The reason for the caching is that every call to get the current thread's name creates a new String object, which I found impacted performance measurably.
Why Thread is implemented to store its name in a char[] array and create a new String on each query I don't know. May have to do with interaction with native code.
Remko
Sent from my iPhone
> On Feb 16, 2017, at 4:37, Leon Finker <le...@gmail.com> wrote:
>
> Hi,
>
> Is there any thread name caching going on with log4j2 (doesn't matter sync/async)? If I have a thread pool of tasks and call Thread.currentThread().setName (with unique id) in the beginning of the task execution, I sometimes see reuse of previous thread name in the log statements. Id is UUID, so it's definitely unique. And if I do System.out on the current thread name after setting it, I do see the new name as expected. But in log statements the thread name is from the previous set. The pattern layout is: [%date{DEFAULT}{UTC}Z][%level][%thread:%tid][%c{3}] %message%n
>
> log4j:2.7
>
> Any ideas what could be causing the thread name reuse?
>
> Thank you
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>