性能文章>JAVA 变量的作用域真的是代码块吗?>

JAVA 变量的作用域真的是代码块吗?原创

7月前
205633

        近期,笔者在生产环境中发现了一个问题,客户在上传文件的时候使用SDK上传,程序在线上稳定跑了一天半,通过一个定时任务不停的上传文件,但是某个时刻后,所有的上传请求都开始报错,报错内容则是上传的流被关闭了。笔者首先对服务端的日志,监控等数据进行排查,排除了服务端关闭流的可能性,然后开始对客户的代码和SDK进行分析,通过逐步排查,发现SDK中重写了一个类的finalize方法,在finalize方法中存在关流的操作。

        直觉上判断,问题可能出现在这个finalize方法中,但是我们都知道,finalize方法只有在对象不可达,即将被回收前才会执行,而这个类在客户的代码中仍然是可达的,其所在的代码块并未执行完,就触发了finalize方法。

        如果真的是finalize方法,那岂不是说明变量引用的对象在其代码块中都是危险的,有被回收的风险?

        排查到这里,笔者发现,这个问题似乎并没有那么简单,将同样的代码和环境变量拿到测试环境进行验证,但始终无法复现问题。测试环境一切都正常,而产线仍然在不停的报错上传失败。

        既然在测试环境无法复现,就不能轻易下结论,笔者又仔细复盘了下问题的现象,发现有一点被忽略了,客户的程序在线上稳定跑了一天半都没有出现问题,是否是因为在测试环境跑的案例量不够大,又或者是测试环境的并发量不够大导致无法复现,之后再测试环境增加了更多的测试数据进行测试,但仍然无法复现。

        那会不会是跑的不够久?还真有这个可能,因为笔者之前在对JVM源码分析的时候接触到了一些关于JIT即时编译的知识,于是就大胆猜想,会不会是同样的代码,跑的次数达到了JIT即时编译的阈值,其对代码进行了编译优化,导致对象被回收,执行了finalize方法,提前关闭了流。

        为了更直观的看问题,笔者准备了一段伪代码模拟客户的代码:

Test类:

public class Test {

    public static void main(String[] args) {
        test();
    }

    //模拟客户的调用方法
    public static void test() {
        //创建一个finalize类
        FinalizeTest finalizeTest = new FinalizeTest();
        try {
            //在同一个代码块中执行循环,但不使用finalize引用
            int i = 0;
            do {
                i++;
                //手动执行gc,观察是否触发finalize方法
                System.gc();
            }while (i < 1000);
        }catch (Exception e) {
            System.out.println("exception");
        }finally {
            System.out.println("finally");
        }
    }
}

FinalizeTest类:

public class FinalizeTest {

    String name;

    public FinalizeTest() {}

    public FinalizeTest(String name) {
        this.name = name;
    }

    //重写finalize方法
    @Override
    protected void finalize() throws Throwable {
        System.out.println("finalize function run");
    }
}

        正常情况下执行这段代码,发现永远不输出“finalize function run”,但是当笔者在JVM参数中添加以下三个参数,让JVM完全使用JIT的编译模式:

            -Xcomp                               直接将代码翻译成机器码,使用编译模式

            -XX:TieredStopAtLevel=1    仅使用JIT C1编译

            -XX:CompileThreshold=1    即时编译阈值设置为1

        神奇的事情发生了,每次执行,都会在代码块执行完之前,输出“finalize function run”。有兴趣的读者可以用代码自己执行下。

        现在基本可以确定同样的一段代码,JVM使用编译模式,编译出的机器码和JVM使用解释模式编译出的字节码执行的结果不一样。可以确定确实是JIT进行编译的时候会对代码进行优化,导致提前执行finalize方法了。

        这个发现有点颠覆了大家以前的认知,局部变量的声明周期是代码块,这是我们一般的常识,事实上,使用字节码进行解释编译的执行结果确实也是这样的。但是为什么使用JIT即时编译产生的结果就不一样了呢?

        为了探究问题的本质,笔者继续进行分析,在JVM参数中又添加了两个参数:

                -XX:+UnlockDiagnosticVMOptions

                -XX:+PrintAssembly

        这两个参数可以打印出JVM的编译信息,我们借助hsdis插件(官方的反汇编插件,有兴趣的读者可以自行搜索)将编译好的汇编命令打印出来,然后使用JITWatch进行分析(由于汇编命令比较多,笔者仅挑出部分重要的):

        

//test方法编译结果
# {method} {0x00000159c8be04d8} 'test' '()V' in 'Test'
#           [sp+0x50]  (sp of caller)
[Entry Point]
0x00000159b4ceed40: mov %eax,-0x6000(%rsp)
//入栈
0x00000159b4ceed47: push %rbp
0x00000159b4ceed48: sub $0x40,%rsp
0x00000159b4ceed4c: nopl 0x0(%rax)
             L0000: jmpq L000f  ;   {no_reloc}
0x00000159b4ceed55: add %al,(%rax)
0x00000159b4ceed57: add %al,(%rax)
0x00000159b4ceed59: add %ch,%cl
0x00000159b4ceed5b: nop
0x00000159b4ceed5c: add %eax,(%rax)
//执行new关键字
0x00000159b4ceed5e: add %cl,-0x75(%rax)  ;*new  ; - Test::test@0 (line 8)
0x00000159b4ceed61: rorb -0x77(%rax)  ;*invokespecial <init>
                                      ; - Test::test@4 (line 8)
0x00000159b4ceed64: rex
//可以理解为调用Finalize的初始化方法
//注意这里的OopMap,其中有一个变量位于偏移量32处——指向一个对象
0x00000159b4ceed67: callq 0x00000159b4b261a0  ; OopMap{[32]=Oop off=44}
                                              ;*invokespecial <init>
                                              ; - Test::test@4 (line 8)
                                              ;   {optimized virtual_call}
0x00000159b4ceed6c: mov $0x0,%esi  ;*iinc
                                   ; - Test::test@10 (line 12)
0x00000159b4ceed71: nopl 0x0(%rax)
             L0002: inc %esi
0x00000159b4ceed7a: mov %esi,0x28(%rsp)
0x00000159b4ceed7e: nop
//调用静态方法gc(),此时OopMap中的变量没有了
0x00000159b4ceed7f: callq 0x00000159b4b26620  ; OopMap{off=68}
                                              ;*invokestatic gc
                                              ; - Test::test@13 (line 13)
                                              ;   {static_call}
0x00000159b4ceed84: nop  ; OopMap{off=69}
                         ;*if_icmplt
                         ; - Test::test@20 (line 14)
0x00000159b4ceed85: test %eax,-0x1fbec8b(%rip)  # 0x00000159b2d30100
                                                ;   {poll} *** SAFEPOINT POLL ***
0x00000159b4ceed8b: mov 0x28(%rsp),%esi
0x00000159b4ceed8f: cmp $0x3e8,%esi
0x00000159b4ceed95: jl L0002  ;*if_icmplt
                              ; - Test::test@20 (line 14)
0x00000159b4ceed97: nop
             L0003: jmpq L0010  ;   {no_reloc}
0x00000159b4ceed9d: add %al,(%rax)
0x00000159b4ceed9f: add %al,(%rax)
0x00000159b4ceeda1: add %ah,0xf(%rsi)
0x00000159b4ceeda4: (bad)
0x00000159b4ceeda5: add %r8b,(%rax)
             L0005: jmpq L0011  ; implicit exception: dispatches to 0x00000159b4ceef63
0x00000159b4ceedad: nop
0x00000159b4ceedae: nop  ;*getstatic out
                         ; - Test::test@23 (line 18)
0x00000159b4ceedaf: cmp (%rdx),%rax  ; implicit exception: dispatches to 0x00000159b4ceef7e
0x00000159b4ceedb2: movabs $0xd63a78f0,%r8  ;*invokevirtual println
                                            ; - Test::test@28 (line 18)
                                            ;   {oop(&quot;finally&quot;)}
0x00000159b4ceedbc: nop
0x00000159b4ceedbd: movabs $0xffffffffffffffff,%rax
0x00000159b4ceedc7: callq 0x00000159b4b263e0  ; OopMap{off=140}
                                              ;*invokevirtual println
                                              ; - Test::test@28 (line 18)
                                              ;   {virtual_call}
0x00000159b4ceedcc: add $0x40,%rsp
//出栈
0x00000159b4ceedd0: pop %rbp
0x00000159b4ceedd1: test %eax,-0x1fbecd7(%rip)  # 0x00000159b2d30100
                                                ;   {poll_return} *** SAFEPOINT POLL ***

代码比较多,我们重点看下OopMap,OopMap的含义为:

被JIT编译过的方法会在一些地方记录下OopMap,记录了执行到该方法的某条指令的时候,栈上和寄存器里哪些位置是引用。这样GC在扫描栈的时候就会查询这些OopMap就知道哪里是引用了。

我们可以看到,在new完finalize之后 OopMap中是有一个引用指向对象的,而在执行到手动GC方法时,OopMap中的引用没有了,所以我们可以得出结论,JIT使用C1进行即时编译时,会对代码进行优化,如果引用在后面没有使用,则可能不被记录在OopMap映射表中,从而被GC回收。

至此,这个问题算是告一段落了,笔者使用客户的代码在测试环境使用C1编译执行了几遍后,就复现了相同的报错,再结合实际产线上的问题,我们也可以解释原因了,一开始的一天半,JVM使用的是解释模式,使用字节码执行相关的方法,但是因为是定时任务执行相同的代码块,当执行到一定次数达到即时编译的阈值后,就会触发即时编译,现在来看应该是触发了C1的编译方式,导致代码被优化,被引用对象的生命周期改变,JVM本意是希望更精细化管理对象,但是由于有人重写了finalize方法,导致了问题的发生。

看来有时候我们对于JVM的一些特性不了解,可能就会导致代码产生一些不可估量的结果与问题,所以学习JVM的一些特性和知识还是很有必要的。

点赞收藏
自成溪
请先登录,查看3条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

聊聊数据库连接池 Druid

聊聊数据库连接池 Druid

一次 GDB 源码角度分析 jvm 无响应问题

一次 GDB 源码角度分析 jvm 无响应问题

日常Bug排查-集群逐步失去响应

日常Bug排查-集群逐步失去响应

浅析AbstractQueuedSynchronizer

浅析AbstractQueuedSynchronizer

3
3