PhantomReference导致CMS GC耗时严重

PhantomReference导致CMS GC耗时严重

简书 涤生
转载请注明原创出处,谢谢!
如果读完觉得有收获的话,欢迎点赞加关注。

介绍

GC优化关键是找到优化的点,如果明确GC过程中耗时的阶段在哪里,优化起来应该也就不难了。这篇文章主要讲述最近一次CMS GC优化过程,是一次分享,也是一次总结。闲话少说,我们开始吧。

现象

Old GC监控信息

上图很明显(公司内部监控没有区分Old GC和Full GC)Old GC耗时严重,大致看了几天的监控,基本上每次都很耗时,时间约1s左右,这里统计的1s左右的耗时指的是stop-the-world的时间。

排查

那到底哪里耗时呢?我们得去看看GC日志,日志中有更多的信息

2018-01-13T19:21:36.254: [GC [1 CMS-initial-mark: 2097444K(4194304K)] 2143492K(6081792K), 0.2197240 secs] [Times: user=0.01 sys=0.17, real=0.22 secs] 
2018-01-13T19:21:36.474: [CMS-concurrent-mark-start]
2018-01-13T19:21:36.654: [CMS-concurrent-mark: 0.180/0.180 secs] [Times: user=0.65 sys=0.07, real=0.18 secs] 
2018-01-13T19:21:36.654: [CMS-concurrent-preclean-start]
2018-01-13T19:21:36.700: [CMS-concurrent-preclean: 0.045/0.045 secs] [Times: user=0.05 sys=0.01, real=0.04 secs] 
2018-01-13T19:21:36.700: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2018-01-13T19:21:41.765: [CMS-concurrent-abortable-preclean: 5.051/5.065 secs] [Times: user=7.08 sys=0.51, real=5.07 secs] 
2018-01-13T19:21:41.768: [GC[YG occupancy: 503315 K (1887488 K)]2018-01-13T19:21:41.768: [Rescan (parallel) , 0.0975470 secs]
2018-01-13T19:21:41.866: [weak refs processing, 0.7034340 secs]
2018-01-13T19:21:42.569: [class unloading, 0.0152410 secs]
2018-01-13T19:21:42.585: [scrub symbol table, 0.0118450 secs]
2018-01-13T19:21:42.597: [scrub string table, 0.0021360 secs] 
[1 CMS-remark: 2097444K(4194304K)] 2600759K(6081792K), 0.8884580 secs] [Times: user=1.17 sys=0.00, real=0.89 secs] 
2018-01-13T19:21:42.657: [CMS-concurrent-sweep-start]
2018-01-13T19:21:44.283: [CMS-concurrent-sweep: 1.571/1.626 secs] [Times: user=2.77 sys=0.15, real=1.62 secs] 
2018-01-13T19:21:44.284: [CMS-concurrent-reset-start]
2018-01-13T19:21:44.363: [CMS-concurrent-reset: 0.079/0.079 secs] [Times: user=0.04 sys=0.08, real=0.08 secs] 

CMS GC日志比较详细,会打印各个阶段处理的详细信息。
这里我们重点关注两个stop-the-world的阶段CMS-initial-mark和CMS-remark。可以看到CMS-initial-mark耗时0.22s,CMS-remark耗时0.89s,所以主要是CMS-remark阶段比较耗时。remark阶段做的事情分好几块,具体是哪块耗时严重呢?
细看下CMS-remark阶段的日志,应该很快能发现weak refs processing处理比较耗时。

    [weak refs processing, 0.7034340 secs

看到这里,大家一定很想知道weak refs processing是什么?
为什么处理这么耗时?

void ReferenceProcessor::process_discovered_references(
  BoolObjectClosure*           is_alive,
  OopClosure*                  keep_alive,
  VoidClosure*                 complete_gc,
  AbstractRefProcTaskExecutor* task_executor) {
  NOT_PRODUCT(verify_ok_to_handle_reflists());

  assert(!enqueuing_is_done(), "If here enqueuing should not be complete");
  // Stop treating discovered references specially.
  disable_discovery();

  bool trace_time = PrintGCDetails && PrintReferenceGC;
  // Soft references
  {
    TraceTime tt("SoftReference", trace_time, false, gclog_or_tty);
    process_discovered_reflist(_discoveredSoftRefs, _current_soft_ref_policy, true,
                               is_alive, keep_alive, complete_gc, task_executor);
  }

  update_soft_ref_master_clock();

  // Weak references
  {
    TraceTime tt("WeakReference", trace_time, false, gclog_or_tty);
    process_discovered_reflist(_discoveredWeakRefs, NULL, true,
                               is_alive, keep_alive, complete_gc, task_executor);
  }

  // Final references
  {
    TraceTime tt("FinalReference", trace_time, false, gclog_or_tty);
    process_discovered_reflist(_discoveredFinalRefs, NULL, false,
                               is_alive, keep_alive, complete_gc, task_executor);
  }

  // Phantom references
  {
    TraceTime tt("PhantomReference", trace_time, false, gclog_or_tty);
    process_discovered_reflist(_discoveredPhantomRefs, NULL, false,
                               is_alive, keep_alive, complete_gc, task_executor);
  }

  // Weak global JNI references. It would make more sense (semantically) to
  // traverse these simultaneously with the regular weak references above, but
  // that is not how the JDK1.2 specification is. See #4126360. Native code can
  // thus use JNI weak references to circumvent the phantom references and
  // resurrect a "post-mortem" object.
  {
    TraceTime tt("JNI Weak Reference", trace_time, false, gclog_or_tty);
    if (task_executor != NULL) {
      task_executor->set_single_threaded_mode();
    }
    process_phaseJNI(is_alive, keep_alive, complete_gc);
  }
}

看JVM源码,weak refs processing主要包括SoftReference、WeakReference、FinalReference、PhantomReference以及JNI Weak Reference这五种Reference对象的处理,处理的主要内容是对之前标记的Reference对象重新处理,重新判断是否需要标记(不标记就是要回收的),如果不标记就需要放到refqueue里,等待java ReferenceHandler线程处理。
所以从工作的主要内容看各种Reference的处理时间跟reference的个数成正比。

那么接下来我们需要做的是确定是哪种Reference比较耗时,然后进行针对性优化。所以加了个参数-XX:+PrintReferenceGC,来具体显示各种Reference的个数和处理时间。

2018-01-30T08:30:08.188: [GC[YG occupancy: 254029 K (1887488 K)]
2018-01-30T08:30:08.188: [Rescan (parallel) , 0.0503640 secs]
2018-01-30T08:30:08.239: [weak refs processing
2018-01-30T08:30:08.239: [SoftReference, 4468 refs, 0.0006040 secs]
2018-01-30T08:30:08.239: [WeakReference, 286808 refs, 0.0336870 secs]
2018-01-30T08:30:08.273: [FinalReference, 35456 refs, 0.0271650 secs]
2018-01-30T08:30:08.300: [PhantomReference, 8041 refs, 3 refs, 0.4335280 secs]
2018-01-30T08:30:08.734: [JNI Weak Reference, 0.0000250 secs], 0.4951020 secs]
2018-01-30T08:30:08.734: [class unloading, 0.0143290 secs]
2018-01-30T08:30:08.748: [scrub symbol table, 0.0110140 secs]
2018-01-30T08:30:08.759: [scrub string table, 0.0015380 secs] [1 CMS-remark: 2098695K(4194304K)] 2352725K(6081792K), 0.6112680 secs] [Times: user=0.76 sys=0.00, real=0.61 secs]

从上面的日志就能很明显看出来是PhantomReference处理时间较长。
找到了优化的点,处理起来也就简单了。

解决

我们需要做下面两件事。

1、确定PhantomReference的产生的原因,从源头控制;
2、通过JVM提供的参数,进行优化。

参数优化

我们先来做第二件事吧,因为它比较容易,JVM确实提供了相关的优化参数,通过-XX:+ParallelRefProcEnabled参数来并行处理Reference,加快处理速度,缩短耗时。
这里并行处理的线程数,是-XX:ParallelGCThreads这个参数控制的,如果没有设置ParallelGCThreads默认跟cpu核数相关,是可以计算的

对应的JVM源码是

unsigned int Abstract_VM_Version::nof_parallel_worker_threads(
                                                      unsigned int num,
                                                      unsigned int den,
                                                      unsigned int switch_pt) {
  if (FLAG_IS_DEFAULT(ParallelGCThreads)) {
    assert(ParallelGCThreads == 0, "Default ParallelGCThreads is not 0");
    unsigned int threads;
    // For very large machines, there are diminishing returns
    // for large numbers of worker threads.  Instead of
    // hogging the whole system, use a fraction of the workers for every
    // processor after the first 8.  For example, on a 72 cpu machine
    // and a chosen fraction of 5/8
    // use 8 + (72 - 8) * (5/8) == 48 worker threads.
    unsigned int ncpus = (unsigned int) os::initial_active_processor_count();
    threads = (ncpus <= switch_pt) ?
             ncpus :
             (switch_pt + ((ncpus - switch_pt) * num) / den);
#ifndef _LP64
    // On 32-bit binaries the virtual address space available to the JVM
    // is usually limited to 2-3 GB (depends on the platform).
    // Do not use up address space with too many threads (stacks and per-thread
    // data). Note that x86 apps running on Win64 have 2 stacks per thread.
    // GC may more generally scale down threads by max heap size (etc), but the
    // consequences of over-provisioning threads are higher on 32-bit JVMS,
    // so add hard limit here:
    threads = MIN2(threads, (2*switch_pt));
#endif
    return threads;
  } else {
    return ParallelGCThreads;
  }

简单根据源码翻译下就是

  if ( ncpus  <=  8) {
      return ncpus;
  } else {
      return 8 + (ncpus - 8) * 5 / 8;
  }

设置-XX:+ParallelRefProcEnabled参数后效果也很明显

  [PhantomReference, 6117 refs, 9 refs, 0.1351920 secs]

根源解决

要想从根源解决,我们必须找到PhantomReference产生的相关代码,这里一般存在两种方式:
1、简单通过jmap -histo [pid],找到相关的类。
这种方式比较轻量,对应用损伤较小,不过只能看到各个类的对象个数,总体占用空间大小,看不到很多详细信息。
2、jmap -dump:format=b,file=dumpFileName [pid],拿到堆的dump文件,然后通过mat分析。
这种方式比较重,dump时间一般很长,需要先摘除机器流量,然后进行操作。

我们选择了第二种,用mat分析了下dump文件。从下图类的名字上也能很明显看出,就是ConnectionPhantomReference对象了。


mat分析结果

根据包名com.mysql.jdbc,看来要想搞清楚问题的根源,还得撸下jdbc的源码了。

ConnectionPhantomReference产生的原因

一般PhantomReference是用来在GC时做相关的做资源回收,这里也不例外。
我们来看下ConnectionPhantomReference类,从构造方法上看,有两个参数:
一个是ConnnectionImpl,不用想也知道是与数据库之间的连接对象。
一个是ReferenceQueue。
另外还有一个cleanup方法,是用来回收connection相关资源。

ReferenceQueue是用来做什么的呢?要了解这个问题就需要了解下PhantomReference是如何回收资源的。

被PhantomReference引用的对象在被GC时,JVM会将PhantomReference对象扔到refqueue,由ReferenceHandler线程取出放入到ReferenceQueue中,放入ReferenceQueue中做什么,莫急,待我慢慢道来。

static class ConnectionPhantomReference extends PhantomReference<ConnectionImpl> {
        private NetworkResources io;

        ConnectionPhantomReference(ConnectionImpl connectionImpl, ReferenceQueue<ConnectionImpl> q) {
            super(connectionImpl, q);

            try {
                this.io = connectionImpl.getIO().getNetworkResources();
            } catch (SQLException e) {
                // if we somehow got here and there's really no i/o, we deal with it later
            }
        }

        void cleanup() {
            if (this.io != null) {
                try {
                    this.io.forceClose();
                } finally {
                    this.io = null;
                }
            }
        }
    }

了解了上述PhantomReference原理后,再看看ConnectionPhantomReference什么时候生成的。看下面代码,很明显是在生成数据库连接对象connection时,将connection包装成ConnectionPhantomReference存入connectionPhantomRefs这个ConcurrentHashMap中。

   protected static void trackConnection(Connection newConn) {

        ConnectionPhantomReference phantomRef = new ConnectionPhantomReference((ConnectionImpl) newConn, refQueue);
        connectionPhantomRefs.put(phantomRef, phantomRef);
    }
  protected static final ConcurrentHashMap<ConnectionPhantomReference, ConnectionPhantomReference> connectionPhantomRefs = new ConcurrentHashMap<ConnectionPhantomReference, ConnectionPhantomReference>();

  protected static final ReferenceQueue<ConnectionImpl> refQueue = new ReferenceQueue<ConnectionImpl>();

上面的connectionPhantomRefs和refQueue是NonRegisteringDriver这个类的类成员。

那connection资源的回收是怎么完成的呢?

public class AbandonedConnectionCleanupThread extends Thread {
    private static boolean running = true;
    private static Thread threadRef = null;

    public AbandonedConnectionCleanupThread() {
        super("Abandoned connection cleanup thread");
    }

    @Override
    public void run() {
        threadRef = this;
        while (running) {
            try {
                Reference<? extends ConnectionImpl> ref = NonRegisteringDriver.refQueue.remove(100);
                if (ref != null) {
                    try {
                        ((ConnectionPhantomReference) ref).cleanup();
                    } finally {
                        NonRegisteringDriver.connectionPhantomRefs.remove(ref);
                    }
                }

            } catch (Exception ex) {
                // no where to really log this if we're static
            }
        }
    }

    public static void shutdown() throws InterruptedException {
        running = false;
        if (threadRef != null) {
            threadRef.interrupt();
            threadRef.join();
            threadRef = null;
        }
    }

}

原来是有另外一个类AbandonedConnectionCleanupThread在偷偷干这个事,AbandonedConnectionCleanupThread这个线程就是从NonRegisteringDriver.refQueue中拿到ConnectionPhantomReference,然后执行cleanup方法,最后删除connectionPhantomRefs这个ConcurrentHashMap中的ConnectionPhantomReference对象,完成connection相关资源的回收。
这里NonRegisteringDriver.refQueue中的PhantomReference就是之前提到由ReferenceHandler线程放进去的ConnectionPhantomReference对象。

看到这里大家应该明白,感情是jdbc为每个connection都生成了一个ConnectionPhantomReference,目的是为了当connection对象回收时,顺便回收相关资源。这其实是一个保底操作,是怕connnection资源被上层的连接池或者使用者忘记close,从而导致资源泄漏。

但是为什么这么多PhantomReference,通过GC日志看约有8000多个,也就是有8000多个数据库连接资源,而且都在Old Gen?
都在Old区很好解释,因为连接资源一般存活时间比较久,经过多次Young GC都能存活到Old区。
8000多个连接这确实有点多,其实存活的没那么多,看了下这个应用使用的数据源比较多有10多个,每个数据源一主两从,并且连接池的最大连接数是36,随着程序使用过程中的数据库连接资源的回收与生成,时间长了,连接确实会不少。另外这个应用Old GC的时间间隔比较长,很多废弃的连接都不会及时回收。

说了这么多都是在解释为什么有这么多PhantomReference对象。
现在问题的源头也找到了,我们怎么从源头解决这个问题呢?

其实也很简单,首先PhantomReference的产生是jdbc的保底措施,其实这种保底措施也不见得需要,一般数据库连接都是有连接池控制,连接池自身是会确保连接资源的回收,所以这个保底措施是不是可以disable掉,看了下源码,没有disable的地方,那只能程序解决了,解决方式也很简单,删掉connectionPhantomRefs这个ConcurrentHashMap中的数据就好了,这就减少PhantomReference的数量。来降低weak refs processing的处理时间,怎么删就不用说了吧。

总结

GC优化的问题,其实思路都是差不多的,找到问题的原因,也就找到了优化的点,下手起来也就没那么困难了。目前为止,这个问题确实是解决了,但是对于JVM处理8000多个PhantomReference,为啥耗时就这么长,具体到底做了什么,本人一直还有疑问,后面还需继续细细考究。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 155,541评论 4 358
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 65,987评论 1 285
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 105,387评论 0 236
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 43,325评论 0 201
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 51,657评论 3 284
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 40,125评论 1 202
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 31,519评论 2 305
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 30,242评论 0 193
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 33,863评论 1 234
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,198评论 2 239
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 31,747评论 1 255
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 28,106评论 2 249
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 32,635评论 3 227
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 25,926评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,631评论 0 190
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 35,131评论 2 261
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 35,083评论 2 257