Too much safepoint logging in info level?

[Sundara Mohan M]

Hi Stefan
   Good to know. Thanks for the update.


-Sundar

On Mon, Jun 24, 2019 at 2:28 AM Stefan Karlsson <stefan.karlsson at oracle.com>
wrote:

> [sent too early]
>
> On 2019-06-24 11:22, Stefan Karlsson wrote:
> > Hi Sundar,
> >
> > FWIW, those log lines were removed in JDK 13. See:
> > https://bugs.openjdk.java.net/browse/JDK-8219436
> >
> > According to the bug report: "All logs should use the same timestamp and
> > some logs are not meaningful."
> >
>
> So, I guess these lines were not deemed important enough to keep.
>
> StefanK
>
> > On 2019-06-22 01:03, Sundara Mohan M wrote:
> >> Hi All,
> >>      I am seeing following behavior when gc log is set at info level.
> >>
> >> In JDK8 we used to see only Application stopped time and Time taken to
> >> stop
> >> time in logs.
> >> In JDK12 i am seeing additional lines Entering and Leaving safepoints
> are
> >> printed at info level.
> >> This seems to fill logs very quickly and also doesn't help much at high
> >> level.
> >>
> >> Is there a compelling reason that it has to be at info level? If not
> >> can we
> >> look at moving it to debug level?
> >>
> >> [2019-06-21T22:47:33.638+0000][2.495s][info][safepoint] Application
> time:
> >> 0.0092823 seconds
> >>
> >> *[2019-06-21T22:47:33.638+0000][2.495s][info][safepoint] Entering
> >> safepoint
> >> region:
> >> ZOperation*[2019-06-21T22:47:33.640+0000][2.496s][info][gc,phases]
> >> GC(0) Pause Mark End 1.506ms
> >>
> >> *[2019-06-21T22:47:33.640+0000][2.496s][info][safepoint] Leaving
> >> safepoint
> >> region*
> >> [2019-06-21T22:47:33.640+0000][2.496s][info][safepoint] Total time for
> >> which application threads were stopped: 0.0016777 seconds, Stopping
> >> threads
> >> took: 0.0000301 seconds
> >> ...
> >> [2019-06-21T22:47:33.656+0000][2.513s][info][safepoint] Application
> time:
> >> 0.0166108 seconds
> >>
> >> *[2019-06-21T22:47:33.656+0000][2.513s][info][safepoint] Entering
> >> safepoint
> >> region:
> >> ZOperation*[2019-06-21T22:47:33.657+0000][2.513s][info][gc,phases]
> >> GC(0) Pause Mark End 0.264ms
> >> *[2019-06-21T22:47:33.657+0000][2.513s][info][safepoint] Leaving
> >> safepoint
> >> region*
> >> [2019-06-21T22:47:33.657+0000][2.513s][info][safepoint] Total time for
> >> which application threads were stopped: 0.0004208 seconds, Stopping
> >> threads
> >> took: 0.0000272 seconds
> >> ...
> >>
> >>
> >> Sorry if this is not the correct forum for this topic. Please point me
> to
> >> the correct forum.
> >>
> >> TIA
> >> - Sundar
> >>
>