Strange STW pauses

[David Holmes]

Hi Nick,

AFAICS the "no vm operation" safepoints are not consuming the time. What 
do the actual vm operation safepoints show? What do GC logs show?

Cheers,
David

On 23/08/2017 8:52 AM, Nick Chadwick wrote:
> Hi,
> 
> My Java application is suffering from long (5s+) STW pauses. Latency is a
> priority for the application, so I need to get to the bottom of what's going
> on.
> 
> With all the usual JVM options on, I see the following in the logs:
> 
> [deflating idle monitors, 0.0000102 secs]
> [updating inline caches, 0.0000149 secs]
> [compilation policy safepoint handler, 0.0000005 secs]
> [mark nmethods, 0.0000549 secs]
> [purging class loader data graph, 0.0000002 secs]
>           vmop                    [threads: total initially_running
> wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
> 915.696: no vm operation                  [      24          1
> 1    ]      [     0     0  7303     0     0    ]  1
> Total time for which application threads were stopped: 0.0002608 seconds,
> Stopping threads took: 0.0001250 seconds
> 
> [deflating idle monitors, 0.0000110 secs]
> [updating inline caches, 0.0000706 secs]
> [compilation policy safepoint handler, 0.0000006 secs]
> [mark nmethods, 0.0000576 secs]
> [purging class loader data graph, 0.0000003 secs]
>           vmop                    [threads: total initially_running
> wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
> 1051.564: no vm operation                  [      24          0
> 1    ]      [     0     0  1652     0     0    ]  0
> Total time for which application threads were stopped: 0.0002285 seconds,
> Stopping threads took: 0.0000414 seconds
> 
> [deflating idle monitors, 0.0000135 secs]
> [updating inline caches, 0.0000083 secs]
> [compilation policy safepoint handler, 0.0000005 secs]
> [mark nmethods, 0.0000894 secs]
> [purging class loader data graph, 0.0000002 secs]
>           vmop                    [threads: total initially_running
> wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
> 1056.223: no vm operation                  [      24          0
> 0    ]      [     0     0     0  5704     0    ]  0
> Total time for which application threads were stopped: 5.7042454 seconds,
> Stopping threads took: 0.0000270 seconds
> 
> [deflating idle monitors, 0.0000116 secs]
> [updating inline caches, 0.0000093 secs]
> [compilation policy safepoint handler, 0.0000005 secs]
> [mark nmethods, 0.0000540 secs]
> [purging class loader data graph, 0.0000001 secs]
>           vmop                    [threads: total initially_running
> wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
> 1756.475: no vm operation                  [      24          0
> 0    ]      [     0     0     0  4402     0    ]  0
> Total time for which application threads were stopped: 4.4023833 seconds,
> Stopping threads took: 0.0000268 seconds
> 
> I've done some reading up, here and elsewhere, on "guaranteed safepoints"
> etc, but am stumped as to what it's spending its time doing.
> 
> Please can anyone give me a clue?
> 
> Thanks,
> Nick
> 
> 
> 
> --
> View this message in context: http://openjdk.5641.n7.nabble.com/Strange-STW-pauses-tp312324.html
> Sent from the OpenJDK Hotspot Runtime System mailing list archive at Nabble.com.
>