打印性能
是日志打印框架的核心关注点之一,从logback的日志打印流程看看其性能如何?
本文基于logback1.2.3
版本,以下配置(1.2.0版本后,logback提供了 SizeAndTimeBasedRollingPolicy
策略,可同时基于时间
+空间
两个维度控制日志文件的滚动)
形如下面这句debug日志的打印,调用栈是这样的
LOGGER.debug("msg {}", msg);
Appender接口&实现类
Appender
接口作为logback的核心三大件(Logger、Appender、Layout)之一,所有的日志打印Appender类都必须遵循Appender接口的规范。
关于性能的代码
根据上文的调用栈,可以看到Logger.debug()
最终调用了OutputStreamAppender.subAppend()
,其中核心代码就两句:encode
和writeBytes
/**
* Actual writing occurs here.
* <p>
* Most subclasses of <code>WriterAppender</code> will need to override this
* method.
*
* @since 0.9.0
*/
protected void subAppend(E event) {
if (!isStarted()) {
return;
}
try {
// this step avoids LBCLASSIC-139
if (event instanceof DeferredProcessingAware) {
((DeferredProcessingAware) event).prepareForDeferredProcessing();
}
// the synchronization prevents the OutputStream from being closed while we
// are writing. It also prevents multiple threads from entering the same
// converter. Converters assume that they are in a synchronized block.
// lock.lock();
byte[] byteArray = this.encoder.encode(event);
writeBytes(byteArray); // 写入encode的日志内容
} catch (IOException ioe) {
// as soon as an exception occurs, move to non-started state
// and add a single ErrorStatus to the SM.
this.started = false;
addStatus(new ErrorStatus("IO failure in appender", this, ioe));
}
}
官方注释:OutputStream
的输出需要同步
,同时为了防止多个线程同时使用,converter
对event对象向输出流数据的转换需要得到串行化保障。
再看下writeBytes()
的实现,可以看到所有的日志打印线程到这个方法中需要阻塞、同步执行
write方法。
// OutputStreamAppender line: 54,默认立即刷新=true
boolean immediateFlush = true;
/**
* All synchronization in this class is done via the lock object.
*/
protected final ReentrantLock lock = new ReentrantLock(false);
private void writeBytes(byte[] byteArray) throws IOException {
if(byteArray == null || byteArray.length == 0)
return;
lock.lock(); // 重入锁
try {
this.outputStream.write(byteArray);
if (immediateFlush) { // 是否立即刷新缓冲内容
this.outputStream.flush();
}
} finally {
lock.unlock();
}
}
其次需要关注immediateFlush
变量,因为我们没有配置,默认是开启
立即刷新。
官方注释:1.2.0版本后,支持在logback.xml的<appender>
节点设置immediateFlush
属性,如果不设置,默认值是true
,即每次日志输出流缓冲队列都将被刷新。
同时提醒,开启立即刷新,虽然比较“安全”
,但将降低
系统日志输出的整体性能
。
/**
* Sets the immediateFlush option. The default value for immediateFlush is 'true'. If set to true,
* the doEncode() method will immediately flush the underlying OutputStream. Although immediate flushing
* is safer, it also significantly degrades logging throughput.
*
* @since 1.0.3
*/
public void setImmediateFlush(boolean immediateFlush) {
addWarn("As of version 1.2.0 \"immediateFlush\" property should be set within the enclosing Appender.");
addWarn("Please move \"immediateFlush\" property into the enclosing appender.");
this.immediateFlush = immediateFlush;
}
为了确认缓冲
是真实存在的,就要看看这里this.outputStream
的具体实现类:ch.qos.logback.core.recovery.ResilientFileOutputStream
,其中组合
了一个os(BufferedOutputStream)
对象
// FileAppender中定义了缓冲区大小,默认是 8192 字节(8kb)
public static final long DEFAULT_BUFFER_SIZE = 8192;
private FileSize bufferSize = new FileSize(DEFAULT_BUFFER_SIZE);
// 构造方法,组合BufferedOutputStream
public ResilientFileOutputStream(File file, boolean append, long bufferSize) throws FileNotFoundException {
this.file = file;
fos = new FileOutputStream(file, append);
this.os = new BufferedOutputStream(fos, (int) bufferSize);
this.presumedClean = true;
}
// 抽象父类默认方法,调用os.write
public void write(byte b[], int off, int len) {
if (isPresumedInError()) {
if (!recoveryCoordinator.isTooSoon()) {
attemptRecovery();
}
return; // return regardless of the success of the recovery attempt
}
try {
os.write(b, off, len);
postSuccessfulWrite();
} catch (IOException e) {
postIOFailure(e);
}
}
至此我们已经知道 RollingFileAppender
的日志打印最终会调用BufferedOutpuStream.write
方法,那么说明日志打印存在缓冲,且缓冲队列的默认是8kb
。
在FileAppender
有bufferSize
字段,找到了其setter方法,没有其他类调用,猜测是可以通过反射配置的。
public void setBufferSize(FileSize bufferSize) {
addInfo("Setting bufferSize to ["+bufferSize.toString()+"]");
this.bufferSize = bufferSize;
}
那我们能显示的设置FileAppender#bufferSize
大小吗?我做了以下尝试:
1.Logback官网查找Appender目录中的bufferSize设置,无果
2.项目中直接配置 <bufferSize>1MB</bufferSize>
没有起作用
3.stackoverflow搜索无果
总结
1.对于同步的RollingFileAppender
而言,多线程
的log appender打印是有意义的,因为只会在调用BufferedOutpuStream.write
方法时加锁同步,encode等方法也是比较耗时的,多线程可以增加系统吞吐量;对于 AsyncAppender
而言,增加日志消费线程
则意义不大, 这应该也是AsyncAppender
中只提供了一个worker守护线程
的原因。
2.使用 RollingFileAppender
时,logback提供给我们<ImmediateFlush>
标签使用,设置为false时可获得更高的logging吞吐量。
3.FileAppender中的bufferSize字段无法从外部设置,默认大小是8kb
,在ImmediateFlush=false
的情况下满8kb
刷新一次缓冲区。