CODEWITHSUNDEEP
javaloggingplayframeworkconfigurationlog4j2
user1676426
user1676426

Reputation: 73

Log4J2 AsyncLogger is filling up LMAX disruptor's ring buffer at high concurrency

I am using Log4J2 AsyncLogger in my Java Play Framework based application. I see that at high concurrency (~3000 users per server) the ring buffer's remaining size reaches zero quickly and my requests start to fail. My ring buffer size is 1048576 (512*2048). The number of application threads are 8 (1 thread per core as stated in Play's official documentation.) My questions are:

1> How can I increase the speed at which the consumer writes to the log file? 2> Can I explicitly use multiple consumers to write to my log file? If so, where do I specify these consumers?

I have included my log4j2.xml file. Any help will be highly appreciated :)

Things I tried:

1> Increased ring buffer size (always as a power of 2). But eventually the same problem arises, and using too much memory does not seem very elegant. This option will be shot down in production. Am I missing anything?

2> Tried different waiting strategies. No luck.

<?xml version="1.0" encoding="UTF-8"?>

<Configuration>
<!--  status="trace" attribute for Configuration tag prints in logs [ Starting AsyncLoggerConfig disruptor for this configuration with ringbufferSize=262144] -->
<!-- default log file names in case it fails to read it from property file -->
<Properties>
    <Property name="FILE_NAME">/opt/lol/logs/meh.log</Property>
    <Property name="FILE_PATTERN">/opt/lol/logs/meh_%d{yyyy-MM-dd_HH}.log</Property>
</Properties>

<Appenders>
    <RollingRandomAccessFile name="ASYNCFILE" fileName="${sys:FILE_NAME}" filePattern="${sys:FILE_PATTERN}">
        <PatternLayout pattern="[meh:%d{yyyy-MM-dd HH:mm:ss},%d{SSS}] %-5level[%thread][%C{1}:%L] %msg%n"/>
        <Policies>
            <TimeBasedTriggeringPolicy />
        </Policies>
    </RollingRandomAccessFile>

    <Console name="CONSOLE" target="SYSTEM_OUT">
        <PatternLayout pattern="[meh:%d{yyyy-MM-dd HH:mm:ss},%d{SSS}] %-5level[%thread][%C{1}:%L] %msg%n"/>
    </Console>
</Appenders>

<Loggers>
    <logger name="akka" level="INFO" />
    <AsyncRoot level="INFO" includeLocation="true">
       <!-- <AppenderRef ref="CONSOLE"/>-->
        <AppenderRef ref="ASYNCFILE"/>
    </AsyncRoot>
</Loggers>
</Configuration>

I expect the concurrency to hit at least 4000 per box (the same as without loggers). But I am stuck at around 2500.

Upvotes: 5

Views: 3620

Answers (1)

Remko Popma
Remko Popma

Reputation: 36754

  1. You can increase the speed by not using location: replace [%C{1}:%L] with simply %c. The Log4j 2 performance documentation shows that logging location is 100x slower.
  2. Multiple consumers will not speed up logging. The hard disk is still the single end-consumer and having multiple threads trying to write at the same time (using locking to prevent data corruption) is actually slower. This is why the disruptor is designed the way it is.

Upvotes: 7

Related Questions