Hello,
As suggested, I'm trying to reduce the ringbuffer size to 1024 or other
experimental values(even numbers). But log4j2 is taking the default
value 262144, even though I have added the system properties.
I have tried 3 ways,
1. Added VM argument as
-Dlog4j2.asyncLoggerRingBufferSize=1024
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
-Dlog4j2.debug
2. Added environment variable
LOG4J_ASYNC_LOGGER_RING_BUFFER_SIZE=1024
3. Added the log4j2.component.properties file in the resources folder of
spring boot application with the value log4j2.asyncLoggerRingBufferSize=1024
But still log4j2 is picking the default ringbuffer size 262144.
Starting AsyncLogger disruptor for this context with ringbufferSize=262144,
waitStrategy=TimeoutBlockingWaitStrategy
Version details.
1. Spring boot version 3.0.5 (spring-boot-starter-parent),
excluded spring-boot-starter-logging from startup web
2. Java version: 17
3. log4j2 version 2.20.0 (log4j-core and log4j-api)
4. tomcat version 10.1.7
5. disruptor version 3.4.4
Below is the log
DEBUG StatusLogger Starting OutputStreamManager SYSTEM_OUT.false.false-1
TRACE StatusLogger [AsyncContext@46fbb2c1] AsyncLoggerDisruptor creating
new disruptor for this context.
DEBUG StatusLogger No AsyncWaitStrategyFactory was configured in the
configuration, using default factory...
TRACE StatusLogger DefaultAsyncWaitStrategyFactory property
AsyncLogger.WaitStrategy=TIMEOUT
TRACE StatusLogger DefaultAsyncWaitStrategyFactory creating
TimeoutBlockingWaitStrategy(timeout=10, unit=MILLIS)
DEBUG StatusLogger [AsyncContext@46fbb2c1] Starting AsyncLogger disruptor
for this context with ringbufferSize=262144,
waitStrategy=TimeoutBlockingWaitStrategy,
exceptionHandler=org.apache.logging.log4j.core.async.AsyncLoggerDefaultExceptionHandler@418e7838.
..
TRACE StatusLogger [AsyncContext@46fbb2c1] AsyncLoggers use a threadlocal
translator
DEBUG StatusLogger Starting LoggerContext[name=AsyncContext@46fbb2c1,
org.apache.logging.log4j.core.async.AsyncLoggerContext@3c130745]...
TRACE StatusLogger Reregistering MBeans after reconfigure.
Selector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector@51dcb805
TRACE StatusLogger Reregistering context (1/1): 'AsyncContext@46fbb2c1'
org.apache.logging.log4j.core.async.AsyncLoggerContext@3c130745
TRACE StatusLogger Unregistering 1 MBeans:
[org.apache.logging.log4j2:type=AsyncContext@46fbb2c1]
TRACE StatusLogger Unregistering 1 MBeans:
[org.apache.logging.log4j2:type=AsyncContext@46fbb2c1
,component=StatusLogger]
TRACE StatusLogger Unregistering 1 MBeans:
[org.apache.logging.log4j2:type=AsyncContext@46fbb2c1
,component=ContextSelector]
TRACE StatusLogger Unregistering but no MBeans found matching
'org.apache.logging.log4j2:type=AsyncContext@46fbb2c1
,component=Loggers,name=*'
TRACE StatusLogger Unregistering 1 MBeans:
[org.apache.logging.log4j2:type=AsyncContext@46fbb2c1
,component=Appenders,name=DefaultConsole-2]
TRACE StatusLogger Unregistering but no MBeans found matching
'org.apache.logging.log4j2:type=AsyncContext@46fbb2c1
,component=AsyncAppenders,name=*'
TRACE StatusLogger Unregistering 1 MBeans:
[org.apache.logging.log4j2:type=AsyncContext@46fbb2c1
,component=AsyncLoggerRingBuffer]
TRACE StatusLogger Unregistering but no MBeans found matching
'org.apache.logging.log4j2:type=AsyncContext@46fbb2c1
,component=Loggers,name=*,subtype=RingBuffer'
DEBUG StatusLogger Registering MBean
org.apache.logging.log4j2:type=AsyncContext@46fbb2c1
DEBUG StatusLogger Registering MBean
org.apache.logging.log4j2:type=AsyncContext@46fbb2c1
,component=AsyncLoggerRingBuffer
DEBUG StatusLogger Registering MBean
org.apache.logging.log4j2:type=AsyncContext@46fbb2c1,component=StatusLogger
DEBUG StatusLogger Registering MBean
org.apache.logging.log4j2:type=AsyncContext@46fbb2c1
,component=ContextSelector
DEBUG StatusLogger Registering MBean
org.apache.logging.log4j2:type=AsyncContext@46fbb2c1
,component=Appenders,name=DefaultConsole-3
TRACE StatusLogger Using DummyNanoClock for nanosecond timestamps.
Thanks,
Ganesh S
On Tue, Feb 20, 2024 at 4:43 PM Remko Popma <remko.po...@gmail.com> wrote:
> 197 KB for each log message!
> That’s about 100-1000x larger than the average message size.
>
> I would suggest having a much smaller ringbuffer, meaning fewer slots.
>
> The system property that controls this is
> log4j2.asyncLoggerRingBufferSize
>
> The default is (256 * 1024), which is a lot. The minimum is 128. You will
> have to experiment what works best for the workload and “spikeyness” of
> your application.
>
> If you specify 1024, then you’ll reduce memory usage by 256x.
>
> See https://logging.apache.org/log4j/2.x/manual/async.html for details.
>
>
>
> > On Feb 20, 2024, at 20:00, Anthony Maire <maire.anth...@gmail.com>
> wrote:
> >
> > There are JVM properties to reduce both the number of slot of the ring
> > buffer, and the maximum size of the StringBuilder used inside each slot.
> > Tuning these should help to lower the extra memory footprint. I don't
> > remember them (and cannot do the search right now) but they are
> documented
> > on log4j website.
> >
> > Using async loggers is a tradeoff, you hide the disk storage latency and
> > reduce object allocations at the cost of some extra memory footprint. If
> > this is a limiting factor, maybe you should re-evaluate your options to
> see
> > if async loggers are the best configuration for your use case, especially
> > if your application does not log massively.
> >
> >> Le mar. 20 févr. 2024 à 11:24, Ganesh S <ganesh123.g...@gmail.com> a
> écrit :
> >>
> >> Hello,
> >> I'm using asynchronous Rolling file appender by passing
> >>
> *-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector*
> >> as VM argument, which internally uses lmax disruptor.
> >> *Load test specs:*
> >> 1000 threads, 0 ramp-up period, 1 loop count.
> >> Business application which will log 197 KB json for each log message
> >> and each request thread will log 2 MB considering all the log
> statements in
> >> the application. Similarly there will be 1000 simultaneous request
> threads
> >> coming to the tomcat server.
> >> When we compare asynchronous logging with synchronous logging the memory
> >> consumption is too high in asynchronous logging.
> >>
> >> The major memory contributor is the byte[] object, which is 2.02 GB and
> >> instance count is 1,73,734.
> >> Whereas in synchronous logging the byte[] object took 900 MB max.
> >> [image: image.png]
> >>
> >> If we check the incoming reference to the byte[] object,
> >> RingBufferLogEvent is pointing to the byte[] object through
> SimpleMessage
> >> class.
> >> [image: image.png]
> >>
> >> *RingBufferLogEvent is pointing to SimpleMessage which is storing the
> log
> >> message as byte[], which is of the size 197 kB (equal to single log
> message
> >> size).*
> >>
> >> [image: image.png]
> >> *Similar to that, there are 1,73,534 instances.*
> >>
> >> *If we see the shallow size of RingBufferLogEvent, it is 27 MB, but
> >> including the external reference object, i.e., byte[], it reaches 2.02
> GB.*
> >> [image: image.png]
> >> *In Async logging, number of waiting thread are high, since lmax
> >> disruptor is based on inter-thread messaging*
> >>
> >> [image: image.png]
> >>
> >> *In sync logging number of blocking threads are high, since it uses lock
> >> based logging*
> >>
> >> [image: image.png]
> >>
> >> Waiting and runnable threads are more in async logging therefore the
> >> memory consumed could be high. If we see the throughput of request
> threads,
> >> sync took 32 sec and async took 5 sec for 1000 concurrent requests.
> Async
> >> logging took an extra 5 sec in the background, since the daemon thread
> was
> >> pushing remaining logs to the file, which won't affect the business
> thread
> >> throughput.
> >>
> >> *Problem:*
> >> But the problem is, we can't afford extra 2 GB memory on top of the
> memory
> >> required for running the business logic. Atleast async logging should
> take
> >> reasonable memory near to synchronous logging with good throughput. If
> we
> >> allocate reasonable memory, due to a spike in the memory (though GC will
> >> collect the unreferred objects after the load is less), application will
> >> return the heap memory issue.
> >>
> >> Below is the programmatic initialization of the rolling file appender
> that
> >> we are using.
> >>
> >> ConfigurationBuilder<BuiltConfiguration> builder =
> ConfigurationBuilderFactory.newConfigurationBuilder();
> >> LayoutComponentBuilder layoutBuilder =
> builder.newLayout("PatternLayout")
> >> .addAttribute("pattern", "%m%n");
> >> AppenderComponentBuilder appenderBuilder =
> builder.newAppender("rolling", "RollingFile")
> >> .addAttribute("fileName", path)
> >> .addAttribute("filePattern", name + "-%i.log")
> >> .add(layoutBuilder);
> >> appenderBuilder.addComponent(builder.newComponent("Policies")
> >>
> .addComponent(builder.newComponent("SizeBasedTriggeringPolicy")
> >> .addAttribute("size", maxFileSize)));
> >>
> appenderBuilder.addComponent(builder.newComponent("DefaultRolloverStrategy")
> >> .addAttribute("max", maxBackUpFile)
> >> .addAttribute("fileIndex", "max"));
> >> appenderBuilder.add(builder.newFilter("ThresholdFilter",
> Filter.Result.ACCEPT, Filter.Result.DENY)
> >> .addAttribute("level", fileLevel));
> >> builder.add(appenderBuilder);
> >> builder.add(builder.newRootLogger(fileLevel)
> >> .add(builder.newAppenderRef("rolling")));
> >> Configurator.reconfigure(builder.build());
> >>
> >> Which is similar to
> >>
> >> <?xml version="1.0" encoding="UTF-8"?>
> >> <Configuration status="INFO">
> >> <Appenders>
> >> <RollingFile
> >> name="rolling"
> >> fileName="path"
> >> filePattern="name-%i.log">
> >> <PatternLayout pattern="%m%n"/>
> >> <Policies>
> >> <SizeBasedTriggeringPolicy size="10MB"/>
> >> </Policies>
> >> <DefaultRolloverStrategy max="5" fileIndex="max"/>
> >> <Filters>
> >> <ThresholdFilter level="debug" onMatch="ACCEPT"
> onMismatch="DENY"/>
> >> </Filters>
> >> </RollingFile>
> >> </Appenders>
> >>
> >> <Loggers>
> >> <Root level="debug">
> >> <AppenderRef ref="rolling"/>
> >> </Root>
> >> </Loggers>
> >> </Configuration>
> >>
> >> logger = LogManager.getLogger();
> >> logger.info("message1");
> >> logger.debug("message2");
> >> logger.error("message3");
> >>
> >> Any input or solution is appreciated. Thanks in advance.
> >>
> >> Thanks,
> >> Ganesh S
> >>
> >>
> >>
> >>
>
