Logging Config and Static init

[Stuart Douglas]

Hi Everyone,

At the moment our logging config is RUNTIME_INIT, so logging is setup very early on in the runtime init phase. 

For JVM based applications this means that all through STATIC_INIT log messages are queued in the delayed handler, and written out when logging is setup. Unfortunately for larger applications this can result in the queue being overrun, as things like Hibernate can do quite a lot of DEBUG/TRACE logging in static init. Because we don't actually know the configured log level this results in a nasty warning being printed and the log records being dropped (which Keycloak is running into).

I have tried to work around this problem by setting up the logging earlier, but because of bootstrap config sources (e.g. Vault) that are needed to establish the full runtime config I have been unsuccessful.

The only way I can really think to solve this is to introduce some build time config for the min log level during static init, and basically setup logging during static init with build time configured values. I don't really like this, as it means that you can't actually see DEBUG logging during static init without rebuilding the application.

Another idea I thought of while typing out this email would be to track exactly which messages had been dropped in the log handler, and only display the handler overrun message if a dropped message would have actually been logggable. This seems very hacky but I don't really have any better ideas.

Does anyone have any ideas as to how we can handle this better?

Stuart

[Stuart Douglas]

(Adding back the list)

We could, but there is no real guarantee that the ExtLogRecord is serializable, and it would also potentially slow down JVM startup for no real gain (as the majority of the messages will not be loggable anyway).

Something that did just occur to me is maybe I could hold TRACE/DEBUG messages in a queue held by a SoftReference, so they are only dropped if there is actual memory pressure. Maintaining order across two different queues would be a bit of a pain though.

Stuart

On Mon, 15 Nov 2021 at 15:13, Jason Greene <jason....@redhat.com> wrote:

What if we had a FS backed overflow log? It could probably be done pretty efficiently since you would be writing in batches. 

--
You received this message because you are subscribed to the Google Groups "Quarkus Development mailing list" group.
To unsubscribe from this group and stop receiving emails from it, send an email to quarkus-dev...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/quarkus-dev/CAD%2BL2cwmU8LJ%2BMqp4X5TsvDehUNEX1gsyV2F%3DQqzVw5zzzDZZg%40mail.gmail.com.

[Jason Greene]

Oops, thanks. As to serialization, i see you what mean., I thought it had to be since it needs to eventually be written somewhere but I suppose the problem is this is reliant on the formatters. 

I think you could minimize the impact to startup by doing it in a separate thread. Although perhaps direct memory is sufficient and we just need to raise the limit. IMO I would stay away from soft reference for lots of logging records, they tend to have a very negative impact on GC performance.

BTW, relatedly, I think it makes sense to treat DEBUG and TRACE differently.  We could just let them roll off since they are mostl likely dropped (default config) and provide a warning to increase the queue size if TRACE was enabled and a rolloff occurred. 

[Stuart Douglas]

On Mon, 15 Nov 2021 at 16:17, Jason Greene <jason....@redhat.com> wrote:

Oops, thanks. As to serialization, i see you what mean., I thought it had to be since it needs to eventually be written somewhere but I suppose the problem is this is reliant on the formatters. 

I think you could minimize the impact to startup by doing it in a separate thread. Although perhaps direct memory is sufficient and we just need to raise the limit. IMO I would stay away from soft reference for lots of logging records, they tend to have a very negative impact on GC performance.

BTW, relatedly, I think it makes sense to treat DEBUG and TRACE differently.  We could just let them roll off since they are mostl likely dropped (default config) and provide a warning to increase the queue size if TRACE was enabled and a rolloff occurred. 

That is basically what I suggested in terms of only logging the warning if a message that would have been displayed was dropped. At the moment the queue is cleaned based on priority, so if the limit is hit all TRACE messages are dropped, then DEBUG etc.

Stuart

[Martin Kouba]

On 15. 11. 21 6:03, Stuart Douglas wrote:
> (Adding back the list)
>
> We could, but there is no real guarantee that the ExtLogRecord is
> serializable,

It should be, or? I mean it's Serializable and has its own
readObject/writeObject methods and LogRecord is also Serializable and
parameters are serialized as an array of Object.toString() values.

> and it would also potentially slow down JVM startup for no
> real gain (as the majority of the messages will not be loggable anyway).

Would it make sense to serialize the log levels separately (several
files) and then rebuild the queue according to the minimal log level
used at runtime? Of course, each log record would have to retain the
"index" and the reconstruction would not be for free but in most cases
only few log records will be loaded (INFO/WARN/ERROR).

>
> Something that did just occur to me is maybe I could hold TRACE/DEBUG
> messages in a queue held by a SoftReference, so they are only dropped if
> there is actual memory pressure. Maintaining order across two different
> queues would be a bit of a pain though.
>
> Stuart
>
> On Mon, 15 Nov 2021 at 15:13, Jason Greene <jason....@redhat.com
> <mailto:jason....@redhat.com>> wrote:
>
> What if we had a FS backed overflow log? It could probably be done
> pretty efficiently since you would be writing in batches.
>
> On Nov 14, 2021 at 9:32:35 PM, Stuart Douglas <sdou...@redhat.com

>> <mailto:quarkus-dev...@googlegroups.com>.

>> To view this discussion on the web visit
>> https://groups.google.com/d/msgid/quarkus-dev/CAD%2BL2cwmU8LJ%2BMqp4X5TsvDehUNEX1gsyV2F%3DQqzVw5zzzDZZg%40mail.gmail.com

>> <https://groups.google.com/d/msgid/quarkus-dev/CAD%2BL2cwmU8LJ%2BMqp4X5TsvDehUNEX1gsyV2F%3DQqzVw5zzzDZZg%40mail.gmail.com?utm_medium=email&utm_source=footer>.

>
> --
> You received this message because you are subscribed to the Google
> Groups "Quarkus Development mailing list" group.
> To unsubscribe from this group and stop receiving emails from it, send
> an email to quarkus-dev...@googlegroups.com

> <mailto:quarkus-dev...@googlegroups.com>.

> To view this discussion on the web visit

> https://groups.google.com/d/msgid/quarkus-dev/CAD%2BL2cxh%3DM%3DmfXPxwwdozhpxb12VDLmWbJVGi%3DGrw2bNiaZL0Q%40mail.gmail.com
> <https://groups.google.com/d/msgid/quarkus-dev/CAD%2BL2cxh%3DM%3DmfXPxwwdozhpxb12VDLmWbJVGi%3DGrw2bNiaZL0Q%40mail.gmail.com?utm_medium=email&utm_source=footer>.

--
Martin Kouba
Software Engineer
Red Hat, Czech Republic

[David Lloyd]

On Mon, Nov 15, 2021 at 7:57 AM Martin Kouba <mko...@redhat.com> wrote:

Would it make sense to serialize the log levels separately (several
files) and then rebuild the queue according to the minimal log level
used at runtime? Of course, each log record would have to retain the
"index" and the reconstruction would not be for free but in most cases
only few log records will be loaded (INFO/WARN/ERROR).

I think this is a very reasonable solution. The log records already carry an index IIRC so reconstruction should be pretty fast, given that each individual queue would be pre-sorted.

--

- DML • he/him

[Stuart Douglas]

It's more the marker object that may potentially have issues with Serialization, although it is unlikely to actually be an issue for our startup code.

I still don't like the idea of doing disk IO on startup to basically solve a problem of our own making. I have gone for the 'only warn if a dropped message is loggable approach': https://github.com/quarkusio/quarkus/pull/21473