标签: JVM

Javassist结合JavaAgent修改Java.class文件字节码实践

续上一篇Javassist动态修改jar包内java类字节码,有了上一篇的基础之后我们再尝试结合JavaAgent来实现更加强大的AOP功能。

首先提一嘴JavaAgent。在 jdk 1.5 之后引入了 java.lang.instrument 包,该包提供了检测 java 程序的 Api,比如用于监控、收集性能信息、诊断问题,通过 java.lang.instrument 实现的工具我们称之为 Java Agent。

其基本原理可以理解为,当JVM在加载.class类文件的时候会触发ClassFileLoadHook回调JNI执行sun.instrument.InstrumentationImpl#transform方法,如果我们自己实现了ClassFileTransformer的transform方法,则会用transform方法返回的字节码内容替换掉原来读取到的.class文件的字节码。https://www.cnblogs.com/yichengtech/p/15854415.html

接下来我们来自己做一个简单的实现,顺便结合之前文章中的Javassist工具做一点“有意思”的事情。

创建Agent Jar包

创建一个新的工程,代码结构基本如下。一个MyAgent入口类、一个名为MyClassFileTransformer的ClassFileTransformer接口实现类

两个类的对应实现代码,首先是MyAgent类,在这里写一个premain方法,并在这里引入我们下面要实现的MyClassFileTransformer类

package com.myagent;

import java.lang.instrument.Instrumentation;

/**
 * MyAgent<br>
 *
 * @author CheungQ
 * @date 2023/3/15 16:43
 */
public class MyAgent {
    public static void premain(String agentArgs, Instrumentation inst) {
        System.out.println("premain begin");
        inst.addTransformer(new MyClassFileTransformer());
    }
}

而在MyClassFileTransformer类中实现了ClassFileTransformer接口,并在transform方法中实现我们自己的逻辑。先判断一下当前加载的类,如果不需要调整修改的则直接return null即可。此处我们假设需要修改com.cheungq.demo.service.RedisService这个类

Continue reading

一个SafePoint和STW的问题

起因是前几天看的一篇文章,里面贴了一段代码,大意如下

public class SafePointTest {

    public static AtomicInteger num = new AtomicInteger(0);

    public static void main(String[] args) throws InterruptedException {
        Runnable runnable = ()->{
            for (int i = 0; i < 1000000000; i++) {
                num.getAndAdd(1);
            }
            System.out.println(Thread.currentThread().getName()+"执行结束!");
        };

        Thread t1 = new Thread(runnable);
        Thread t2 = new Thread(runnable);
        t1.start();
        t2.start();
        Thread.sleep(1000);
        System.out.println("num = " + num);
    }
}

执行之后输出如下,环境为Java8,没有添加其他jvm参数

从上面的结果可以看到,主线程在`Thread.sleep(1000)`的睡眠1秒之后并没有能直接执行下一步的sout代码,来输出num的的值,而是一直“阻塞”等到两个线程的for循环结束之后,才执行了sout输出代码。所以,我们可以很明显的猜测到,是这两个for循环的执行,对主线程的Thread.sleep产生了影响,让主线程未能从sleep的TIMED_WAITING状态返回RUNNABLE状态,我们可以改造下代码,观察下主线程的状态

略有点粗糙的改造,不过可以大致看到Thread.sleep之后主线程的状态变化,代码如下

public class SafePointTest {

    public static AtomicInteger num = new AtomicInteger(0);

    public static void main(String[] args) {
        Runnable runnable = new Runnable() {
            @Override
            public void run() {
                Runnable r = () -> {
                    for (int i = 0; i < 1000000000; i++) {
                        num.getAndAdd(1);
                    }
                    System.out.println(Thread.currentThread().getName() + "执行结束!");
                };
                Thread t1 = new Thread(r);
                Thread t2 = new Thread(r);
                t1.start();
                t2.start();
                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                System.out.println("num = " + num);
            }
        };
        long time = System.currentTimeMillis();
        Thread t = new Thread(runnable);
        System.out.println((System.currentTimeMillis()-time) +" \t"+ t.getState());
        t.start();
        System.out.println((System.currentTimeMillis()-time) +" \t"+ t.getState());
        Thread.State state = t.getState();
        while (t.isAlive()){
            Thread.State currentState = t.getState();
            if (state.compareTo(currentState) != 0){
                System.out.println((System.currentTimeMillis()-time) +" \t"+ currentState);
                state = currentState;
            }
        }
        System.out.println((System.currentTimeMillis()-time) +" \t"+ t.getState());
    }
}

运行得到结果如下

也有可能获取到主线程(t)最后进入到BLOCKED状态的情况,如下

看下Thread.State的源码,BLOCKED状态的说明,我们可以看到如下注释内容,竞争锁资源的失败,加入等待锁的同步阻塞队列,进入阻塞状态。

Thread state for a thread blocked waiting for a monitor lock. A thread in the blocked state is waiting for a monitor lock to enter a synchronized block/method or reenter a synchronized block/method after calling

看到锁,回头来看下刚才的代码,那么我们很自然的想到了sout方法中其实是有个锁的

那么这里出现主线程(t)BLOCKED状态很明显就是在和子线程(t1、t2)以及当前的main函数的线程,3个线程同时竞争打印锁的时候没有竞争成功而进入了阻塞状态。测试下,把t线程和t1、t2线程中的sout方法同时注释掉。这样就只有main函数的线程需要占用打印锁,多次运行之后均没有发现t线程出现BLOCKED状态的情况,在没有注释之前,主线程(t)进入BLOCKED的情况还是比较频繁容易出现的。

好了,BLOCKED的问题搞清楚之后,我们重新回到原来的问题之上,根据输出的内容,我们可以看到主线程(t)在sleep之后进入TIMED_WAITING状态,直到两个子线程(t1、t2)都执行结束的时候才恢复到RUNNABLE状态。

不卖关子,我们直接说结论

SafePoint

这就是产生这个现象的原因,JVM有个参数-XX:GuaranteedSafepointInterval,作用是控制所有线程进入SafePoint的时间间隔,默认是

-XX:GuaranteedSafepointInterval=1000

即每隔1000毫秒,所有线程进入一次SafePoint。如果有线程无法进入SafePoint,那么其他线程一直等待,直到所有线程都进入SafePoint了,再立刻从SafePoint中恢复。那么,什么是SafePoint呢?

Safepoint 可以理解成是在代码执行过程中的一些特殊位置当线程执行到这些位置的时候,线程可以暂停。线程在执行的时候,如果JVM要STW,暂停线程的执行,线程并不是可以在任意地方立刻暂停下来的,这可能和我们直觉有点不一样,在日常开发中,我们可以在代码的任意地方添加断点,从而让程序在断点的地方停下来。这个断点其实就是我们在代码中强制添加的SafePoint,稍后我们会再提到。

在我们的Java代码编写完之后,开始执行代码,理论上,JVM可以在每条字节码的边界都可以放一个SafePoint,但是更多的SafePoint就意味着需要更多的占用内存空间,因为在SafePoint中需要保存当前线程的各种上下文信息,因为随时可能在这个SafePoint处暂停。同时也会生成polling代码询问JVM是否要“进入SafePoint”,而polling操作也是有开销的。不同的 JVM 选用不同的位置放置 SafePoint。

通过JIT的优化,只在部分地方放置SafePoint。其中一个情况需要事先了解下,比如我们上面的例子中的for循环的counted loop的循环(可数循环),特指这种for ( int )的循环,相应的long类型的并不是,算作是uncounted loop(不可数循环),在我们使用的Java8版本中,JIT会认为counted loop较小,不会再循环中添加SafePoint。所以我们知道上面的代码中for (int i = 0; i < 1000000000; i++)的循环体内部是没有SafePoint的。

当然也有其他需要添加SafePoint的情况,根据之前RednaxelaFX的说法(see https://www.zhihu.com/question/29268019/answer/43762165

而在JIT编译的代码里,HotSpot会在所有方法的临返回之前,以及所有非counted loop的循环的回跳之前放置safepoint。

另外我们需要知道一点(see https://zhuanlan.zhihu.com/p/161710652

当运行 native 代码时,VM 线程略过这个线程,但是给这个线程设置 poll armed,让它在执行完 native 代码之后,它会检查是否 poll armed,如果还需要停在 SafePoint,则直接 block

回到我们当前的代码中,我们看原来的第一版代码,主线程在t1、t2线程启动之后,执行了一个Thread.sleep(1000);,而Thread.sleep方法就是一个native方法,进入native方法后主线程不受JVM控制,而等待1000毫秒

1000毫秒之后。尝试回到JVM环境的控制中,需要检查SafePoint的状态,但是根据JVM的默认设定-XX:GuaranteedSafepointInterval=1000,每1000毫秒所有线程应当进入SafePoint一次,那么当前主线程应当进入SafePoint,此时两个子线程t1、t2还在进行1000000000的循环当中,这里的循环当中没有SafePoint,无法暂停,必须等到循环结束。

所以此时主线程就一直卡在当前这个状态,直到t1、t2两个线程执行完for循环进入了SafePoint。

为了验证上面的想法,我们再次修改下初版的代码,如下

public class SafePointTest {

    public static AtomicInteger num = new AtomicInteger(0);

    public static void main(String[] args) throws InterruptedException {
        Runnable runnable = () -> {
            for (int i = 0; i < 1000000000; i++) {
                num.getAndAdd(1);
            }
            System.out.println(Thread.currentThread().getName() + "执行结束!");
        };

        Thread t1 = new Thread(runnable);
        Thread t2 = new Thread(runnable);
        t1.start();
        t2.start();
        tryMakeSafePoint();
        System.out.println("num = " + num);
    }

    private static void tryMakeSafePoint() {
        int i = 0;
        for (; i < 10000000; i++) {
        }
        System.out.println(1);
    }
}

我们新增了一个tryMakeSafePoint方法,尝试强制添加一个SafePoint,怎么添加呢?我们在System.out.println(1);这里打上一个断点。同时,为了不触发这个断点,我们给这个断点设置一个条件

当i==0的时候才触发断点,那么根据当前的条件,这个断点永远都不会触发。在这里我们需要知道,我们打的断点,本质上就是强制在对应代码行的位置添加了一个SafePoint,并让当前程序运行的时候停止在这个SafePoint。所以在这个SafePoint的位置,我们可以通过debug查看到当前线程的上下文,各种变量等。另外为了排除定时进入SafePoint参数的影响,我们给JVM添加参数-XX:GuaranteedSafepointInterval=100000,把定时进入SafePoint的时间配置为100秒,排除这项的影响,因为子线程t1、t2最终执行完也只需要不到30秒

所以主线程在现在的断点位置进入SafePoint,并停在SafePoint,等待其他线程进入SafePoint。

那么接下来跑一下debug看下结果。

可以看到,结果确实如我们所预测的那样

下一步,我们重新回到初版代码,再进一步验证,我们给JVM在添加两个新的参数,现在的参数如下(默认定时每1000毫秒进入一次SafePoint)

-XX:+SafepointTimeout
-XX:SafepointTimeoutDelay=1000

这两个参数用于控制启用进入SafePoint的超时提示机制,以及超时的时间。运行得到如下结果

从打印出来的结果,可以看到JVM检测到两个线程(Thread-0和Thread-1)在尝试定时进入SafePoint的时候超时了,并不包含主线程,因为主线程从native代码回来后直接进入SafePoint了。

再一次修改JVM参数,如下

-XX:+SafepointTimeout
-XX:SafepointTimeoutDelay=1000
-XX:+PrintSafepointStatistics
-XX:PrintSafepointStatisticsCount=1

我们新增了PrintSafepointStatistics参数,-XX:+PrintSafepointStatistics –XX:PrintSafepointStatisticsCount=1这两个参数可以强制JVM打印safepoint的一些统计信息,运行后可以看到如下结果

打印出来的spin值指的是SafepointSynchronize在同步每个线程时做的自旋。(see https://www.cnblogs.com/liboware/p/15431232.html)即,主线程等待两个子线程t1、t2进入SafePoint的时候进行自旋花费了25.8秒,又主线程之前sleep了1000毫秒,总时间也就是这边显示的大概26.9秒

不过从上面的结果中我们还看到了在SafePoint中进行的一些其他操作EnableBiasedLocking、RevokeBias,这两个就是JVM在SafePoint中进行的启用和取消偏向锁相关的操作

摒除这部分信息,我们在JVM参数中再加一条

-XX:-UseBiasedLocking

再跑一遍加了断点的代码看下,可以看到

多了ForceSafepoint,不过ForceSafepoint的相关信息我搜了下却非常少,不过这也是我断定打的断点就是强制在对应的代码处添加了SafePoint的原因,有兴趣的同学可以继续深入探索下。

饶了几圈兜兜转转,我们再次回到这个问题本身,要解决这个问题也很简单,

  1. 把int的for循环修改为long的就可以,因为long的属于uncounted loop(不可数循环),其中可以插入SafePoint
  2. 使用-XX:+UseCountedLoopSafepoints 参数去强制在可数循环中也放置安全点,不过这个参数在 JDK 8 下有 Bug,有导致虚拟机崩溃的风险
  3. 居官方说法,JDK10之后修复了这个问题,我电脑上只有18,索性我就直接拿18跑了下看下

输出字符集有点问题,不过不影响我们看到结果主线程在sleep了1000毫秒后正确输出了结果

另外还看到了一个有趣的操作,又想加SafePoint,又不想让代码每次都检查SafePoint,在遍历循环中,手动插入能进入SafePoint的代码,并只在一定的情况下才进入这个SafePoint,这也是我写本文的起因

这个代码片段出自 RocketMQ 的源码

相关文章https://mp.weixin.qq.com/s/JQgzDAuCcVL0AAHEvtI_-g

而进行相关搜索的时候我也发现有文章提到STW时间过长,发现清理时间其实很短,但是等待某些线程进入SafePoint的时间很长,而导致整个STW时间过长的问题