I'm conducting a load test on System.out
, System.err
and logger.info
(using SLF4J + Logback) in a Java 8 environment with Spring Boot 2.6.0 and Logback 1.2.7. I have packaged my project into an executable JAR and run it on Windows 11 using the following command: java -jar -Xms256m -Xmx256m .\happyTest-1.0.2-SNAPSHOT.jar > .\logs\happyTest2.log 2>&1
.
Here is API code:
@RestController
@RequestMapping("/log")
public class LogController {
private static final Logger logger = .slf4j.LoggerFactory.getLogger(LogController.class);
private static final int LOOP_COUNT = 100;
@GetMapping("/system-out")
public String logSystemOut() {
long startTime = System.currentTimeMillis();
for (int i = 0; i < LOOP_COUNT; i++) {
System.out.println("hello world");
}
long endTime = System.currentTimeMillis();
return "Logged messages in " + (endTime - startTime) + " ms";
}
@GetMapping("/system-err")
public String logSystemErr() {
long startTime = System.currentTimeMillis();
for (int i = 0; i < LOOP_COUNT; i++) {
System.err.println("hello world");
}
long endTime = System.currentTimeMillis();
return "Logged messages in " + (endTime - startTime) + " ms";
}
@GetMapping("/info")
public String logInfo() {
long startTime = System.currentTimeMillis();
for (int i = 0; i < LOOP_COUNT; i++) {
logger.info("hello world");
}
long endTime = System.currentTimeMillis();
return "Logged messages in " + (endTime - startTime) + " ms";
}
}
My logback.xml configuration is below:
<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="30 seconds">
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>logs/happyTest.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>logs/happyTest.%d{yyyy-MM-dd}.log</fileNamePattern>
<maxHistory>30</maxHistory>
</rollingPolicy>
<encoder>
<pattern>%msg%n</pattern>
</encoder>
</appender>
<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
<discardingThreshold>0</discardingThreshold>
<queueSize>8192</queueSize>
<appender-ref ref="FILE"/>
</appender>
<root level="INFO">
<appender-ref ref="ASYNC"/>
</root>
</configuration>
I use JMeter in other computer, use CLI mode run this test plan.
Note that every different API just change the request path to test.
Based on my understanding, the performance of System.out
and System.err
should be similar and generally lower than logger.info
due to I configure the ch.qos.logback.classic.AsyncAppender
in logback.xml.
Yes, it worked as I expected. logger.info
is best.
Hower I was surprised to find that the performance of System.err
is significantly lower than System.out
.
Here is System.err
performance. Significantly slower.
Here is System.out
performence. Faster compared to System.err
.
After reviewing the source code of System.java, I noticed that the different of System.out
and System.err
only is the encode and file descriptor. Both they are BufferedOutputStream
, not like some AI claims that System.err
is unbufferd.
// java.lang.System
// ... other code
public final static PrintStream out = null;
public final static PrintStream err = null;
// ... other code
private static void initializeSystemClass() {
// ... other code
FileInputStream fdIn = new FileInputStream(FileDescriptor.in);
FileOutputStream fdOut = new FileOutputStream(FileDescriptor.out);
FileOutputStream fdErr = new FileOutputStream(FileDescriptor.err);
setIn0(new BufferedInputStream(fdIn));
setOut0(newPrintStream(fdOut, props.getProperty("sun.stdout.encoding")));
setErr0(newPrintStream(fdErr, props.getProperty("sun.stderr.encoding")));
// ... other code
}
// ... other code
private static PrintStream newPrintStream(FileOutputStream fos, String enc) {
if (enc != null) {
try {
return new PrintStream(new BufferedOutputStream(fos, 128), true, enc);
} catch (UnsupportedEncodingException uee) {}
}
return new PrintStream(new BufferedOutputStream(fos, 128), true);
}
So, why is the performance of System.err
is significantly lower than System.out
?
Thank you for your insights!