0

I am experiencing some performance related issues (works ok most of the time, and from time to time there's a spike in the response time from 100ms to 4/5s with no apparent reason) in services implemented in OSB. One of the hypothesis to explain this situation is the fact that the JVM could be performing a Full GC during those spikes and we are monitoring the JVM using mission control.

The admins tell me that the jvm is running with full gc's disabled, using G1GC and I can see that in the startup command:

-XX:+DisableExplicitGC  
-XX:+UseG1GC 
-XX:MaxGCPauseMillis=500 -verbosegc 
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps

Also, when I analyse the gc logs, there's no logging of Full GC's performed, I could only find (which makes sense based on those configurations):

2017-05-02T04:46:10.916-0700: 39228.353: [GC pause (G1 Evacuation Pause) (young), 0.0173177 secs]

However, as soon as I turned on flight recorder in jmc and started some load testing, I immediately noticed Full GCs being performed

Full GC example

and I can see it in the logs:

2017-05-02T05:41:31.297: 548.719: [Full GC (Heap Inspection Initiated GC) 1780->705M(2048M), 3.040 secs]

As soon as I disable flight recorder, I can run the exact same load test over and over again and no Full GC's are recorded in the logs.

Am I missing something here, or is Flight Recorder really forcing the JVM to do Full GC's?

Regards

Kire Haglin
  • 6,569
  • 22
  • 27
Fabio
  • 59
  • 2
  • 13

3 Answers3

2

The documentation says as much:

The flight recording generated with Heap Statistics enabled will start and end with an old GC. Select that old GC in the list of GCs, and then choose the General tab to see the GC Reason as - Heap Inspection Initiated GC. These GCs usually take slightly longer than other GCs.

the8472
  • 40,999
  • 5
  • 70
  • 122
0

If you enable Heap Statistics in the recording wizard, the JVM will stop the application and sweep the heap to collect information about it. If you want to be sure of low overhead (1%), use the default recording template (without modifications).

Kire Haglin
  • 6,569
  • 22
  • 27
-1

Yes, JFR recording does run Full GC at regular interval. INitially we also wondered about the same but below documentation gives proper details.

https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/tooldescr005.html

The flight recording generated with Heap Statistics enabled will start and end with an old GC. Select that old GC in the list of GCs, and then choose the General tab to see the GC Reason as - Heap Inspection Initiated GC. These GCs usually take slightly longer than other GCs.

Basically the idea is to look at the objects which are not getting collected even after GC which points towards memory leak.

If you want to just take a look at entire heap to get idea of all objects in heap, then JFR is not the right way. Just take a heap dump & view it using visual vm by java or any other tools available freely. While taking heap dump also verify the documentation of command to make sure that heap dump command doesn't run GC. There are options available for that, need to search.

Update: Also regarding the GC hypothesis in your question, the best way is to print GC logs through JVM args. There are tools available which takes GC log as input & shows nice graphs with readable stats. So just keep GC logs enabled & do the testing. Then when you see issue/slowness etc. take a look at GC log using tools & see how long GC happpened & how much memory got cleared etc.

Ravi K
  • 976
  • 7
  • 9