Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Why does my heap consist mostly of unreachable objects?

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] 
like image 244
St.Antario Avatar asked Aug 30 '17 15:08

St.Antario


People also ask

What are unreachable objects in heap dump?

A heap dump can contain unreachable objects, e.g. objects which should be garbage collected but stay around for various reasons. Usually this is due to optimizations in the garbage collection algorithm. The Memory Analyzer removes these objects by default from the object graph.

Why are objects stored in heap memory?

Heap space is used for the dynamic memory allocation of Java objects and JRE classes at runtime. New objects are always created in heap space, and the references to these objects are stored in stack memory. These objects have global access and we can access them from anywhere in the application.

Why are unreachable objects not garbage collected?

First and foremost, having unreachable objects inside heap at any given time is perfectly normal. Garbage Collection will clean the unreachable objects during the next run and will clean the heap from them. So, seeing unreachable data structures in heap dump is not evil nor abnormal.

How do I investigate heap dump?

Eclipse Memory Analyzer Tool ( MAT ) is used for analyzing heap dump files which contain objects in memory. Each heap dump file can be thought of as a snapshot in time and details the memory occupied by specific JVM threads.


1 Answers

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.

like image 57
Vladimir Kondratyev Avatar answered Oct 23 '22 20:10

Vladimir Kondratyev