前言
在之前的文章解析了slf4j，上层的框架已经了解清楚了，那就接着看底层日志吧。
本文中不对JCL和JUL进行源码解读，只是对logback进行主要代码解读。
logback是java的日志开源组件，是log4j创始人写的，性能比log4j要好，目前主要分为3个模块
- logback-core: 核心代码模块
- logback-classic: log4j的一个改良版本，同时实现了slf4j的接口，这样你如果之后要切换其他日志组件也是一件很容易的事
- logback-access: 访问模块与Servlet容器集成提供通过Http来访问日志的功能
本文主要分析core模块
源码探索
我们还是从桥接的部分开始看起。找到LogbackServiceProvider，跟进getLoggerFactory
public ILoggerFactory getLoggerFactory() {
return defaultLoggerContext;
// if (!initialized) {
// return defaultLoggerContext;
//
//
// if (contextSelectorBinder.getContextSelector() == null) {
// throw new IllegalStateException("contextSelector cannot be null. See also " + NULL_CS_URL);
// }
// return contextSelectorBinder.getContextSelector().getLoggerContext();
}这里很干脆，直接返回了defaultLoggerContext，让我们看看这个是个啥玩意。defaultLoggerContext的类型是LoggerContext。让我们来看看这个类。
这个类也是有点意思的，是ContextBase和ILoggerFactory的子类。一个类即是上下文又是工厂，有点似曾相识的感觉。其实这个思想和spring很像，spring的context中可以去获取bean，是不是也有一种工厂类的感觉呢？同理，Logback学习了spring的管理bean的那套思想。
接下来就是getLogger了，
public Logger getLogger(final String name) {
if (name == null) {
throw new IllegalArgumentException("name argument cannot be null");
}
// if we are asking for the root logger, then let us return it without
// wasting time
if (Logger.ROOT_LOGGER_NAME.equalsIgnoreCase(name)) {
return root;
}
int i = 0;
Logger logger = root;
// check if the desired logger exists, if it does, return it
// without further ado.
Logger childLogger = (Logger) loggerCache.get(name);
// if we have the child, then let us return it without wasting time
if (childLogger != null) {
return childLogger;
}
// 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;
}
}
}这里的逻辑如下：
- 判断获取的logger是不是root，是的话直接返回rootlogger
- 从cache中获取logger，如果存在直接返回
- 如果logger不存在，则按照层级创建logger
- 返回logger。
直接来看Logger好了，Logger的类图如下：
可以看的出来，logback在Logger类的设计上比log4j要好很多，log4j存在着Logger和Category两个类，Logger还是依赖Category的，我也不知道这种设计的好处在哪里。logback中改了过来，去掉了Category，所有和log相关的代码全在Logger中。
随便找一个打日志的类，就找trace好了。发现trace一共有10个方法（其实每个日志等级都有10个方法）：
public void trace(String msg) {
filterAndLog_0_Or3Plus(FQCN, null, Level.TRACE, msg, null, null);
}
public void trace(String format, Object arg) {
filterAndLog_1(FQCN, null, Level.TRACE, format, arg, null);
}
public void trace(String format, Object arg1, Object arg2) {
filterAndLog_2(FQCN, null, Level.TRACE, format, arg1, arg2, null);
}
public void trace(String format, Object... argArray) {
filterAndLog_0_Or3Plus(FQCN, null, Level.TRACE, format, argArray, null);
}
public void trace(String msg, Throwable t) {
filterAndLog_0_Or3Plus(FQCN, null, Level.TRACE, msg, null, t);
}
public void trace(Marker marker, String msg) {
filterAndLog_0_Or3Plus(FQCN, marker, Level.TRACE, msg, null, null);
}
public void trace(Marker marker, String format, Object arg) {
filterAndLog_1(FQCN, marker, Level.TRACE, format, arg, null);
}
public void trace(Marker marker, String format, Object arg1, Object arg2) {
filterAndLog_2(FQCN, marker, Level.TRACE, format, arg1, arg2, null);
}
public void trace(Marker marker, String format, Object... argArray) {
filterAndLog_0_Or3Plus(FQCN, marker, Level.TRACE, format, argArray, null);
}
public void trace(Marker marker, String msg, Throwable t) {
filterAndLog_0_Or3Plus(FQCN, marker, Level.TRACE, msg, null, t);
}然后我们发现，这10个api，其实就是在反复调用三个方法：
/**
* The next methods are not merged into one because of the time we gain by not
* creating a new Object[] with the params. This reduces the cost of not
* logging by about 20 nanoseconds.
*/
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);
}
private void filterAndLog_1(final String localFQCN, final Marker marker, final Level level, final String msg, final Object param, final Throwable t) {
final FilterReply decision = loggerContext.getTurboFilterChainDecision_1(marker, this, level, msg, param, t);
if (decision == FilterReply.NEUTRAL) {
if (effectiveLevelInt > level.levelInt) {
return;
}
} else if (decision == FilterReply.DENY) {
return;
}
buildLoggingEventAndAppend(localFQCN, marker, level, msg, new Object[] { param }, t);
}
private void filterAndLog_2(final String localFQCN, final Marker marker, final Level level, final String msg, final Object param1, final Object param2,
final Throwable t) {
final FilterReply decision = loggerContext.getTurboFilterChainDecision_2(marker, this, level, msg, param1, param2, t);
if (decision == FilterReply.NEUTRAL) {
if (effectiveLevelInt > level.levelInt) {
return;
}
} else if (decision == FilterReply.DENY) {
return;
}
buildLoggingEventAndAppend(localFQCN, marker, level, msg, new Object[] { param1, param2 }, t);
}这三个方法也是有点意思的，filterAndLog后面跟着的是具体的入参数量。。。其实我不明白为啥要这样设计api，讲道理一个filterAndLog_0_Or3Plus就可以覆盖filterAndLog_1和filterAndLog_2的情况了吧。如果有明白的同学麻烦下面评论写一下，让我也学习一下【捂脸】
这三个方法基本都是一样的，都会去调用一个getTurboFilterChainDecision_?的方法（？表示类似的方法），这个是干嘛用的呢，我们跟进看下。
final FilterReply getTurboFilterChainDecision_0_3OrMore(final Marker marker, final Logger logger, final Level level, final String format,
final Object[] params, final Throwable t) {
if (turboFilterList.size() == 0) {
return FilterReply.NEUTRAL;
}
return turboFilterList.getTurboFilterChainDecision(marker, logger, level, format, params, t);
}发现其实就是调用TurboFilter进行过滤的一个过程。TurboFilter这是个啥玩意呢？看起来和Filter很像。然后我看官方文档发现：
TurboFilter的工作方式与前面提到的Filter过滤方式非常相似。但是，Filter和TurboFilter对象之间存在两个主要区别。TurboFilter对象绑定到LogContext。因此，不仅在使用给定的Appender时调用它们，而且每次都发出日志记录请求。它们的范围比附加到Appender的Filter更宽。更重要的是，它们在LoggingEvent对象创建之前被调用。TurboFilter对象不需要实例化LoggingEvent来过滤日志记录请求。因此，TurboFilter旨在用于记录事件的高性能过滤，甚至在创建事件之前。
结合代码一起看，你会发现的确是这么一会事。
回到filterAndLog方法，发现过滤之后，就是buildLoggingEventAndAppend了，跟进。
private void buildLoggingEventAndAppend(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params,
final Throwable t) {
LoggingEvent le = new LoggingEvent(localFQCN, this, level, msg, t, params);
le.setMarker(marker);
callAppenders(le);
}这里很简单，直接跟进callAppenders。
/**
* Invoke all the appenders of this logger.
*
* @param event
* The event to log
*/
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);
}
}这里的代码和之前看的Log4j差不多（logback果然是Log4j原班人马打造）。这里的逻辑很清晰，就是将时间派发给logger下的Appender去执行。跟进appendLoopOnAppenders
private int appendLoopOnAppenders(ILoggingEvent event) {
if (aai != null) {
return aai.appendLoopOnAppenders(event);
} else {
return 0;
}
}跟进appendLoopOnAppenders。
/**
* Call the <code>doAppend</code> method on all attached appenders.
*/
public int appendLoopOnAppenders(E e) {
int size = 0;
final Appender<E>[] appenderArray = appenderList.asTypedArray();
final int len = appenderArray.length;
for (int i = 0; i < len; i++) {
appenderArray[i].doAppend(e);
size++;
}
return size;
}(调用栈和Log4j一毛一样)
直接看doAppend。
这时候我们发现，我们需要看到具体的Appender了。我们看一下Appender的继承结构
从图中可以清楚的看到，Appender分成了两个阵营：AppenderBase和UnsynchronizedAppenderBase。
先来看AppenderBase(忽略getter，setter)
abstract public class AppenderBase<E> extends ContextAwareBase implements Appender<E> {
protected volatile boolean started = false;
/**
* The guard prevents an appender from repeatedly calling its own doAppend
* method.
*/
private boolean guard = false;
/**
* Appenders are named.
*/
protected String name;
private FilterAttachableImpl<E> fai = new FilterAttachableImpl<E>();
private int statusRepeatCount = 0;
private int exceptionCount = 0;
static final int ALLOWED_REPEATS = 5;
public synchronized void doAppend(E eventObject) {
// WARNING: The guard check MUST be the first statement in the
// doAppend() method.
// prevent re-entry.
if (guard) {
return;
}
try {
guard = 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 = false;
}
}
abstract protected void append(E eventObject);
}我们仔细看下doAppend方法，发现步骤如下：
- 检查guard状态（guard是干嘛的，注释写的很清楚，这个属性就是防止同一个appender重复调用doAppend的）
- 使用Filter进行过滤
- 关联真正实现append的子类去执行。
很简单，接下来我们再来看UnsynchronizedAppenderBase（忽略了getter，setter）
abstract public class UnsynchronizedAppenderBase<E> extends ContextAwareBase implements Appender<E> {
protected boolean started = false;
// using a ThreadLocal instead of a boolean add 75 nanoseconds per
// doAppend invocation. This is tolerable as doAppend takes at least a few microseconds
// on a real appender
/**
* The guard prevents an appender from repeatedly calling its own doAppend
* method.
*/
private ThreadLocal<Boolean> guard = new ThreadLocal<Boolean>();
/**
* Appenders are named.
*/
protected String name;
private FilterAttachableImpl<E> fai = new FilterAttachableImpl<E>();
private int statusRepeatCount = 0;
private int exceptionCount = 0;
static final int ALLOWED_REPEATS = 3;
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);
}
}
abstract protected void append(E eventObject);
}就连UnsynchronizedAppenderBase的类注释上也写着，这个类和AppenderBase是很像的，只是在同步情况下的处理是不同的。
UnsynchronizedAppenderBase的guard是一个ThreadLocal类，也就是说，在多线程情况下，UnsynchronizedAppenderBase的工作情况会比AppenderBase要好很多。
从上面的类图上我们也看到了，UnsynchronizedAppenderBase的子类都是一些我们很常用的Appender，比如AsyncAppender，OutputStreamAppender等。OutputStreamAppender顾名思义，就是用来真正打日志的，这部分的逻辑不是很难，这里不表。我们主要来看看AsyncAppender。
public class AsyncAppender extends AsyncAppenderBase<ILoggingEvent> {
boolean includeCallerData = false;
/**
* Events of level TRACE, DEBUG and INFO are deemed to be discardable.
* @param event
* @return true if the event is of level TRACE, DEBUG or INFO false otherwise.
*/
protected boolean isDiscardable(ILoggingEvent event) {
Level level = event.getLevel();
return level.toInt() <= Level.INFO_INT;
}
protected void preprocess(ILoggingEvent eventObject) {
eventObject.prepareForDeferredProcessing();
if (includeCallerData)
eventObject.getCallerData();
}
public boolean isIncludeCallerData() {
return includeCallerData;
}
public void setIncludeCallerData(boolean includeCallerData) {
this.includeCallerData = includeCallerData;
}
}发现AsyncAppender没有做什么实质性的事情，回去看看它的父类：AsyncAppenderBase(同样是去掉了getter和setter)。
/**
* This appender and derived classes, log events asynchronously. In order to avoid loss of logging events, this
* appender should be closed. It is the user's responsibility to close appenders, typically at the end of the
* application lifecycle.
* <p>
* This appender buffers events in a {@link BlockingQueue}. {@link Worker} thread created by this appender takes
* events from the head of the queue, and dispatches them to the single appender attached to this appender.
* <p>
* Please refer to the <a href="http://logback.qos.ch/manual/appenders.html#AsyncAppender">logback manual</a> for
* further information about this appender.</p>
*
* @param <E>
* @author Ceki Gülcü
* @author Torsten Juergeleit
* @since 1.0.4
*/
public class AsyncAppenderBase<E> extends UnsynchronizedAppenderBase<E> implements AppenderAttachable<E> {
AppenderAttachableImpl<E> aai = new AppenderAttachableImpl<E>();
BlockingQueue<E> blockingQueue;
/**
* The default buffer size.
*/
public static final int DEFAULT_QUEUE_SIZE = 256;
int queueSize = DEFAULT_QUEUE_SIZE;
int appenderCount = 0;
static final int UNDEFINED = -1;
int discardingThreshold = UNDEFINED;
boolean neverBlock = false;
Worker worker = new Worker();
/**
* The default maximum queue flush time allowed during appender stop. If the
* worker takes longer than this time it will exit, discarding any remaining
* items in the queue
*/
public static final int DEFAULT_MAX_FLUSH_TIME = 1000;
int maxFlushTime = DEFAULT_MAX_FLUSH_TIME;
/**
* Is the eventObject passed as parameter discardable? The base class's implementation of this method always returns
* 'false' but sub-classes may (and do) override this method.
* <p>
* Note that only if the buffer is nearly full are events discarded. Otherwise, when the buffer is "not full"
* all events are logged.
*
* @param eventObject
* @return - true if the event can be discarded, false otherwise
*/
protected boolean isDiscardable(E eventObject) {
return false;
}
/**
* Pre-process the event prior to queueing. The base class does no pre-processing but sub-classes can
* override this behavior.
*
* @param eventObject
*/
protected void preprocess(E eventObject) {
}
@Override
public void start() {
if (isStarted())
return;
if (appenderCount == 0) {
addError("No attached appenders found.");
return;
}
if (queueSize < 1) {
addError("Invalid queue size [" + queueSize + "]");
return;
}
blockingQueue = new ArrayBlockingQueue<E>(queueSize);
if (discardingThreshold == UNDEFINED)
discardingThreshold = queueSize / 5;
addInfo("Setting discardingThreshold to " + discardingThreshold);
worker.setDaemon(true);
worker.setName("AsyncAppender-Worker-" + getName());
// make sure this instance is marked as "started" before staring the worker Thread
super.start();
worker.start();
}
@Override
public void stop() {
if (!isStarted())
return;
// mark this appender as stopped so that Worker can also processPriorToRemoval if it is invoking
// aii.appendLoopOnAppenders
// and sub-appenders consume the interruption
super.stop();
// interrupt the worker thread so that it can terminate. Note that the interruption can be consumed
// by sub-appenders
worker.interrupt();
InterruptUtil interruptUtil = new InterruptUtil(context);
try {
interruptUtil.maskInterruptFlag();
worker.join(maxFlushTime);
// check to see if the thread ended and if not add a warning message
if (worker.isAlive()) {
addWarn("Max queue flush timeout (" + maxFlushTime + " ms) exceeded. Approximately " + blockingQueue.size()
+ " queued events were possibly discarded.");
} else {
addInfo("Queue flush finished successfully within timeout.");
}
} catch (InterruptedException e) {
int remaining = blockingQueue.size();
addError("Failed to join worker thread. " + remaining + " queued events may be discarded.", e);
} finally {
interruptUtil.unmaskInterruptFlag();
}
}
@Override
protected void append(E eventObject) {
if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) {
return;
}
preprocess(eventObject);
put(eventObject);
}
private boolean isQueueBelowDiscardingThreshold() {
return (blockingQueue.remainingCapacity() < discardingThreshold);
}
private void put(E eventObject) {
if (neverBlock) {
blockingQueue.offer(eventObject);
} else {
putUninterruptibly(eventObject);
}
}
private void putUninterruptibly(E eventObject) {
boolean interrupted = false;
try {
while (true) {
try {
blockingQueue.put(eventObject);
break;
} catch (InterruptedException e) {
interrupted = true;
}
}
} finally {
if (interrupted) {
Thread.currentThread().interrupt();
}
}
}
/**
* The remaining capacity available in the blocking queue.
* <p>
* See also {@link java.util.concurrent.BlockingQueue#remainingCapacity() BlockingQueue#remainingCapacity()}
*
* @return the remaining capacity
*
*/
public int getRemainingCapacity() {
return blockingQueue.remainingCapacity();
}
public void addAppender(Appender<E> newAppender) {
if (appenderCount == 0) {
appenderCount++;
addInfo("Attaching appender named [" + newAppender.getName() + "] to AsyncAppender.");
aai.addAppender(newAppender);
} else {
addWarn("One and only one appender may be attached to AsyncAppender.");
addWarn("Ignoring additional appender named [" + newAppender.getName() + "]");
}
}
class Worker extends Thread {
public void run() {
AsyncAppenderBase<E> parent = AsyncAppenderBase.this;
AppenderAttachableImpl<E> aai = parent.aai;
// loop while the parent is started
while (parent.isStarted()) {
try {
E e = parent.blockingQueue.take();
aai.appendLoopOnAppenders(e);
} catch (InterruptedException ie) {
break;
}
}
addInfo("Worker thread will flush remaining events before exiting. ");
for (E e : parent.blockingQueue) {
aai.appendLoopOnAppenders(e);
parent.blockingQueue.remove(e);
}
aai.detachAndStopAllAppenders();
}
}
}主要看append方法，发现append方法除了一个判断就是直接put，我们直接去看put：
private void put(E eventObject) {
if (neverBlock) {
blockingQueue.offer(eventObject);
} else {
putUninterruptibly(eventObject);
}
}这里用neverBlock作为是否阻塞的标识位，这里其实就是使用了阻塞队列的方法而已，offer是不阻塞放，put是阻塞放。好了，生产者这一部分看完了，接下来就是看消费者。之前提到过logback是Log4j的原班人马打造的，所以这里肯定有一个类似于Dispatcher的类，果不其然，在logback中摇身一变就成了Worker类。直接看它的run方法。
public void run() {
AsyncAppenderBase<E> parent = AsyncAppenderBase.this;
AppenderAttachableImpl<E> aai = parent.aai;
// loop while the parent is started
while (parent.isStarted()) {
try {
E e = parent.blockingQueue.take();
aai.appendLoopOnAppenders(e);
} catch (InterruptedException ie) {
break;
}
}
addInfo("Worker thread will flush remaining events before exiting. ");
for (E e : parent.blockingQueue) {
aai.appendLoopOnAppenders(e);
parent.blockingQueue.remove(e);
}
aai.detachAndStopAllAppenders();
}这里的逻辑比较简单，就是从blockingQueue中取出LogEvent，然后在进行转发，和log4j中的逻辑是一样的，稍稍有点不同的是，这里多了一层异常处理，就是当worker退出的时候，会将blockingQueue中的事件处理完成之后在退出，相较于log4j是一层进步。
小结
可以看出logback在各方面均有提升，尤其是在多线程的情况下有更出色的表现。当然logback作为一款很优秀的日志系统，还有很多很优秀的特性，比如RollingFileAppender在产生新文件的时候，会自动压缩已经打出来的日志文件，再者FileAppender可以设定一个值，使多个jvm可以安全得打日志到同一个文件，值得探索的地方还有很多。下一篇再来看看据说性能上可以吊打logback的log4j2吧。
