大堆的 Java 速度较慢,没有过多的 gc-ing

Posted

技术标签:

【中文标题】大堆的 Java 速度较慢,没有过多的 gc-ing【英文标题】:Java slower with large heap, no excessive gc-ing 【发布时间】:2015-09-22 09:13:13 【问题描述】:

原问题

我正在运行一个 Java 程序,比如 program.jar,它有一个“小”初始堆 (1gb) 和一个“大”初始堆 (16gb)。当我使用小的初始堆运行它时,即

java -jar -Xms1g -Xmx16g program.jar

程序在 12 秒后终止(多次运行的平均值)。相反,当我使用较大的初始堆运行它时,即

java -jar -Xms16g -Xmx16g program.jar

程序在 30 秒后终止(多次运行的平均值)。

我从 SO 的其他问题了解到,一般来说,大堆可能会导致过多的垃圾收集,从而减慢程序的速度:

Java very large heap sizes Does the Sun JVM slow down when more memory is allocated via -Xmx? Under what circumstances does Java performance degrade with more memory? Java slower with big heap

但是,当我运行带有标志 -verbose:gc 的 program.jar 时,由于初始堆很大,因此不会报告任何 gc 活动。对于小的初始堆,在我开始测量时间之前,在程序的初始化阶段只有一些 gc 活动。因此,过多的垃圾收集似乎并不能澄清我的观察。

为了让它更混乱(至少对我来说),我有一个功能等效的程序,比如 program2.jar,它具有与 program.jar 相同的输入输出行为。主要区别在于 program2.jar 使用的数据结构效率低于 program.jar,至少在内存方面(实际上我正在尝试确定 program2.jar 在时间方面是否也效率较低)。但不管我是用小的初始堆还是大的初始堆运行 program2.jar,它总是在大约 22 秒内终止(包括大约 2-3 秒的 gc-ing)。

所以,这是我的问题:(如何)大堆可以减慢程序,除了过度 gc-ing 吗?

(这个问题可能看起来和Georg在“Java slower with big heap”中的问题很像,但他的问题竟然与堆无关。就我而言,我觉得它必须有事可做使用堆,因为它是 program.jar 的两次运行之间的唯一区别。)

以下是一些可能相关的细节。我正在使用 Java 7,OpenJDK:

> java -version
java version "1.7.0_75"
OpenJDK Runtime Environment (rhel-2.5.4.0.el6_6-x86_64 u75-b13)
OpenJDK 64-Bit Server VM (build 24.75-b04, mixed mode)

我的机器在两个插槽中有两个 E5-2690V3 处理器 (http://ark.intel.com/products/81713)(超线程和 Turbo Boost 已禁用),并且有充足的内存 (64gb),其中大约一半在运行程序之前是空闲的:

> free
             total       used       free     shared    buffers     cached
Mem:      65588960   31751316   33837644         20     154616   23995164
-/+ buffers/cache:    7601536   57987424
Swap:      1023996      11484    1012512

最后,程序有多个线程(大约 70 个)。

编辑 1

回复Bruno Reis和kdgregory

我收集了一些额外的统计数据。这适用于具有较小初始堆的 program.jar:

Command being timed: "java -Xms1g -Xmx16g -verbose:gc -jar program.jar"
User time (seconds): 339.11
System time (seconds): 29.86
Percent of CPU this job got: 701%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:52.61
Average shared text size (kbytes): 0
Average unshared data size (kbytes): 0
Average stack size (kbytes): 0
Average total size (kbytes): 0
Maximum resident set size (kbytes): 12192224
Average resident set size (kbytes): 0
Major (requiring I/O) page faults: 1
Minor (reclaiming a frame) page faults: 771372
Voluntary context switches: 7446
Involuntary context switches: 27788
Swaps: 0
File system inputs: 10216
File system outputs: 120
Socket messages sent: 0
Socket messages received: 0
Signals delivered: 0
Page size (bytes): 4096
Exit status: 0

这适用于具有较大初始堆的 program.jar:

Command being timed: "java -Xms16g -Xmx16g -verbose:gc -jar program.jar"
User time (seconds): 769.13
System time (seconds): 28.04
Percent of CPU this job got: 1101%
Elapsed (wall clock) time (h:mm:ss or m:ss): 1:12.34
Average shared text size (kbytes): 0
Average unshared data size (kbytes): 0
Average stack size (kbytes): 0
Average total size (kbytes): 0
Maximum resident set size (kbytes): 10974528
Average resident set size (kbytes): 0
Major (requiring I/O) page faults: 16
Minor (reclaiming a frame) page faults: 687727
Voluntary context switches: 6769
Involuntary context switches: 68465
Swaps: 0
File system inputs: 2032
File system outputs: 160
Socket messages sent: 0
Socket messages received: 0
Signals delivered: 0
Page size (bytes): 4096
Exit status: 0

(这里报告的挂钟时间与我原来的帖子中报告的时间不同,因为之前的初始化阶段是不定时的。)

编辑 2

响应 8472 最初的answer 和后来的comment

我收集了一些关于缓存的统计数据。这是针对具有较小初始堆(平均超过 30 次运行)的 program.jar:

  2719852136 cache-references                                              ( +-  1.56% ) [42.11%]
  1931377514 cache-misses              #   71.010 % of all cache refs      ( +-  0.07% ) [42.11%]
 56748034419 L1-dcache-loads                                               ( +-  1.34% ) [42.12%]
 16334611643 L1-dcache-load-misses     #   28.78% of all L1-dcache hits    ( +-  1.70% ) [42.12%]
 24886806040 L1-dcache-stores                                              ( +-  1.47% ) [42.12%]
  2438414068 L1-dcache-store-misses                                        ( +-  0.19% ) [42.13%]
           0 L1-dcache-prefetch-misses                                    [42.13%]
    23243029 L1-icache-load-misses                                         ( +-  0.66% ) [42.14%]
  2424355365 LLC-loads                                                     ( +-  1.73% ) [42.15%]
   278916135 LLC-stores                                                    ( +-  0.30% ) [42.16%]
   515064030 LLC-prefetches                                                ( +-  0.33% ) [10.54%]
 63395541507 dTLB-loads                                                    ( +-  0.17% ) [15.82%]
  7402222750 dTLB-load-misses          #   11.68% of all dTLB cache hits   ( +-  1.87% ) [21.08%]
 20945323550 dTLB-stores                                                   ( +-  0.69% ) [26.34%]
   294311496 dTLB-store-misses                                             ( +-  0.16% ) [31.60%]
    17012236 iTLB-loads                                                    ( +-  2.10% ) [36.86%]
      473238 iTLB-load-misses          #    2.78% of all iTLB cache hits   ( +-  2.88% ) [42.12%]
 29390940710 branch-loads                                                  ( +-  0.18% ) [42.11%]
    19502228 branch-load-misses                                            ( +-  0.57% ) [42.11%]

53.771209341 seconds time elapsed                                          ( +-  0.42% )

这适用于具有较大初始堆(平均超过 30 次运行)的 program.jar:

 10465831994 cache-references                                              ( +-  3.00% ) [42.10%]
  1921281060 cache-misses              #   18.358 % of all cache refs      ( +-  0.03% ) [42.10%]
 51072650956 L1-dcache-loads                                               ( +-  2.14% ) [42.10%]
 24282459597 L1-dcache-load-misses     #   47.54% of all L1-dcache hits    ( +-  0.16% ) [42.10%]
 21447495598 L1-dcache-stores                                              ( +-  2.46% ) [42.10%]
  2441970496 L1-dcache-store-misses                                        ( +-  0.13% ) [42.10%]
           0 L1-dcache-prefetch-misses                                    [42.11%]
    24953833 L1-icache-load-misses                                         ( +-  0.78% ) [42.12%]
 10234572163 LLC-loads                                                     ( +-  3.09% ) [42.13%]
   240843257 LLC-stores                                                    ( +-  0.17% ) [42.14%]
   462484975 LLC-prefetches                                                ( +-  0.22% ) [10.53%]
 62564723493 dTLB-loads                                                    ( +-  0.10% ) [15.80%]
 12686305321 dTLB-load-misses          #   20.28% of all dTLB cache hits   ( +-  0.01% ) [21.06%]
 19201170089 dTLB-stores                                                   ( +-  1.11% ) [26.33%]
   279236455 dTLB-store-misses                                             ( +-  0.10% ) [31.59%]
    16259758 iTLB-loads                                                    ( +-  4.65% ) [36.85%]
      466127 iTLB-load-misses          #    2.87% of all iTLB cache hits   ( +-  6.68% ) [42.11%]
 28098428012 branch-loads                                                  ( +-  0.13% ) [42.10%]
    18707911 branch-load-misses                                            ( +-  0.82% ) [42.10%]

73.576058909 seconds time elapsed                                          ( +-  0.54% )

比较绝对数字,较大的初始堆导致 L1-dcache-load-misses 多 50% 和 dTLB-load-misses 多 70%。我对 dTLB-load-misses 进行了粗略计算,假设在我的 2.6 ghz 机器上为 100 个周期/未命中(来源:Wikipedia),这为大型初始堆提供了 484 秒的延迟,而284 秒延迟与小一个。我不知道如何将这个数字转换回每核延迟(可能不只是除以核数?),但数量级似乎是合理的。

在收集了这些统计信息后,我还对大小初始堆的 -XX:+PrintFlagsFinal 的输出进行了比较(基于这两种情况中的每一种情况的一次运行):

<     uintx InitialHeapSize                          := 17179869184     product           
---
>     uintx InitialHeapSize                          := 1073741824      product  

因此,-Xms 似乎不会影响其他标志。这也是具有较小初始堆的 program.jar 的 -XX:+PrintGCDetails 的输出:

[GC [PSYoungGen: 239882K->33488K(306176K)] 764170K->983760K(1271808K), 0.0840630 secs] [Times: user=0.70 sys=0.66, real=0.09 secs]
[Full GC [PSYoungGen: 33488K->0K(306176K)] [ParOldGen: 950272K->753959K(1508352K)] 983760K->753959K(1814528K) [PSPermGen: 2994K->2993K(21504K)], 0.0560900 secs] [Times: user=0.20 sys=0.03, real=0.05 secs]
[GC [PSYoungGen: 234744K->33056K(306176K)] 988704K->983623K(1814528K), 0.0416120 secs] [Times: user=0.69 sys=0.03, real=0.04 secs]
[GC [PSYoungGen: 264198K->33056K(306176K)] 1214765K->1212999K(1814528K), 0.0489600 secs] [Times: user=0.61 sys=0.23, real=0.05 secs]
[Full GC [PSYoungGen: 33056K->0K(306176K)] [ParOldGen: 1179943K->1212700K(2118656K)] 1212999K->1212700K(2424832K) [PSPermGen: 2993K->2993K(21504K)], 0.1589640 secs] [Times: user=2.27 sys=0.10, real=0.16 secs]
[GC [PSYoungGen: 230538K->33056K(431616K)] 1443238K->1442364K(2550272K), 0.0523620 secs] [Times: user=0.69 sys=0.23, real=0.05 secs]
[GC [PSYoungGen: 427431K->33152K(557568K)] 1836740K->1835676K(2676224K), 0.0774750 secs] [Times: user=0.64 sys=0.72, real=0.08 secs]
[Full GC [PSYoungGen: 33152K->0K(557568K)] [ParOldGen: 1802524K->1835328K(2897920K)] 1835676K->1835328K(3455488K) [PSPermGen: 2993K->2993K(21504K)], 0.2019870 secs] [Times: user=2.74 sys=0.13, real=0.20 secs]
[GC [PSYoungGen: 492503K->33280K(647168K)] 2327831K->2327360K(3545088K), 0.0870810 secs] [Times: user=0.61 sys=0.92, real=0.09 secs]
[Full GC [PSYoungGen: 33280K->0K(647168K)] [ParOldGen: 2294080K->2326876K(3603968K)] 2327360K->2326876K(4251136K) [PSPermGen: 2993K->2993K(21504K)], 0.0512730 secs] [Times: user=0.09 sys=0.12, real=0.05 secs]

Heap
 PSYoungGen  total 647168K, used 340719K [0x00000006aaa80000, 0x00000006dd000000, 0x0000000800000000)
  eden space 613376K, 55% used [0x00000006aaa80000,0x00000006bf73bc10,0x00000006d0180000)
  from space 33792K, 0% used [0x00000006d2280000,0x00000006d2280000,0x00000006d4380000)
  to   space 33792K, 0% used [0x00000006d0180000,0x00000006d0180000,0x00000006d2280000)
 ParOldGen   total 3603968K, used 2326876K [0x0000000400000000, 0x00000004dbf80000, 0x00000006aaa80000)
  object space 3603968K, 64% used [0x0000000400000000,0x000000048e0572d8,0x00000004dbf80000)
 PSPermGen   total 21504K, used 3488K [0x00000003f5a00000, 0x00000003f6f00000, 0x0000000400000000)
  object space 21504K, 16% used [0x00000003f5a00000,0x00000003f5d68070,0x00000003f6f00000)

对于具有较大初始堆的 program.jar:

Heap
 PSYoungGen  total 4893696K, used 2840362K [0x00000006aaa80000, 0x0000000800000000, 0x0000000800000000)
  eden space 4194816K, 67% used [0x00000006aaa80000,0x000000075804a920,0x00000007aab00000)
  from space 698880K, 0% used [0x00000007d5580000,0x00000007d5580000,0x0000000800000000)
  to   space 698880K, 0% used [0x00000007aab00000,0x00000007aab00000,0x00000007d5580000)
 ParOldGen   total 11185152K, used 0K [0x00000003fff80000, 0x00000006aaa80000, 0x00000006aaa80000)
  object space 11185152K, 0% used [0x00000003fff80000,0x00000003fff80000,0x00000006aaa80000)
 PSPermGen   total 21504K, used 3489K [0x00000003f5980000, 0x00000003f6e80000, 0x00000003fff80000)
  object space 21504K, 16% used [0x00000003f5980000,0x00000003f5ce8400,0x00000003f6e80000)

【问题讨论】:

在两次运行期间(1GB 与 16GB Xms),您是否有任何关于页面输出/输入量的信息? “没有报告任何 gc 活动”似乎很可疑;它表明您的程序的所有数据都保留在堆的“伊甸园”部分。任何可能需要 16 Gb 堆的东西似乎都至少涉及一些次要集合。 除了@BrunoReis 关于页面错误的建议之外,我还会查看交换统计信息和驻留集大小 (RSS)。我可以想象一个可能的情况,其中线程局部分配块分散并导致内存子系统需要更多工作,但是(1)70个线程似乎太低而不能成为一个真正的问题, (2) 除非您遇到分页,否则我无法想象会导致 3 倍的减速。 这里有一个链接可以帮助您获取每个进程的交换统计信息:***.com/a/7180078 我在问题中添加了一些统计数据。这足够还是您需要更多? 【参考方案1】:

访问内存会消耗 CPU 时间。访问更多内存不仅会线性地花费更多 CPU 时间,而且可能会增加缓存压力并因此增加未命中率,从而超线性地花费更多 CPU 时间。

使用perf stat java -jar ... 运行您的程序以查看缓存未命中数。见Perf tutorial

图片来源: “系统性能:企业和云平装本”,Brendan Gregg,ISBN:978-0133390094


由于初始堆大小也会影响 eden 空间大小,并且较小的 eden 空间会触发 GC,这可以导致更紧凑的堆,这可能对缓存更加友好(没有临时启动对象在堆中乱扔垃圾)。

要减少两次运行之间的差异数量,请尝试将两次运行的初始和最大年轻代大小设置为相同的值,以便只有老一代大小不同。这应该 - 可能 - 导致相同的性能。

顺便说一句:您也可以尝试使用大页面启动 JVM,它可能(您需要衡量!)通过进一步减少 TLB 未命中来为您带来一些额外的 % 性能。

未来读者注意:限制新生代大小并不一定会让你的 JVM 更快,它只会触发一次 GC,而这恰好使 @Peng 的特定工作负载更快。 启动后手动触发 GC 也会有同样的效果。

【讨论】:

我关于没有 gc-activity 的声明不够精确(现已修复)。我的意思是在我开始测量时间后没有 gc-activity。对于小的初始堆,其实在程序的初始化阶段有一些gc-activity。我将 gc 输出添加到问题中(在编辑 2 中)。我没有意识到这可能很重要——对不起。当你提到“一切都适合年轻代”时,我意识到在初始堆较小的情况下,老年代的 64% 似乎被占用,而在初始堆较大的情况下则为 0%,所以压缩可能在这里起作用? 叹息。是的。很重要。如果没有 GC,您将在堆上混合短期对象和长期存在的临时对象。使用 GC,您可以剔除所有短寿命的 GC,并将长寿命的 GC 并排放置,这可能使其对缓存更加友好。 就是这样!如果我将年轻代大小设置为相同的值,则小/大初始堆的性能变得相当。所以,总结一下:性能的差异是由缓存行为的差异来解释的,这是由 gc 行为的差异来解释的,这是由年轻代大小的大小来解释的,它是由初始堆大小来解释的。非常感谢您的帮助:)。

以上是关于大堆的 Java 速度较慢,没有过多的 gc-ing的主要内容,如果未能解决你的问题,请参考以下文章

Oracle 11 查询在前 2 次执行时运行速度很快,随后运行速度较慢,没有计划更改

近期学习Java的收获

使用 MKL 编译时,Eigen C++ 运行速度较慢

遇到GitHub上图片无法加载或者加载速度较慢的解决办法

由于消费者速度较慢,Kafka 重新平衡主题中的数据

动态内存使用速度较慢是啥? [复制]