GC调优相关

1.如何理解Latency和Throughput: 吞吐量和延迟

       延迟一般包括单向延迟（One-way Latency）和往返延迟（Round Trip Latency），实际测量时一般取往返延迟。它的单位一般是ms、s、min、h等。

      而吞吐量一般指相当一段时间内测量出来的系统单位时间处理的任务数或事务数（TPS）。注意“相当一段时间”，不是几秒，而可能是十几分钟、半个小时、一天、几周甚至几月。它的单位一般是TPS、每单位时间写入磁盘的字节数等。

下面的比喻是关于吞吐量（throughput）和延迟（latency）的。如果你要搞网络性能优化，这两个概念是你必须要知道的，它们看似简单实则不是。我相信包括我在内的很多人都曾经认为大的吞吐量就意味着低延迟，高延迟就意味着吞吐量变小。下面的比喻可以解释这种观点根本不对。该比喻来自这里，我来做个大体意译（非逐字翻译）。

我们可以把网络发送数据包比喻成去街边的 ATM 取钱。每一个人从开始使用 ATM 到取钱结束整个过程都需要一分钟，所以这里的延迟是60秒，那吞吐量呢？当然是 1/60 人/秒。现在银行升级了他们的 ATM 机操作系统，每个人只要30秒就可以完成取款了！延迟是 30秒，吞吐量是 1/30 人/秒。很好理解，可是前面的问题依然存在对不对？别慌，看下面。

因为这附近来取钱的人比较多，现在银行决定在这里增加一台 ATM 机，一共有两台 ATM 机了。现在，一分钟可以让4个人完成取钱了，虽然你去排队取钱时在 ATM 机前还是要用 30 秒！也就是说，延迟没有变，但吞吐量增大了！可见，吞吐量可以不用通过减小延迟来提高。

好了，现在银行为了改进服务又做出了一个新的决定：每个来取钱的客户在取完钱之后必须在旁边填写一个调查问卷，用时也是30秒。那么，现在你去取钱的话从开始使用 ATM 到完成调查问卷离开的时间又是 60 秒了！换句话说，延迟是60秒。而吞吐量根本没变！一分钟之内还是可以进来4个人！可见，延迟增加了，而吞吐量没有变。

从这个比喻中我们可以看出，延迟测量的是每个客户（每个应用程序）感受到的时间长短，而吞吐量测量的是整个银行（整个操作系统）的处理效率，是两个完全不同的概念。用作者的原话说是：

In short, the throughput is a function of how many stages are in parallel while latency is a function of how many are in series when there are multiple stages in the processing. The stage with the lowest throughput determines the overall throughput.

正如银行为了让客户满意不光要提高自身的办事效率外，还要尽量缩短客户在银行办事所花的时间一样，操作系统不光要尽量让网络吞吐量大，而且还要让每个应用程序发送数据的延迟尽量小。这是两个不同的目标。

2.快速解读GC日志

我们通过 -XX:+UseSerialGC 选项,指定JVM使用串行垃圾收集器, 并使用下面的启动参数让 JVM 打印出详细的GC日志:

-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGCTimeStamps

这样配置以后，发生GC时输出的日志就类似于下面这种格式(为了显示方便,已手工折行):

2015-05-26T14:45:37.987-0200: 151.126:
  [GC (Allocation Failure) 151.126:
    [DefNew: 629119K->69888K(629120K), 0.0584157 secs]
    1619346K->1273247K(2027264K), 0.0585007 secs]
  [Times: user=0.06 sys=0.00, real=0.06 secs]

2015-05-26T14:45:59.690-0200: 172.829:
  [GC (Allocation Failure) 172.829:
    [DefNew: 629120K->629120K(629120K), 0.0000372 secs]
    172.829: [Tenured: 1203359K->755802K(1398144K), 0.1855567 secs]
    1832479K->755802K(2027264K),
    [Metaspace: 6741K->6741K(1056768K)], 0.1856954 secs]
  [Times: user=0.18 sys=0.00, real=0.18 secs]

上面的GC日志暴露了JVM中的一些信息。事实上，这个日志片段中发生了 2 次垃圾回收事件(Garbage Collection events)。其中一次清理的是年轻代(Young generation), 而第二次处理的是整个堆内存。下面我们来看，如何解读第一次GC事件，发生在年轻代中的小型GC(Minor GC):

    2015-05-26T14:45:37.987-0200 – GC事件(GC event)开始的时间点.
    151.126 – GC事件的开始时间,相对于JVM的启动时间,单位是秒(Measured in seconds).
    GC – 用来区分(distinguish)是 Minor GC 还是 Full GC 的标志(Flag). 这里的 GC 表明本次发生的是 Minor GC.
    Allocation Failure – 引起垃圾回收的原因. 本次GC是因为年轻代中没有任何合适的区域能够存放需要分配的数据结构而触发的.
    DefNew – 使用的垃圾收集器的名字. DefNew 这个名字代表的是: 单线程(single-threaded), 采用标记复制(mark-copy)算法的, 使整个JVM暂停运行(stop-the-world)的年轻代(Young generation) 垃圾收集器(garbage collector).
    629119K->69888K – 在本次垃圾收集之前和之后的年轻代内存使用情况(Usage).
    (629120K) – 年轻代的总的大小(Total size).
    1619346K->1273247K – 在本次垃圾收集之前和之后整个堆内存的使用情况(Total used heap).
    (2027264K) – 总的可用的堆内存(Total available heap).
    0.0585007 secs – GC事件的持续时间(Duration),单位是秒.
    [Times: user=0.06 sys=0.00, real=0.06 secs] – GC事件的持续时间,通过多种分类来进行衡量:

    user – 此次垃圾回收, 垃圾收集线程消耗的所有CPU时间(Total CPU time).
    sys – 操作系统调用(OS call) 以及等待系统事件的时间(waiting for system event)
    real – 应用程序暂停的时间(Clock time). 由于串行垃圾收集器(Serial Garbage Collector)只会使用单个线程, 所以 real time 等于 user 以及 system time 的总和.

通过上面的分析, 我们可以计算出在垃圾收集期间, JVM 中的内存使用情况。在垃圾收集之前, 堆内存总的使用了 1.54G (1,619,346K)。其中, 年轻代使用了 614M(629,119k)。可以算出老年代使用的内存为: 967M(990,227K)。

下一组数据( -> 右边)中蕴含了更重要的结论, 年轻代的内存使用在垃圾回收后下降了 546M(559,231k), 但总的堆内存使用(total heap usage)只减少了 337M(346,099k). 通过这一点,我们可以计算出, 有 208M(213,132K) 的年轻代对象被提升到老年代(Old)中。

这个GC事件可以用下面的示意图来表示, 上方表示GC之前的内存使用情况, 下方表示结束后的内存使用情况:

参考文章：

1. 关于吞吐量和延时

2.快速解读GC日志