I'm attempting to construct a minimal example of a program which uses log4j2 and is both garbage free and takes advantage of asynchronous logging. I believe I've followed all the guidelines discussed in their documentation, but I cannot get to a zero (steady state) allocation rate. The work attached here allocates about 60 bytes per log message.
Does anyone have such an example, or, instead, can they see the error in what I've done.
UPDATE: The solution was to use Unbox.box() on the primitive types, which prevented auto-boxing, and the associated allocation. The code below has been updated.
Code:
public class Example {
static private final Logger logger = LogManager.getLogger(Example.class);
public static void main(String[] args) throws Exception {
int count = Integer.parseInt(args[0]);
System.gc();
Thread.sleep(10000);
for(int i = 0; i < count; i++) {
logSomething();
}
}
private static void logSomething() {
logger.info("{} occurred at {}, here is some useful info {}, here is some more {}.",
"AN_EVENT_I_WANT_TO_LOG", box(System.currentTimeMillis()), "ABCD", box(1234L));
}
}
Log4J2 Config:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
<Appenders>
<File name="File" fileName="/dev/null" append="false" immediateFlush="false" >
<PatternLayout pattern="%d %p %c{1.} [%t] %m %ex %map{} %n"/>
</File>
</Appenders>
<Loggers>
<Root level="info">
<AppenderRef ref="File"/>
</Root>
</Loggers>
</Configuration>
(Relevant) JVM Arguments:
-Dlog4j2.garbagefreeThreadContextMap=true
-Dlog4j2.enableThreadlocals=true
-Dlog4j2.enableDirectEncoders=true
-Dlog4j2.asyncLoggerWaitStrategy=yield
-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
The solution was to manually box the primitive values, using Unbox.box(). This prevented autoboxing and the associated allocation.
The code in the question above has been updated with the correct code.
UPDATE:
In the code below, I've extended the solution to illustrate garbage-free asynchronous logging with message objects. To be precise, this means that I can pass a reusable message to the logger (so no allocations of these objects), the message can be updated without any additional allocations, the message can be formatted without requiring allocations, the underlying logger will not do any further allocations, and that it is safe to hand this to an asynchronous logger (it will write the context as of the instant it was passed to logger.info(), not when the asynchronous logger finally gets around to it).
I post this update because I couldn't find anything similar on the web.
Code:
public class ExtendedExample {
static class ApplicationEvent {
long identifier;
String detail;
long timestamp;
public ApplicationEvent initialize(long identifier, String detail, long timestamp) {
this.identifier = identifier;
this.detail = detail;
this.timestamp = timestamp;
return this;
}
}
static private final Logger logger = LogManager.getLogger();
public static void main(String[] args) throws Exception {
int count = Integer.parseInt(args[0]);
System.gc();
Thread.sleep(10000);
final ApplicationEvent event = new ApplicationEvent();
for(int i = 0; i < count; i++) {
event.initialize(i, "ABCD_EVENT", System.currentTimeMillis());
onApplicationEvent(event);
}
}
private static class ApplicationEventLogMessage extends ReusableObjectMessage {
private final String eventType = ApplicationEvent.class.getSimpleName();
private long eventTimestamp;
private String eventDetail;
private long eventIdentifier;
private final StringBuilderFormattable formattable = new StringBuilderFormattable() {
@Override
public void formatTo(StringBuilder buffer) {
buffer.append('{')
.append("eventType").append('=').append(eventType).append(", ")
.append("eventTimestamp").append('=').append(eventTimestamp).append(", ")
.append("eventDetail").append('=').append(eventDetail).append(", ")
.append("eventIdentifier").append('=').append(eventIdentifier)
.append('}');
}
};
ReusableObjectMessage prepare(ApplicationEvent applicationEvent){
// It is very important that we call set(), every time, before we pass this to the logger -
// as the logger will clear() it.
set(formattable);
eventTimestamp = applicationEvent.timestamp;
eventDetail = applicationEvent.detail;
eventIdentifier = applicationEvent.identifier;
return this;
}
}
final static ApplicationEventLogMessage reusableEventLogMessage = new ApplicationEventLogMessage();
private static void onApplicationEvent(ApplicationEvent applicationEvent) {
logger.info( reusableEventLogMessage.prepare(applicationEvent) );
}
}
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With