Why does my heap consist mostly of unreachable objects?

1.1k views Asked by At

I just looked at my heap dump in YourKit profiler and saw the following reachable/unreachable statistics.

enter image description here

I'm not quite sure about this. Does it mean that almost all my heap consists of some garbage data and I need to strongly tune my G1. Or this is usual statistic?

Problem: GC time is about 10% of the application running time.

Is my understanding correct about that unreachable objects are ones which can be Garbage Collected or YourKit meant something different about it? Here is the piece of GC log (Using CMS):

2.823: [GC (Metadata GC Threshold) [PSYoungGen: 420257K->52400K(564736K)] 420257K->52488K(1854976K), 0.0607756 secs] [Times: user=0.18 sys=0.01, real=0.06 secs] 
2.884: [Full GC (Metadata GC Threshold) [PSYoungGen: 52400K->0K(564736K)] [ParOldGen: 88K->51480K(903680K)] 52488K->51480K(1468416K), [Metaspace: 20809K->20809K(1067008K)], 0.1990115 secs] [Times: user=0.59 sys=0.01, real=0.20 secs] 
5.760: [GC (Metadata GC Threshold) [PSYoungGen: 287353K->65545K(664576K)] 338833K->117033K(1568256K), 0.0571198 secs] [Times: user=0.13 sys=0.02, real=0.06 secs] 
5.818: [Full GC (Metadata GC Threshold) [PSYoungGen: 65545K->0K(664576K)] [ParOldGen: 51488K->103745K(1605120K)] 117033K->103745K(2269696K), [Metaspace: 34820K->34772K(1079296K)], 0.1841317 secs] [Times: user=0.51 sys=0.02, real=0.18 secs] 
9.099: [GC (Allocation Failure) [PSYoungGen: 598528K->61614K(796672K)] 702273K->165367K(2401792K), 0.0557993 secs] [Times: user=0.23 sys=0.03, real=0.06 secs] 
9.965: [GC (Allocation Failure) [PSYoungGen: 796334K->33251K(969216K)] 900087K->173388K(2574336K), 0.0492724 secs] [Times: user=0.22 sys=0.04, real=0.05 secs] 
11.085: [GC (Allocation Failure) [PSYoungGen: 969187K->49292K(1016320K)] 1109324K->189430K(2621440K), 0.0904503 secs] [Times: user=0.40 sys=0.00, real=0.09 secs] 
11.855: [GC (Allocation Failure) [PSYoungGen: 985228K->64233K(1375232K)] 1125366K->204379K(2980352K), 0.1003579 secs] [Times: user=0.38 sys=0.06, real=0.10 secs] 
12.625: [GC (Allocation Failure) [PSYoungGen: 1363689K->75774K(1375232K)] 1503835K->227247K(2980352K), 0.0790738 secs] [Times: user=0.37 sys=0.16, real=0.08 secs] 
13.341: [GC (Allocation Failure) [PSYoungGen: 1375230K->87028K(2066944K)] 1526703K->249534K(3672064K), 0.1147762 secs] [Times: user=0.55 sys=0.09, real=0.12 secs] 
14.375: [GC (Allocation Failure) [PSYoungGen: 2066932K->98795K(2078720K)] 2229438K->284557K(3683840K), 0.1174134 secs] [Times: user=0.57 sys=0.18, real=0.12 secs] 
15.465: [GC (Allocation Failure) [PSYoungGen: 2078699K->117243K(2798080K)] 2264461K->317809K(4403200K), 0.1130871 secs] [Times: user=0.76 sys=0.19, real=0.11 secs] 
16.769: [GC (Allocation Failure) [PSYoungGen: 2798075K->134647K(2815488K)] 2998641K->363601K(4420608K), 0.1855432 secs] [Times: user=1.05 sys=0.29, real=0.19 secs] 
18.117: [GC (Allocation Failure) [PSYoungGen: 2815479K->133511K(3842560K)] 3044433K->411609K(5447680K), 0.2329040 secs] [Times: user=0.81 sys=0.13, real=0.23 secs] 
19.965: [GC (Allocation Failure) [PSYoungGen: 3816327K->117907K(3852288K)] 4094425K->476525K(5457408K), 0.1902845 secs] [Times: user=1.06 sys=0.33, real=0.19 secs] 
21.745: [GC (Allocation Failure) [PSYoungGen: 3800723K->70957K(4020224K)] 4159341K->541079K(5625344K), 0.1766376 secs] [Times: user=1.02 sys=0.33, real=0.17 secs] 
23.425: [GC (Allocation Failure) [PSYoungGen: 3924781K->73249K(4021760K)] 4394903K->607715K(5626880K), 0.1285575 secs] [Times: user=0.70 sys=0.18, real=0.13 secs] 
25.186: [GC (Allocation Failure) [PSYoungGen: 3927073K->73147K(4021248K)] 4461539K->674821K(5626368K), 0.1243413 secs] [Times: user=0.69 sys=0.21, real=0.12 secs] 
26.906: [GC (Allocation Failure) [PSYoungGen: 3936187K->72831K(4022272K)] 4537861K->741865K(5627392K), 0.1476289 secs] [Times: user=0.85 sys=0.29, real=0.15 secs] 
28.644: [GC (Allocation Failure) [PSYoungGen: 3935871K->74110K(4028928K)] 4604905K->811056K(5634048K), 0.1401820 secs] [Times: user=0.58 sys=0.38, real=0.14 secs] 
30.420: [GC (Allocation Failure) [PSYoungGen: 3954046K->74890K(4030464K)] 4690992K->880140K(5635584K), 0.1217263 secs] [Times: user=1.02 sys=0.14, real=0.12 secs] 
32.119: [GC (Allocation Failure) [PSYoungGen: 3954826K->74036K(4038656K)] 4760076K->947726K(5643776K), 0.1349601 secs] [Times: user=0.79 sys=0.17, real=0.14 secs] 
33.844: [GC (Allocation Failure) [PSYoungGen: 3971892K->74611K(4039680K)] 4845582K->1016221K(5644800K), 0.1579372 secs] [Times: user=1.31 sys=0.18, real=0.16 secs] 
35.604: [GC (Allocation Failure) [PSYoungGen: 3972467K->73896K(4047360K)] 4914077K->1084130K(5652480K), 0.1553432 secs] [Times: user=0.89 sys=0.09, real=0.16 secs] 
37.416: [GC (GCLocker Initiated GC) [PSYoungGen: 3988648K->73759K(4048384K)] 4998892K->1152107K(5653504K), 0.1948397 secs] [Times: user=0.94 sys=0.18, real=0.19 secs] 
39.315: [GC (Allocation Failure) [PSYoungGen: 3988511K->74582K(4056064K)] 5066932K->1221883K(5661184K), 0.1410819 secs] [Times: user=0.83 sys=0.34, real=0.14 secs] 
41.105: [GC (Allocation Failure) [PSYoungGen: 4005206K->76174K(4057088K)] 5152507K->1292051K(5662208K), 0.1966487 secs] [Times: user=0.96 sys=0.23, real=0.19 secs] 
42.866: [GC (Allocation Failure) [PSYoungGen: 4006798K->75063K(4064768K)] 5222675K->1361707K(5669888K), 0.1755286 secs] [Times: user=0.77 sys=0.13, real=0.17 secs] 
44.841: [GC (Allocation Failure) [PSYoungGen: 4020535K->76560K(4064768K)] 5307179K->1432324K(5669888K), 0.1492622 secs] [Times: user=0.93 sys=0.23, real=0.15 secs] 
46.652: [GC (Allocation Failure) [PSYoungGen: 4022032K->76593K(4071936K)] 5377796K->1503428K(5677056K), 0.1457041 secs] [Times: user=0.92 sys=0.07, real=0.15 secs] 
48.803: [GC (Allocation Failure) [PSYoungGen: 4035377K->72513K(4071424K)] 5462212K->1570356K(5676544K), 0.1883641 secs] [Times: user=1.09 sys=0.18, real=0.19 secs] 
48.992: [Full GC (Ergonomics) [PSYoungGen: 72513K->0K(4071424K)] [ParOldGen: 1497843K->1521336K(3507200K)] 1570356K->1521336K(7578624K), [Metaspace: 41385K->41378K(1085440K)], 2.5937473 secs] [Times: user=23.36 sys=0.04, real=2.60 secs] 
1

There are 1 answers

0
Vladimir Kondratyev On

Your application creates a lot of temporary objects. That is why GC takes so much time. Please take a look at article "Excessive garbage allocation" https://www.yourkit.com/docs/java/help/excessive_gc.jsp You will be able to find places that create temporary objects.