注册 登录  
 加关注
   显示下一条  |  关闭
温馨提示!由于新浪微博认证机制调整,您的新浪微博帐号绑定已过期,请重新绑定!立即重新绑定新浪微博》  |  关闭

断尘居

温柔的男人像海洋。

 
 
 
 
 

日志

 
 

关注性能: 谈论垃圾  

2012-02-09 16:55:56|  分类: JVM/ HotSpot |  标签: |举报 |字号 订阅

  下载LOFTER 我的照片书  |

 

                                      





作者Jack Shirazi

编写时间20122月9

电邮 未知

最后更新20122月9

类型: 转载

来源网址点击查看>


       许多开发人员认为,内存管理至多是开发业务逻辑的主要任务之外的一项不重要的工作 —— 直到 业务逻辑不能像预期的或者测试时那样执行得好。出现这种情况时,就需要知道哪里出错了及其原因, 这意味着要理解应用程序如何与底层计算资源(特别是内存)进行交互。理解应用程序如何利用内存的最好方式 是观察垃圾收集器的行动。

为什么我的应用程序不连贯了?

Java 虚拟机中最大的一个性能问题是应用程序线程与同时运行的 GC 的互斥性。 垃圾收集器要完成其工作,需要在一段时间内防止所有其他线程访问它正在处理的堆空间(内存)。 按 GC 的术语,这段时间称为“stop-the-world”,并且,正如其名字所表明的, 在垃圾收集器努力工作时,应用程序有一个急刹车。幸运的是,这种暂停通常是很短的,很难察觉到, 但是很容易想像,如果应用程序在随机的时刻出现随机且较长时间的暂停,对应用程序的响应性和吞吐能力会有破坏性的影响。

不过 GC 只是应用程序出现不连贯和停顿的一个原因。那么如何确定 GC 对产生这些问题是否负有 责任呢?要回答这个问题,我们需要测量垃圾收集器的工作强度,并当在系统中进行改变时继续这些 测量,以定量地确定所做的改变是否有所期望的效果。

我需要多少内存?

普遍接受的信念是,在系统中添加内存将解决许多性能问题。虽然这个原则对于 JVM 来说经常是正确的, 但是太多好东西可能对性能是有害的。因此技巧在于 Java 应用程序需要多少内存就给它多少,但是绝不多给。问题是, 应用程序需要多少内存?对于应用程序不连贯的情况,我们需要观察垃圾收集行为以了解看它做的是否比所需要的 更多。这些观察将告诉我们所做的改变是否有所期望的效果。



测量 GC 的活动

生成 GC 日志的标准方式是使用 -verbose:gc 旗标,设置这个旗标后,垃圾收集器 会在每次运行时生成它所做的事情的汇总,一般是写入到控制台(通过标准输出或者标准错误)。许多 VM 支持一个 允许 verbose GC 输出转向到一个文件的选项。例如,在 Sun 的 1.4 JVM 中,可以使用开关 -Xloggc:filename 将 GC 输出写到文件中。对于 HP JVM,要使用 -Xverbosegc=file 开关。在本文中,我们将分析 Sun 1.4.2 和 IBM 1.4.1 JVM 捕获的 verbose GC 输出。

使用这个方法监视内存使用的一个最大好处是它对应用程序的性能的影响很小。 不幸的是,这个解决方案并不完美,因为这些日志文件可能变得特别大,而维护它们可能需要重新启动 JVM。 尽管如此,这种技术在生产环境中仍然是可行的,因为它可以帮助诊断只在这种环境中才列出的性能问题。

更深入观察 GC

-verbose:gc 旗标生成的输出根据 JVM 厂商而不同,不同的 垃圾收集器选项会报告特定于该实现的信息。例如,由 IBM JVM 生成的输出比由 Sun JVM 生成的输出冗长得多,而 Sun 的输出更适合于由工具读取。就是说,每一个 GC 日志 传达基本信息 —— 使用了多少内存、恢复了多少内存、GC 周期用了多少时间,以及在收集期间是否 采取了其他行动。从这些基本测量中,我们可以推断出有助于更好地理解所发生的事情的细节。 我们要计算的统计如下所示:

  • 考虑的运行时的持续时间
  • 收集总数
  • 收集频率
  • 收集所用最长时间
  • 收集所用总时间
  • 收集所用平均时间
  • 收集的平均间隔
  • 分配的字节总数
  • 每次收集每秒分配的字节数
  • 恢复的字节总数
  • 每次收集每秒恢复的字节总数

理解了暂停时间,我们就可以理解 GC 对应用程序不响应是否 负有部分或者全部责任了。 一种实现这一任务的方法是将详细(verbose) GC 日志中的 GC 活动与系统采集的 其他日志(如 Web 服务器日志中的请求 backlog)相对应。几乎可以肯定 最长的 GC 暂停会导致整个系统响应可感觉的下降,所以知道什么时候响应下降 是很有用的,这样就可以将 GC 活动与应用程序吞吐相关联起来。

另一种可能的竞争因素是堆内存分配和恢复的比率,称为 churn。产生大量立即释放的对象的应用程序通常会受到 churn 的拖累。 更高的 churn 比率对垃圾收集器加以很大压力,创造了更多的内存资源 竞争,这又可导致更长的暂停或者可怕的 OutOfMemoryError

了解应用程序是否遭遇这些问题的一个方法是测量所考虑的整个运行时期间 GC 所占用的总时间。有了这种计算,我们就可以了解 GC 做的是否比它所应该做的 更多。让我们推导出进行这种判断所需要的公式。



Sun GC 日志记录

清单 1 是由 Sun 1.4.2_03 JVM 以 -Xloggc:filename 运行默认的标记-清除收集器所生成的日志记录的例子。 可以看到,日志项非常精确地记录了每次所做的事情。


清单 1. 使用 -Xloggc:filename 旗标的 GC 日志记录

69.713: [GC 11536K->11044K(12016K), 0.0032621 secs]
69.717: [Full GC 11044K->5143K(12016K), 0.1429698 secs]
69.865: [GC 5958K->5338K(11628K), 0.0021492 secs]
69.872: [GC 6169K->5418K(11628K), 0.0021718 secs]
69.878: [GC 6248K->5588K(11628K), 0.0029761 secs]
69.886: [GC 6404K->5657K(11628K), 0.0017877 secs]

首先注意到的可能是每一项日志记录是写在一组方括号内的。 其他 GC 算法,如并发收集器, 可能将一些值分解为更细的信息。如果是这种情况, 这些被分解的值会由包围在嵌入的一组方括号中的细节所替代,这使工具可以更容易地处理详细 GC 输出。

我们的研究首先从分析清单 1 中标记为 69.713 的记录开始。这个标记是 JVM 开始后的秒数和毫秒数的时间戳。在这个例子中,JVM 在这个 GC 周期开始之前运行 了 69.713 秒。从左到右的字段为:执行的收集的类型、GC 之前的堆使用、总的堆能力和 GC 事件的持续时间。从这个描述中我们可以看出第一个 GC 事件是一个小的收集。在 GC 开始之前,使用了 11536 Kb 的堆空间。在完成时,使用了 11044 Kb,堆能力为 12016 Kb,而 整个收集用了 .0032621 秒。下一个事件,一个完全的 GC,在 69.717 秒时或者上一个小 GC 事件之后 0.003 秒时开始。 注意,如果将小 GC 事件的持续时间加到其开始时间上,就会看到它在完全的 GC 开始之前不到 1毫秒 结束。因此我们可以得出结论:小收集没有恢复足够的空间,这种失败触发了完全的 GC。对应用程序来说, 这像是一个持续了 0.1462319 秒的事件。让我们继续确定如何计算其他值。

GC 日志记录的参数确定

我们通过确定每个 GC 日志记录中的值的参数来开始分析:

R(n) = T(n): [ <GC> HB->HE(HC), D]
n 清单中记录的索引,1 是第一个,m 是最后一个
R(n) GC 记录
T(n) 第 n 个 GC 发生的时间
HB GC 之前堆的数量
HE GC 之后使用的堆数量
HC 堆空间的总量
D GC 周期的持续时间

有了这些定义,我们现在可以推导出用于计算前面描述的值的公式。



基本值

我们要计算的第一个值是日志所覆盖的运行时整个持续时间。如果 要考虑每一项记录,那么就要分析最后一项记录的时间戳。因为清单 1 只表示全部 日志记录的一部分,我们需要从最后一项中提取出第一个时间戳。尽管对这个例子来说, 这个数字足够精确,但是为了绝对准确,需要加上最后 GC 的持续时间。其原因是时间戳是 在 GC 开始时记录的,而记录表示在记录了时间戳以后发生的事情。

剩余值是取记录中相应的值的总和计算的。值得注意的是恢复的字节可以通过 分析记录中测量的关系而计算,而分配的字节可以通过分析前后记录测量之间的关系计算。 例如,如果考虑在时间戳 69.872 和 69.878 之间发现的记录对,可以用第一个记录中 GC 之后占用的内存数量减去第二个记录在 GC 之前占用的字节数量计算在新的一代(generation)中分配的字节数量: 6248 Kb - 5418 Kb = 830 Kb 。下面表 1 展示了其他值的公式。

要找出最长的 GC 暂停,我们只需要查看持续时间并寻找 D(n) (记录 n 的持续时间)的最大值。

表 1. 统计公式

统计 计算(时间单位调整为秒)
运行时持续时间 RT = (T(M) + D(M)) - T(1)
小收集的总数 TMC = Sum( R(n)) 其中 GC(n) = GC
完全收集的总数 TFC = Sum( R(n)) 其中 GC(n) = Full
收集频率(小收集) CFM = TMC / RT
收集频率(完全) CFF = TFC / RT
收集的时间(最长的小收集) MAX(D(n)) for all n 其中 GC(n) = GC
收集的时间(最长的完全收集) MAX(D(n)) for all n 其中 GC(n) = Full
小收集的时间(总数) TTMC = Sum(D(n)) for all n 其中 GC(n) = GC
完全收集的时间(总数) TTFC Sum(D(n)) for all n 其中 GC(n) = Full
收集的时间(总数) TTC = TTMC + TTFC
小收集的时间(平均) ATMC = TTMC / RT
完全收集的时间(平均) ATFC = TTFC / RT
收集的时间(平均) ATC = TTC / RT
收集间隔(平均) Sum( T(n+1) - T(n)) / (TMC + TFC) for all n
分配的字节(总数) TBA = Sum(HB(n+1) - HE(n)) 对于所有 n
分配的字节(每秒) TBA / RT
分配的字节(每次收集) TBA / (TMC + TFC)
小收集恢复的字节(总数) BRM = Sum(HB(n) - HE(n)) 其中 GC(n) = GC
完全收集恢复的字节(总数) BRF = Sum(HB(n) - HE(n)) 其中 GC(n) = Full
恢复的字节(总数) BRT = BRM + BRF
恢复的字节(每次小收集) BRPM = BRM / TMC
恢复的字节(每次完全收集) BRPF = BRF / TMF
恢复的字节(小收集每秒) BRP = BRM / TTMC
恢复的字节(完全收集每秒) BRF = BRF / TTFC

可以从公式中看出,我们经常需要分别考虑完全 GC 和小 GC。小 GC 与完全 GC 有根本性的不同,一般来说前者至少比后者要快一个数量级。我们可以通过快速分析清单 1 看出这一点 —— 最长的小收集比完全收集快 50 倍。

下面表 2 显示对清单 1 中的值使用表 1 中的公式的结果。

表 2. Sun GC 日志分析

统计 计算(时间单位调整为秒)
运行时持续时间(69.886 + 0.0017877) - 69.713 = 0.1747877
小收集总数5
完全收集总数1
收集频率(小收集)5 / 0.1747877 = 28.6 per second
收集频率(完全)1 / 0.1747877 = 5.27 per second
收集时间(最长的小收集)0.0032621
收集时间(最长的完全收集)0.1429698
小收集的时间(总数)0.0123469
完全收集的时间(总数)0.1429698
收集的时间(总数)0.1553167
小收集的时间(平均)7.1%
完全收集的时间(平均)81.8%
收集的时间(平均)88.9%
收集间隔(平均).173/5=0.0346
分配的字节(总数)3292
分配的字节(每秒)18834 Kb/second
分配的字节(每次收集)549 Kb
小收集恢复的字节(总数)3270 Kb
完全收集恢复的字节(总数)5901 Kb
恢复的字节(总数)5901 + 3270 = 9171 Kb
恢复的字节(每次小收集)3270/5 = 654
恢复的字节(每次完全收集)5901/1 = 5901
恢复的字节(小收集每秒)3270/0.0123469 = 264843 Kb/second
恢复的字节(完全收集每秒)5901/0.1429698 = 41274K/second

表 2 包含从这些看来简单的日志中推算出的大量信息。取决于所关注 的问题,可能不需要计算所有这些值,因为其中一些值比另一些更有用。对于应用程序 长时间不响应的情况,要关注的是 GC 持续时间和计数。



IBM GC 日志记录

与 Sun 日志不同,IBM 日志特别冗长。即使这样,仍然需要一个指导以完全理解 所提供的信息。清单 2 是这种 verbose:gc 日志文件的一部分。


清单 2. IBM JVM verbose:gc 输出

<AF[31]: Allocation Failure. need 528 bytes, 969 ms since last AF>
<AF[31]: managing allocation failure, action=1 (0/97133320) (1082224/1824504)>
<GC(31): GC cycle started Wed Feb 25 23:08:41 2004
<GC(31): freed 36259000 bytes, 37% free (37341224/98957824), in 569 ms>
<GC(31): mark: 532 ms, sweep: 37 ms, compact: 0 ms>
<GC(31): refs: soft 0 (age >= 32), weak 0, final 2, phantom 0>
<AF[31]: managing allocation failure, action=3 (37341224/98957824)>
<GC(31): need to expand mark bits for 116324864-byte heap>
<GC(31): expanded mark bits by 270336 to 1818624 bytes>
<GC(31): need to expand alloc bits for 116324864-byte heap>
<GC(31): expanded alloc bits by 270336 to 1818624 bytes>
<GC(31): need to expand FR bits for 116324864-byte heap>
<GC(31): expanded FR bits by 544768 to 3637248 bytes>
<GC(31): expanded heap by 17367040 to 116324864 bytes, 47% free, ratio:0.417>
<AF[31]: completed in 812 ms>
<AF[32]: Allocation Failure. need 528 bytes, 1765 ms since last AF>
<AF[32]: managing allocation failure, action=1 (0/115394264) (930600/930600)>
<GC(32): GC cycle started Wed Feb 25 23:08:43 2004
<GC(32): freed 54489184 bytes, 47% free (55419784/116324864), in 326 ms>
<GC(32): mark: 292 ms, sweep: 34 ms, compact: 0 ms>
<GC(32): refs: soft 0 (age >= 32), weak 0, final 0, phantom 0>
<AF[32]: completed in 328 ms>
<AF[33]: Allocation Failure. need 528 bytes, 1686 ms since last AF>
<AF[33]: managing allocation failure, action=1 (0/115510592) (814272/814272)>
<GC(33): GC cycle started Wed Feb 25 23:08:45 2004
<GC(33): freed 56382392 bytes, 49% free (57196664/116324864), in 323 ms>
<GC(33): mark: 285 ms, sweep: 38 ms, compact: 0 ms>
<GC(33): refs: soft 0 (age >= 32), weak 0, final 18, phantom 0>
<AF[33]: completed in 324 ms>

清单 2 中有三项 GC 日志记录。我将不会提供完全的说明,而是推荐一篇由 Sam Borman 所写的很好 的文章“Sensible Sanitation”(请参阅 参考资料)。对于我们的目的, 需要与像对 Sun JVM 的日志那样推算出同样类型的信息。好的方面是有一些计算结果已经是现成的了。 例如,如果分析 AF[31] (事件 31 分配失败),将会看到 GC 之间 的间隔、恢复的内存数量、事件的持续时间。我们可以根据这些数字计算其他所需要的值。


这些数字有什么意义

如何看待这些数字取决于所要得到的结果。在许多服务器应用程序中,它归结为 缩短暂停时间,这又归结为减少所发生的完全收集的持续时间和次数。下个月,我们将探讨如何用这些信息 调优曾经受这个问题困扰的一个真实应用程序。


参考资料


作者简介

Jack Shirazi 是 JavaPerformanceTuning.com的董事,也是 Java Performance Tuning, 2nd Edition (O'Reilly) 一书的作者。

Kirk Pepperdine 是 Java Performance Tuning.com 的首席技术官,并且在过去 15 年一直关注对象技术和性能调优。Kirk 是 Ant Developer's Handbook (MacMillan)一书的合著者。

  评论这张
 
阅读(1214)| 评论(0)
推荐 转载

历史上的今天

在LOFTER的更多文章

评论

<#--最新日志,群博日志--> <#--推荐日志--> <#--引用记录--> <#--博主推荐--> <#--随机阅读--> <#--首页推荐--> <#--历史上的今天--> <#--被推荐日志--> <#--上一篇,下一篇--> <#-- 热度 --> <#-- 网易新闻广告 --> <#--右边模块结构--> <#--评论模块结构--> <#--引用模块结构--> <#--博主发起的投票-->
 
 
 
 
 
 
 
 
 
 
 
 
 
 

页脚

网易公司版权所有 ©1997-2017