账号密码登录
微信安全登录
微信扫描二维码登录

登录后绑定QQ、微信即可实现信息互通

手机验证码登录
找回密码返回
邮箱找回 手机找回
注册账号返回
其他登录方式
分享
  • 收藏
    X
    G1的termination阶段耗时过大
    45
    0

    各位大大好,我在使用G1的时候遇到一个问题,G1的termination阶段耗时占整个young gc的90%以上,一般耗时在100ms左右,进而导致整个程序吞吐上不去。。
    GC日志如下:

    2018-05-16T00:00:49.665+0800: 10761.953: [GC pause (G1 Evacuation Pause) (young) 10761.953: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 7554, predicted base time: 4.22 ms, remaining time: 25.78 ms, target pause time: 30.00 ms]
     10761.953: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1680 regions, survivors: 40 regions, predicted young region time: 25.59 ms]
     10761.953: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1680 regions, survivors: 40 regions, old: 0 regions, predicted pause time: 29.81 ms, target pause time: 30.00 ms]
    , 0.2301618 secs]
       [Parallel Time: 225.6 ms, GC Workers: 13]
          [GC Worker Start (ms): Min: 10761953.5, Avg: 10761953.6, Max: 10761953.7, Diff: 0.2]
          [Ext Root Scanning (ms): Min: 0.3, Avg: 0.4, Max: 0.5, Diff: 0.2, Sum: 5.4]
          [Update RS (ms): Min: 0.9, Avg: 1.2, Max: 1.6, Diff: 0.7, Sum: 15.3]
             [Processed Buffers: Min: 2, Avg: 2.7, Max: 5, Diff: 3, Sum: 35]
          [Scan RS (ms): Min: 0.1, Avg: 0.4, Max: 0.6, Diff: 0.5, Sum: 4.9]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
          [Object Copy (ms): Min: 15.5, Avg: 23.2, Max: 34.8, Diff: 19.3, Sum: 301.0]
          [Termination (ms): Min: 188.5, Avg: 200.2, Max: 207.8, Diff: 19.3, Sum: 2602.1]
             [Termination Attempts: Min: 3064, Avg: 3240.0, Max: 3397, Diff: 333, Sum: 42120]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.8]
          [GC Worker Total (ms): Min: 225.2, Avg: 225.4, Max: 225.5, Diff: 0.3, Sum: 2929.6]
          [GC Worker End (ms): Min: 10762178.9, Avg: 10762179.0, Max: 10762179.0, Diff: 0.1]
       [Code Root Fixup: 0.0 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 0.9 ms]
       [Other: 3.6 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 0.2 ms]
          [Ref Enq: 0.0 ms]
          [Redirty Cards: 0.1 ms]
          [Humongous Register: 0.3 ms]
          [Humongous Reclaim: 0.0 ms]
          [Free CSet: 2.4 ms]
       [Eden: 1680.0M(1680.0M)->0.0B(1742.0M) Survivors: 40.0M->40.0M Heap: 2882.1M(8192.0M)->1206.7M(8192.0M)]
    Heap after GC invocations=1702 (full 0):
     garbage-first heap   total 8388608K, used 1235671K [0x00000005fa400000, 0x00000005fa510000, 0x00000007fa400000)
      region size 1024K, 40 young (40960K), 40 survivors (40960K)
     Metaspace       used 20923K, capacity 21108K, committed 21376K, reserved 1069056K
      class space    used 2342K, capacity 2414K, committed 2432K, reserved 1048576K
    }
     [Times: user=2.95 sys=0.00, real=0.23 secs]
    

    主要耗时就是termination,总GC实际耗时240ms,但是termination阶段耗时avg为210ms

    [Termination (ms): Min: 201.7, Avg: 212.0, Max: 219.3, Diff: 17.6, Sum: 2755.5]
    [Times: user=3.11 sys=0.00, real=0.24 secs]
    

    我的JVM参数如下:

    -XX:+AlwaysPreTouch -XX:CompressedClassSpaceSize=96468992 
    -XX:ErrorFile=/dev/shm/hs_error%p.log 
    -XX:G1HeapRegionSize=1048576 
    -XX:G1ReservePercent=25 -XX:GCLogFileSize=31457280 
    -XX:InitialHeapSize=8589934592 
    -XX:InitiatingHeapOccupancyPercent=30 
    -XX:MaxDirectMemorySize=34359738368 
    -XX:MaxGCPauseMillis=30 
    -XX:MaxHeapSize=8589934592 
    -XX:MaxMetaspaceSize=104857600 
    -XX:NumberOfGCLogFiles=5 
    -XX:-OmitStackTraceInFastThrow 
    -XX:ParallelGCThreads=13 
    -XX:+PrintAdaptiveSizePolicy 
    -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime 
    -XX:+PrintGCDateStamps -XX:+PrintGCDetails 
    -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC 
    -XX:SoftRefLRUPolicyMSPerMB=0 -XX:SurvivorRatio=8 
    -XX:+UnlockExperimentalVMOptions -XX:-UseBiasedLocking 
    -XX:+UseCompressedClassPointers -XX:+UseCompressedOops 
    -XX:+UseG1GC -XX:+UseGCLogFileRotation
    

    使用的JVM版本是jdk1.8.0_171(应该和JDK版本无关,我尝试了最新的jdk10,termination阶段耗时仍是最高的),机器硬件配置是一台32core,96G内存的物理机。
    关于我的程序:
    我的程序目前是一个测试demo,非常简单:
    整个程序由三条线程组成:

    1. produceThread 负责创建128字节固定大小的对象ProducerRequest,整个对象最大为256字节(包含一些监控信息,运行耗时打点),然后放入一条阻塞队列(LinkedBlockingQueue)
    2. WriteThread,负责从阻塞队列中将ProducerRequest取出来,然后写到一个directByteBuffer中,如果directByteBuffer的剩余空间不足以存放一个ProducerRequest,那么将这个directByteBuffer扔到另外一个阻塞队列dirtyQueue(LinkedBlockingQueue)中
    3. FlushThread,负责从dirtyQueue中取出directByteBuffer,将directByteBuffer中的数据写到磁盘上(randomAccessFile),每写完一个directByteBuffer,就将这个directByteBuffer放到另外一个阻塞队列(cleanQueue)中,以供WriteThread使用
    private final int PAGE_SIZE = 1024 * 4 ;//4K 一个页面
    private int pageNum = 1024 * 1024 * 4;    //4K * 1024 * 1024 * 4= 16G
    
    private final LinkedBlockingQueue<ByteBuffer> cleanQueue = new LinkedBlockingQueue<>() ;
    private final LinkedBlockingQueue<ByteBuffer> dirtyQueue = new LinkedBlockingQueue<>() ;
    

    我目前排查到的点:

    1. 查看了Stack Overflow上的一个问题:https://stackoverflow.com/que...,上面回复说是由于GC worker线程太多了,导致CPU竞争太严重,然后我就设置了XX:ParallelGCThreads为13条(线上16Core的机器为13条),但实际效果不明显
    2. 然后在相同的问题的评论说是由于Object Copy太慢了导致的,尽管我不同意他的说法(因为我的程序非常简单,对于巨无霸对象创建是不存在的,基本都是小对象),但是也查看了GC日志,没有找到由于humongous allocations导致的GC日志
    3. 查看之前的日志,发现有由于metadata区太小导致的GC,因此配置了XX:MaxMetaspaceSize为100M,后面这个GC基本消失了,但是termination引发的GC还是存在
    4. 通过强制配置年轻代的大小为1G,可以有效降低termination带来的时延,我把年轻代设置为5G,然后改为1G,termination的耗时从500ms降到100ms,对应的总体时延也成比例下降
    5. 修改过一次程序:没有使用直接内存的缓存池(仍然创建了缓存池),将WriteThread和FlushThread合并,每次有ProducerRequest进入时,直接将ProducerRequest通过randomAccessFile写到磁盘上。这种方式就不会出现termination占用耗时很大的情况,总体gc在10ms以下,绝大多数在1ms以内。通过这个测试,我基本可以确定和堆外内存的使用有关系,但是现在又想不到直接的关系能说明这个猜测

    相关GC的完整log:https://pan.baidu.com/s/16iVf...
    还希望相关大大给我指点一下,谢谢~

    0
    打赏
    收藏
    点击回答
        全部回答
    • 0
    • missyou 普通会员 1楼

      G1(Grouping 1)是Google的MapReduce项目中的一个阶段,主要用于对大规模数据集进行处理。G1的终止阶段可能会因为以下几个原因导致耗时过长:

      1. 数据处理效率低:G1是MapReduce的一个重要阶段,但是在这个阶段,数据处理的效率并不是很高。如果数据处理效率低,那么G1的终止阶段可能会花费更长的时间。

      2. 分布式计算问题:G1在处理大规模数据时,可能会遇到分布式计算的问题。如果在分布式计算中遇到问题,那么G1的终止阶段可能会花费更长的时间。

      3. 算法问题:如果G1的终止阶段使用的算法有问题,那么也可能会导致耗时过长。例如,如果G1的终止阶段使用的算法不是最高效的算法,那么它可能需要花费更长的时间来完成任务。

      4. 硬件问题:如果G1的终止阶段使用的硬件有问题,那么它也可能会导致耗时过长。例如,如果G1的终止阶段使用的硬件性能不足,那么它可能需要花费更长的时间来完成任务。

      为了解决这些问题,可以尝试以下方法:

      1. 提高数据处理效率:可以尝试优化G1的终止阶段,例如,可以通过增加内存或者提高CPU的性能来提高数据处理效率。

      2. 分散分布式计算:可以尝试将大规模数据分散到多个节点上进行处理,以分散分布式计算的问题。

      3. 优化算法:可以尝试使用更高效的算法来处理大规模数据。

      4. 优化硬件:可以尝试更换性能更好的硬件来提高G1的终止阶段的性能。

    更多回答
    扫一扫访问手机版
    • 回到顶部
    • 回到顶部