[log4j] performance issue 2.22.1 vs. 2.22.0

2024-01-29 Thread andpro77
Hi,

there is a performance issue in Log4j2 2.22.1 compared to 2.22.0.

I upgraded just the two files log4j-api-2.22.1.jar and log4j-core-2.22.1.jar, 
no other file.
As an example, in my application, the streaming of about 460 MB slowed down 
from about 10-15 seconds
to more than 1000 seconds.
Parts of this can surely be explained by an inefficient internal stream 
manipulation implementation,
which does certains things more often than necessary. However, with 2.22.0 this 
doesn't cause problems. 
And also outside of that sub-optimal streaming, everything is slower, 
measurable for instance
in the range of about 270 milliseconds instead of about 80 millis.

Note, this happens even though effectively just two lines are really logged.
If DEBUG or TRACE were enabled in the loggers, then tens if not hundreds of 
thousands of lines would be logged - so definitely,
there is a lot of logging going on.

This has to do with the org.apache.logging.log4j.ThreadContext.
If I remove just the following one line from my code, then the performance is 
back at normal.

ThreadContext.put(key, value);

So I think this could have been caused by issue 2238
(Avoid a slow exception catch in JdkMapAdapterStringMap constructor #2238).


Kind regards

Andreas


Aw: Re: [log4j] performance issue 2.22.1 vs. 2.22.0

2024-01-29 Thread andpro77
Thank you both for the responses.
 
You asked for the log4j configuration.
I try to extract the relevant parts.
 
Indeed the application has got a DynamicThresholdFilter in the game.





There two appenders referenced from the loggers, one usual RollingFile appender 
with the following pattern:

%d{-MM-dd HH:mm:ss,SSS 'UTC'Z} %-5p [%t] (%X{reqtype}) 
[%X{reqtag}] %c -- %m%n

And one Null appender as placeholder.


The loggers are configured to INFO, that's why just the two lines.
They have no extra threshold configured.



If I remove the (%X{reqtype}) [%X{reqtag}], then this doesn't improve the 
performance.
But indeed, if I remove the DynamicThresholdFilter, then the performance is 
back at normal, if loggers remain on INFO.
I didn't test with DEBUG enabled, and haven't got figures to compare.