日志打印产生的相关问题
日志打印过多，会对磁盘IO和CPU性能造成比较大的压力，所以可以通过日志分级去控制日志的输出。
日志级别
日志通常使用到ERROR、WARN、INFO、DEBUG级别，日志虽然可以提示更多的信息，但是生产打印大量日志消耗性能。
- DEBUG级别：一般是调试程序的时候开启。
- INFO级别：消息在粗粒度级别上突出强调应用程序的运行过程。打印一些你感兴趣的或者重要的信息，这个可以用于生产环境中输出程序运行的一些重要信息，但是不能滥用，避免打印过多的日志。
- WARNING：没有发生错误或者错误不太重要，但需要给出一些警告信息。
- ERROR：指出虽然发生错误事件，但仍然不影响系统的继续运行。打印错误和异常信息，如果不想输出太多的日志，可以使用这个级别。
日志打印影响性能的原因
- 同步打印日志磁盘 I/O 成为瓶颈，导致大量线程 Block,多个线程输出到同一个文件中，需要加锁去完成线程安全，其他没获取到锁的线程阻塞等待，造成卡顿。
- 高并发下日志打印异常堆栈造成线程 Block，qps过高，上下游出现异常，导致打印日志堆栈信息。
优化手段
- 选择合适的日志打印级别
- 采用异步打印的方式，AsyncLogger是Log4j2 官方推荐的异步方式。
- 对日志设置打印格式，不要打印堆栈信息。
Log4j2异步日志配置原理
Log4j2 异步日志基于高性能数据结构 Disruptor，Disruptor 是一个环形 buffer，通过环形无阻塞队列作为缓冲，多生产者多线程的竞争是通过CAS（compare and swap）无锁化实现，可以极大的提高日志输出效率。
记一次日志打印引发的问题
Blocked线程堆栈中可以看出，线程阻塞在类加载流程上，查看WebAppClassLoader相关代码片段如下图11所示，发现加载类时确实会根据类名来加synchronized同步块，因此初步猜测是类加载导致线程Block。
继续从Blocked线程堆栈着手分析，查看堆栈中的ThrowableProxy相关代码，发现其构造函数会遍历整个异常堆栈中的所有堆栈元素，最终获取所有堆栈元素类所在的JAR名称和版本信息。具体流程如下：
- 首先获取堆栈元素的类名称。
- 再通过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 >= 0 && stackIndex >= 0 && rootTrace[rootIndex].equals(stackTrace[stackIndex])) {
--rootIndex;
--stackIndex;
}
this.commonElementCount = stackTrace.length - 1 - stackIndex;
stackLength = stackIndex + 1;
} else {
this.commonElementCount = 0;
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 >= 0; --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 >= 0 && 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);
}ThrowableProxy#toExtendedStackTrace方法通过Map<String, CacheEntry>缓存当前堆栈元素类对应的CacheEntry，来避免重复解析CacheEntry。
因此正常情况下，一个类加载器对于一种类只会加载一次，类加载器保存有类缓存，无需重复加载，因此是有一个类一直重复加载不了，导致的问题。
第一阶段 Tomcat + Spring Boot
这个阶段是 Spring Boot 接收到一个 Http 请求到进入业务代码之前。Spring Boot 把收到的 Http 请求转发到业务代码，这个过程使用Method.invoke反射。在sun.reflect包中Method.invoke使用代理类，代理类有如下 2 种方式实现：
- NativeMethodAccessorImpl
- GeneratedMethodAccessorXX
这 2 个代理类都包含invoke方法，都能完成对反射类方法的调用。不同点是：1、NativeMethodAccessorImpl 通过new方法生成，invoke方法底层调用native方法；2、GeneratedMethodAccessorXX 通过bytecode动态生成。前 16 次调用使用NativeMethodAccessorImpl，从 17 次调用开始使用GeneratedMethodAccessorXX，这种方式称为Inflation机制。
- 默认条件使用native方法进行反射操作
- 一定条件下会生成字节码进行反射操作，即生成sun.reflect.GeneratedMethodAccessor类，它是一个反射调用方法的包装类，代理不同的方法，类后缀序号递增。
从MethodAccessorGenerator#generateName方法可以看到，字节码生成的类名称规则是sun.reflect.GeneratedConstructorAccessor，其中N是从0开始的递增数字，且生成类是由DelegatingClassLoader类加载器定义，所以其他类加载器无法加载该类，也就无法生成类缓存数据，从而导致每次加载类时都需要遍历JarFile，极大地降低了类查找速度，且类加载过程是synchronized同步调用，在高并发情况下会更加恶化，从而导致线程Block。
其实这是JVM对反射调用的一种优化手段，在sun.reflect.ReflectionFactory的文档注释里对此做了解释，这是一种“Inflation”机制，加载字节码的调用方式在第一次调用时会比Native调用的速度要慢3~4倍，但是在后续调用时会比Native调用速度快20多倍
Log4j2打印异常日志时，AsyncAppender会先创建日志事件快照，并进一步触发解析、加载异常堆栈类。JVM通过生成字节码的方式优化反射调用性能，但该动态生成的类无法被WebAppClassLoader类加载器加载，因此当大量包含反射调用的异常堆栈被输出到日志时，会频繁地触发类加载，由于类加载过程是synchronized同步加锁的，且每次加载都需要读取文件，速度较慢，从而导致线程Block。
通过以上分析，总结如下：
1、日志Layout默认使用%xEx打印异常栈的类信息，而异常栈中包含动态类GeneratedMethodAccessorXX的加载，需要类加载；
2、Log4j2 最终调用TomcatEmbeddedWebappClassLoader.loadclass进行类加载，由于是动态类和类加载器使用的原因，导致无法加载。每次日志打印都会进行类加载过程，而在上面的方法中有synchronized发生同步等待，线程阻塞后，并发能力下降。
解决方法
1、在Layout中增加标识符%ex{n}，这个不会打印类信息，不会因为类加载导致线程阻塞；n 表示打印多少行栈信息，一般只需要把业务调用栈信息打印出来即可，框架栈信息不需要。经过压测效果有提升，但还会发生其他方面的线程阻塞；
