Log4j是广泛使用的日志类库,本文基于Log4j2分析Logger组件的设计和流程,对高性能低延迟和garbage-free等主要特性进行分析。
一、Log4j2-Overview
1. 1 Log4j2组件图(来源官方)
以下组件在后面会对主要实现类进行分析。从用户使用的角度,直接面向用户的只有Logger,其他组件在Java应用启动过程中根据不同的配置项均已完成初始化。
组件名称 | 使用 |
---|---|
LoggerContext | 日志系统的上下文管理类,维护管理所有的Logger及其相关配,AsyncLoggerContext是异步日志上下文实现 |
Configuration | 全局的配置信息,包含整个日志系统的各种配置,也包含针对单个Logger的定制化配置,该类可以实现动态配置变更,默认30s检测一次 |
Logger | Log4j2核心组件,主要的日志记录接口,logger#info() |
LoggerConfig | 每个Logger会分配一个相应的LoggerConfig,用来在Logger记录的时候找到相应的配置行为,例如找到输出的appender,输出的日志layout,pattern等等 |
Appender | 日志持久化组件,Logger记录的每条LogEvent会在Appender流向最终的持久化destination,Appender有多种多样的实现,常用的是文件记录类型 |
Layout | Appender在持久化日志的时候最终输出格式,如时间格式,线程名称等信息的排版需要一个Layout,如果不提供走默认的格式 |
Filter | Filter存在多处,用来对日志等级,特定Logger的LogEvent进行过滤和筛选,比如常见的Logger.isDebugEnable() |
StrSubstitutor | TODO |
如果直接使用Log4j2,一般都是使用slf4j进行绑定。
// 直接使用Log4j2
Logger logger = LogManager.getLogger(className)
1. 2 Log4j2主要调用流程
TODO 主要调用流程,流程中的数据转化
二、Log4j2初始化,在Logger准备好之前发生什么
2.1 以xml配置文件进行流程梳理
2.2 LoggerContext初始化
LoggerContext接口,LogManager#getLogger()最终会调用LoggerContext#getLogger()
public class LogManager {
// getLogger
public static Logger getLogger(final Class<?> clazz) {
final Class<?> cls = callerClass(clazz);
return getContext(cls.getClassLoader(), false).getLogger(toLoggerName(cls));
}
// getContext
public static LoggerContext getContext(final ClassLoader loader, final boolean currentContext) {
try {
// private static volatile LoggerContextFactory factory; LogManager成员变量
return factory.getContext(FQCN, loader, null, currentContext);
} catch (final IllegalStateException ex) {
LOGGER.warn(ex.getMessage() + " Using SimpleLogger");
return new SimpleLoggerContextFactory().getContext(FQCN, loader, null, currentContext);
}
}
}
// 注意该包名
package org.apache.logging.log4j.spi;
public interface LoggerContext {
/**
* An anchor for some other context, such as a ClassLoader or ServletContext.
*/
Object getExternalContext();
/**
* Returns an ExtendedLogger.
*/
ExtendedLogger getLogger(String name);
/**
* Returns an ExtendedLogger.
*/
ExtendedLogger getLogger(String name, MessageFactory messageFactory);
/**
* Detects if a Logger with the specified name exists.
*/
boolean hasLogger(String name);
/**
* Detects if a Logger with the specified name and MessageFactory exists.
*/
boolean hasLogger(String name, MessageFactory messageFactory);
/**
* Detects if a Logger with the specified name and MessageFactory type exists.
*/
boolean hasLogger(String name, Class<? extends MessageFactory> messageFactoryClass);
}
LoggerContextFactory在调用时进行LazyInit,通过反射读取System#getProperty(),默认实现为org.apache.logging.log4j.core.impl.Log4jContextFactory。Log4jContextFactory#getContext()会将调用转到ContextSelector#getContext(),ContextSelector为接口,
public class Log4jContextFactory implements LoggerContextFactory, ShutdownCallbackRegistry {
private static final StatusLogger LOGGER = StatusLogger.getLogger();
private final ContextSelector selector;
private final ShutdownCallbackRegistry shutdownCallbackRegistry;
/**
* Initializes the ContextSelector from system property {@link Constants#LOG4J_CONTEXT_SELECTOR}.
*/
public Log4jContextFactory() {
this(createContextSelector(), createShutdownCallbackRegistry());
}
private static ContextSelector createContextSelector() {
try {
//
final ContextSelector selector = Loader.newCheckedInstanceOfProperty(Constants.LOG4J_CONTEXT_SELECTOR,
ContextSelector.class);
if (selector != null) {
return selector;
}
} catch (final Exception e) {
LOGGER.error("Unable to create custom ContextSelector. Falling back to default.", e);
}
return new ClassLoaderContextSelector();
}
}
初始化ContextSelector根据System.prop("Log4jContextSelector")传入的类名进行反射新建实例。
public interface ContextSelector {
default boolean hasContext(String fqcn, ClassLoader loader, boolean currentContext) {
return false;
}
LoggerContext getContext(String fqcn, ClassLoader loader, boolean currentContext);
LoggerContext getContext(String fqcn, ClassLoader loader, boolean currentContext, URI configLocation);
List<LoggerContext> getLoggerContexts();
void removeContext(LoggerContext context);
}
ContextSelector主要实现类为ClassLoaderContextSelector(内部维护一个静态的Map,key为ClassLoader#hashCode,同时在 ContextAnchor.THREAD_CONTEXT的ThreadLocal变量中维护当前线程中的LoggerContext),AsyncLoggerContextSelector(异步Logger,后面详细分析流程)
ClassLoaderContextSelector#getContext返回org.apache.logging.log4j.core.LoggerContext,该实现类与实现接口org.apache.logging.log4j.spi.LoggerContext同名了。
三、一次Logger#info的流程,非异步流程,异步流程参考
3.1 Logger#info()
Logger的初始化和生成,我们在3.2小节进行介绍。
先来了解下Logger的继承和调用关系,我们一Logger#info()来跟踪和分析,Logger继承体系如下图。Logger的主要方法如下,精简了大量的方法。
public interface Logger {
// Logger接口定义了各个日志等级的常用方法,以下以info的来说明,注意,方法族比较庞大,只保留常用方法,具体查看源码
/** 当前的日志等级 */
Level getLevel();
/** 以下提供了常用的日志操作方法族,object列表最长到从1 ~ 10个参数 */
void info(String message, Object p0 /*Object p1, Object p2, Object p3, Object p4, Object p5, Object p6, Object p7,
Object p8, Object p9*/);
/** 当前日志等级能否输出日志 */
boolean isEnabled(Level level);
/** 是否info等级能输出日志 */
boolean isInfoEnabled();
/** log 系列方法族,info等方法最后会调用 */
void log(Level level, String message, Object p0 /*, Object p1, Object p2, Object p3, Object p4, Object p5, Object p6, Object p7,
Object p8, Object p9 */);
/** 注意该方法,最终调用会流向这里 */
default void logMessage(Level level, Marker marker, String fqcn, StackTraceElement location, Message message,
Throwable throwable) {
}
}
ExtendedLogger接口继承了Logger接口,主要提供了以下方法,便于对特定Level日志记录操作。
public interface ExtendedLogger extends Logger {
/** 决定是否要在该等级下输出日志,定义了一系列的方法族 */
boolean isEnabled(Level level, Marker marker, String message, Object p0, Object p1, Object p2, Object p3,
Object p4, Object p5, Object p6, Object p7, Object p8, Object p9);
/** 如果在该等级下满足筛选条件,直接输出日志,否则不输出,定义一系列方法族*/
void logIfEnabled(String fqcn, Level level, Marker marker, String message, Object p0, Object p1, Object p2,
Object p3, Object p4, Object p5, Object p6, Object p7, Object p8, Object p9);
/** 如果满足特定level条件,进行日志记录,注意Message参数,由以上方法message + param组成,即logger.info("{} hello world", "villcore")*/
void logMessage(String fqcn, Level level, Marker marker, Message message, Throwable t);
}
AbstractLogger实现了ExtendLogger,将日志的主要调用流程构建了起来,主流程骨架基本清晰,注意Message的创建 , Logger#info()调用如下,特别注意logMessage方法,该方法从一个MesssgeFactory创建了Message,后续会详细分析该方法和工厂类,还有logMessageSafely中finally块中的ReusableMessageFactory.release调用,该方法与复用Message有关,通过使用ReuseMessageFactory和ThreadLocal结合,能避免创建大量对象,这是一个优化特性,后续分析
public abstract class AbstractLogger implements ExtendedLogger, Serializable {
protected final String name;
// 注意该MessageFactory,如果使用ThreadLocal 为ReusableMessageFactory, 否则为ParameterizedMessageFactory.class
private final MessageFactory messageFactory;
private static ThreadLocal<int[]> recursionDepthHolder = new ThreadLocal<>(); // LOG4J2-1518, LOG4J2-2031
protected final ThreadLocal<DefaultLogBuilder> logBuilder;
private static final String FQCN = AbstractLogger.class.getName();
public AbstractLogger() {
this.name = getClass().getName();
this.messageFactory = null; // 此处简略,实际逻辑为正常初始化
this.logBuilder = null; // 此处简略,实际逻辑为正常初始化
}
@Override
public void info(final String message, final Object... params) {
logIfEnabled(FQCN, Level.INFO, null, message, params);
}
@Override
public void logIfEnabled(final String fqcn, final Level level, final Marker marker, final String message,
final Object... params) {
if (isEnabled(level, marker, message, params)) {
logMessage(fqcn, level, marker, message, params);
}
}
protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message,
final Object... params) {
// 注意该Message的创建
final Message msg = messageFactory.newMessage(message, params);
logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
}
@PerformanceSensitive
// NOTE: This is a hot method. Current implementation compiles to 30 bytes of byte code.
// This is within the 35 byte MaxInlineSize threshold. Modify with care!
private void logMessageSafely(final String fqcn, final Level level, final Marker marker, final Message msg,
final Throwable throwable) {
try {
logMessageTrackRecursion(fqcn, level, marker, msg, throwable);
} finally {
// LOG4J2-1583 prevent scrambled logs when logging calls are nested (logging in toString())
ReusableMessageFactory.release(msg);
}
}
@PerformanceSensitive
// NOTE: This is a hot method. Current implementation compiles to 33 bytes of byte code.
// This is within the 35 byte MaxInlineSize threshold. Modify with care!
private void logMessageTrackRecursion(final String fqcn,
final Level level,
final Marker marker,
final Message msg,
final Throwable throwable) {
try {
// incrementRecursionDepth(); // LOG4J2-1518, LOG4J2-2031
tryLogMessage(fqcn, null, level, marker, msg, throwable);
} finally {
// decrementRecursionDepth();
}
}
@PerformanceSensitive
// NOTE: This is a hot method. Current implementation compiles to 27 bytes of byte code.
// This is within the 35 byte MaxInlineSize threshold. Modify with care!
private void tryLogMessage(final String fqcn,
final StackTraceElement location,
final Level level,
final Marker marker,
final Message msg,
final Throwable throwable) {
try {
log(level, marker, fqcn, location, msg, throwable);
} catch (final Exception e) {
// ignore
}
}
public void logMessage(final Level level, final Marker marker, final String fqcn, final StackTraceElement location,
final Message message, final Throwable throwable) {
try {
// incrementRecursionDepth();
log(level, marker, fqcn, location, message, throwable);
} catch (Exception ex) {
// handleLogMessageException(ex, fqcn, message); // 处理异常,打印system.err
} finally {
// decrementRecursionDepth(); 防止递归层次太深
ReusableMessageFactory.release(message);
}
}
protected void log(final Level level, final Marker marker, final String fqcn, final StackTraceElement location,
final Message message, final Throwable throwable) {
logMessage(fqcn, level, marker, message, throwable);
}
}
最终走向了ExtendedLogger的logMessage,那么看实现类Logger如何实现该方法
/**
* Always logs a message at the specified level. It is the responsibility of the caller to ensure the specified
* level is enabled.
*
* @param fqcn The fully qualified class name of the logger entry point, used to determine the caller class and
* method when location information needs to be logged.
* @param level The logging Level to check.
* @param marker A Marker or null.
* @param message The Message.
* @param t the exception to log, including its stack trace.
*/
void logMessage(String fqcn, Level level, Marker marker, Message message, Throwable t);
Logger的实现类org.apache.logging.log4j.core.Logger的实现如下
public class Logger extends AbstractLogger implements Supplier<LoggerConfig> {
/**
* Config should be consistent across threads.
*/
protected volatile PrivateConfig privateConfig;
private final LoggerContext context;
protected Logger(final LoggerContext context, final String name, final MessageFactory messageFactory) {
super(name, messageFactory);
this.context = context;
privateConfig = new PrivateConfig(context.getConfiguration(), this);
}
@Override
public LoggerConfig get() {
return privateConfig.loggerConfig;
}
@Override
public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message,
final Throwable t) {
final Message msg = message == null ? new SimpleMessage(Strings.EMPTY) : message;
final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
strategy.log(this, getName(), fqcn, marker, level, msg, t);
}
@Override
protected void log(final Level level, final Marker marker, final String fqcn, final StackTraceElement location,
final Message message, final Throwable throwable) {
final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
strategy.log(this, getName(), fqcn, location, marker, level, message, throwable);
}
@Override
public boolean isEnabled(final Level level, final Marker marker, final String message, final Object p0,
final Object p1, final Object p2, final Object p3,
final Object p4, final Object p5, final Object p6,
final Object p7, final Object p8, final Object p9) {
return privateConfig.filter(level, marker, message, p0, p1, p2, p3, p4, p5, p6, p7, p8, p9);
}
/**
* The binding between a Logger and its configuration.
*/
protected class PrivateConfig {
// config fields are public to make them visible to Logger subclasses
/**
* LoggerConfig to delegate the actual logging to.
*/
public final LoggerConfig loggerConfig; // SUPPRESS CHECKSTYLE
/**
* The current Configuration associated with the LoggerConfig.
*/
public final Configuration config; // SUPPRESS CHECKSTYLE
private final Level loggerConfigLevel;
private final int intLevel;
private final Logger logger;
public PrivateConfig(final Configuration config, final Logger logger) {
this.config = config;
this.loggerConfig = config.getLoggerConfig(getName());
this.loggerConfigLevel = this.loggerConfig.getLevel();
this.intLevel = this.loggerConfigLevel.intLevel();
this.logger = logger;
}
// LOG4J2-151: changed visibility to public
public void logEvent(final LogEvent event) {
loggerConfig.log(event);
}
}
}
Logger会将logMessage的调用给PrivateConfig,PrivateConfig最重要的字段为重要字段是LoggerConfig loggerConfig,该类有Configuration config全局的配置类生成,每个Logger会有一个对应的PrivateConfig,包含私有的配置信息,比如Appender, Filter,以及xml配置文件解析得到的配置信息(全局的和单个Logger定制化的配置)。
Logger#LogMessage方法会将调用按如下的顺序执行
// Logger类
@Override
public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message,
final Throwable t) {
final Message msg = message == null ? new SimpleMessage(Strings.EMPTY) : message;
final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
strategy.log(this, getName(), fqcn, marker, level, msg, t);
}
ReliabilityStrategy以DefaultReliabilityStrategy#log来分析, Logger实现了Supplier<LoggerConfig> ,DefaultReliabilityStrategy中没有使用到该属性
ReliabilityStrategy
@Override
public void log(final Supplier<LoggerConfig> reconfigured, final String loggerName, final String fqcn, final Marker marker, final Level level,
final Message data, final Throwable t) {
loggerConfig.log(loggerName, fqcn, marker, level, data, t);
}
loggerConfig.log调用会将Message等信息build成LogEvent给Appender[],由Appender列表内的Appender执行最后的持久化,具体如下。
// loggerConfig类
public void log(final String loggerName, final String fqcn, final Marker marker, final Level level,
final Message data, final Throwable t) {
List<Property> props = null;
if (!propertiesRequireLookup) {
props = properties;
} else {
if (properties != null) {
props = new ArrayList<>(properties.size());
final LogEvent event = Log4jLogEvent.newBuilder()
.setMessage(data)
.setMarker(marker)
.setLevel(level)
.setLoggerName(loggerName)
.setLoggerFqcn(fqcn)
.setThrown(t)
.build();
for (int i = 0; i < properties.size(); i++) {
final Property prop = properties.get(i);
final String value = prop.isValueNeedsLookup() // since LOG4J2-1575
? config.getStrSubstitutor().replace(event, prop.getValue()) //
: prop.getValue();
props.add(Property.createProperty(prop.getName(), value));
}
}
}
StackTraceElement location = requiresLocation() ? StackLocatorUtil.calcLocation(fqcn) : null;
final LogEvent logEvent = logEventFactory.createEvent(loggerName, marker, fqcn, location, level, data, props, t);
try {
log(logEvent, LoggerConfigPredicate.ALL);
} finally {
// LOG4J2-1583 prevent scrambled logs when logging calls are nested (logging in toString())
ReusableLogEventFactory.release(logEvent);
}
}
LoggerConfig#log
// loggerConfig类
protected void log(final LogEvent event, final LoggerConfigPredicate predicate) {
if (!isFiltered(event)) {
processLogEvent(event, predicate);
}
}
调用Appender
// loggerConfig类
private void processLogEvent(final LogEvent event, LoggerConfigPredicate predicate) {
event.setIncludeLocation(isIncludeLocation());
if (predicate.allow(this)) {
callAppenders(event);
}
logParent(event, predicate);
}
//
@PerformanceSensitive("allocation")
protected void callAppenders(final LogEvent event) {
final AppenderControl[] controls = appenders.get();
//noinspection ForLoopReplaceableByForEach
for (int i = 0; i < controls.length; i++) {
controls[i].callAppender(event);
}
}
整体的调用流程如图四、核心组件分析
以上对Log4j2 Logger#info的主要流程简要分析了一下,在整个执行流程中有多个重要的组件参与,接下来我们针对这些重要组件的实现和功能进一步的分析,以下的分析注重实现与功能,并没有带入主流程。
4.1 LoggerContext与Logger
Logger的继承关系如下,AsyncLogger的分析相关会在后续介绍,Logger功能的主要实现在Logger中均已实现。
4.2 Message与MessageFactory
4.2.1 Message
Message在Log4j2中是一个关键的数据封装类,当用户使用logger的记录日志方法后,日志的format,参数,throwable会被封装到Message,同时Message提供了一个Message#getFormattedMessage()方法,将format和参数,throwable格式化成最终日志内容的日志体。
String format = "This is a error log, param is {}, value is {}";
Throwable throwable = new IlegalStageException("xxx");
logger.error(format, "foo", "bar", throwable);
Message为一个接口,常见的实现类有SimpleMessage,ParameterizedMessage。
public interface Message extends Serializable {
String getFormattedMessage();
String getFormat();
Object[] getParameters();
Throwable getThrowable();
}
Message的继承图如下,注意某些Message继承了StringBuilderFormattable,该接口的主要方法只有一个
/**
* 调用方提供一个StringBuilder,将Message#getFormattedMessage()的内容写入提供的StringBuilder(StringBuilder的实例可以一直复用的)
*/
public interface StringBuilderFormattable {
void formatTo(StringBuilder buffer);
}
下面我们对ParameterizedMessage进行分析,SimpleMessage的实现非常简单略过,ReusableMessage类型后续在做分析(主要使用ThreadLocal对内部的Message进行复用,核心功能均在内部包装的Message内) 。
ParameterizedMessage是我们最常用的Message封装,format通过{}的占位符声明参数,这里面的核心方法为formatTo(),getFormattedMessage()从ThreadLocal中复用了一个StringBuilder。
public class ParameterizedMessage implements Message, StringBuilderFormattable {
private static final int DEFAULT_STRING_BUILDER_SIZE = 255;
private static final int HASHVAL = 31;
// storing JDK classes in ThreadLocals does not cause memory leaks in web apps, so this is okay
private static ThreadLocal<StringBuilder> threadLocalStringBuilder = new ThreadLocal<>();
// format pattern
private String messagePattern;
// param array
private transient Object[] argArray;
private String formattedMessage;
private transient Throwable throwable;
private int[] indices;
private int usedCount;
public ParameterizedMessage(final String messagePattern, final Object[] arguments, final Throwable throwable) {
this.argArray = arguments;
this.throwable = throwable;
init(messagePattern);
}
public ParameterizedMessage(final String messagePattern, final Object... arguments) {
this.argArray = arguments;
init(messagePattern);
}
/**
* 计算有多少个占位符{},同时解析args中的throwable
*/
private void init(final String messagePattern) {
this.messagePattern = messagePattern;
final int len = Math.max(1, messagePattern == null ? 0 : messagePattern.length() >> 1); // divide by 2
this.indices = new int[len]; // LOG4J2-1542 ensure non-zero array length
final int placeholders = ParameterFormatter.countArgumentPlaceholders2(messagePattern, indices);
initThrowable(argArray, placeholders);
this.usedCount = Math.min(placeholders, argArray == null ? 0 : argArray.length);
}
// 解析throwable
private void initThrowable(final Object[] params, final int usedParams) {
if (params != null) {
final int argCount = params.length;
if (usedParams < argCount && this.throwable == null && params[argCount - 1] instanceof Throwable) {
this.throwable = (Throwable) params[argCount - 1];
}
}
}
@Override
public String getFormat() {
return messagePattern;
}
@Override
public Object[] getParameters() {
return argArray;
}
@Override
public Throwable getThrowable() {
return throwable;
}
@Override
public String getFormattedMessage() {
if (formattedMessage == null) {
final StringBuilder buffer = getThreadLocalStringBuilder();
formatTo(buffer);
formattedMessage = buffer.toString();
StringBuilders.trimToMaxSize(buffer, Constants.MAX_REUSABLE_MESSAGE_SIZE);
}
return formattedMessage;
}
private static StringBuilder getThreadLocalStringBuilder() {
StringBuilder buffer = threadLocalStringBuilder.get();
if (buffer == null) {
buffer = new StringBuilder(DEFAULT_STRING_BUILDER_SIZE);
threadLocalStringBuilder.set(buffer);
}
buffer.setLength(0);
return buffer;
}
@Override
public void formatTo(final StringBuilder buffer) {
if (formattedMessage != null) {
buffer.append(formattedMessage);
} else {
if (indices[0] < 0) {
ParameterFormatter.formatMessage(buffer, messagePattern, argArray, usedCount);
} else {
ParameterFormatter.formatMessage2(buffer, messagePattern, argArray, usedCount, indices);
}
}
}
/**
* Replace placeholders in the given messagePattern with arguments.
*/
public static String format(final String messagePattern, final Object[] arguments) {
return ParameterFormatter.format(messagePattern, arguments);
}
}
ParameterizedMessage#formatTo()调用了工具方法ParameterFormatter.formatMessage2(buffer, messagePattern, argArray, usedCount, indices)
进行内容的拼接
static void formatMessage2(final StringBuilder buffer, final String messagePattern,
final Object[] arguments, final int argCount, final int[] indices) {
if (messagePattern == null || arguments == null || argCount == 0) {
buffer.append(messagePattern);
return;
}
int previous = 0;
for (int i = 0; i < argCount; i++) {
buffer.append(messagePattern, previous, indices[i]);
previous = indices[i] + 2;
recursiveDeepToString(arguments[i], buffer, null);
}
buffer.append(messagePattern, previous, messagePattern.length());
}
indices的计算在ParameterizedMessage#init()中计算好。
static int countArgumentPlaceholders2(final String messagePattern, final int[] indices) {
if (messagePattern == null) {
return 0;
}
final int length = messagePattern.length();
int result = 0;
boolean isEscaped = false;
for (int i = 0; i < length - 1; i++) {
final char curChar = messagePattern.charAt(i);
if (curChar == ESCAPE_CHAR) {
isEscaped = !isEscaped;
indices[0] = -1; // escaping means fast path is not available...
result++;
} else if (curChar == DELIM_START) {
if (!isEscaped && messagePattern.charAt(i + 1) == DELIM_STOP) {
indices[result] = i;
result++;
i++;
}
isEscaped = false;
} else {
isEscaped = false;
}
}
return result;
}
4.2.2 MessageFactory
Message的创建一般不会主动调用new来新建,在Logger4j2内部通过MessageFactory#newMessage()来实例化一个Message,好处是MessageFactory可以进行定制,复用Message,后续分析中会有相关内容。