JVM YGC 系统耗时很长
 |
qwertasdfg123
2013-05-15
{Heap before GC invocations=1091 (full 7):
PSYoungGen total 536448K, used 531633K [0x00000007d5560000, 0x00000007fce30000, 0x0000000800000000) eden space 530688K, 100% used [0x00000007d5560000,0x00000007f5ba0000,0x00000007f5ba0000) from space 5760K, 16% used [0x00000007f5ba0000,0x00000007f5c8c5c8,0x00000007f6140000) to space 5568K, 0% used [0x00000007fc8c0000,0x00000007fc8c0000,0x00000007fce30000) PSOldGen total 699072K, used 184580K [0x0000000780000000, 0x00000007aaab0000, 0x00000007d5560000) object space 699072K, 26% used [0x0000000780000000,0x000000078b441310,0x00000007aaab0000) PSPermGen total 151744K, used 87681K [0x0000000770000000, 0x0000000779430000, 0x0000000780000000) object space 151744K, 57% used [0x0000000770000000,0x00000007755a07a0,0x0000000779430000) 2013-05-10T07:59:48.348+0800: 23088.496: [GC [PSYoungGen: 531633K->3201K(642304K)] 716214K->187911K(1341376K), 5.7257820 secs] [Times: user=18.12 sys=5.45, real=5.73 secs] Heap after GC invocations=1091 (full 7): PSYoungGen total 642304K, used 3201K [0x00000007d5560000, 0x00000007fce70000, 0x0000000800000000) eden space 636736K, 0% used [0x00000007d5560000,0x00000007d5560000,0x00000007fc330000) from space 5568K, 57% used [0x00000007fc8c0000,0x00000007fcbe0518,0x00000007fce30000) to space 5696K, 0% used [0x00000007fc330000,0x00000007fc330000,0x00000007fc8c0000) PSOldGen total 699072K, used 184709K [0x0000000780000000, 0x00000007aaab0000, 0x00000007d5560000) object space 699072K, 26% used [0x0000000780000000,0x000000078b461770,0x00000007aaab0000) PSPermGen total 151744K, used 87681K [0x0000000770000000, 0x0000000779430000, 0x0000000780000000) object space 151744K, 57% used [0x0000000770000000,0x00000007755a07a0,0x0000000779430000) } {Heap before GC invocations=1093 (full 7): PSYoungGen total 642432K, used 642410K [0x00000007d5560000, 0x0000000800000000, 0x0000000800000000) eden space 636736K, 100% used [0x00000007d5560000,0x00000007fc330000,0x00000007fc330000) from space 5696K, 99% used [0x00000007fc330000,0x00000007fc8baae8,0x00000007fc8c0000) to space 8512K, 0% used [0x00000007ff7b0000,0x00000007ff7b0000,0x0000000800000000) PSOldGen total 699072K, used 189769K [0x0000000780000000, 0x00000007aaab0000, 0x00000007d5560000) object space 699072K, 27% used [0x0000000780000000,0x000000078b952670,0x00000007aaab0000) PSPermGen total 151744K, used 87721K [0x0000000770000000, 0x0000000779430000, 0x0000000780000000) object space 151744K, 57% used [0x0000000770000000,0x00000007755aa468,0x0000000779430000) 2013-05-10T08:00:16.698+0800: 23116.846: [GC [PSYoungGen: 642410K->8501K(683072K)] 832180K->204136K(1382144K), 0.9704810 secs] [Times: user=2.22 sys=9.37, real=0.97 secs] Heap after GC invocations=1093 (full 7): PSYoungGen total 683072K, used 8501K [0x00000007d5560000, 0x0000000800000000, 0x0000000800000000) eden space 674560K, 0% used [0x00000007d5560000,0x00000007d5560000,0x00000007fe820000) from space 8512K, 99% used [0x00000007ff7b0000,0x00000007ffffd658,0x0000000800000000) to space 12224K, 0% used [0x00000007fe820000,0x00000007fe820000,0x00000007ff410000) PSOldGen total 699072K, used 195634K [0x0000000780000000, 0x00000007aaab0000, 0x00000007d5560000) object space 699072K, 27% used [0x0000000780000000,0x000000078bf0c9b0,0x00000007aaab0000) PSPermGen total 151744K, used 87721K [0x0000000770000000, 0x0000000779430000, 0x0000000780000000) object space 151744K, 57% used [0x0000000770000000,0x00000007755aa468,0x0000000779430000) } {Heap before GC invocations=1094 (full 7): PSYoungGen total 683072K, used 683061K [0x00000007d5560000, 0x0000000800000000, 0x0000000800000000) eden space 674560K, 100% used [0x00000007d5560000,0x00000007fe820000,0x00000007fe820000) from space 8512K, 99% used [0x00000007ff7b0000,0x00000007ffffd658,0x0000000800000000) to space 12224K, 0% used [0x00000007fe820000,0x00000007fe820000,0x00000007ff410000) PSOldGen total 699072K, used 195634K [0x0000000780000000, 0x00000007aaab0000, 0x00000007d5560000) object space 699072K, 27% used [0x0000000780000000,0x000000078bf0c9b0,0x00000007aaab0000) PSPermGen total 151744K, used 87734K [0x0000000770000000, 0x0000000779430000, 0x0000000780000000) object space 151744K, 57% used [0x0000000770000000,0x00000007755ad948,0x0000000779430000) 2013-05-10T08:00:19.275+0800: 23119.423: [GC [PSYoungGen: 683061K->10061K(684672K)] 878696K->211940K(1383744K), 0.9747900 secs] [Times: user=4.68 sys=6.25, real=0.98 secs] Heap after GC invocations=1094 (full 7): PSYoungGen total 684672K, used 10061K [0x00000007d5560000, 0x0000000800000000, 0x0000000800000000) eden space 674560K, 0% used [0x00000007d5560000,0x00000007d5560000,0x00000007fe820000) from space 10112K, 99% used [0x00000007fe820000,0x00000007ff1f3790,0x00000007ff200000) to space 13632K, 0% used [0x00000007ff2b0000,0x00000007ff2b0000,0x0000000800000000) PSOldGen total 699072K, used 201878K [0x0000000780000000, 0x00000007aaab0000, 0x00000007d5560000) object space 699072K, 28% used [0x0000000780000000,0x000000078c525ac8,0x00000007aaab0000) PSPermGen total 151744K, used 87734K [0x0000000770000000, 0x0000000779430000, 0x0000000780000000) object space 151744K, 57% used [0x0000000770000000,0x00000007755ad948,0x0000000779430000) } 采用的是ParallelGC，NewRadio=2，-Xms1024m -Xmx2048m。 |
|
qwertasdfg123
2013-05-15
sys time主要耗在哪儿呢
|
 |
RednaxelaFX
2013-05-15
sys高本来最容易怀疑的原因就是发生了swap。你的程序如果持续出现GC时sys高的情况，可以查一下日志看看相近的时间有没有频繁swap。《Java Performance》书里详细讲了如何使用各种工具来查看这些信息。
为啥说“本来”呢？因为GC时遇到swap（主要是page in）通常在full GC时会比较严重，因为old gen可能比较大，而里面可能有很多对象已经好长一段时间没被碰过，背后的内存页已经被swap出去了；到GC时要访问堆里所有活对象，这些已经被swap out的对象又得再swap in，这就慢了。 而楼主所说的情况是在YGC时发生的。YGC主要碰到的是young gen里的对象，这些对象都应该很热所以不太可能被swap出去。但YGC其实也会跟old gen打交道： 1、root set的一部分是old gen的remember set 2、young gen里活对象可能被晋升到old gen 从楼主给的日志可以看到几次YGC后确实有一些对象被晋升到old gen，而且old gen也发生了扩容。这些行为有可能伴随swap。所以还是请楼主先看看swap相关的数据。 |
|
qwertasdfg123
2013-05-16
出现这个状况的几率其实很少，从监控数据来看，swap很少。但中断和上下文特多。有时候系统cpu达到了98%，这个是否跟UseAdaptiveSizePolicy有关？
promotion到old gen的对象其实很少，而且old gen也是比较大。 Young gen扩容的时候，是不是需要通过内核分配内存呢？ 在出现cpu高的vmstat数据： procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 48 0 36144 1411692 271876 12661920 0 0 1 7 0 0 5 1 94 0 0 49 0 36144 1410324 271876 12662240 0 0 0 0 34640 9184 3 97 0 0 0 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 39 0 37380 1452452 267888 12400984 0 0 1 7 0 0 5 1 94 0 0 6 0 37436 1464964 267720 12379936 0 56 0 56 56708 38711 40 23 37 0 0 |
|
RednaxelaFX
2013-05-16
HotSpot VM里GC堆的空间扩容都要做系统调用。Linux上用的是mmap。
CPU高多半跟UseAdaptiveSizePolicy没关系。那个计算很简单，不怎么吃资源。 有两个想法： 1、要不要试试减少ParallelGC的线程数？-XX:ParallelGCThreads= 可以先用jinfo看看当前这个参数被VM自动设置到了多少，然后稍微设小点 2、这个应用是需要跟网卡打交道的么？是的话，请求量大不？ |
|
qwertasdfg123
2013-05-16
1. ParallelGCThreads默认的，18个线程。
2. 网络IO、连接都不高 出现System CPU高的情况非常少。一般都是Eden 100%， Survivor 99%的情况。但不是充分条件。 现在调整了一下jvm参数，-Xms2048m -Xmx2048m -Xss256k -Xmn1024m -XX:-UseAdaptiveSizePolicy 还是有Sys Time较大的情况，像Old Gen的对象由几M到100多M的时候，Sys Time花了30多s。但只在开始阶段出现这样的情况，几个小时过后，基本上Sys Time都是0。有没有可能是JVM本身有问题呢？用的1.6.0.25-b06 没有做调整的机器还是毫无规律的出现这样的问题。 以下是调整过后的GC {Heap before GC invocations=18 (full 1): PSYoungGen total 917504K, used 916793K [0x00000007c0000000, 0x0000000800000000, 0x0000000800000000) eden space 786432K, 100% used [0x00000007c0000000,0x00000007f0000000,0x00000007f0000000) from space 131072K, 99% used [0x00000007f8000000,0x00000007fff4e7b8,0x0000000800000000) to space 131072K, 0% used [0x00000007f0000000,0x00000007f0000000,0x00000007f8000000) PSOldGen total 1048576K, used 6562K [0x0000000780000000, 0x00000007c0000000, 0x00000007c0000000) object space 1048576K, 0% used [0x0000000780000000,0x0000000780668b90,0x00000007c0000000) PSPermGen total 92288K, used 92181K [0x0000000770000000, 0x0000000775a20000, 0x0000000780000000) object space 92288K, 99% used [0x0000000770000000,0x0000000775a055e0,0x0000000775a20000) 2013-05-14T21:06:36.203+0800: 137.229: [GC [PSYoungGen: 916793K->46390K(917504K)] 923356K->138541K(1966080K), 5.6026200 secs] [Times: user=0.00 sys=35.20 [Times: user=0.00 sys=40.97, real=5.94 secs] Heap after GC invocations=18 (full 1): PSYoungGen total 917504K, used 45699K [0x00000007c0000000, 0x0000000800000000, 0x0000000800000000) eden space 786432K, 0% used [0x00000007c0000000,0x00000007c0000000,0x00000007f0000000) from space 131072K, 34% used [0x00000007f0000000,0x00000007f2ca0ca8,0x00000007f8000000) to space 131072K, 0% used [0x00000007f8000000,0x00000007f8000000,0x0000000800000000) PSOldGen total 1048576K, used 101418K [0x0000000780000000, 0x00000007c0000000, 0x00000007c0000000) object space 1048576K, 9% used [0x0000000780000000,0x000000078630abb0,0x00000007c0000000) PSPermGen total 87680K, used 87672K [0x0000000770000000, 0x00000007755a0000, 0x0000000780000000) object space 87680K, 99% used [0x0000000770000000,0x000000077559e218,0x00000007755a0000) } {Heap before GC invocations=19 (full 1): PSYoungGen total 917504K, used 832131K [0x00000007c0000000, 0x0000000800000000, 0x0000000800000000) eden space 786432K, 100% used [0x00000007c0000000,0x00000007f0000000,0x00000007f0000000) from space 131072K, 34% used [0x00000007f0000000,0x00000007f2ca0ca8,0x00000007f8000000) to space 131072K, 0% used [0x00000007f8000000,0x00000007f8000000,0x0000000800000000) PSOldGen total 1048576K, used 101418K [0x0000000780000000, 0x00000007c0000000, 0x00000007c0000000) object space 1048576K, 9% used [0x0000000780000000,0x000000078630abb0,0x00000007c0000000) PSPermGen total 87872K, used 87739K [0x0000000770000000, 0x00000007755d0000, 0x0000000780000000) object space 87872K, 99% used [0x0000000770000000,0x00000007755aefb0,0x00000007755d0000) 2013-05-14T21:06:54.719+0800: 173.502: [GC [PSYoungGen: 832131K->32220K(917504K)] 933550K->1477 [Times: user=0.00 sys=5.63, r [Times: user=0.27 sys=0.09, real=0.03 secs] Heap after GC invocations=19 (full 1): PSYoungGen total 917504K, used 32220K [0x00000007c0000000, 0x0000000800000000, 0x0000000800000000) eden space 786432K, 0% used [0x00000007c0000000,0x00000007c0000000,0x00000007f0000000) from space 131072K, 24% used [0x00000007f8000000,0x00000007f9f77130,0x0000000800000000) to space 131072K, 0% used [0x00000007f0000000,0x00000007f0000000,0x00000007f8000000) PSOldGen total 1048576K, used 115524K [0x0000000780000000, 0x00000007c0000000, 0x00000007c0000000) object space 1048576K, 11% used [0x0000000780000000,0x00000007870d1188,0x00000007c0000000) PSPermGen total 87872K, used 87739K [0x0000000770000000, 0x00000007755d0000, 0x0000000780000000) object space 87872K, 99% used [0x0000000770000000,0x00000007755aefb0,0x00000007755d0000) } {Heap before GC invocations=77 (full 1): PSYoungGen total 917504K, used 787894K [0x00000007c0000000, 0x0000000800000000, 0x0000000800000000) eden space 786432K, 99% used [0x00000007c0000000,0x00000007efffd3d8,0x00000007f0000000) from space 131072K, 1% used [0x00000007f0000000,0x00000007f01704f0,0x00000007f8000000) to space 131072K, 0% used [0x00000007f8000000,0x00000007f8000000,0x0000000800000000) PSOldGen total 1048576K, used 153539K [0x0000000780000000, 0x00000007c0000000, 0x00000007c0000000) object space 1048576K, 14% used [0x0000000780000000,0x00000007895f0ce8,0x00000007c0000000) PSPermGen total 89024K, used 88854K [0x0000000770000000, 0x00000007756f0000, 0x0000000780000000) object space 89024K, 99% used [0x0000000770000000,0x00000007756c5ba0,0x00000007756f0000) 2013-05-14T21:16:22.784+0800: 741.568: [GC [PSYoungGen: 787894K->1391K(917504K)] 941433K->155067K(1966080K), 0.2376500 secs] [Times: user=2.14 sys=1.42, real=0.24 secs] Heap after GC invocations=77 (full 1): PSYoungGen total 917504K, used 1391K [0x00000007c0000000, 0x0000000800000000, 0x0000000800000000) eden space 786432K, 0% used [0x00000007c0000000,0x00000007c0000000,0x00000007f0000000) from space 131072K, 1% used [0x00000007f8000000,0x00000007f815bf18,0x0000000800000000) to space 131072K, 0% used [0x00000007f0000000,0x00000007f0000000,0x00000007f8000000) PSOldGen total 1048576K, used 153675K [0x0000000780000000, 0x00000007c0000000, 0x00000007c0000000) object space 1048576K, 14% used [0x0000000780000000,0x0000000789612ce8,0x00000007c0000000) PSPermGen total 89024K, used 88854K [0x0000000770000000, 0x00000007756f0000, 0x0000000780000000) object space 89024K, 99% used [0x0000000770000000,0x00000007756c5ba0,0x00000007756f0000) } {Heap before GC invocations=481 (full 2): PSYoungGen total 917504K, used 787960K [0x00000007c0000000, 0x0000000800000000, 0x0000000800000000) eden space 786432K, 100% used [0x00000007c0000000,0x00000007f0000000,0x00000007f0000000) from space 131072K, 1% used [0x00000007f8000000,0x00000007f817e3f8,0x0000000800000000) to space 131072K, 0% used [0x00000007f0000000,0x00000007f0000000,0x00000007f8000000) PSOldGen total 1048576K, used 200707K [0x0000000780000000, 0x00000007c0000000, 0x00000007c0000000) object space 1048576K, 19% used [0x0000000780000000,0x000000078c400e68,0x00000007c0000000) PSPermGen total 198144K, used 94605K [0x0000000770000000, 0x000000077c180000, 0x0000000780000000) object space 198144K, 47% used [0x0000000770000000,0x0000000775c63428,0x000000077c180000) 2013-05-14T22:19:20.956+0800: 4519.739: [GC [PSYoungGen: 787960K->1814K(917504K)] 988668K->202666K(1966080K), 0.2685890 secs] [Times: user=2.36 sys=2.12, real=0.27 secs] Heap after GC invocations=481 (full 2): PSYoungGen total 917504K, used 1814K [0x00000007c0000000, 0x0000000800000000, 0x0000000800000000) eden space 786432K, 0% used [0x00000007c0000000,0x00000007c0000000,0x00000007f0000000) from space 131072K, 1% used [0x00000007f0000000,0x00000007f01c5a40,0x00000007f8000000) to space 131072K, 0% used [0x00000007f8000000,0x00000007f8000000,0x0000000800000000) PSOldGen total 1048576K, used 200851K [0x0000000780000000, 0x00000007c0000000, 0x00000007c0000000) object space 1048576K, 19% used [0x0000000780000000,0x000000078c424e68,0x00000007c0000000) PSPermGen total 198144K, used 94605K [0x0000000770000000, 0x000000077c180000, 0x0000000780000000) object space 198144K, 47% used [0x0000000770000000,0x0000000775c63428,0x000000077c180000) } |
