1

Seen from this log that FinalReference takes lots of time.

 2018-07-27T18:14:33.101+0800: 38.263: [GC pause (G1 Evacuation Pause) (young)38.278: [SoftReference, 0 refs, 0.0004133 secs]38.279: [WeakReference, 232 refs, 0.0002595 secs]38.279: [FinalReference, 481 refs, 0.0938618 secs]38.373: [PhantomReference, 0 refs, 1 refs, 0.0003031 secs]38.373: [JNI Weak Reference, 0.0000113 secs], 0.1118731 secs]
       [Parallel Time: 15.0 ms, GC Workers: 4]
          [GC Worker Start (ms): Min: 38263.1, Avg: 38263.9, Max: 38266.1, Diff: 3.0]
          [Ext Root Scanning (ms): Min: 0.0, Avg: 1.7, Max: 2.5, Diff: 2.5, Sum: 6.7]
          [Update RS (ms): Min: 1.9, Avg: 2.4, Max: 2.7, Diff: 0.8, Sum: 9.5]
             [Processed Buffers: Min: 8, Avg: 37.2, Max: 91, Diff: 83, Sum: 149]
          [Scan RS (ms): Min: 0.5, Avg: 0.8, Max: 1.2, Diff: 0.7, Sum: 3.4]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.6, Max: 2.3, Diff: 2.3, Sum: 2.5]
          [Object Copy (ms): Min: 7.1, Avg: 8.6, Max: 9.2, Diff: 2.1, Sum: 34.2]
          [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
          [GC Worker Total (ms): Min: 11.9, Avg: 14.2, Max: 14.9, Diff: 3.0, Sum: 56.7]
          [GC Worker End (ms): Min: 38278.0, Avg: 38278.0, Max: 38278.0, Diff: 0.0]
       [Code Root Fixup: 0.2 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 0.2 ms]
       [Other: 96.5 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 95.1 ms]
          [Ref Enq: 0.1 ms]
          [Redirty Cards: 0.2 ms]
          [Humongous Reclaim: 0.0 ms]
          [Free CSet: 0.1 ms]
       [Eden: 262.0M(262.0M)->0.0B(262.0M) Survivors: 38.0M->38.0M Heap: 716.0M(4096.0M)->546.0M(4096.0M)]
     [Times: user=0.37 sys=0.03, real=0.11 secs]

the jvm options as following

$JAVA_HOME/bin/java -Dfile.encoding=utf-8 -server -XX:+UseCompressedOops -Xms4096m -Xmx4096m -XX:NewSize=300m -XX:MaxNewSize=300m -XX:+UseG1GC -XX:+PrintReferenceGC -XX:+ParallelRefProcEnabled -XX:MaxGCPauseMillis=100 -Xloggc:/data/dataLogs/gc/gc.log -verbose:gc -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+DisableExplicitGC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/dataLogs/dump -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false com.xx.ServerApp >/data/logs/stdoutdate +"%Y%m%d%H%M%S".log 2>&1 &

what's the matter ?

lawrence
  • 353
  • 2
  • 17
  • You think, 0.0938618 seconds is “lots of time”? – Holger Jul 27 '18 at 11:07
  • 1
    @Holger Yes. see the total time is 0.1118731 secs, 90% was wasted on the final reference phase – lawrence Jul 27 '18 at 11:10
  • …and how much of your actual application life time is that? 0.001%? If you have an actual problem you should articulate the actual problem, not create an artificial problem about one tiny number being 90% of another tiny number. Besides that, it is well known that finalization can cause performance issues and should be avoided. But think twice before wasting hours in redesigning your software, to save 0.09 seconds at runtime. – Holger Jul 27 '18 at 11:17
  • @Holger I have searched issue like this, but the final reference phase only take little part of this total GC time. see https://stackoverflow.com/questions/23101817/g1gc-remark-phase-is-taking-too-long – lawrence Jul 27 '18 at 11:30
  • I don’t get you. In the linked question, processing of the `FinalReference` took less time, but it only had 32 references to process while you have 481 references. Surely, having 122658 soft references, 714 weak references and only 32 final references causes a different ratio in the processing times than your application having *zero* soft refs, 232 weak refs and 481 final refs. Besides that, what makes you sure that you are using exactly the same garbage collector implementation than the author of that question from 2014? – Holger Jul 27 '18 at 11:38
  • @Holger Did not see the time 2014. But any arguments or tools for the jvm options to see why it has so many final reference? what is the root cause? I think if I can reduce the final reference then the GC will be faster – lawrence Jul 27 '18 at 11:55
  • 1
    Well, you have to look for classes with a “non-trivial `finalize()` method”, i.e. a class which overrides the `finalize()` method with a method that is not just empty. Or make a heap dump and check for instances of `java.lang.ref.Finalizer` and their `referent`s. – Holger Jul 27 '18 at 13:51

0 Answers0