初探logback日志框架
logback简介
Logback is intended as a successor to the popular log4j project. It was designed by Ceki Gülcü, log4j’s founder. It builds upon a decade of experience gained in designing industrial-strength logging systems. The resulting product, i.e. logback, is faster and has a smaller footprint than all existing logging systems, sometimes by a wide margin. Just as importantly, logback offers unique and rather useful features missing in other logging systems.
对比其他日志框架
1.logback属于slf4j阵营；log4j2属于common logging阵营。
2.Java中，logback和log4j2都是目前最流行的日志框架。
3.开发公司不同，log4j2是apache开发，而logback由qos开发。
执行流程
大体流程：创建LoggerFactory->创建Logger->过滤日志->根据日志级别输出日志->根据同异步处理日志
1.通过StaticLoggerBinder创建了一个单例的LoggerFactory，初始化时利用了双从检验锁的形式获得了一个单例的LoggerFactory。
if (INITIALIZATION_STATE == UNINITIALIZED) {
synchronized (LoggerFactory.class) {
if (INITIALIZATION_STATE == UNINITIALIZED) {
INITIALIZATION_STATE = ONGOING_INITIALIZATION;
performInitialization();
}
}
}
2.利用获得的LoggerFactory创建了一个树状的Logger树，当然也会用缓存存一份来加快加载速度，缓存用了concurrentHashMap来保证线程安全。
// if the desired logger does not exist, them create all the loggers
// in between as well (if they don't already exist)
String childName;
while (true) {
int h = LoggerNameUtil.getSeparatorIndexOf(name, i);
if (h == -1) {
childName = name;
} else {
childName = name.substring(0, h);
}
// move i left of the last point
i = h + 1;
synchronized (logger) {
childLogger = logger.getChildByName(childName);
if (childLogger == null) {
childLogger = logger.createChildByName(childName);
loggerCache.put(childName, childLogger);
incSize();
}
}
logger = childLogger;
if (h == -1) {
return childLogger;
}
可以看到用了loggerCache作为缓存，真正加载日志树的时候也用了synchronized来保证线程安全。
真正创建日志树节点的在：
Logger createChildByName(final String childName) {
int i_index = LoggerNameUtil.getSeparatorIndexOf(childName, this.name.length() + 1);
if (i_index != -1) {
throw new IllegalArgumentException("For logger [" + this.name + "] child name [" + childName
+ " passed as parameter, may not include '.' after index" + (this.name.length() + 1));
}
if (childrenList == null) {
childrenList = new CopyOnWriteArrayList<Logger>();
}
Logger childLogger;
childLogger = new Logger(childName, this, this.loggerContext);
childrenList.add(childLogger);
childLogger.effectiveLevelInt = this.effectiveLevelInt;
return childLogger;
}
可以看到初始化了一个个的日志树节点，但是节点却用到了CopyOnWriteArrayList来保证线程安全，而且这个方法只有一个地方在调用，调用的地方用了synchronized锁，理论上在这里使用CopyOnWriteArrayList是多余的，反而会增加开销。 但是，synchronized锁的是一个日志树的节点。
在真正调用logger.info/logger.debug…时，根据配置的TurboFilterChain和effectiveLevelInt来确定是否输出日志
private void filterAndLog_0_Or3Plus(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params,
final Throwable t) {
final FilterReply decision = loggerContext.getTurboFilterChainDecision_0_3OrMore(marker, this, level, msg, params, t);
if (decision == FilterReply.NEUTRAL) {
if (effectiveLevelInt > level.levelInt) {
return;
}
} else if (decision == FilterReply.DENY) {
return;
}
buildLoggingEventAndAppend(localFQCN, marker, level, msg, params, t);
}
buildLoggingEventAndAppend方法是真正处理日志的地方。通过appendLoopOnAppenders来选择一个appender来处理日志：
public void callAppenders(ILoggingEvent event) {
int writes = 0;
for (Logger l = this; l != null; l = l.parent) {
writes += l.appendLoopOnAppenders(event);
if (!l.additive) {
break;
}
}
// No appenders in hierarchy
if (writes == 0) {
loggerContext.noAppenderDefinedWarning(this);
}
}
可以看到，如果没有找到对应的appender也是不会输出日志的。
真正处理日志的是doAppend方法：
public void doAppend(E eventObject) {
// WARNING: The guard check MUST be the first statement in the
// doAppend() method.
// prevent re-entry.
if (Boolean.TRUE.equals(guard.get())) {
return;
}
try {
guard.set(Boolean.TRUE);
if (!this.started) {
if (statusRepeatCount++ < ALLOWED_REPEATS) {
addStatus(new WarnStatus("Attempted to append to non started appender [" + name + "].", this));
}
return;
}
if (getFilterChainDecision(eventObject) == FilterReply.DENY) {
return;
}
// ok, we now invoke derived class' implementation of append
this.append(eventObject);
} catch (Exception e) {
if (exceptionCount++ < ALLOWED_REPEATS) {
addError("Appender [" + name + "] failed to append.", e);
}
} finally {
guard.set(Boolean.FALSE);
}
}
最后走的是OutputStreamAppender的subAppend方法:
/**
* 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);
} 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));
}
}
在encoder的时候，PatternLayout利用先前先前加载好的converter进行解析具体的日志格式：
public String doLayout(ILoggingEvent event) {
if (!isStarted()) {
return CoreConstants.EMPTY_STRING;
}
return writeLoopOnConverters(event);
}
converter:
static {
defaultConverterMap.putAll(Parser.DEFAULT_COMPOSITE_CONVERTER_MAP);
defaultConverterMap.put("d", DateConverter.class.getName());
defaultConverterMap.put("date", DateConverter.class.getName());
defaultConverterMap.put("r", RelativeTimeConverter.class.getName());
defaultConverterMap.put("relative", RelativeTimeConverter.class.getName());
defaultConverterMap.put("level", LevelConverter.class.getName());
defaultConverterMap.put("le", LevelConverter.class.getName());
defaultConverterMap.put("p", LevelConverter.class.getName());
defaultConverterMap.put("t", ThreadConverter.class.getName());
defaultConverterMap.put("thread", ThreadConverter.class.getName());
defaultConverterMap.put("lo", LoggerConverter.class.getName());
defaultConverterMap.put("logger", LoggerConverter.class.getName());
defaultConverterMap.put("c", LoggerConverter.class.getName());
defaultConverterMap.put("m", MessageConverter.class.getName());
defaultConverterMap.put("msg", MessageConverter.class.getName());
defaultConverterMap.put("message", MessageConverter.class.getName());
defaultConverterMap.put("C", ClassOfCallerConverter.class.getName());
defaultConverterMap.put("class", ClassOfCallerConverter.class.getName());
defaultConverterMap.put("M", MethodOfCallerConverter.class.getName());
defaultConverterMap.put("method", MethodOfCallerConverter.class.getName());
defaultConverterMap.put("L", LineOfCallerConverter.class.getName());
defaultConverterMap.put("line", LineOfCallerConverter.class.getName());
defaultConverterMap.put("F", FileOfCallerConverter.class.getName());
defaultConverterMap.put("file", FileOfCallerConverter.class.getName());
defaultConverterMap.put("X", MDCConverter.class.getName());
defaultConverterMap.put("mdc", MDCConverter.class.getName());
defaultConverterMap.put("ex", ThrowableProxyConverter.class.getName());
defaultConverterMap.put("exception", ThrowableProxyConverter.class.getName());
defaultConverterMap.put("rEx", RootCauseFirstThrowableProxyConverter.class.getName());
defaultConverterMap.put("rootException", RootCauseFirstThrowableProxyConverter.class.getName());
defaultConverterMap.put("throwable", ThrowableProxyConverter.class.getName());
defaultConverterMap.put("xEx", ExtendedThrowableProxyConverter.class.getName());
defaultConverterMap.put("xException", ExtendedThrowableProxyConverter.class.getName());
defaultConverterMap.put("xThrowable", ExtendedThrowableProxyConverter.class.getName());
defaultConverterMap.put("nopex", NopThrowableInformationConverter.class.getName());
defaultConverterMap.put("nopexception", NopThrowableInformationConverter.class.getName());
defaultConverterMap.put("cn", ContextNameConverter.class.getName());
defaultConverterMap.put("contextName", ContextNameConverter.class.getName());
defaultConverterMap.put("caller", CallerDataConverter.class.getName());
defaultConverterMap.put("marker", MarkerConverter.class.getName());
defaultConverterMap.put("property", PropertyConverter.class.getName());
defaultConverterMap.put("n", LineSeparatorConverter.class.getName());
defaultConverterMap.put("black", BlackCompositeConverter.class.getName());
defaultConverterMap.put("red", RedCompositeConverter.class.getName());
defaultConverterMap.put("green", GreenCompositeConverter.class.getName());
defaultConverterMap.put("yellow", YellowCompositeConverter.class.getName());
defaultConverterMap.put("blue", BlueCompositeConverter.class.getName());
defaultConverterMap.put("magenta", MagentaCompositeConverter.class.getName());
defaultConverterMap.put("cyan", CyanCompositeConverter.class.getName());
defaultConverterMap.put("white", WhiteCompositeConverter.class.getName());
defaultConverterMap.put("gray", GrayCompositeConverter.class.getName());
defaultConverterMap.put("boldRed", BoldRedCompositeConverter.class.getName());
defaultConverterMap.put("boldGreen", BoldGreenCompositeConverter.class.getName());
defaultConverterMap.put("boldYellow", BoldYellowCompositeConverter.class.getName());
defaultConverterMap.put("boldBlue", BoldBlueCompositeConverter.class.getName());
defaultConverterMap.put("boldMagenta", BoldMagentaCompositeConverter.class.getName());
defaultConverterMap.put("boldCyan", BoldCyanCompositeConverter.class.getName());
defaultConverterMap.put("boldWhite", BoldWhiteCompositeConverter.class.getName());
defaultConverterMap.put("highlight", HighlightingCompositeConverter.class.getName());
defaultConverterMap.put("lsn", LocalSequenceNumberConverter.class.getName());
}
writeBytes的时候加了锁，用的是非公平锁，可能是为了提高速度，但是日志可能会乱序：
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();
}
}
看起来这就是logback的默认行为了。
我们也可以通过配置文件增加多个Appender，比如ConsoleAppender、FileAppender、RollingFileAppender等,当然也可以自定义自己的Appender，在打印日志的时候，会依次遍历所有的Appender处理日志。值得注意的是，ConsoleAppender，FileAppender
和RollingFileAppender都是OutputStreamAppender的子类，在真正doAppend和writeBytes的时候都是走的OutputStreamAppender，因此他们写日志的时候都会加锁。看起来日志框架用了悲观锁来处理的，效率应该是堪忧的。当然，logback也有提供异步的Appender，比如：AsyncAppenderBase、AsyncAppender。
经过对比，AsyncAppender效率上优于RollingFileAppender，下面是实验数据，以40万日志为条件,5个线程并发，机器配置为4核8G，第一组为字符串拼接形式，第二组为参数替换形式，第三组为异步：
| 执行总耗(ms) | t1(ms) | t2(ms) | t3(ms) | t4(ms) | t5(ms) |
|---|---|---|---|---|---|
| 11000 | 11046 | 11287 | 11317 | 11317 | 11329 |
| 11837 | 11161 | 11439 | 11471 | 11654 | 11688 |
| 799 | 651 | 652 | 652 | 653 | 553 |
| 可以看出字符串拼接比占位符形式效率要高一些，异步日志要比同步日志效率提高大约十几倍。 |
926
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
