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
