Windows环境下Java中System.err性能显著低于System.out的原因探究
最近我在做Java日志相关的性能测试,环境是Java 8 + Spring Boot 2.6.0 + Logback 1.2.7,把项目打成可执行Jar包后在Windows 11上运行,启动命令是:
java -jar -Xms256m -Xmx256m .\happyTest-1.0.2-SNAPSHOT.jar > .\logs\happyTest2.log 2>&1
我的测试API代码很简单,就是三个接口分别循环输出100条日志,统计耗时:
@RestController @RequestMapping("/log") public class LogController { private static final Logger logger = org.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"; } }
Logback配置用了异步Appender,确保logger.info的性能最优:
<?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>
测试工具用的是另一台电脑上的JMeter,以CLI模式运行测试计划,每个接口只修改请求路径即可。
按照我的预期,System.out和System.err性能应该差不多,而且都比不上用了异步Appender的logger.info——结果确实如预期,logger.info的性能是最好的,但意外的是Windows环境下System.err的性能比System.out慢了一大截:
- System.err测试结果:平均响应时间显著偏高,性能表现很差
- System.out测试结果:响应时间明显更低,比System.err快不少
我特意去翻了Java的源码,发现System.out和System.err其实都是用BufferedOutputStream包装的,不像有些说法说err是无缓冲的,两者的区别只是编码和文件描述符不同:
// java.lang.System相关源码片段 public final static PrintStream out = null; public final static PrintStream err = null; private static void initializeSystemClass() { // ... 其他代码 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"))); // ... 其他代码 } 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); }
为了搞清楚原因,我转到Ubuntu环境重试了测试:
- 把API里的LOOP_COUNT改成500
- 启动命令改成:
nohup java -jar -Xms256m -Xmx256m ./happyTest-1.0.2-SNAPSHOT.jar > ./logs/happyTest2.log 2> ./logs/happyTest3.log & - 调整JMeter配置后运行测试
结果在Ubuntu下,System.out和System.err的性能表现几乎一致,这说明问题大概率出在Windows系统的底层处理上。
回到Windows环境,我又做了一轮更严谨的测试:按顺序交替测试System.out和System.err,每次测试间隔约4分钟,重复多次。但结果还是一样——System.err的性能始终明显低于System.out,没有任何改观。
目前看来,虽然Java层面System.out和System.err都是缓冲流,但Windows系统对标准错误流(stderr)和标准输出流(stdout)的底层处理机制存在差异,比如可能是stderr的刷新策略更激进、系统级别的调度优先级不同,或者重定向到文件时的处理逻辑不一样,这些内核级别的差异最终导致了两者在Windows下的性能差距。
备注:内容来源于stack exchange,提问作者Pai

