日志导致线程Block的这些坑，你不得不防
研发人员在项目开发中不可避免地要使用日志，通过它来记录信息和排查问题。Apache Log4j2提供了灵活且强大的日志框架，虽然上手比较快，但稍有不慎也非常容易踩“坑”。
1. 前言
2. 背景
3. 踩过的坑
3.1 日志队列满导致线程Block
3.2 AsyncAppender导致线程Block
3.3 Lambda表达式导致线程Block
3.4 AsyncLoggerConfig导致线程Block
4. 避坑指南
4.1 问题总结
4.2 对症下药
5. 佳实践
1. 前言
2. 背景
JDK版本
java version "1.8.0_45"
Java(TM) SE Runtime Environment (build 1.8.0_45-b14)
Java HotSpot(TM) 64-Bit Server VM (build 25.45-b02, mixed mode)
日志依赖版本
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-api</artifactId>
<version>2.7</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-core</artifactId>
<version>2.7</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-slf4j-impl</artifactId>
<version>2.7</version>
</dependency>
日志配置文件
<?xml version="1.0" encoding="UTF-8"?>
<configuration status="warn">
<appenders>
<Console name="Console" target="SYSTEM_OUT" follow="true">
<PatternLayout pattern="%d{yyyy/MM/dd HH:mm:ss.SSS} %t [%p] %c{1} (%F:%L) %msg%n" />
</Console>
<XMDFile name="ShepherdLog" fileName="shepherd.log"/>
<!--XMDFile异步磁盘日志配置示例-->
<!--默认按天&按512M文件大小切分日志，默认多保留30个日志文件。-->
<!--注意：fileName前会自动增加文件路径，只配置文件名即可-->
<XMDFile name="LocalServiceLog" fileName="request.log"/>
<Scribe name="LogCenterSync">
<!-- 在指定日志名方面，scribeCategory 和 appkey 两者至少存在一种，且 scribeCategory 高于 appkey。-->
<!-- <Property name="scribeCategory">data_update_test_lc</Property> -->
<LcLayout/>
</Scribe>
<Async name="LogCenterAsync" blocking="false">
<AppenderRef ref="LogCenterSync"/>
</Async>
</appenders>
<loggers>
<AsyncLogger name="com.sankuai.shepherd" level="info" additivity="false">
<AppenderRef ref="ShepherdLog" level="warn"/>
<AppenderRef ref="LogCenterAsync" level="info"/>
</AsyncLogger>
<root level="info">
<!--Console日志是同步、阻塞的，推荐只在本地调试时使用，线上将该配置去掉-->
<!--appender-ref ref="Console" /-->
<appender-ref ref="LocalServiceLog"/>
<appender-ref ref="LogCenterAsync"/>
</root>
</loggers>
</configuration>
3. 踩过的坑
3.1 日志队列满导致线程Block
3.1.1 问题现场
3.1.2 为什么会Block线程？
如果仅仅因为日志量过大就导致线程Block，那日志框架也太不堪重用了，根本没法在高并发、高吞吐业务场景下使用。
日志配置里明明是输出日志到文件，怎么会输出到Console PrintStream？
3.1.3 为什么会输出到Console？
// org.apache.logging.log4j.core.appender.AsyncAppender
// 内部维护的阻塞队列，队列大小默认是128
private final BlockingQueue<LogEvent> queue;
@Override
public void append(final LogEvent logEvent) {
if (!isStarted()) {
throw new IllegalStateException("AsyncAppender " + getName() + " is not active");
}
if (!Constants.FORMAT_MESSAGES_IN_BACKGROUND) { // LOG4J2-898: user may choose
logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
}
final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation);
// 日志事件转入异步队列
if (!transfer(memento)) {
// 执行到这里说明队列满了，入队失败，根据是否blocking执行具体策略
if (blocking) {
// 阻塞模式，选取特定的策略来处理，策略可能是 "忽略日志"、"日志入队并阻塞"、"当前线程打印日志"
// delegate to the event router (which may discard, enqueue and block, or log in current thread)
final EventRoute route = asyncQueueFullPolicy.getRoute(thread.getId(), memento.getLevel());
route.logMessage(this, memento);
} else {
// 非阻塞模式，交由 ErrorHandler 处理失败日志
error("Appender " + getName() + " is unable to write primary appenders. queue is full");
logToErrorAppenderIfNecessary(false, memento);
}
}
}
private boolean transfer(final LogEvent memento) {
return queue instanceof TransferQueue
? ((TransferQueue<LogEvent>) queue).tryTransfer(memento)
: queue.offer(memento);
}
public void error(final String msg) {
handler.error(msg);
}
如果blocking配置为true，会选择相应的处理策略，默认是SYNCHRONOUS策略，可以在log4j2.component.properties文件中，通过log4j2.AsyncQueueFullPolicy参数配置日志框架提供的其他策略或自定义策略。 DISCARD策略，直接忽略日志。 SYNCHRONOUS策略，当前线程直接发送日志到Appender。 ENQUEUE策略，强制阻塞入队。 如果blocking配置为false，则由ErrorHandler和ErrorAppender处理失败日志。日志框架提供了默认的ErrorHandler实现，即DefaultErrorHandler，目前暂不支持业务在XML、JSON等日志配置文件里自定义ErrorHandler。日志框架默认不提供ErrorAppender，业务如有需要可在XML、JSON等日志配置文件里自定义error-ref配置。
// org.apache.logging.log4j.core.appender.DefaultErrorHandler
private static final Logger LOGGER = StatusLogger.getLogger();
private static final int MAX_EXCEPTIONS = 3;
// 5min 时间间隔
private static final long EXCEPTION_INTERVAL = TimeUnit.MINUTES.toNanos(5);
private int exceptionCount = ;
private long lastException = System.nanoTime() - EXCEPTION_INTERVAL - 1;
public void error(final String msg) {
final long current = System.nanoTime();
// 当前时间距离上次异常处理时间间隔超过5min 或者异常处理数小于3次
if (current - lastException > EXCEPTION_INTERVAL || exceptionCount++ < MAX_EXCEPTIONS) {
// StatusLogger 负责处理
LOGGER.error(msg);
}
lastException = current;
}
两条日志处理间隔超过5min。
异常日志数量不超过3次。
lastException用于标记上次异常的时间戳，该变量可能被多线程访问，无法保证多线程情况下的线程安全。
exceptionCount用于统计异常日志次数，该变量可能被多线程访问，无法保证多线程情况下的线程安全。
如果StatusLogger内部注册了StatusListener，则由对应的StatusListener负责处理日志。 否则由SimpleLogger负责处理日志，直接输出日志到System.err输出流。
// org.apache.logging.log4j.status.StatusLogger
private static final StatusLogger STATUS_LOGGER = new StatusLogger(StatusLogger.class.getName(),
ParameterizedNoReferenceMessageFactory.INSTANCE);
// StatusListener
private final Collection<StatusListener> listeners = new CopyOnWriteArrayList<>();
private final SimpleLogger logger;
private StatusLogger(final String name, final MessageFactory messageFactory) {
super(name, messageFactory);
this.logger = new SimpleLogger("StatusLogger", Level.ERROR, false, true, false, false, Strings.EMPTY,
messageFactory, PROPS, System.err);
this.listenersLevel = Level.toLevel(DEFAULT_STATUS_LEVEL, Level.WARN).intLevel();
}
/**
* Retrieve the StatusLogger.
*
* @return The StatusLogger.
*/
public static StatusLogger getLogger() {
return STATUS_LOGGER;
}
@Override
public void logMessage(final String fqcn, final Level level, final Marker marker, final Message msg,
final Throwable t) {
StackTraceElement element = null;
if (fqcn != null) {
element = getStackTraceElement(fqcn, Thread.currentThread().getStackTrace());
}
final StatusData data = new StatusData(element, level, msg, t, null);
msgLock.lock();
try {
messages.add(data);
} finally {
msgLock.unlock();
}
if (listeners.size() > ) {
// 如果系统注册了 listener，由 StatusConsoleListener 处理日志
for (final StatusListener listener : listeners) {
if (data.getLevel().isMoreSpecificThan(listener.getStatusLevel())) {
listener.log(data);
}
}
} else {
// 否则由 SimpleLogger 处理日志，直接输出到 System.err
logger.logMessage(fqcn, level, marker, msg, t);
}
}
3.1.4 StatusConsoleListener是怎么来的？
XmlConfiguration，即XML格式日志配置
JsonConfiguration，即JSON格式日志配置
XMDConfiguration，即美团内部日志组件XMD-Log定义的日志配置（XML格式）
......
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug" name="RoutingTest">
<Properties>
<Property name="filename">target/rolling1/rollingtest-$${sd:type}.log</Property>
</Properties>
<ThresholdFilter level="debug"/>
<Appenders>
<Console name="STDOUT">
<PatternLayout pattern="%m%n"/>
<ThresholdFilter level="debug"/>
</Console>
<Routing name="Routing">
<Routes pattern="$${sd:type}">
<Route>
<RollingFile name="Rolling-${sd:type}" fileName="${filename}"
filePattern="target/rolling1/test1-${sd:type}.%i.log.gz">
<PatternLayout>
<pattern>%d %p %c{1.} [%t] %m%n</pattern>
</PatternLayout>
<SizeBasedTriggeringPolicy size="500" />
</RollingFile>
</Route>
<Route ref="STDOUT" key="Audit"/>
</Routes>
</Routing>
</Appenders>
<Loggers>
<Logger name="EventLogger" level="info" additivity="false">
<AppenderRef ref="Routing"/>
</Logger>
<Root level="error">
<AppenderRef ref="STDOUT"/>
</Root>
</Loggers>
</Configuration>
// org.apache.logging.log4j.core.config.xml.XmlConfiguration
public XmlConfiguration(final LoggerContext loggerContext, final ConfigurationSource configSource) {
super(loggerContext, configSource);
final File configFile = configSource.getFile();
byte[] buffer = null;
try {
final InputStream configStream = configSource.getInputStream();
try {
buffer = toByteArray(configStream);
} finally {
Closer.closeSilently(configStream);
}
final InputSource source = new InputSource(new ByteArrayInputStream(buffer));
source.setSystemId(configSource.getLocation());
final DocumentBuilder documentBuilder = newDocumentBuilder(true);
Document document;
try {
// 解析 xml 配置文件
document = documentBuilder.parse(source);
} catch (final Exception e) {
// LOG4J2-1127
final Throwable throwable = Throwables.getRootCause(e);
if (throwable instanceof UnsupportedOperationException) {
LOGGER.warn(
"The DocumentBuilder {} does not support an operation: {}."
+ "Trying again without XInclude...",
documentBuilder, e);
document = newDocumentBuilder(false).parse(source);
} else {
throw e;
}
}
rootElement = document.getDocumentElement();
// 处理根节点属性配置，即 <Configuration></Configuration> 节点
final Map<String, String> attrs = processAttributes(rootNode, rootElement);
// 创建 StatusConfiguration
final StatusConfiguration statusConfig = new StatusConfiguration().withVerboseClasses(VERBOSE_CLASSES)
.withStatus(getDefaultStatus());
for (final Map.Entry<String, String> entry : attrs.entrySet()) {
final String key = entry.getKey();
final String value = getStrSubstitutor().replace(entry.getValue());
// 根据配置文件中的 status 属性值，来设置 StatusConfiguration 的 status level
if ("status".equalsIgnoreCase(key)) {
statusConfig.withStatus(value);
// 根据配置文件中的 dest 属性值，来设置 StatusConfiguration 的日志输出 destination
} else if ("dest".equalsIgnoreCase(key)) {
statusConfig.withDestination(value);
} else if ("shutdownHook".equalsIgnoreCase(key)) {
isShutdownHookEnabled = !"disable".equalsIgnoreCase(value);
} else if ("verbose".equalsIgnoreCase(key)) {
statusConfig.withVerbosity(value);
} else if ("packages".equalsIgnoreCase(key)) {
pluginPackages.addAll(Arrays.asList(value.split(Patterns.COMMA_SEPARATOR)));
} else if ("name".equalsIgnoreCase(key)) {
setName(value);
} else if ("strict".equalsIgnoreCase(key)) {
strict = Boolean.parseBoolean(value);
} else if ("schema".equalsIgnoreCase(key)) {
schemaResource = value;
} else if ("monitorInterval".equalsIgnoreCase(key)) {
final int intervalSeconds = Integer.parseInt(value);
if (intervalSeconds > ) {
getWatchManager().setIntervalSeconds(intervalSeconds);
if (configFile != null) {
final FileWatcher watcher = new ConfiguratonFileWatcher(this, listeners);
getWatchManager().watchFile(configFile, watcher);
}
}
} else if ("advertiser".equalsIgnoreCase(key)) {
createAdvertiser(value, configSource, buffer, "text/xml");
}
}
// 初始化 StatusConfiguration
statusConfig.initialize();
} catch (final SAXException | IOException | ParserConfigurationException e) {
LOGGER.error("Error parsing " + configSource.getLocation(), e);
}
if (getName() == null) {
setName(configSource.getLocation());
}
// 忽略以下内容
}
// org.apache.logging.log4j.core.config.status.StatusConfiguration
private static final PrintStream DEFAULT_STREAM = System.out;
private static final Level DEFAULT_STATUS = Level.ERROR;
private static final Verbosity DEFAULT_VERBOSITY = Verbosity.QUIET;
private final Collection<String> errorMessages = Collections.synchronizedCollection(new LinkedList<String>());
// StatusLogger
private final StatusLogger logger = StatusLogger.getLogger();
private volatile boolean initialized = false;
private PrintStream destination = DEFAULT_STREAM;
private Level status = DEFAULT_STATUS;
private Verbosity verbosity = DEFAULT_VERBOSITY;
public void initialize() {
if (!this.initialized) {
if (this.status == Level.OFF) {
this.initialized = true;
} else {
final boolean configured = configureExistingStatusConsoleListener();
if (!configured) {
// 注册新 StatusConsoleListener
registerNewStatusConsoleListener();
}
migrateSavedLogMessages();
}
}
}
private boolean configureExistingStatusConsoleListener() {
boolean configured = false;
for (final StatusListener statusListener : this.logger.getListeners()) {
if (statusListener instanceof StatusConsoleListener) {
final StatusConsoleListener listener = (StatusConsoleListener) statusListener;
// StatusConsoleListener 的 level 以 StatusConfiguration 的 status 为准
listener.setLevel(this.status);
this.logger.updateListenerLevel(this.status);
if (this.verbosity == Verbosity.QUIET) {
listener.setFilters(this.verboseClasses);
}
configured = true;
}
}
return configured;
}
private void registerNewStatusConsoleListener() {
// 创建 StatusConsoleListener，级别以 StatusConfiguration 为准
// 默认 status 是 DEFAULT_STATUS 即 ERROR
// 默认 destination 是 DEFAULT_STREAM 即 System.out
final StatusConsoleListener listener = new StatusConsoleListener(this.status, this.destination);
if (this.verbosity == Verbosity.QUIET) {
listener.setFilters(this.verboseClasses);
}
this.logger.registerListener(listener);
}
// org.apache.logging.log4j.status.StatusConsoleListener
private Level level = Level.FATAL; // 级别
private String[] filters;
private final PrintStream stream; // 输出流
public StatusConsoleListener(final Level level, final PrintStream stream) {
if (stream == null) {
throw new IllegalArgumentException("You must provide a stream to use for this listener.");
}
this.level = level;
this.stream = stream;
}
status，可选值包括OFF、FATAL、ERROR、WARN、INFO、DEBUG、TRACE、ALL，该值决定StatusConsoleListener级别，默认是ERROR。
dest，可选值包括out、err、标准的URI路径，该值决定StatusConsoleListener输出流目的地，默认是System.out。
3.1.5 StatusLogger有什么用？
// org.apache.logging.log4j.status.StatusLogger
@Override
public void logMessage(final String fqcn, final Level level, final Marker marker, final Message msg,
final Throwable t) {
StackTraceElement element = null;
if (fqcn != null) {
element = getStackTraceElement(fqcn, Thread.currentThread().getStackTrace());
}
final StatusData data = new StatusData(element, level, msg, t, null);
msgLock.lock();
try {
messages.add(data);
} finally {
msgLock.unlock();
}
// 系统注册了 listener，由 StatusConsoleListener 处理日志
if (listeners.size() > ) {
for (final StatusListener listener : listeners) {
// 比较当前日志的 leve 和 listener 的 level
if (data.getLevel().isMoreSpecificThan(listener.getStatusLevel())) {
listener.log(data);
}
}
} else {
logger.logMessage(fqcn, level, marker, msg, t);
}
}
Troubleshooting tip for the impatient: From log4j-2.9 onward, log4j2 will print all internal logging to the console if system property log4j2.debug is defined (with any or no value). Prior to log4j-2.9, there are two places where internal logging can be controlled:
Before a configuration is found, status logger level can be controlled with system property org.apache.logging.log4j.simplelog.StatusLogger.level. After a configuration is found, status logger level can be controlled in the configuration file with the "status" attribute, for example: <Configuration status="trace">. Just as it is desirable to be able to diagnose problems in applications, it is frequently necessary to be able to diagnose problems in the logging configuration or in the configured components. Since logging has not been configured, "normal" logging cannot be used during initialization. In addition, normal logging within appenders could create infinite recursion which Log4j will detect and cause the recursive events to be ignored. To accomodate this need, the Log4j 2 API includes a StatusLogger.
3.1.6 问题小结
3.2 AsyncAppender导致线程Block
3.2.1 问题现场
3.2.2 为什么会Block线程？
项目代码里只是普通地输出一条ERROR日志而已，为何会触发类加载？
通常情况下类加载几乎不会触发线程Block，不然一个项目要加载成千上万个类，如果因为加载类就导致Block，那项目就没法正常运行了。
3.2.3 为什么会触发类加载？
首先获取堆栈元素的类名称。
再通过loadClass的方式获取对应的Class对象。
进一步获取该类所在的JAR信息，从CodeSource中获取JAR名称，从Package中获取JAR版本。
// org.apache.logging.log4j.core.impl.ThrowableProxy
private ThrowableProxy(final Throwable throwable, final Set<Throwable> visited) {
this.throwable = throwable;
this.name = throwable.getClass().getName();
this.message = throwable.getMessage();
this.localizedMessage = throwable.getLocalizedMessage();
final Map<String, CacheEntry> map = new HashMap<>();
final Stack<Class<?>> stack = ReflectionUtil.getCurrentStackTrace();
// 获取堆栈扩展信息
this.extendedStackTrace = this.toExtendedStackTrace(stack, map, null, throwable.getStackTrace());
final Throwable throwableCause = throwable.getCause();
final Set<Throwable> causeVisited = new HashSet<>(1);
this.causeProxy = throwableCause == null ? null : new ThrowableProxy(throwable, stack, map, throwableCause,
visited, causeVisited);
this.suppressedProxies = this.toSuppressedProxies(throwable, visited);
}
ExtendedStackTraceElement[] toExtendedStackTrace(final Stack<Class<?>> stack, final Map<String, CacheEntry> map,
final StackTraceElement[] rootTrace,
final StackTraceElement[] stackTrace) {
int stackLength;
if (rootTrace != null) {
int rootIndex = rootTrace.length - 1;
int stackIndex = stackTrace.length - 1;
while (rootIndex >= && stackIndex >= && rootTrace[rootIndex].equals(stackTrace[stackIndex])) {
--rootIndex;
--stackIndex;
}
this.commonElementCount = stackTrace.length - 1 - stackIndex;
stackLength = stackIndex + 1;
} else {
this.commonElementCount = ;
stackLength = stackTrace.length;
}
final ExtendedStackTraceElement[] extStackTrace = new ExtendedStackTraceElement[stackLength];
Class<?> clazz = stack.isEmpty() ? null : stack.peek();
ClassLoader lastLoader = null;
for (int i = stackLength - 1; i >= ; --i) {
// 遍历 StackTraceElement
final StackTraceElement stackTraceElement = stackTrace[i];
// 获取堆栈元素对应的类名称
final String className = stackTraceElement.getClassName();
// The stack returned from getCurrentStack may be missing entries for java.lang.reflect.Method.invoke()
// and its implementation. The Throwable might also contain stack entries that are no longer
// present as those methods have returned.
ExtendedClassInfo extClassInfo;
if (clazz != null && className.equals(clazz.getName())) {
final CacheEntry entry = this.toCacheEntry(stackTraceElement, clazz, true);
extClassInfo = entry.element;
lastLoader = entry.loader;
stack.pop();
clazz = stack.isEmpty() ? null : stack.peek();
} else {
// 对加载过的 className 进行缓存，避免重复加载
final CacheEntry cacheEntry = map.get(className);
if (cacheEntry != null) {
final CacheEntry entry = cacheEntry;
extClassInfo = entry.element;
if (entry.loader != null) {
lastLoader = entry.loader;
}
} else {
// 通过加载类来获取类的扩展信息，如 location 和 version 等
final CacheEntry entry = this.toCacheEntry(stackTraceElement,
// 获取 Class 对象
this.loadClass(lastLoader, className), false);
extClassInfo = entry.element;
map.put(stackTraceElement.toString(), entry);
if (entry.loader != null) {
lastLoader = entry.loader;
}
}
}
extStackTrace[i] = new ExtendedStackTraceElement(stackTraceElement, extClassInfo);
}
return extStackTrace;
}
/**
* Construct the CacheEntry from the Class's information.
*
* @param stackTraceElement The stack trace element
* @param callerClass The Class.
* @param exact True if the class was obtained via Reflection.getCallerClass.
* @return The CacheEntry.
*/
private CacheEntry toCacheEntry(final StackTraceElement stackTraceElement, final Class<?> callerClass,
final boolean exact) {
String location = "?";
String version = "?";
ClassLoader lastLoader = null;
if (callerClass != null) {
try {
// 获取 jar 文件信息
final CodeSource source = callerClass.getProtectionDomain().getCodeSource();
if (source != null) {
final URL locationURL = source.getLocation();
if (locationURL != null) {
final String str = locationURL.toString().replace('\\', '/');
int index = str.lastIndexOf("/");
if (index >= && index == str.length() - 1) {
index = str.lastIndexOf("/", index - 1);
location = str.substring(index + 1);
} else {
location = str.substring(index + 1);
}
}
}
} catch (final Exception ex) {
// Ignore the exception.
}
// 获取类所在 jar 版本信息
final Package pkg = callerClass.getPackage();
if (pkg != null) {
final String ver = pkg.getImplementationVersion();
if (ver != null) {
version = ver;
}
}
lastLoader = callerClass.getClassLoader();
}
return new CacheEntry(new ExtendedClassInfo(exact, location, version), lastLoader);
}
// java.lang.StackTraceElement
public String getClassName() {
return declaringClass;
}
public String toString() {
return getClassName() + "." + methodName +
(isNativeMethod() ? "(Native Method)" :
(fileName != null && lineNumber >= ?
"(" + fileName + ":" + lineNumber + ")" :
(fileName != null ? "("+fileName+")" : "(Unknown Source)")));
}
3.2.4 到底什么类加载不了？
sun.reflect.NativeMethodAccessorImpl（参见图12）。
sun.reflect.GeneratedMethodAccessor261（参见图13）。
默认使用native方法进行反射操作。
一定条件下会生成字节码进行反射操作，即生成sun.reflect.GeneratedMethodAccessor<N>类，它是一个反射调用方法的包装类，代理不同的方法，类后缀序号递增。
// java.lang.reflect.Method
@CallerSensitive
public Object invoke(Object obj, Object... args)
throws IllegalAccessException, IllegalArgumentException,
InvocationTargetException
{
if (!override) {
if (!Reflection.quickCheckMemberAccess(clazz, modifiers)) {
Class<?> caller = Reflection.getCallerClass();
checkAccess(caller, clazz, obj, modifiers);
}
}
MethodAccessor ma = methodAccessor; // read volatile
if (ma == null) {
// 获取 MethodAccessor
ma = acquireMethodAccessor();
}
// 通过 MethodAccessor 调用
return ma.invoke(obj, args);
}
private MethodAccessor acquireMethodAccessor() {
MethodAccessor tmp = null;
if (root != null) tmp = root.getMethodAccessor();
if (tmp != null) {
methodAccessor = tmp;
} else {
// 通过 ReflectionFactory 创建 MethodAccessor
tmp = reflectionFactory.newMethodAccessor(this);
setMethodAccessor(tmp);
}
return tmp;
}
// sun.reflect.ReflectionFactory
public MethodAccessor newMethodAccessor(Method method) {
// 通过启动参数获取并解析 noInflation 和 inflationThreshold 值
// noInflation 默认为 false
// inflationThreshold 默认为15
checkInitted();
if (noInflation && !ReflectUtil.isVMAnonymousClass(method.getDeclaringClass())) {
return new MethodAccessorGenerator().
generateMethod(method.getDeclaringClass(),
method.getName(),
method.getParameter*(),
method.getReturnType(),
method.getException*(),
method.getModifiers());
} else {
NativeMethodAccessorImpl acc =
new NativeMethodAccessorImpl(method);
DelegatingMethodAccessorImpl res =
new DelegatingMethodAccessorImpl(acc);
acc.setParent(res);
// 返回代理 DelegatingMethodAccessorImpl
return res;
}
}
private static void checkInitted() {
if (initted) return;
AccessController.doPrivileged(
new PrivilegedAction<Void>() {
public Void run() {
// Tests to ensure the system properties table is fully
// initialized. This is needed because reflection code is
// called very early in the initialization process (before
// command-line arguments have been parsed and therefore
// these user-settable properties installed.) We assume that
// if System.out is non-null then the System class has been
// fully initialized and that the bulk of the startup code
// has been run.
if (System.out == null) {
// java.lang.System not yet fully initialized
return null;
}
String val = System.getProperty("sun.reflect.noInflation");
if (val != null && val.equals("true")) {
noInflation = true;
}
val = System.getProperty("sun.reflect.inflationThreshold");
if (val != null) {
try {
inflationThreshold = Integer.parseInt(val);
} catch (NumberFormatException e) {
throw new RuntimeException("Unable to parse property sun.reflect.inflationThreshold", e);
}
}
initted = true;
return null;
}
});
}
// sun.reflect.DelegatingMethodAccessorImpl
class DelegatingMethodAccessorImpl extends MethodAccessorImpl {
// 内部代理 MethodAccessorImpl
private MethodAccessorImpl delegate;
DelegatingMethodAccessorImpl(MethodAccessorImpl delegate) {
setDelegate(delegate);
}
public Object invoke(Object obj, Object[] args)
throws IllegalArgumentException, InvocationTargetException
{
return delegate.invoke(obj, args);
}
void setDelegate(MethodAccessorImpl delegate) {
this.delegate = delegate;
}
}
// sun.reflect.NativeMethodAccessorImpl
class NativeMethodAccessorImpl extends MethodAccessorImpl {
private final Method method;
private DelegatingMethodAccessorImpl parent;
private int numInvocations;
NativeMethodAccessorImpl(Method method) {
this.method = method;
}
public Object invoke(Object obj, Object[] args)
throws IllegalArgumentException, InvocationTargetException
{
// We can't inflate methods belonging to vm-anonymous classes because
// that kind of class can't be referred to by name, hence can't be
// found from the generated bytecode.
// 每次调用时 numInvocations 都会自增加1，如果超过阈值（默认是15次），就会修改父类的代理对象，从而改变调用链路
if (++numInvocations > ReflectionFactory.inflationThreshold()
&& !ReflectUtil.isVMAnonymousClass(method.getDeclaringClass())) {
MethodAccessorImpl acc = (MethodAccessorImpl)
// 动态生成字节码，优化反射调用速度
new MethodAccessorGenerator().
generateMethod(method.getDeclaringClass(),
method.getName(),
method.getParameter*(),
method.getReturnType(),
method.getException*(),
method.getModifiers());
// 修改父代理类的代理对象
parent.setDelegate(acc);
}
return invoke0(method, obj, args);
}
void setParent(DelegatingMethodAccessorImpl parent) {
this.parent = parent;
}
private static native Object invoke0(Method m, Object obj, Object[] args);
}
// sun.reflect.MethodAccessorGenerator
public MethodAccessor generateMethod(Class<?> declaringClass,
String name,
Class<?>[] parameter*,
Class<?> returnType,
Class<?>[] checkedExceptions,
int modifiers)
{
return (MethodAccessor) generate(declaringClass,
name,
parameter*,
returnType,
checkedExceptions,
modifiers,
false,
false,
null);
}
private MagicAccessorImpl generate(final Class<?> declaringClass,
String name,
Class<?>[] parameter*,
Class<?> returnType,
Class<?>[] checkedExceptions,
int modifiers,
boolean isConstructor,
boolean forSerialization,
Class<?> serializationTargetClass)
{
final String generatedName = generateName(isConstructor, forSerialization);
// 忽略以上代码
return AccessController.doPrivileged(
new PrivilegedAction<MagicAccessorImpl>() {
public MagicAccessorImpl run() {
try {
return (MagicAccessorImpl)
ClassDefiner.defineClass
(generatedName,
bytes,
,
bytes.length,
declaringClass.getClassLoader()).newInstance();
} catch (InstantiationException | IllegalAccessException e) {
throw new InternalError(e);
}
}
});
}
// 生成反射类名，看到了熟悉的 sun.reflect.GeneratedConstructorAccessor<N>
private static synchronized String generateName(boolean isConstructor, boolean forSerialization)
{
if (isConstructor) {
if (forSerialization) {
int num = ++serializationConstructorSymnum;
return "sun/reflect/GeneratedSerializationConstructorAccessor" + num;
} else {
int num = ++constructorSymnum;
return "sun/reflect/GeneratedConstructorAccessor" + num;
}
} else {
int num = ++methodSymnum;
return "sun/reflect/GeneratedMethodAccessor" + num;
}
}
// sun.reflect.ClassDefiner
static Class<?> defineClass(String name, byte[] bytes, int off, int len,
final ClassLoader parentClassLoader)
{
ClassLoader newLoader = AccessController.doPrivileged(
new PrivilegedAction<ClassLoader>() {
public ClassLoader run() {
return new DelegatingClassLoader(parentClassLoader);
}
});
// 通过 DelegatingClassLoader 类加载器定义生成类
return unsafe.defineClass(name, bytes, off, len, newLoader, null);
}
"Inflation" mechanism. Loading bytecodes to implement Method.invoke() and Constructor.newInstance() currently costs 3-4x more than an invocation via native code for the first invocation (though subsequent invocations have been benchmarked to be over 20x faster). Unfortunately this cost increases startup time for certain applications that use reflection intensively (but only once per class) to bootstrap themselves. To avoid this penalty we reuse the existing JVM entry points for the first few invocations of Methods and Constructors and then switch to the bytecode-based implementations.
3.2.5 为什么要解析异常堆栈？
// org.apache.logging.log4j.core.appender.AsyncAppender
@Override
public void append(final LogEvent logEvent) {
if (!isStarted()) {
throw new IllegalStateException("AsyncAppender " + getName() + " is not active");
}
if (!Constants.FORMAT_MESSAGES_IN_BACKGROUND) { // LOG4J2-898: user may choose
logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
}
// 创建 日志数据快照
final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation);
// 放入 BlockingQueue 中
if (!transfer(memento)) {
if (blocking) {
// delegate to the event router (which may discard, enqueue and block, or log in current thread)
final EventRoute route = asyncQueueFullPolicy.getRoute(thread.getId(), memento.getLevel());
route.logMessage(this, memento);
} else {
error("Appender " + getName() + " is unable to write primary appenders. queue is full");
logToErrorAppenderIfNecessary(false, memento);
}
}
}
Log4jLogEvent类型，先执行Log4jLogEvent#getThrownProxy方法，触发创建ThrowableProxy实例。
MutableLogEvent类型，先创建LogEventProxy实例，在构造函数内执行MutableLogEvent#getThrownProxy方法，触发创建ThrowableProxy实例。
// org.apache.logging.log4j.core.impl.Log4jLogEvent
// 生成Log4jLogEvent快照
public static Log4jLogEvent createMemento(final LogEvent event, final boolean includeLocation) {
// TODO implement Log4jLogEvent.createMemento()
return deserialize(serialize(event, includeLocation));
}
public static Serializable serialize(final LogEvent event, final boolean includeLocation) {
if (event instanceof Log4jLogEvent) {
// 确保 ThrowableProxy 已完成初始化
event.getThrownProxy(); // ensure ThrowableProxy is initialized
// 创建 LogEventProxy
return new LogEventProxy((Log4jLogEvent) event, includeLocation);
}
// 创建 LogEventProxy
return new LogEventProxy(event, includeLocation);
}
@Override
public ThrowableProxy getThrownProxy() {
if (thrownProxy == null && thrown != null) {
thrownProxy = new ThrowableProxy(thrown);
}
return thrownProxy;
}
public LogEventProxy(final LogEvent event, final boolean includeLocation) {
this.loggerFQCN = event.getLoggerFqcn();
this.marker = event.getMarker();
this.level = event.getLevel();
this.loggerName = event.getLoggerName();
final Message msg = event.getMessage();
this.message = msg instanceof ReusableMessage
? memento((ReusableMessage) msg)
: msg;
this.timeMillis = event.getTimeMillis();
this.thrown = event.getThrown();
// 创建 ThrownProxy 实例
this.thrownProxy = event.getThrownProxy();
this.contextData = memento(event.getContextData());
this.contextStack = event.getContextStack();
this.source = includeLocation ? event.getSource() : null;
this.threadId = event.getThreadId();
this.threadName = event.getThreadName();
this.threadPriority = event.getThreadPriority();
this.isLocationRequired = includeLocation;
this.isEndOfBatch = event.isEndOfBatch();
this.nanoTime = event.getNanoTime();
}
// org.apache.logging.log4j.core.impl.MutableLogEvent
@Override
public ThrowableProxy getThrownProxy() {
if (thrownProxy == null && thrown != null) {
// 构造 ThrowableProxy 时打印异常堆栈
thrownProxy = new ThrowableProxy(thrown);
}
return thrownProxy;
}
3.2.6 问题小结
3.3 Lambda表达式导致线程Block
3.3.1 问题现场
3.3.2 为什么会Block线程？
3.3.3 为什么会触发类加载？
3.3.4 到底什么类加载不了？
com.sankuai.shepherd.core.process.ProcessHandlerFactory$$Lambda$35/1331430278
NoClassDefFound error in transforming lambdas JVMTI RedefineClasses doesn't handle anonymous classes properly
3.3.5 为什么要解析异常堆栈？
3.3.6 问题小结
3.4 AsyncLoggerConfig导致线程Block
3.4.1 问题现场
3.4.2 为什么会Block线程？
3.4.3 为什么会触发类加载？
3.4.4 到底是什么类加载不了？
3.4.5 为什么要解析异常堆栈？
<Logger>，日志配置标签，用于XML日志配置文件中，对应Log4j2框架中的LoggerConfig类，同步分发日志事件到对应Appender。
<AsyncLogger>，日志配置标签，用于XML日志配置文件中，对应Log4j2框架中的AsyncLoggerConfig类，内部使用Disruptor队列异步分发日志事件到对应Appender。
Logger，同步日志类，用于创建同步日志实例，同步调用ReliabilityStrategy处理日志。
AsyncLogger，异步日志类，用于创建异步日志实例，内部使用Disruptor队列实现异步调用ReliabilityStrategy处理日志。
// org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$EventTranslatorTwoArg
/**
* Object responsible for passing on data to a RingBuffer event with a MutableLogEvent.
*/
private static final EventTranslatorTwoArg<Log4jEventWrapper, LogEvent, AsyncLoggerConfig> MUTABLE_TRANSLATOR =
new EventTranslatorTwoArg<Log4jEventWrapper, LogEvent, AsyncLoggerConfig>() {
@Override
public void translateTo(final Log4jEventWrapper ringBufferElement, final long sequence,
final LogEvent logEvent, final AsyncLoggerConfig loggerConfig) {
// 初始化 Disruptor RingBuffer 日志元素字段
((MutableLogEvent) ringBufferElement.event).initFrom(logEvent);
ringBufferElement.loggerConfig = loggerConfig;
}
};
// org.apache.logging.log4j.core.impl.MutableLogEvent
public void initFrom(final LogEvent event) {
this.loggerFqcn = event.getLoggerFqcn();
this.marker = event.getMarker();
this.level = event.getLevel();
this.loggerName = event.getLoggerName();
this.timeMillis = event.getTimeMillis();
this.thrown = event.getThrown();
// 触发创建 ThrowableProxy 实例
this.thrownProxy = event.getThrownProxy();
// NOTE: this ringbuffer event SHOULD NOT keep a reference to the specified
// thread-local MutableLogEvent's context data, because then two threads would call
// ReadOnlyStringMap.clear() on the same shared instance, resulting in data corruption.
this.contextData.putAll(event.getContextData());
this.contextStack = event.getContextStack();
this.source = event.isIncludeLocation() ? event.getSource() : null;
this.threadId = event.getThreadId();
this.threadName = event.getThreadName();
this.threadPriority = event.getThreadPriority();
this.endOfBatch = event.isEndOfBatch();
this.includeLocation = event.isIncludeLocation();
this.nanoTime = event.getNanoTime();
setMessage(event.getMessage());
}
@Override
public ThrowableProxy getThrownProxy() {
if (thrownProxy == null && thrown != null) {
// 构造 ThrowableProxy 时打印异常堆栈
thrownProxy = new ThrowableProxy(thrown);
}
return thrownProxy;
}
3.4.6 问题小结
4. 避坑指南
4.1 问题总结
业务线程组装日志事件对象，如创建日志快照或者初始化日志字段等。
日志事件对象入队，如BlockingQueue队列或Disruptor RingBuffer队列等。
日志异步线程从队列获取日志事件对象，并输出至目的地，如本地磁盘文件或远程日志中心等。
如上图标号①所示，日志事件对象在入队前，组装日志事件时触发了异常堆栈类解析、加载，从而引发线程Block。
如上图标号②所示，日志事件对象在入队时，由于队列满，无法入队，从而引发线程Block。
如上图标号③所示，日志事件对象在出队后，对日志内容进行格式化处理时触发了异常堆栈类解析、加载，从而引发线程 Block。
标号①和②处如果发生线程Block，那么会直接影响业务线程池内的所有线程。 标号③出如果发生线程Block，那么会影响日志异步线程，该线程通常为单线程。
4.2 对症下药
4.2.1 入队前避免线程Block
日志事件入队前避免触发异常堆栈类解析、加载操作。
禁用JVM反射调用优化。
升级JDK版本修复Lambda类Bug。
自定义Appender实现，创建日志事件快照时避免触发异常堆栈类解析、加载，美团内部Scribe-Log提供的AsyncScribeAppender即是如此。
日志配置文件中不使用<AsyncLogger>标签，可以使用<Logger>标签来代替。
对于AsyncAppender场景来说，可以通过自定义Appender实现，在生成日志事件快照时避免触发解析、加载异常堆栈类，并在配置文件中使用自定义的Appender代替Log4j2提供的AsyncAppender。自定义AsyncScribeAppender相关代码片段如下。
// org.apache.logging.log4j.scribe.appender.AsyncScribeAppender
@Override
public void append(final LogEvent logEvent) {
// ... 以上部分忽略 ...
Log4jLogEvent.Builder builder = new Log4jLogEvent.Builder(event);
builder.setIncludeLocation(includeLocation);
// 创建日志快照，避免解析、加载异常堆栈类
final Log4jLogEvent memento = builder.build();
// ... 以下部分忽略 ...
}
对于AsyncLoggerConfig场景来说，可以考虑使用非ReusableLogEventFactory类型的LogEventFactory来规避该问题，除此之外也可以考虑换用LoggerConfig来避免该问题。
4.2.2 入队时避免线程Block
日志队列满时，Appender忽略该日志。
Appender使用自定义的ErrorHandler实现处理日志。
关闭StatusConfigListener日志输出。
对于AsyncAppender在blocking场景来说，可以通过配置log4j2.AsyncQueueFullPolicy=Discard来使用DISCARD策略忽略日志。
对于AsyncAppender在非blocking场景来说，可以通过自定义Appender实现，在日志事件入队失败后直接忽略错误日志，并在配置文件中使用自定义的Appender代替Log4j2提供的AsyncAppender。自定义AsyncScribeAppender相关代码片段如下。
// org.apache.logging.log4j.scribe.appender.AsyncScribeAppender
@Override
public void append(final LogEvent logEvent) {
// ... 以上部分忽略 ...
if (!transfer(memento)) {
if (blocking) {
// delegate to the event router (which may discard, enqueue and block, or log in current thread)
final EventRouteAsyncScribe route = asyncScribeQueueFullPolicy.getRoute(processingThread.getId(), memento.getLevel());
route.logMessage(this, memento);
} else {
// 自定义printDebugInfo参数，控制是否输出error信息，默认为false
if (printDebugInfo) {
error("Appender " + getName() + " is unable to write primary appenders. queue is full");
}
logToErrorAppenderIfNecessary(false, memento);
}
}
// ... 以下部分忽略 ...
}
配置文件中设置Configuration的status属性值为off，则不会创建StatusConfigListener，但此时StatusLogger会调用SimpleLogger来输出日志到System.err，仍不解决问题。
配置文件中设置Configuration的status属性值为fatal，则只有fatal级别的日志才会输出，普通的error日志直接忽略，但fatal条件过于严苛，可能会忽略一些重要的error日志。
4.2.3 出队后避免线程Block
// org.apache.logging.log4j.core.layout.PatternLayout
// 将 LogEvent 转换为可以输出的 String
@Override
public String toSerializable(final LogEvent event) {
// 由 PatternSerializer 对日志事件格式化处理
return eventSerializer.toSerializable(event);
}
// org.apache.logging.log4j.core.layout.PatternLayout.PatternSerializer
@Override
public String toSerializable(final LogEvent event) {
final StringBuilder sb = getStringBuilder();
try {
return toSerializable(event, sb).toString();
} finally {
trimToMaxSize(sb);
}
}
@Override
public StringBuilder toSerializable(final LogEvent event, final StringBuilder buffer) {
final int len = formatters.length;
for (int i = ; i < len; i++) {
// 由 PatternFormatter 对日志事件格式化处理
formatters[i].format(event, buffer);
}
if (replace != null) { // creates temporary objects
String str = buffer.toString();
str = replace.format(str);
buffer.setLength();
buffer.append(str);
}
return buffer;
}
// org.apache.logging.log4j.core.pattern.PatternFormatter
public void format(final LogEvent event, final StringBuilder buf) {
if (skipFormattingInfo) {
// 由 LogEventPatternConverter 对日志事件进行格式化处理
converter.format(event, buf);
} else {
formatWithInfo(event, buf);
}
}
private void formatWithInfo(final LogEvent event, final StringBuilder buf) {
final int startField = buf.length();
// 由 LogEventPatternConverter 对日志事件进行格式化处理
converter.format(event, buf);
field.format(startField, buf);
}
// org.apache.logging.log4j.core.pattern.LogEventPatternConverter
public abstract class LogEventPatternConverter extends AbstractPatternConverter {
/**
* 将日志事件 LogEvent 转换为 String
* Formats an event into a string buffer.
*
* @param event event to format, may not be null.
* @param toAppendTo string buffer to which the formatted event will be appended. May not be null.
*/
public abstract void format(final LogEvent event, final StringBuilder toAppendTo);
}
// org.apache.logging.log4j.core.pattern.ThrowablePatternConverter
@Plugin(name = "ThrowablePatternConverter", category = PatternConverter.CATEGORY)
@ConverterKeys({ "ex", "throwable", "exception" })
public class ThrowablePatternConverter extends LogEventPatternConverter {
/**
* {@inheritDoc}
*/
@Override
public void format(final LogEvent event, final StringBuilder buffer) {
final Throwable t = event.getThrown();
if (isSubShortOption()) {
formatSubShortOption(t, getSuffix(event), buffer);
}
else if (t != null && options.anyLines()) {
formatOption(t, getSuffix(event), buffer);
}
}
private boolean isSubShortOption() {
return ThrowableFormatOptions.MESSAGE.equalsIgnoreCase(rawOption) ||
ThrowableFormatOptions.LOCALIZED_MESSAGE.equalsIgnoreCase(rawOption) ||
ThrowableFormatOptions.FILE_NAME.equalsIgnoreCase(rawOption) ||
ThrowableFormatOptions.LINE_NUMBER.equalsIgnoreCase(rawOption) ||
ThrowableFormatOptions.METHOD_NAME.equalsIgnoreCase(rawOption) ||
ThrowableFormatOptions.CLASS_NAME.equalsIgnoreCase(rawOption);
}
private void formatSubShortOption(final Throwable t, final String suffix, final StringBuilder buffer) {
StackTraceElement[] trace;
StackTraceElement throwingMethod = null;
int len;
if (t != null) {
trace = t.getStackTrace();
if (trace !=null && trace.length > ) {
throwingMethod = trace[];
}
}
if (t != null && throwingMethod != null) {
String toAppend = Strings.EMPTY;
if (ThrowableFormatOptions.CLASS_NAME.equalsIgnoreCase(rawOption)) {
toAppend = throwingMethod.getClassName();
}
else if (ThrowableFormatOptions.METHOD_NAME.equalsIgnoreCase(rawOption)) {
toAppend = throwingMethod.getMethodName();
}
else if (ThrowableFormatOptions.LINE_NUMBER.equalsIgnoreCase(rawOption)) {
toAppend = String.valueOf(throwingMethod.getLineNumber());
}
else if (ThrowableFormatOptions.MESSAGE.equalsIgnoreCase(rawOption)) {
toAppend = t.getMessage();
}
else if (ThrowableFormatOptions.LOCALIZED_MESSAGE.equalsIgnoreCase(rawOption)) {
toAppend = t.getLocalizedMessage();
}
else if (ThrowableFormatOptions.FILE_NAME.equalsIgnoreCase(rawOption)) {
toAppend = throwingMethod.getFileName();
}
len = buffer.length();
if (len > && !Character.isWhitespace(buffer.charAt(len - 1))) {
buffer.append(' ');
}
buffer.append(toAppend);
if (Strings.isNotBlank(suffix)) {
buffer.append(' ');
buffer.append(suffix);
}
}
}
private void formatOption(final Throwable throwable, final String suffix, final StringBuilder buffer) {
final StringWriter w = new StringWriter();
throwable.printStackTrace(new PrintWriter(w));
final int len = buffer.length();
if (len > && !Character.isWhitespace(buffer.charAt(len - 1))) {
buffer.append(' ');
}
if (!options.allLines() || !Strings.LINE_SEPARATOR.equals(options.getSeparator()) || Strings.isNotBlank(suffix)) {
final StringBuilder sb = new StringBuilder();
final String[] array = w.toString().split(Strings.LINE_SEPARATOR);
final int limit = options.minLines(array.length) - 1;
final boolean suffixNotBlank = Strings.isNotBlank(suffix);
for (int i = ; i <= limit; ++i) {
sb.append(array[i]);
if (suffixNotBlank) {
sb.append(' ');
sb.append(suffix);
}
if (i < limit) {
sb.append(options.getSeparator());
}
}
buffer.append(sb.toString());
} else {
buffer.append(w.toString());
}
}
/**
* This converter obviously handles throwables.
*
* @return true.
*/
@Override
public boolean handlesThrowable() {
return true;
}
protected String getSuffix(final LogEvent event) {
//noinspection ForLoopReplaceableByForEach
final StringBuilder toAppendTo = new StringBuilder();
for (int i = , size = formatters.size(); i < size; i++) {
formatters.get(i).format(event, toAppendTo);
}
return toAppendTo.toString();
}
public ThrowableFormatOptions getOptions() {
return options;
}
}
// org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter
@Plugin(name = "ExtendedThrowablePatternConverter", category = PatternConverter.CATEGORY)
@ConverterKeys({ "xEx", "xThrowable", "xException" })
public final class ExtendedThrowablePatternConverter extends ThrowablePatternConverter {
/**
* {@inheritDoc}
*/
@Override
public void format(final LogEvent event, final StringBuilder toAppendTo) {
// 获取 ThrowableProxy 对象，触发解析、加载异常堆栈类
final ThrowableProxy proxy = event.getThrownProxy();
final Throwable throwable = event.getThrown();
if ((throwable != null || proxy != null) && options.anyLines()) {
if (proxy == null) {
super.format(event, toAppendTo);
return;
}
final String extStackTrace = proxy.getExtendedStackTraceAsString(options.getIgnorePackages(),
options.getTextRenderer(), getSuffix(event), options.getSeparator());
final int len = toAppendTo.length();
if (len > && !Character.isWhitespace(toAppendTo.charAt(len - 1))) {
toAppendTo.append(' ');
}
toAppendTo.append(extStackTrace);
}
}
}
5. 佳实践
建议日志配置文件中对所有Appender的PatternLayout都增加%ex配置，因为如果没有显式配置%ex，则异常格式化输出的默认配置是%xEx，此时会打印异常的扩展信息（JAR名称和版本），可能导致业务线程Block。
不建议日志配置文件中使用AsyncAppender，建议自定义Appender实现，因为AsyncAppender是日志框架默认提供的，目前新版本中仍然存在日志事件入队前就触发加载异常堆栈类的问题，可能导致业务线程Block。
不建议生产环境使用ConsoleAppender，因为输出日志到Console时有synchronized同步操作，高并发场景下非常容易导致业务线程Block。
不建议在配置文件中使用<AsyncLogger>标签，因为日志事件元素在入队前就会触发加载异常堆栈类，可能导致业务线程Block。如果希望使用Log4j2提供的异步日志AsyncLogger，建议配置Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector参数，开启异步日志。
<configuration status="warn">
<appenders>
<Console name="Console" target="SYSTEM_OUT" follow="true">
<PatternLayout pattern="%d{yyyy/MM/dd HH:mm:ss.SSS} %t [%p] %c{1} (%F:%L) %msg%n %ex" />
</Console>
<XMDFile name="ShepherdLog" fileName="shepherd.log">
<PatternLayout pattern="%d{yyyy/MM/dd HH:mm:ss.SSS} %t [%p] %c{1} (%F:%L) %msg%n %ex" />
</XMDFile>
<!--XMDFile异步磁盘日志配置示例-->
<!--默认按天&按512M文件大小切分日志，默认多保留30个日志文件。-->
<!--注意：fileName前会自动增加文件路径，只配置文件名即可-->
<XMDFile name="LocalServiceLog" fileName="request.log">
<PatternLayout pattern="%d{yyyy/MM/dd HH:mm:ss.SSS} %t [%p] %c{1} (%F:%L) %msg%n %ex" />
</XMDFile>
<!-- 使用自定义的AsyncScribeAppender代替原有的AsycncAppender -->
<AsyncScribe name="LogCenterAsync" blocking="false">
<!-- 在指定日志名方面，scribeCategory 和 appkey 两者至少存在一种，且 scribeCategory 高于 appkey。-->
<!-- <Property name="scribeCategory">data_update_test_lc</Property> -->
<LcLayout/>
</AsyncScribe>
</appenders>
<loggers>
<logger name="com.sankuai.shepherd" level="info" additivity="false">
<AppenderRef ref="ShepherdLog" level="warn"/>
<AppenderRef ref="LogCenterAsync" level="info"/>
</logger>
<root level="info">
<!--Console日志是同步、阻塞的，推荐只在本地调试时使用，线上将该配置去掉-->
<!--appender-ref ref="Console" /-->
<appender-ref ref="LocalServiceLog"/>
<appender-ref ref="LogCenterAsync"/>
</root>
</loggers>
</configuration>
6. 作者简介
相关文章