6

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]
trincot
  • 317,000
  • 35
  • 244
  • 286
St.Antario
  • 26,175
  • 41
  • 130
  • 318
  • What is the problem you're trying to debug? What are the symptoms? – biziclop Aug 30 '17 at 15:05
  • @biziclop GC time is about 10% of the whole application running time... – St.Antario Aug 30 '17 at 15:06
  • So what you need to tune is not your garbage collection but the number of objects that you are creating and get discarded. – RealSkeptic Aug 30 '17 at 15:07
  • @RealSkeptic The issue is that is a spark application. I don't kind of control all this objects – St.Antario Aug 30 '17 at 15:08
  • Okay, in that case you need to look at how that time is distributed: do you have a few massive GC rounds or many tiny ones all the time? (From the data I suspect it's the former.) Ideally you also need to identify what objects make up the unreachable part of the heap. And yeah, ideally you should just not allocate that many objects. – biziclop Aug 30 '17 at 15:09
  • Just adding to @biziclop suggestion, if you're using oracle's JVM, you can add the following options to your VM `-verbosegc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -Xloggc:/gc.log` to have a pretty verbose gc log. To analyse it, in my opinion, I found [gceasy.io](http://gceasy.io/) to be pretty helpful – pabrantes Aug 30 '17 at 15:17
  • @pabrantes Is it true that unreachable objects are ones that can be garbage collected? – St.Antario Aug 30 '17 at 15:19
  • @St.Antario Yes, unreachable objects (objects with no hard/strong references) are collected when GC runs. – Vince Aug 30 '17 at 15:21
  • @St.Antario yes. In Java terminology an object is said to be unreachable when there are no reachable path to it using only strong references from a GC Root. This means it's eligible to be garbage collected. – pabrantes Aug 30 '17 at 15:22
  • @St.Antario you should also check this [yourkit memory analysis documentation](https://www.yourkit.com/docs/java/help/inspections_mem.jsp) where they show how to explore your heap. It will help you out finding which objects are unreachable, maybe it will give you a few more points on where to look. – pabrantes Aug 30 '17 at 15:27
  • You aren't exposing enough details for anyone to even make proper assumpsions. If you can use JMC, I highly recommend using it, as you can easily view where the allocations are coming from (VisualVM also allows this, but it seems to be bugged). Show us the heap dump so we can see what types of objects are being allocated. Show us your side of the code that's involved. – Vince Aug 30 '17 at 15:29
  • One thing that you definitely need to check is if you've got objects that have `finalize()` methods. Overuse of `finalize()` can cause exactly the kind of symptoms you're describing. – biziclop Aug 30 '17 at 15:29
  • @bizclop VisualVM & Yourkit gives that notice when objects are ready to be finalized, whether you create a custom implementation of `finalize` or not. His notification suggests `finalize` is definitely not the issue. Albeit it was suggested "*tuning the GC is not right solution*", that statement was made without any real basis - tuning the GC may be what is required. We can't really determine until OP releases the heap dump and allocations. – Vince Aug 30 '17 at 17:03
  • I ran your gc log through [gceasy](http://gceasy.io) and noticed that it reports 77.94gb of created bytes total, with an average creation of 1.69gb/s, that's way too much. I would say that the best bet would be to check the creation of temporary objects. – pabrantes Aug 31 '17 at 08:14

1 Answers1

2

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.

Vladimir Kondratyev
  • 709
  • 5
  • 6