现象

在压测一个新上线服务核心接口的时候，出现接口响应时间、TPS不满足预期的问题。

jsf_block01
jsf_block01

问题排查

通过Jstack发现大量JSF线程处于阻塞状态，都在ClassLoader.loadClass方法中等待锁，同时可以看到是由log4j触发的。

1
2
3
4
5
6
7
8
9
10
11
12
13
"JSF-BZ-22000-31-T-944" #1672 daemon prio=5 os_prio=0 tid=0x00007f3234047800 nid=0x72f5 waiting for monitor entry [0x00007f2d9ece9000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:404)
	- waiting to lock <0x00000006c3893e80> (a java.lang.Object)
	at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:331)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
	at org.apache.logging.log4j.core.impl.ThrowableProxyHelper.loadClass(ThrowableProxyHelper.java:205)
	at org.apache.logging.log4j.core.impl.ThrowableProxyHelper.toExtendedStackTrace(ThrowableProxyHelper.java:112)

	// ...
	
   Locked ownable synchronizers:
	- <0x00000006c8cd5570> (a java.util.concurrent.ThreadPoolExecutor$Worker)

从堆栈可以看出，在log4j打印日志的过程中，调用ClassLoader.loadClass方法，导致线程Block。那就带来两个问题：

  1. 为什么log4j打印异常堆栈，会触发ClassLoader.loadClass方法的调用？
  2. ClassLoader.loadClass方法为什么需要加锁？

简化代码

我们简化一下线上代码，让大家更加容易跟上我们的思路。

1
2
3
4
5
public class MathUtil {
    public static int div(int a, int b) {
        return a / b;
    }
}

接口的主体逻辑是通过反射调用目标方法MathUtil.div()

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
@Slf4j
public class LogTest {

    public static void main(String[] args) {
        for (int i = 0; i < 50; i++) {
            Thread thread = new Thread(new Runnable() {
    
                @Override
                public void run() {
                    long start = System.currentTimeMillis();
                    for (int i = 0; i < 1000; i++) {
                        LogTest.run();
                    }
                    System.out.println("time:" + (System.currentTimeMillis() - start));
                }
            });
            thread.start();
        }
    }
    
    private static void run() {
        try {
            callDiv(1, 0);
        } catch (Exception e) {
            log.error("div error", e);
            e.printStackTrace();
        }
    }
    
    private static int callDiv(int a, int b) throws Exception {
        Method method = MathUtil.class.getMethod("div", new Class[]{int.class, int.class});
        return (int) method.invoke(null, a, b);
    }
}

log4j打印异常堆栈机制

在上面的例子中，写了两个打印异常堆栈的方式，我们先看一下这两种方式输出内容的差异。
log4j的Logger.error()

1
2
3
4
5
6
7
8
9
10
11
12
13
14
2023-11-11 11:25:00.010[ERROR]div error[com.jdl.shenji.sdk.predict.LogTest.run:42][]- 
java.lang.reflect.InvocationTargetException: null
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_161]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_161]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_161]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_161]
	at com.jdl.shenji.sdk.predict.LogTest.callDiv(LogTest.java:49) ~[classes/:?]
	at com.jdl.shenji.sdk.predict.LogTest.run(LogTest.java:40) ~[classes/:?]
	at com.jdl.shenji.sdk.predict.LogTest.access$000(LogTest.java:19) ~[classes/:?]
	at com.jdl.shenji.sdk.predict.LogTest$1.run(LogTest.java:29) ~[classes/:?]
	at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_161]
Caused by: java.lang.ArithmeticException: / by zero
	at com.jdl.shenji.sdk.predict.MathUtil.div(MathUtil.java:10) ~[classes/:?]
	... 9 more

e.printStackTrace()

1
2
3
4
5
6
7
8
9
10
11
12
13
java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.jdl.shenji.sdk.predict.LogTest.callDiv(LogTest.java:50)
	at com.jdl.shenji.sdk.predict.LogTest.run(LogTest.java:40)
	at com.jdl.shenji.sdk.predict.LogTest.access$000(LogTest.java:19)
	at com.jdl.shenji.sdk.predict.LogTest$1.run(LogTest.java:29)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.ArithmeticException: / by zero
	at com.jdl.shenji.sdk.predict.MathUtil.div(MathUtil.java:10)
	... 9 more

对比上面两种方式的结果，会发现Logger.error打印的堆栈信息更加完善，在每行堆栈信息后面多了对应类的辅助信息。JDK包中的类打印了JDK版本[?:1.8.0_161]，class path下的类打印了[classes/:?]，实际上如果存在其他jar文件中的类，还会打印类所在的jar文件名如[demo-1.0-SNAPSHOT.jar:?]。

log4j对应构建辅助信息在org.apache.logging.log4j.core.impl.ThrowableProxyHelper#toCacheEntry中

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
private static CacheEntry toCacheEntry(final Class<?> callerClass, final boolean exact) {
    String location = "?";
    String version = "?";
    ClassLoader lastLoader = null;
    if (callerClass != null) {
        try {
            CodeSource source = callerClass.getProtectionDomain().getCodeSource();
            if (source != null) {
                URL locationURL = source.getLocation();
                if (locationURL != null) {
                    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);
                }
            }
        } catch (Exception var10) {
        }
    
        Package pkg = callerClass.getPackage();
        if (pkg != null) {
            String ver = pkg.getImplementationVersion();
            if (ver != null) {
                version = ver;
            }
        }
    
        try {
            lastLoader = callerClass.getClassLoader();
        } catch (SecurityException var9) {
            lastLoader = null;
        }
    }
    
    return new CacheEntry(new ExtendedClassInfo(exact, location, version), lastLoader);
}

可以看到想要获得类所在位置的辅助信息，需要拿到Class对象，而堆栈对象StackTraceElement定义的declaringClass是String类型，想要得到相应的Class对象，必须使用Classloader进行类加载，从而触发了Classloader.loadClass方法的执行。

classload加载class锁机制

1. classloader.loadClass加锁过程分析

Classload调用loadClass进行类加载的过程是线程安全的，loadClass的代码如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
protected Class<?> loadClass(String name, boolean resolve)
    throws ClassNotFoundException
{
    // 加锁的地方！！
    synchronized (getClassLoadingLock(name)) {
        // 下面的代码不是我们这次问题需要关注的哈，可以忽略
        Class<?> c = findLoadedClass(name);
        if (c == null) {
            long t0 = System.nanoTime();
            try {
                if (parent != null) {
                    c = parent.loadClass(name, false);
                } else {
                    c = findBootstrapClassOrNull(name);
                }
            } catch (ClassNotFoundException e) {
                // ClassNotFoundException thrown if class not found
                // from the non-null parent class loader
            }

            if (c == null) {
                // If still not found, then invoke findClass in order
                // to find the class.
                long t1 = System.nanoTime();
                c = findClass(name);
    
                // this is the defining class loader; record the stats
                sun.misc.PerfCounter.getParentDelegationTime().addTime(t1 - t0);
                sun.misc.PerfCounter.getFindClassTime().addElapsedTimeFrom(t1);
                sun.misc.PerfCounter.getFindClasses().increment();
            }
        }
        if (resolve) {
            resolveClass(c);
        }
        return c;
    }
}

synchronized加锁的对象是通过getClassLoadingLock返回的

1
2
3
4
5
6
7
8
9
10
11
protected Object getClassLoadingLock(String className) {
    Object lock = this;
    if (parallelLockMap != null) {
        Object newLock = new Object();
        lock = parallelLockMap.putIfAbsent(className, newLock);
        if (lock == null) {
            lock = newLock;
        }
    }
    return lock;
}

通过分析getClassLoadingLock方法可以得出，loadClass的同步工作模式有两种

  • 串行，synchronized对象是Classloader的this对象，在串行模式下执行，当classloader在加载一个类的时候，其他线程要进行类加载的时候，都必须等待
  • 并行，synchronized对象是从parallelLockMap中根据className查询得到的Object对象，在并行模式下执行，类名完全相同的类还是串行加载，类名不同的类之间是并行加载，加载过程互不影响，这样可以提供加载效率
  • 可以通过调用ClassLoader.registerAsParallelCapable()方法注册为并行加载模式

2.classloader加载无效类效率问题

由于Classloader的加载机制，当Classloader去加载一个他无法加载的类时，loadClass的效率就会变得非常低下，举例说明：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
public class Test {

        private static int COUNTER = 100000;
    
        public static void main(String[] args) throws IOException, ClassNotFoundException {
            ClassLoader loader = ClassLoader.getSystemClassLoader();
            for (int i = 0; i < 1000; i++) {
                // 存在的类
                long time1 = tryLoadClass(loader, "com.jdl.shenji.sdk.predict.StartupRunner");
                // 不存在的类
                long time2 = tryLoadClass(loader, "org.example.sourcecode.threadblock.TryLoadClass2");
    
                System.out.println(time1 + " " + time2);
            }
        }
    
        public static long tryLoadClass(ClassLoader classLoader, String classFullName) {
            long start = System.currentTimeMillis();
            for (int i = 0; i < COUNTER; i++) {
                try {
                    classLoader.loadClass(classFullName);
                } catch (Exception e) {
    
                }
            }
            return System.currentTimeMillis() - start;
        }
}

上面代码执行结果：

jsf_block02
jsf_block02

org.example.sourcecode.threadblock.TryLoadClass2这个类不存在，加载效率比加载存在的类慢了几十倍。
加载过程执行的越慢，高并发的条件下，就越可能发生线程Block情况。

反射调用优化

我们直接从method.invoke跟进来
java.lang.reflect.Method#invoke

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
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);
        }
    }
    // 每个Method对象包含一个root对象，root对象里持有一个MethodAccessor对象
    // 我们获得的Method独享相当于一个root对象的镜像，所有这类Method共享root里的MethodAccessor对象
    MethodAccessor ma = methodAccessor;
    if (ma == null) {
        ma = acquireMethodAccessor();
    }
    return ma.invoke(obj, args);
}

MethodAccessor对象由ReflectionFactory方法生成
java.lang.reflect.Method#acquireMethodAccessor

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
private MethodAccessor acquireMethodAccessor() {
    // First check to see if one has been created yet, and take it
    // if so
    MethodAccessor tmp = null;
    if (root != null) tmp = root.getMethodAccessor();
    if (tmp != null) {
        methodAccessor = tmp;
    } else {
        // Otherwise fabricate one and propagate it up to the root
        tmp = reflectionFactory.newMethodAccessor(this);
        setMethodAccessor(tmp);
    }

    return tmp;
}

MethodAccessor有两个实现，一个是Java实现的，另一个是native实现的
sun.reflect.ReflectionFactory#newMethodAccessor

1
2
3
4
5
6
7
8
9
10
11
12
13
public MethodAccessor newMethodAccessor(Method var1) {
    checkInitted();
    if (noInflation && !ReflectUtil.isVMAnonymousClass(var1.getDeclaringClass())) {
        return (new MethodAccessorGenerator()).generateMethod(var1.getDeclaringClass(), var1.getName(), var1.getParameterTypes(), var1.getReturnType(), var1.getExceptionTypes(), var1.getModifiers());
    } else {
        // 一开始先是使用native的实现
        NativeMethodAccessorImpl var2 = new NativeMethodAccessorImpl(var1);
        // DelegatingMethodAccessorImpl实际上相当于一个代理，方便后续切换Java实现
        DelegatingMethodAccessorImpl var3 = new DelegatingMethodAccessorImpl(var2);
        var2.setParent(var3);
        return var3;
    }
}

JDK使用了inflation的技巧，让方法在被反射调用时，前15次使用native的实现，等反射调用次数超过阈值时则生成一个Java的MethodAccessor实现类，以后对该方法的反射调用就会使用Java的实现。这段逻辑在NativeMethodAccessorImpl的invoke方法中实现。
sun.reflect.NativeMethodAccessorImpl#invoke

1
2
3
4
5
6
7
8
public Object invoke(Object var1, Object[] var2) throws IllegalArgumentException, InvocationTargetException {
    if (++this.numInvocations > ReflectionFactory.inflationThreshold() && !ReflectUtil.isVMAnonymousClass(this.method.getDeclaringClass())) {
        MethodAccessorImpl var3 = (MethodAccessorImpl)(new MethodAccessorGenerator()).generateMethod(this.method.getDeclaringClass(), this.method.getName(), this.method.getParameterTypes(), this.method.getReturnType(), this.method.getExceptionTypes(), this.method.getModifiers());
        this.parent.setDelegate(var3);
    }

    return invoke0(this.method, var1, var2);
}

我们跟进来看下是如何生成一个MethodAccessor的Java对象的
sun.reflect.MethodAccessorGenerator#generateMethod

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
public MethodAccessor generateMethod(Class<?> var1, String var2, Class<?>[] var3, Class<?> var4, Class<?>[] var5, int var6) {
    return (MethodAccessor)this.generate(var1, var2, var3, var4, var5, var6, false, false, (Class)null);
}

private MagicAccessorImpl generate(final Class<?> var1, String var2, Class<?>[] var3, Class<?> var4, Class<?>[] var5, int var6, boolean var7, boolean var8, Class<?> var9) {
    // ...
    // 以上省略的代码主要是通过asm构建反射调用方法的一个字节码文件
    // 我们直接看重点方法
    return (MagicAccessorImpl)AccessController.doPrivileged(new PrivilegedAction<MagicAccessorImpl>() {
        public MagicAccessorImpl run() {
            try {
                return (MagicAccessorImpl)ClassDefiner.defineClass(var13, var17, 0, var17.length, var1.getClassLoader()).newInstance();
            } catch (IllegalAccessException | InstantiationException var2) {
                throw new InternalError(var2);
            }
        }
    });
}

直接看创建Class对象的地方：
sun.reflect.ClassDefiner#defineClass

1
2
3
4
5
6
7
8
static Class<?> defineClass(String var0, byte[] var1, int var2, int var3, final ClassLoader var4) {
    ClassLoader var5 = (ClassLoader)AccessController.doPrivileged(new PrivilegedAction<ClassLoader>() {
        public ClassLoader run() {
            return new DelegatingClassLoader(var4);
        }
    });
    return unsafe.defineClass(var0, var1, var2, var3, var5, (ProtectionDomain)null);
}

可以看到生成的Class对象是由DelegatingClassLoader加载的，到这里我们就可以得出结论，反射优化的动态生成的Class对象，是不能被其他Classloader加载的，结合Classloader加载无效类效率低下的问题，我们出现线程block的问题也就水落石出了。

问题总结

  1. 使用log4j的Logger.error去打印异常堆栈的时候，为了打印出堆栈中类的位置信息，需要使用Classloader进行类加载；
  2. Classloader加载是线程安全的，虽然并行加载可以提高加载不同类的效率，但是多线程加载相同的类时，还是需要互相同步等待，尤其当不同的线程打印的异常堆栈完全相同时，就会增加线程Block的风险，而Classloader去加载一个无法加载的类时，效率会急剧下降，使线程Block的情况进一步恶化；
  3. 因为反射调用效率问题，JDK对反射调用进行了优化，动态生成Java类进行方法调用，替换原来的native调用，而生成的动态类是由DelegatingClassLoader进行加载的，不能被其他的Classloader加载，异常堆栈中有反射优化的动态类，在高并发的条件下，就非常容易产生线程Block的情况。

问题处理

处理方式调用printStackTrace方法将异常堆栈转换为字符串，但是结果相比于log4j打印的日志信息就缺少了类所在位置的辅助信息，这是一个取舍的过程。

1
2
3
4
5
private static String convertStackTraceToString(Throwable throwable){
    StringWriter stringWriter = new StringWriter();
    throwable.printStackTrace(new PrintWriter(stringWriter));
    return stringWriter.toString();
}

结果对比异常堆栈转换为字符串方式

1
2
3
4
5
6
7
8
9
10
2023-10-30 16:08:24.158[ERROR]java.lang.reflect.InvocationTargetException
    at jdk.internal.reflect.GeneratedMethodAccessor2.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at com.jdl.shenji.sdk.predict.LogTest.callDiv(LogTest.java:44)
    at com.jdl.shenji.sdk.predict.LogTest.run(LogTest.java:35)
    at com.jdl.shenji.sdk.predict.LogTest.access$000(LogTest.java:16)
    at com.jdl.shenji.sdk.predict.LogTest$1.run(LogTest.java:24)
    at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.lang.ArithmeticException

log.error打印堆栈方式

1
2
3
4
5
6
7
8
9
10
11
2023-10-30 16:09:17.256[ERROR]div error[com.jdl.shenji.sdk.predict.LogTest.run:37][]- 
java.lang.reflect.InvocationTargetException: null
    at jdk.internal.reflect.GeneratedMethodAccessor2.invoke(Unknown Source) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
    at com.jdl.shenji.sdk.predict.LogTest.callDiv(LogTest.java:44) ~[classes/:?]
    at com.jdl.shenji.sdk.predict.LogTest.run(LogTest.java:35) ~[classes/:?]
    at com.jdl.shenji.sdk.predict.LogTest.access$000(LogTest.java:16) ~[classes/:?]
    at com.jdl.shenji.sdk.predict.LogTest$1.run(LogTest.java:24) ~[classes/:?]
    at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: java.lang.ArithmeticException: / by zero

对比结果发现是有些差异的，异常堆栈转换为字符串方式异常中丢失了message，即/ by zero

其实这个是和JVM的JIT相关的，对于这个情况有一个专业的术语叫：fast throw，在触发JIT之前堆栈、异常信息等是可以正常打印的，但是在执行了大概30 000次后，就开始丢失异常信息了。

堆栈等信息丢失只是表面现象，JIT实际上是这么做优化的：

  1. 创建需要抛出异常的实例
  2. 清空堆栈信息
  3. 将该实例缓存起来
  4. 之后再需要抛出的时候，将缓存实例抛出去

可以通过参数-XX:-OmitStackTraceInFastThrow关闭这一优化，但是对于性能会有比较大的影响，我执行了500 000次，fast throw处理时长是11802ms，而关闭了这个优化后处理时长涨到了32423ms，对于目前的场景，建议是打开优化，如果出现大规模异常的情况，可以搜索异常初期的日志，获得详细的异常信息。

压测结果

jsf_block03
jsf_block03