Very long (nearly 10s, abnormal) "Choose CSet" time in a young collection

[Thomas Schatzl]

Hi,

On Thu, 2019-05-09 at 14:04 -0400, chao chu wrote:
> Hi Thomas,
> 
> Thanks for your reply. The 'user' part is 5.00 for completeness :)
> 
> Yes, weeks ago we identified that we also got impacted by linux THP
> which caused like 90+ seconds in sys time in a full GC. But this one
> looks different as you mentioned, the sys time is very low.
> 
> I saw two things we want to understand here:
> 
> 1. the 5s 'user' time was spent where?

I can't tell without at least that complete log entry. The log output
should be pretty complete and tell you.

Note that user time is total CPU time for all threads scheduled on
cores during the measurement duration, not wallclock time. So it
depends on the amount of parallelism and number of threads used what
this means.

You can't just subtract real - user and get a useful result unless
under very narrow conditions.

> 2. the other 5s (real - user) might be possibly due to the host was
> heavy loaded and the jvm got no CPU time during that?

See above.

As suggested earlier I would monitor I/O and memory activity.

E.g. I/O stalls during flushing the output buffers could create such an
output. Try to route the log output onto a different disk (ramdisk if
acceptable; I think even in jdk8u there are options to limit log size
and do automatic log rotation) than the same disk used for other
processes potentially doing very heavy I/O.

Thanks,
  Thomas