Re: Cek's new log4j vs logback benchmark

[Ralph Goers]

If you look at log4j-perf you will see both a TimeFormatBenchmark and a 
ClocksBenchmark. The time 
benchmark doesn’t include java.time’s formatter but I am pretty sure I added it 
to find that it was still 
slower than our formatters. However, the TimeFormat benchmark tests using 
System.currentTimeMillis
 - it doesn’t use a Clock. So there really isn’t a perf test for all the 
various ways the Date Converter 
could be implemented.

Actually, having a background thread for the date is an interesting idea but I 
don’t think I would have the
thread create dates that might be used. Instead, I would look to see if there 
is a way to request the date 
be formatted asynchronously so that when the DateConverter actually needs it it 
is already available. The 
trick to this would be to know that a date is going to be requested similar to 
how we check whether 
location information is required. Then the async thread could add the formatted 
time to the log event.
The only downside to this is that it assumes the date formatting thread will 
actually run before the Date 
Converter needs the data.

The problem with pre-formatting is that we would have to determine the 
frequency with which log events 
arrive. It doesn’t do any good to format the next 32K milliseconds if logging 
occurs once per second. And 
it doesn’t do any good to format once per second just to have it suddenly start 
generating 10 events per 
second.


Ralph

> On Aug 27, 2021, at 11:16 PM, Ron Grabowski  
> wrote:
> 
> Follow-up to "Formatting the date is expensive. The process of actually 
> formatting a value is reasonable". Is this still an issue from LOG4J2-930:
> %m %ex%n: 1,755,573 msg/sec%d %m %ex%n: 1,194,184 msg/sec
> If so, isn't date rendering essentially a sequence we can generate ahead of 
> time similar to how a local ID generator asks for an allocation of keys then 
> uses that to quickly assign IDs to new objects? When its time to render %d we 
> can just grab it via an index:
> 
> 1)At startup calculate the next 32k formatted dates. If 
> Clock.currentTimeMillis() were configured down to the second, 32000 seconds 
> would pre-allocate %d for the next 8 hours.
> 2)Apply math to Clock.currentTimeMillis() to get an index into the buffer. 
> Seconds precision:
> [10] = "2021-08-28 09:44:31,000"
> [11] = "2021-08-28 09:44:32,000"[12] = "2021-08-28 09:44:33,000"[13] = 
> "2021-08-28 09:44:34,000"[14] = "2021-08-28 09:44:35,000"[15] = "2021-08-28 
> 09:44:36,000"...[31999] = "..."
> 50ms precision:
> [10] = "2021-08-28 09:44:31,050"[11] = "2021-08-28 09:44:31,075"[12] = 
> "2021-08-28 09:44:31,100"[13] = "2021-08-28 09:44:31,150"[14] = "2021-08-28 
> 09:44:31,175"[15] = "2021-08-28 09:44:31,200"...[31999] = "..."
> 
> 3)Rendering %d{SEQ(DEFAULT,32000)} is just a index lookup into the sequence 
> of 32000 pre-calculated %d{DEFAULT} values without the cost of formatting. I 
> made up the "SEQ" notation, there's likely a better way to express the 
> feature. Everything can read from the buffer without locking.
> 4)Have a background thread casually keep the sequence filled in a ring so 
> dates in the past are replaced with future dates so the structure consumes a 
> consistent amount of memory.
>On Friday, August 27, 2021, 10:07:59 PM EDT, Carter Kozak 
>  wrote:  
> 
> Thanks, Remko. The default '%d' uses FixedDateFormat with 
> FixedFormat.DEFAULT. The FastDateFormat alternative does not support 
> microseconds, so it doesn't suffer from the same problem. I think I can 
> substantially reduce the frequency we re-format dates by checking 
> FixedFormat.secondFractionDigits to determine if we meed to compare 
> microseconds.
> 
> On Fri, Aug 27, 2021, at 16:10, Remko Popma wrote:
>> I remember looking at PatternLayout performance, I reported my findings 
>> here, hopefully they’re still useful: 
>> https://issues.apache.org/jira/browse/LOG4J2-930
>> 
>> If %d is used in the pattern, does the FixedDateFormat get used?
>> 
>> 
>> 
>> 
>>> On Aug 28, 2021, at 4:33, Ralph Goers  wrote:
>>> 
>>> All of that agrees with my observations as well.
>>> 
>>> Ralph
>>> 
 On Aug 27, 2021, at 12:23 PM, Carter Kozak  wrote:
 
 I've identified a few things that seem impactful, but bear in mind that I 
 haven't begun to drill down into them yet. I plan to file individual 
 tickets and investigate in greater depth later on:
 
 1. Formatting the date is expensive. The process of actually formatting a 
 value is reasonable, however using a precise clock appears to cause cache 
 misses even when the pattern results in the same value 
 (microseconds/nanoseconds aren't included in the result). Using the 
 SystemMillisClock improves our throughput. I imagine some part of that 
 improvement is the result of currentTimeMillis(): long rather than 
 Clock.instant().
 
 2. Setting 'log4j2.enable.direct.encoders' to false improves performance, 
 otherwise we see a lot of time spent in the StringBuilde

Re: Cek's new log4j vs logback benchmark

[Dominik Psenner]

May a ringbuffer cache be a viable solution?

Knowing the resolution (ticks, microseconds, milliseconds, seconds,..), a
key could be generated to lookup and return a previously created formatted
string from a ringbuffer or create it on the fly and store it for later.
During bursts of log events, this could significantly improve performance.
The ringbuffer may even be very small, only depending on the requested
resolution.

Cheers
Dominik
--
Sent from my phone. Typos are a kind gift to anyone who happens to find
them.

On Sat, Aug 28, 2021, 09:40 Ralph Goers  wrote:

> If you look at log4j-perf you will see both a TimeFormatBenchmark and a
> ClocksBenchmark. The time
> benchmark doesn’t include java.time’s formatter but I am pretty sure I
> added it to find that it was still
> slower than our formatters. However, the TimeFormat benchmark tests using
> System.currentTimeMillis
>  - it doesn’t use a Clock. So there really isn’t a perf test for all the
> various ways the Date Converter
> could be implemented.
>
> Actually, having a background thread for the date is an interesting idea
> but I don’t think I would have the
> thread create dates that might be used. Instead, I would look to see if
> there is a way to request the date
> be formatted asynchronously so that when the DateConverter actually needs
> it it is already available. The
> trick to this would be to know that a date is going to be requested
> similar to how we check whether
> location information is required. Then the async thread could add the
> formatted time to the log event.
> The only downside to this is that it assumes the date formatting thread
> will actually run before the Date
> Converter needs the data.
>
> The problem with pre-formatting is that we would have to determine the
> frequency with which log events
> arrive. It doesn’t do any good to format the next 32K milliseconds if
> logging occurs once per second. And
> it doesn’t do any good to format once per second just to have it suddenly
> start generating 10 events per
> second.
>
>
> Ralph
>
> > On Aug 27, 2021, at 11:16 PM, Ron Grabowski 
> wrote:
> >
> > Follow-up to "Formatting the date is expensive. The process of actually
> formatting a value is reasonable". Is this still an issue from LOG4J2-930:
> > %m %ex%n: 1,755,573 msg/sec%d %m %ex%n: 1,194,184 msg/sec
> > If so, isn't date rendering essentially a sequence we can generate ahead
> of time similar to how a local ID generator asks for an allocation of keys
> then uses that to quickly assign IDs to new objects? When its time to
> render %d we can just grab it via an index:
> >
> > 1)At startup calculate the next 32k formatted dates. If
> Clock.currentTimeMillis() were configured down to the second, 32000 seconds
> would pre-allocate %d for the next 8 hours.
> > 2)Apply math to Clock.currentTimeMillis() to get an index into the
> buffer. Seconds precision:
> > [10] = "2021-08-28 09:44:31,000"
> > [11] = "2021-08-28 09:44:32,000"[12] = "2021-08-28 09:44:33,000"[13] =
> "2021-08-28 09:44:34,000"[14] = "2021-08-28 09:44:35,000"[15] = "2021-08-28
> 09:44:36,000"...[31999] = "..."
> > 50ms precision:
> > [10] = "2021-08-28 09:44:31,050"[11] = "2021-08-28 09:44:31,075"[12] =
> "2021-08-28 09:44:31,100"[13] = "2021-08-28 09:44:31,150"[14] = "2021-08-28
> 09:44:31,175"[15] = "2021-08-28 09:44:31,200"...[31999] = "..."
> >
> > 3)Rendering %d{SEQ(DEFAULT,32000)} is just a index lookup into the
> sequence of 32000 pre-calculated %d{DEFAULT} values without the cost of
> formatting. I made up the "SEQ" notation, there's likely a better way to
> express the feature. Everything can read from the buffer without locking.
> > 4)Have a background thread casually keep the sequence filled in a ring
> so dates in the past are replaced with future dates so the structure
> consumes a consistent amount of memory.
> >On Friday, August 27, 2021, 10:07:59 PM EDT, Carter Kozak <
> cko...@ckozak.net> wrote:
> >
> > Thanks, Remko. The default '%d' uses FixedDateFormat with
> FixedFormat.DEFAULT. The FastDateFormat alternative does not support
> microseconds, so it doesn't suffer from the same problem. I think I can
> substantially reduce the frequency we re-format dates by checking
> FixedFormat.secondFractionDigits to determine if we meed to compare
> microseconds.
> >
> > On Fri, Aug 27, 2021, at 16:10, Remko Popma wrote:
> >> I remember looking at PatternLayout performance, I reported my findings
> here, hopefully they’re still useful:
> https://issues.apache.org/jira/browse/LOG4J2-930
> >>
> >> If %d is used in the pattern, does the FixedDateFormat get used?
> >>
> >>
> >>
> >>
> >>> On Aug 28, 2021, at 4:33, Ralph Goers 
> wrote:
> >>>
> >>> All of that agrees with my observations as well.
> >>>
> >>> Ralph
> >>>
>  On Aug 27, 2021, at 12:23 PM, Carter Kozak  wrote:
> 
>  I've identified a few things that seem impactful, but bear in mind
> that I haven't begun to drill down into them yet. I plan to file individual
> tickets and i

Re: Cek's new log4j vs logback benchmark

[Carter Kozak]

I don’t particularly want to optimize for the benchmarks, in most cases by 
pre-generating the formatted dates we’d end up doing substantially more work 
because we don’t log an event every millisecond/microsecond in practice.
I’ve pushed a relatively naive optimization which takes into account when 
microseconds aren’t used to provide the same performance as java 8 (where 
microseconds weren’t available), but the implementation can be improved to 
cache dates much longer if only second granularity is used. I’m skeptical that 
such improvements would be helpful though because it’s uncommon to combine 
low-precision timestamps with very high rates of logging in my experience.
https://issues.apache.org/jira/browse/LOG4J2-3153 

https://github.com/apache/logging-log4j2/pull/572 


In testing (with direct encoders disabled) this brings us most of the way to 
the logbook results. When I use it with a custom hard-coded layout 
implementation to produce the same output as the pattern, log4j2 performs 15% 
faster than logbook (in a single-threaded benchmark, I haven’t revalidated 
using the async benchmarks because we seem to have a clear lead across the 
asynchronous parts).

> On Aug 28, 2021, at 4:36 AM, Dominik Psenner  wrote:
> 
> May a ringbuffer cache be a viable solution?
> 
> Knowing the resolution (ticks, microseconds, milliseconds, seconds,..), a
> key could be generated to lookup and return a previously created formatted
> string from a ringbuffer or create it on the fly and store it for later.
> During bursts of log events, this could significantly improve performance.
> The ringbuffer may even be very small, only depending on the requested
> resolution.
> 
> Cheers
> Dominik
> --
> Sent from my phone. Typos are a kind gift to anyone who happens to find
> them.
> 
> On Sat, Aug 28, 2021, 09:40 Ralph Goers  wrote:
> 
>> If you look at log4j-perf you will see both a TimeFormatBenchmark and a
>> ClocksBenchmark. The time
>> benchmark doesn’t include java.time’s formatter but I am pretty sure I
>> added it to find that it was still
>> slower than our formatters. However, the TimeFormat benchmark tests using
>> System.currentTimeMillis
>> - it doesn’t use a Clock. So there really isn’t a perf test for all the
>> various ways the Date Converter
>> could be implemented.
>> 
>> Actually, having a background thread for the date is an interesting idea
>> but I don’t think I would have the
>> thread create dates that might be used. Instead, I would look to see if
>> there is a way to request the date
>> be formatted asynchronously so that when the DateConverter actually needs
>> it it is already available. The
>> trick to this would be to know that a date is going to be requested
>> similar to how we check whether
>> location information is required. Then the async thread could add the
>> formatted time to the log event.
>> The only downside to this is that it assumes the date formatting thread
>> will actually run before the Date
>> Converter needs the data.
>> 
>> The problem with pre-formatting is that we would have to determine the
>> frequency with which log events
>> arrive. It doesn’t do any good to format the next 32K milliseconds if
>> logging occurs once per second. And
>> it doesn’t do any good to format once per second just to have it suddenly
>> start generating 10 events per
>> second.
>> 
>> 
>> Ralph
>> 
>>> On Aug 27, 2021, at 11:16 PM, Ron Grabowski 
>> wrote:
>>> 
>>> Follow-up to "Formatting the date is expensive. The process of actually
>> formatting a value is reasonable". Is this still an issue from LOG4J2-930:
>>> %m %ex%n: 1,755,573 msg/sec%d %m %ex%n: 1,194,184 msg/sec
>>> If so, isn't date rendering essentially a sequence we can generate ahead
>> of time similar to how a local ID generator asks for an allocation of keys
>> then uses that to quickly assign IDs to new objects? When its time to
>> render %d we can just grab it via an index:
>>> 
>>> 1)At startup calculate the next 32k formatted dates. If
>> Clock.currentTimeMillis() were configured down to the second, 32000 seconds
>> would pre-allocate %d for the next 8 hours.
>>> 2)Apply math to Clock.currentTimeMillis() to get an index into the
>> buffer. Seconds precision:
>>> [10] = "2021-08-28 09:44:31,000"
>>> [11] = "2021-08-28 09:44:32,000"[12] = "2021-08-28 09:44:33,000"[13] =
>> "2021-08-28 09:44:34,000"[14] = "2021-08-28 09:44:35,000"[15] = "2021-08-28
>> 09:44:36,000"...[31999] = "..."
>>> 50ms precision:
>>> [10] = "2021-08-28 09:44:31,050"[11] = "2021-08-28 09:44:31,075"[12] =
>> "2021-08-28 09:44:31,100"[13] = "2021-08-28 09:44:31,150"[14] = "2021-08-28
>> 09:44:31,175"[15] = "2021-08-28 09:44:31,200"...[31999] = "..."
>>> 
>>> 3)Rendering %d{SEQ(DEFAULT,32000)} is just a index lookup into the
>> sequence of 32000 pre-calculated %d{DEFAULT} values without the cost of
>> formatting. I made up the "SEQ" notation, there's lik

[VOTE] Release Log4j Kotlin API 1.0.1 RC1

[Matt Sicker]

Hey everyone, we have a new release candidate for Log4j Kotlin API.
This is a vote to release Log4j Kotlin API 1.0.1. Please download,
validate, and cast your votes here.
[] +1, release the artifacts
[] -1, don't release because...

The vote will remain open for 72 hours (or more if required). All
votes are welcome and we encourage everyone to test the release, but
only Logging PMC votes are “officially” counted. As always, at least 3
+1 votes and more positive than negative votes are required.

Release info:

Git tag:
git clone https://gitbox.apache.org/repos/asf/logging-log4j-kotlin.git
git checkout tags/log4j-api-kotlin-1.0.1-rc1

Web Site: https://logging.staged.apache.org/log4j/kotlin/

Maven Artifacts:
https://repository.apache.org/content/repositories/orgapachelogging-1063/

Distribution: https://dist.apache.org/repos/dist/dev/logging/log4j/kotlin/

You may download all the Maven artifacts by executing:
wget -e robots=off --cut-dirs=7 -nH -r -p -np --no-check-certificate \
https://repository.apache.org/content/repositories/orgapachelogging-1063/org/apache/logging/log4j/

Re: [VOTE] Release Log4j Kotlin API 1.0.1 RC1

[Matt Sicker]

Apologies, cancelling this release. The changelog wasn't updated yet,
and upon reviewing it, the version number proposed doesn't make sense.
I'll follow up shortly with a 1.1-rc1.

On Sat, Aug 28, 2021 at 2:34 PM Matt Sicker  wrote:
>
> Hey everyone, we have a new release candidate for Log4j Kotlin API.
> This is a vote to release Log4j Kotlin API 1.0.1. Please download,
> validate, and cast your votes here.
> [] +1, release the artifacts
> [] -1, don't release because...
>
> The vote will remain open for 72 hours (or more if required). All
> votes are welcome and we encourage everyone to test the release, but
> only Logging PMC votes are “officially” counted. As always, at least 3
> +1 votes and more positive than negative votes are required.
>
> Release info:
>
> Git tag:
> git clone https://gitbox.apache.org/repos/asf/logging-log4j-kotlin.git
> git checkout tags/log4j-api-kotlin-1.0.1-rc1
>
> Web Site: https://logging.staged.apache.org/log4j/kotlin/
>
> Maven Artifacts:
> https://repository.apache.org/content/repositories/orgapachelogging-1063/
>
> Distribution: https://dist.apache.org/repos/dist/dev/logging/log4j/kotlin/
>
> You may download all the Maven artifacts by executing:
> wget -e robots=off --cut-dirs=7 -nH -r -p -np --no-check-certificate \
> https://repository.apache.org/content/repositories/orgapachelogging-1063/org/apache/logging/log4j/

[VOTE] Release Log4j Kotlin API 1.1.0 RC1

[Matt Sicker]

Hey everyone, we have a new release candidate for Log4j Kotlin API.
This is a vote to release Log4j Kotlin API 1.1.0. Please download,
validate, and cast your votes here.
[] +1, release the artifacts
[] -1, don't release because...

The vote will remain open for 72 hours (or more if required). All
votes are welcome and we encourage everyone to test the release, but
only Logging PMC votes are “officially” counted. As always, at least 3
+1 votes and more positive than negative votes are required.

Changes:

* Support MDCs with coroutines

* Support suspend functions in supplier lambdas

* Update Kotlin baseline version to 1.3.72


Release info:

Git tag:
git clone https://gitbox.apache.org/repos/asf/logging-log4j-kotlin.git
git checkout tags/log4j-api-kotlin-1.1.0-rc1

Web Site: https://logging.staged.apache.org/log4j/kotlin/

Maven Artifacts:
https://repository.apache.org/content/repositories/orgapachelogging-1064/

Distribution: https://dist.apache.org/repos/dist/dev/logging/log4j/kotlin/

You may download all the Maven artifacts by executing:
wget -e robots=off --cut-dirs=7 -nH -r -p -np --no-check-certificate \
https://repository.apache.org/content/repositories/orgapachelogging-1064/org/apache/logging/log4j/

Re: Cek's new log4j vs logback benchmark

[Ralph Goers]

Have you pushed that up somewhere? I would like to test it. 

 Is it possible to have direct encoders disabled by default unless something 
else that indicates GC Free logging is desired is enabled? From what I can tell 
the CPU overhead of GC Free logging makes it not worth it for most Java apps. 
If the application itself isn’t GC Free there isn’t much point for Log4j to be.

When I tested I did see a benefit of using a buffer size larger than the 
default of 8K. But again, that probably is what you want for a typical logging 
scenario.

Ralph

> On Aug 28, 2021, at 11:36 AM, Carter Kozak  wrote:
> 
> I don’t particularly want to optimize for the benchmarks, in most cases by 
> pre-generating the formatted dates we’d end up doing substantially more work 
> because we don’t log an event every millisecond/microsecond in practice.
> I’ve pushed a relatively naive optimization which takes into account when 
> microseconds aren’t used to provide the same performance as java 8 (where 
> microseconds weren’t available), but the implementation can be improved to 
> cache dates much longer if only second granularity is used. I’m skeptical 
> that such improvements would be helpful though because it’s uncommon to 
> combine low-precision timestamps with very high rates of logging in my 
> experience.
> https://issues.apache.org/jira/browse/LOG4J2-3153 
> 
> https://github.com/apache/logging-log4j2/pull/572 
> 
> 
> In testing (with direct encoders disabled) this brings us most of the way to 
> the logbook results. When I use it with a custom hard-coded layout 
> implementation to produce the same output as the pattern, log4j2 performs 15% 
> faster than logbook (in a single-threaded benchmark, I haven’t revalidated 
> using the async benchmarks because we seem to have a clear lead across the 
> asynchronous parts).
> 
>> On Aug 28, 2021, at 4:36 AM, Dominik Psenner  wrote:
>> 
>> May a ringbuffer cache be a viable solution?
>> 
>> Knowing the resolution (ticks, microseconds, milliseconds, seconds,..), a
>> key could be generated to lookup and return a previously created formatted
>> string from a ringbuffer or create it on the fly and store it for later.
>> During bursts of log events, this could significantly improve performance.
>> The ringbuffer may even be very small, only depending on the requested
>> resolution.
>> 
>> Cheers
>> Dominik
>> --
>> Sent from my phone. Typos are a kind gift to anyone who happens to find
>> them.
>> 
>> On Sat, Aug 28, 2021, 09:40 Ralph Goers  wrote:
>> 
>>> If you look at log4j-perf you will see both a TimeFormatBenchmark and a
>>> ClocksBenchmark. The time
>>> benchmark doesn’t include java.time’s formatter but I am pretty sure I
>>> added it to find that it was still
>>> slower than our formatters. However, the TimeFormat benchmark tests using
>>> System.currentTimeMillis
>>> - it doesn’t use a Clock. So there really isn’t a perf test for all the
>>> various ways the Date Converter
>>> could be implemented.
>>> 
>>> Actually, having a background thread for the date is an interesting idea
>>> but I don’t think I would have the
>>> thread create dates that might be used. Instead, I would look to see if
>>> there is a way to request the date
>>> be formatted asynchronously so that when the DateConverter actually needs
>>> it it is already available. The
>>> trick to this would be to know that a date is going to be requested
>>> similar to how we check whether
>>> location information is required. Then the async thread could add the
>>> formatted time to the log event.
>>> The only downside to this is that it assumes the date formatting thread
>>> will actually run before the Date
>>> Converter needs the data.
>>> 
>>> The problem with pre-formatting is that we would have to determine the
>>> frequency with which log events
>>> arrive. It doesn’t do any good to format the next 32K milliseconds if
>>> logging occurs once per second. And
>>> it doesn’t do any good to format once per second just to have it suddenly
>>> start generating 10 events per
>>> second.
>>> 
>>> 
>>> Ralph
>>> 
 On Aug 27, 2021, at 11:16 PM, Ron Grabowski 
 
>>> wrote:
 
 Follow-up to "Formatting the date is expensive. The process of actually
>>> formatting a value is reasonable". Is this still an issue from LOG4J2-930:
 %m %ex%n: 1,755,573 msg/sec%d %m %ex%n: 1,194,184 msg/sec
 If so, isn't date rendering essentially a sequence we can generate ahead
>>> of time similar to how a local ID generator asks for an allocation of keys
>>> then uses that to quickly assign IDs to new objects? When its time to
>>> render %d we can just grab it via an index:
 
 1)At startup calculate the next 32k formatted dates. If
>>> Clock.currentTimeMillis() were configured down to the second, 32000 seconds
>>> would pre-allocate %d for the next 8 hours.
 2)Apply math to Clock.currentTimeMillis() 

Re: Cek's new log4j vs logback benchmark

[Remko Popma]

On Sat, Aug 28, 2021 at 3:16 PM Ron Grabowski
 wrote:

>  Follow-up to "Formatting the date is expensive. The process of actually
> formatting a value is reasonable". Is this still an issue from LOG4J2-930:
> %m %ex%n: 1,755,573 msg/sec%d %m %ex%n: 1,194,184 msg/sec
>

No, I believe that formatting the date is no longer the bottleneck.
The analysis done in LOG4J2-930 led to
https://issues.apache.org/jira/browse/LOG4J2-1097 which resulted in the
FixedDateFormat.
This format gives a good trade-off between speed and flexibility.
The drawback is that it only works for some fixed formats, but those are
the most widely used formats.
I don't think that focusing on the date formatting and pregenerate
formatted timestamps will be fruitful (but I could be wrong).

Avoiding the PreciseTime Instant and using System.currentTimeMillis when it
is known that none of the downstream formatters require sub-millisecond
precision may be a good optimization.

The message formatting (PatternLayout) as a whole is expensive somehow,
there may be more to optimize there.


> If so, isn't date rendering essentially a sequence we can generate ahead
> of time similar to how a local ID generator asks for an allocation of keys
> then uses that to quickly assign IDs to new objects? When its time to
> render %d we can just grab it via an index:
>
> 1)At startup calculate the next 32k formatted dates. If
> Clock.currentTimeMillis() were configured down to the second, 32000 seconds
> would pre-allocate %d for the next 8 hours.
> 2)Apply math to Clock.currentTimeMillis() to get an index into the buffer.
> Seconds precision:
> [10] = "2021-08-28 09:44:31,000"
> [11] = "2021-08-28 09:44:32,000"[12] = "2021-08-28 09:44:33,000"[13] =
> "2021-08-28 09:44:34,000"[14] = "2021-08-28 09:44:35,000"[15] = "2021-08-28
> 09:44:36,000"...[31999] = "..."
> 50ms precision:
> [10] = "2021-08-28 09:44:31,050"[11] = "2021-08-28 09:44:31,075"[12] =
> "2021-08-28 09:44:31,100"[13] = "2021-08-28 09:44:31,150"[14] = "2021-08-28
> 09:44:31,175"[15] = "2021-08-28 09:44:31,200"...[31999] = "..."
>
> 3)Rendering %d{SEQ(DEFAULT,32000)} is just a index lookup into the
> sequence of 32000 pre-calculated %d{DEFAULT} values without the cost of
> formatting. I made up the "SEQ" notation, there's likely a better way to
> express the feature. Everything can read from the buffer without locking.
> 4)Have a background thread casually keep the sequence filled in a ring so
> dates in the past are replaced with future dates so the structure consumes
> a consistent amount of memory.
> On Friday, August 27, 2021, 10:07:59 PM EDT, Carter Kozak <
> cko...@ckozak.net> wrote:
>
>  Thanks, Remko. The default '%d' uses FixedDateFormat with
> FixedFormat.DEFAULT. The FastDateFormat alternative does not support
> microseconds, so it doesn't suffer from the same problem. I think I can
> substantially reduce the frequency we re-format dates by checking
> FixedFormat.secondFractionDigits to determine if we meed to compare
> microseconds.
>
> On Fri, Aug 27, 2021, at 16:10, Remko Popma wrote:
> > I remember looking at PatternLayout performance, I reported my findings
> here, hopefully they’re still useful:
> https://issues.apache.org/jira/browse/LOG4J2-930
> >
> > If %d is used in the pattern, does the FixedDateFormat get used?
> >
> >
> >
> >
> > > On Aug 28, 2021, at 4:33, Ralph Goers 
> wrote:
> > >
> > > All of that agrees with my observations as well.
> > >
> > > Ralph
> > >
> > >> On Aug 27, 2021, at 12:23 PM, Carter Kozak  wrote:
> > >>
> > >> I've identified a few things that seem impactful, but bear in mind
> that I haven't begun to drill down into them yet. I plan to file individual
> tickets and investigate in greater depth later on:
> > >>
> > >> 1. Formatting the date is expensive. The process of actually
> formatting a value is reasonable, however using a precise clock appears to
> cause cache misses even when the pattern results in the same value
> (microseconds/nanoseconds aren't included in the result). Using the
> SystemMillisClock improves our throughput. I imagine some part of that
> improvement is the result of currentTimeMillis(): long rather than
> Clock.instant().
> > >>
> > >> 2. Setting 'log4j2.enable.direct.encoders' to false improves
> performance, otherwise we see a lot of time spent in the
> StringBuilderEncoder, but I haven't had time to investigate that yet.
> Without direct encoders, we are allocating a great deal more byte arrays,
> but they're used across a small space that C2 may be able to inline out.
> > >>
> > >> 3. Setting log4j2.formatMsgNoLookups=true (or using message pattern
> '%m{nolookup}' saves us some time scanning through produced messages --
> I've had this disabled at work for a while.
> > >>
> > >> 4. [in progress] If I implement the full layout directly in java
> (write directly to a stringbuilder based on the event in a custom Layout
> instead of using PatternLayout) combined with [1] and [2] above,
> performance is much better than logb