爱理财boss系统运行速度调优

         Java与C++之间有一堵由内存动态分配和垃圾收集技术所围成的“高墙”，墙外面的人想进去，墙里面的人却想出来。

        天弘基金的爱理财app已经积累了220w用户，当一个应用的体量变得越来越大，优化就变成了必不可少的一部分。这篇文章与读者分享一下爱理财后台管理系统（boss系统）的调优案例。

        一、调优前的程序运行状态

        爱理财boss系统，本质上是运行在jetty容器中的web服务，为了要与调优后的结果进行量化对比，调优开始前先做一次初始数据测试，测试用例很简单，就是收集从boss系统发布开始，直到应用启动完成为止jvm的运行数据，以及运行一个excel批量导入接口时jvm的运行数据。

        先说系统启动时jvm的运行数据，虚拟机的运行数据通过VisualVM及其扩展插件VisualGC进行采集。测试过程中反复启动数次boss系统直到测试结果稳定后，取最后一次运行的结果作为数据样本（为了避免操作系统未能及时进行磁盘缓存而产生的影响），数据样本如图1所示。

图1

 

        根据VisualGC收集到的信息，总结原始配置下的测试结果如下。
        1、最后一次启动的数据样本中，垃圾收集总耗时880.76ms，其中：
             ●Full GC被触发了3次，共耗时418.39ms。
             ●Minor GC被触发了16次，共耗时462.457ms。
        2、加载类7225个，耗时6.358秒。
        3、JIT编译时间为23.997秒。
        4、虚拟机1170M的堆内存被分配为531.5MB的新生代（318.5MB的Eden空间和两个106.5MB的Surviver空间）以及638.5MB的老年代。

        boss系统运行excel批量导入接口时，总耗时和非用户程序时间的数据样本如图2，图3所示。

图2

图3

        根据VisualGC收集到的信息和系统日志，测试结果如下。

        1、excel批量导入功能总耗时58.104秒。
        2、调用接口过程中垃圾收集总耗时1.097s，在启动结束后多做了4次Minor GC
        3、加载类10189个，耗时7.148秒。
        4、JIT编译时间为43.673秒。

        boss系统运行的环境为2核4g的蚂蚁金融云centos虚拟机，从VisualGC中反映的数据来看，boss系统启动时非用户程序时间（图1和图2中的Compile Time、Class Load Time、GC Time）占用了很长的时间。在在虚拟机后台占用太多时间也直接导致boss系统在启动后的使用过程中经常有不时停顿的感觉，所以进行调优有较大的价值。

        二、编译时间和类加载时间的优化

        从图1得知，boss项目启动时非用户时间耗时最长的为编译时间和类加载时间。我们先从这两个主要耗时的地方找一下优化方案：

        类加载生命周期：

    a. 装载（load）
        i. 开始时机：
            1) new实例化对象时，若类没有加载
            2) 读取或设置一个类static字段，若类没有被加载。final除外，因为final字段的值已经在编译期放到了常量池中
            3) 调用类的static方法
            4) 反射调用类
            5) 初始化一个类时，若父类没有被加载，会先加载父类
        ii. 不会加载类的情况
            1) 通过子类去引用父类的static字段，不会导致子类加载
            2) 数组定义引用类，不会导致类加载。 如 Student[] stu = new Student[10], student类不会被加载
            3) 读取类的final字段，不会导致类加载。
        iii. 流程
            1) 通过类的全限定名获取定义此类的二进制流。可以从class文件，网络，或者运行时计算（如动态代理）出这个二进制流
            2) 将字节流代表的static存储结构转化为方法区的运行时数据结构，也就是存储到方法区中
            3) 内存中生成一个代表此类的class对象
    b. 链接
        i. 验证
            1) 目的：防止加载的class文件危害虚拟机本身安全
            2) 流程：
                a) 文件格式验证，如magic是否为0xCAFEBABE，主次版本号是否在当前VM能处理范围内
                b) 元数据验证，主要验证描述信息是否符合Java语言规范
                c) 字节码验证，最复杂，通过数据流和控制流分析，确定程序语义是合法的，符合逻辑的
                d) 符号引用验证，如通过全限定名能否找到类，字段方法的可访问性等。
        ii. 准备
            1) 目的：为static变量分配内存，并将它们统一初始化为0. static final除外
        iii. 解析
            1) 目的：将常量池中的符号引用替换为直接引用
                a) 符号引用：字面量，如类名，方法名等
                b) 直接引用：类或方法存放在内存中的地址
    c. 初始化
        i. 初始化static变量为实际的值。通过执行类构造器<clint>方法来完成。这个方法是编译器自动生成在字节码中的
        ii. clinit：
            1) static变量的赋值 + static{}语句块。 static{}语句块只能访问到定义在它之前的变量。
            2) clinit和实例构造器init不同，不需要显式调用父类构造器。JVM保证子类的clinit执行前，父类的clinit肯定被执行过
            3) 父类的clinit先执行，故父类中的static{}语句块在子类的static变量赋值前被调用
            4) 接口中不能使用static{}语句块，但仍然可以为变量赋值
            5) JVM可以保证clinit方法是线程安全的。多个线程同时去初始化一个类，只有一个线程会执行clinit方法，其他都会阻塞等待。

        累的装载阶段和初始化阶段我们无法干预，在链接阶段的三步中准备步骤和解析步骤也是必不可少。考虑到实际情况：boss系统的war包是通过公司内jekins编译生成，jetty使用者甚多，它的编译代码我们可以认为是可靠的，不需要在加载的时候再进行字节码验证，因此通过参数-Xverify:none禁止掉字节码验证过程也可作为一项优化措施。加入这个参数后，boss系统在启动时的启动数据如图4：

图4

    使用字节码验证与不使用字节码验证的优化时间对比：

        使用字节码验证后的类加载时间：

        

        不使用字节码验证后的类加载时间：

        

    我们发现不使用字节码验证后boss系统的启动速度比之前快了2.5秒，为系统带来了一些性能提升。

        除了类加载时间以外，在VisualGC的监视曲线中显示了另一项很大的非用户程序耗时：编译时间（Compile Time）。编译时间是指虚拟机的JIT编译器编译热点代码的耗时。Java语言为了实现跨平台的特性，Java代码编译出来后形成的Class文件中存储的是字节码，虚拟机通过解释方式执行字节码命令，比起C/C++编译成本地二进制代码来说，速度要慢不少。为了解决程序解释执行的速度问题，虚拟机内置了两个运行时编译器，如果一段Java方法被调用次数达到一定程度，就会被判定为热代码交给JIT编译器即时编译为本地代码，编译需要消耗程序正常的运行时间，也就是编译时间。

        jvm提供了-Xint参数禁止JIT编译，这种杀鸡取卵的方式是不可取的，使用了-Xint参数后，编译时间下降到了0，单批量插入的接口调用总耗时变成了150秒，目前来看想通过缩短虚拟机JIT编译的时间提高运行速度的方式不可行。

        三、调整内存设置控制垃圾收集频率

        非用户程序时间中，还剩下GC时间没有调整，GC时间却是java系统非用户程序事件中最重要的一块，因为它是一个稳定持续的过程。由于我们做的测试是在测程序的启动时间，和单一接口的调用时间，所以类加载和编译时间在这项测试中的影响力被大幅度放大了。在绝大多数的应用中，不可能出现持续不断的类被加载和卸载。在程序运行一段时间后，热点方法被不断编译，新的热点方法数量也总会下降，但是垃圾收集则是随着程序运行而不断运作的，所以它对性能的影响才显得尤为重要。

        我们直接从GC日志中分析一下boss系统中的minor gc和full gc是如何产生的：

0.802: [GC [PSYoungGen: 15360K->2534K(17920K)] 15360K->4419K(58368K), 0.0091330 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
1.178: [GC [PSYoungGen: 17894K->2551K(33280K)] 19779K->4988K(73728K), 0.0080680 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
1.312: [GC [PSYoungGen: 33244K->2168K(33280K)] 35681K->4676K(73728K), 0.0064580 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
1.534: [GC [PSYoungGen: 32888K->2168K(64000K)] 35396K->4676K(104448K), 0.0068860 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
1.847: [GC [PSYoungGen: 63608K->2328K(64000K)] 66116K->4836K(104448K), 0.0075480 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
4.603: [GC [PSYoungGen: 63768K->2840K(126976K)] 66276K->5356K(167424K), 0.0112090 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
6.632: [GC [PSYoungGen: 125720K->4576K(127488K)] 128236K->31786K(167936K), 0.0394160 secs] [Times: user=0.05 sys=0.01, real=0.03 secs] 
6.672: [Full GC [PSYoungGen: 4576K->0K(127488K)] [ParOldGen: 27209K->28310K(64512K)] 31786K->28310K(192000K) [PSPermGen: 9490K->9453K(21504K)], 0.0952790 secs] [Times: user=0.16 sys=0.00, real=0.10 secs] 
8.022: [GC [PSYoungGen: 122880K->17404K(216576K)] 151190K->56530K(281088K), 0.0423470 secs] [Times: user=0.05 sys=0.01, real=0.05 secs] 
9.572: [GC [PSYoungGen: 216572K->25572K(254976K)] 255698K->99064K(328704K), 0.0654460 secs] [Times: user=0.08 sys=0.01, real=0.07 secs] 
9.637: [Full GC [PSYoungGen: 25572K->0K(254976K)] [ParOldGen: 73492K->73142K(133632K)] 99064K->73142K(388608K) [PSPermGen: 9461K->9459K(21504K)], 0.1431700 secs] [Times: user=0.24 sys=0.00, real=0.14 secs] 
11.089: [GC [PSYoungGen: 229376K->44539K(259072K)] 302518K->127289K(392704K), 0.0825660 secs] [Times: user=0.08 sys=0.02, real=0.08 secs] 
13.533: [GC [PSYoungGen: 259067K->38203K(252928K)] 341817K->151321K(386560K), 0.0859670 secs] [Times: user=0.16 sys=0.01, real=0.09 secs] 
13.619: [Full GC [PSYoungGen: 38203K->0K(252928K)] [ParOldGen: 113117K->95891K(173056K)] 151321K->95891K(425984K) [PSPermGen: 14776K->14772K(25088K)], 0.2183000 secs] [Times: user=0.42 sys=0.01, real=0.22 secs] 
17.131: [GC [PSYoungGen: 214528K->14529K(270336K)] 310419K->110420K(443392K), 0.0266560 secs] [Times: user=0.04 sys=0.00, real=0.03 secs] 
18.915: [GC [PSYoungGen: 224961K->7865K(218624K)] 320852K->103764K(391680K), 0.0290080 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
21.433: [GC [PSYoungGen: 218297K->13869K(268800K)] 314196K->109769K(441856K), 0.0722460 secs] [Times: user=0.13 sys=0.00, real=0.08 secs] 
685.158: [GC [PSYoungGen: 227373K->34562K(265728K)] 323273K->130461K(438784K), 0.0559120 secs] [Times: user=0.09 sys=0.00, real=0.05 secs] 
702.625: [GC [PSYoungGen: 248066K->21341K(271872K)] 343965K->117240K(444928K), 0.0353460 secs] [Times: user=0.07 sys=0.00, real=0.04 secs] 
724.756: [GC [PSYoungGen: 240989K->21517K(271872K)] 336888K->117416K(444928K), 0.0390940 secs] [Times: user=0.07 sys=0.00, real=0.04 secs]

        新生代中的Minor GC，GC的总时间只有0.6秒，但却发生了20次，从日志中可以看到，新生代gc的发生，伴随着多次新生代的空间扩容，新生代大小由开始的17920K扩大到271872K。老年代的full gc，总共发生了三次，伴随着一次老年代的扩容，boss系统启动完成后，老年代容量达到峰值638.5MB，而前两次的full gc过程中，回收前后的内存占用分别为[ParOldGen: 27209K->28310K(64512K)] 和 [ParOldGen: 73492K->73142K(133632K)]，这两次回收只是做了扩容，并没有起到什么回收效果，时间相当于白白浪费。

        上述分析可以得出结论：boss系统启动时，Full GC容量扩展和永久代空间扩展会导致无意义的性能浪费。为了避免这些扩展所带来的性能浪费，我们可以把-Xms和-XXPermSize参数值设置为-Xmx和-XX：MaxPermSize参数值一样，这样就强制虚拟机在启动的时候就把老年代和永久代的容量固定下来，避免运行时自动扩展。对于minor gc，我们在避免空间扩展的同时，也可以适当的增加堆大小来减少gc的次数。

        boss系统运行的环境为2核4g的centos虚拟机，我们把新生代容量提升到1024M，避免新生代频繁GC；把Java堆、永久代的容量分别固定为2048MB和256MB，避免内存扩展。这几个数值都是根据机器硬件、系统大小决定的，不同的系统应根据VisualGC中收集到的实际数据进行设置。改动后的jvm参数如下：

        

-Xverify:none -Xms2048m -Xmx2048m -Xss512k -XX:NewSize=1024M -XX:MaxNewSize=1024M -XX:PermSize=256m -XX:MaxPermSize=256m -Xnoclassgc -XX:+PrintGCDetails -Xloggc:/home/admin/logs/trade_gc.log

        

         在这个配置之下，gc次数已经大幅度降低，图5是boss系统在启动后运行excel批量导入功能，总共发生3次minor gc，未发生full gc，gc总共耗时为0.42秒，接口调用时长缩短为46.5s。

图5

图6

        四、降低服务延迟的优化——收集器选择和JIT编译

         一个web服务的主要作用还是对外提供服务，在上面的优化过程中，批量导入的总耗时已经从58s下降到46秒，那对于服务的运行速度优化，我们还有什么其他的优化方法么？我们在编译时间和类装载时间优化那一节讲了JIT编译的作用，当虚拟机运行在默认模式的时候，使用的是一个代号为C1的轻量级编译器，另外还有一个代号为C2的相对重量级的编译器能提供更多的优化措施，如果使用-server模式的虚拟机启动web服务将会使用到C2编译器，这时从VisualGC可以看到启动过程中代码编译的时间会增加，换来的是更高的执行效率。同时对于垃圾收集，jdk使用的hotspot虚拟机默认采用Serial收集器，而是当JVM需要进行垃圾回收的时候，需要中断所有的用户线程，单线程执行垃圾收集，执行效率落后于 ParNew + CMS 收集器。

        我们尝试将 -server 参数和 -XX:+UseConcMarkSweepGC 加入到boss系统启动参数中，指定收集器和编译器，再次测试的结果如图。

图7，项目启动时非程序时间耗时

图8运行完批量导入接口后的日志非用户程序时间

图9第一次导入总耗时

        从结果统计中看出，系统启动的编译时间和类加载时间变长，三次Minor GC的耗时反而有所增加，批量导入接口的总耗时与优化前没有太大变化。编译时间和类加载时间变长是因为我们用了更重量级的C2编译器，由于未发生full gc， 未能体现出ParNew + CMS 收集器的优势。这次优化能为我们带来更多好处的是C2编译器，虽然在项目启动第一次调用接口的时候耗时未发生太大变化，但C2编译器已经将接口中的“热代码”进行了JIT编译，这个效率提升我们可以在下次调用接口时受益。图9是第二次调用服务端接口的耗时，比第一次调用减少了7秒。

第二次调用“热代码”耗时

图10第二次导入总耗时

        

        最终的配置代码如下：

-server -Xverify:none -Xms2048m -Xmx2048m -Xss512k -XX:NewSize=1024M -XX:MaxNewSize=1024M -XX:PermSize=256m -XX:MaxPermSize=256m -Xnoclassgc -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -Xloggc:/home/admin/logs/trade_gc.log

        

       这次优化，项目启动时减少非用户程序时间4s。垃圾收集从20次minor gc和3次full gc减小为3次minor gc。调用接口总耗时从58秒减少为39秒。

        到此，对于虚拟机内存的调优基本就结束了，当然服务端调优还会有更多方面，比如数据库，连接池，磁盘I/O等，但对于虚拟机内存部分的优化思路，与文章中的方法没有太大差别。希望大家有所收获。

        PS:以上操作均是在jdk 1.7.0_71环境下进行的实验，由于蚂蚁金融云技术栈的诸多限制，没有将jdk1.8中的运行情况和上述环境进行对比，大家有兴趣的话不妨使用一下最新版本的jdk运行自己的项目，看看jdk的升级是否能为我们带来“免费的”效率提升。