Sending 2000 message / second with JMSAppender log4j2

Question

I'm trying to use JMSAppender log4j2 to send logs to ActivMQ.

I have done the following conf

<?xml version="1.0" encoding="UTF-8"?>
<Configuration monitorInterval="5">
    <Appenders>
        <Console name="STDOUT" target="SYSTEM_OUT">
            <PatternLayout
                pattern="%d{HH:mm:ss.SSS} %highlight{[%-5p] %c{1.} - %m} %style{(%t)}{Cyan}%n" />
        </Console>
        <RollingFile name="fish" fileName="E:/fish/log/fish.server/fish.log"
            filePattern="/log/fish.server/fish-%-d{yyyy-MM-dd-HH}.log">
            <PatternLayout pattern="%-d{yyyy-MM-dd HH:mm:ss.SSS} %5p %c{1} - %m%n" />
            <Policies>
                <TimeBasedTriggeringPolicy />
            </Policies>
        </RollingFile>

         <JMS name="jmsQueue" destinationBindingName="logQueue"
            factoryName="org.apache.activemq.jndi.ActiveMQInitialContextFactory"
            factoryBindingName="ConnectionFactory" providerURL="tcp://xxxxxx:61616">
            <PatternLayout pattern="%-d{yyyy-MM-dd HH:mm:ss.SSS} %5p %c{1} - %m%n" />
        </JMS>

    </Appenders>
    <Loggers>

        <Logger name="jmsLogger" level="warn">
            <AppenderRef ref="jmsQueue" />
        </Logger>

        <Root level="warn">
            <!-- <AppenderRef ref="STDOUT" /> -->
            <AppenderRef ref="fish" />
        </Root>
    </Loggers>
</Configuration>

After that, I have 32 thread of streamExecutor which do some staff and then use a jmsLogger.warn(xxxx).

I have done a thread dump for my app, and I noticed the following blocking staff :

"Log4j2-AsyncLogger[AsyncContext@14dad5dc]1" - Thread t@27
   java.lang.Thread.State: WAITING
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for <324492ea> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.ArrayBlockingQueue.take(ArrayBlockingQueue.java:403)
    at org.apache.activemq.transport.FutureResponse.getResult(FutureResponse.java:40)
    at org.apache.activemq.transport.ResponseCorrelator.request(ResponseCorrelator.java:87)
    at org.apache.activemq.ActiveMQConnection.syncSendPacket(ActiveMQConnection.java:1366)
    at org.apache.activemq.ActiveMQConnection.syncSendPacket(ActiveMQConnection.java:1305)
    at org.apache.activemq.ActiveMQSession.send(ActiveMQSession.java:1795)
    - locked <1af6596a> (a java.lang.Object)
    at org.apache.activemq.ActiveMQMessageProducer.send(ActiveMQMessageProducer.java:277)
    at org.apache.activemq.ActiveMQMessageProducer.send(ActiveMQMessageProducer.java:212)
    at org.apache.activemq.ActiveMQMessageProducerSupport.send(ActiveMQMessageProducerSupport.java:241)
    at org.apache.logging.log4j.core.appender.mom.JmsAppender.append(JmsAppender.java:65)
    at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
    at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
    at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:310)
    at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:149)
    at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:45)
    at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:29)
    at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

So the question is, why the send mode is synchrone ?org.apache.activemq.ActiveMQConnection.syncSendPacket. This is causing some blocking issue and slowing my performance.

Thnks a lot :)

Answer 1

As of Log4j 2.7, I am not aware of any performance benchmarks for logging using a JMS appender. Most of the published benchmarks are for file logging. Log4j2 can log 800K msg/sec to a file, sustained, synchronously, even in multi-threaded applications. Asynchronous logging can be multiple times faster to handle bursts.

In comparison, 2000 msg/sec does not seem like a very high number. I'm guessing it would depend on the throughput of the JMS implementation library.