logger.isTraceEnabled() is returning true in native mode, regardless of log level defined

[johnaohara]

I have found that native for native applications logger.isTraceEnabled() returns true regardless of logging level defined in application.properties

For example;

quarkus-runner ! com.oracle.svm.core.graal.jdk.ArraycopySnippets.primitiveCopyForward - ArraycopySnippets.java
quarkus-runner ! com.oracle.svm.core.graal.jdk.ArraycopySnippets.doArraycopy + 0x477 - ArraycopySnippets.java:85
quarkus-runner ! java.util.Arrays.copyOfRange + 0x36a - Arrays.java:3667
quarkus-runner ! java.lang.String.<init> + 0x5c - String.java:207
quarkus-runner ! org.hibernate.pretty.MessageHelper.infoString + 0x25a - MessageHelper.java:407
quarkus-runner ! org.hibernate.loader.entity.CacheEntityLoaderHelper.convertCacheEntryToEntity + 0xaa - CacheEntityLoaderHelper.java:281
quarkus-runner ! org.hibernate.loader.entity.CacheEntityLoaderHelper.processCachedEntry + 0x175 - CacheEntityLoaderHelper.java:178
quarkus-runner ! org.hibernate.loader.entity.CacheEntityLoaderHelper.loadFromSecondLevelCache + 0x10d - CacheEntityLoaderHelper.java:151
quarkus-runner ! org.hibernate.event.internal.DefaultLoadEventListener.doLoad + 0x109 - DefaultLoadEventListener.java:436
quarkus-runner ! org.hibernate.event.internal.DefaultLoadEventListener.load + 0x40 - DefaultLoadEventListener.java:203
quarkus-runner ! org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad + 0x160 - DefaultLoadEventListener.java:246
quarkus-runner ! org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad + 0x1a9 - DefaultLoadEventListener.java:105
quarkus-runner ! org.hibernate.event.internal.DefaultLoadEventListener.onLoad + 0x3f8 - DefaultLoadEventListener.java:73
quarkus-runner ! org.hibernate.internal.SessionImpl.fireLoad + 0xf0 - SessionImpl.java:1287
quarkus-runner ! org.hibernate.internal.SessionImpl.internalLoad + 0xcf - SessionImpl.java:1164

I had configured logging to INFO level,

quarkus.log.console.level=INFO

we should not have reached this method call; : https://github.com/hibernate/hibernate-orm/blob/5.4.2/hibernate-core/src/main/java/org/hibernate/loader/entity/CacheEntityLoaderHelper.java#L281

The trace message is not written to the console, but we have the overhead of generating the trace messages.

I do not see this behaviour in JVM mode, in JVM profiling these calls do not appear

[johnaohara]

I will check if I see the same issue if I configure the root logger, and not just the console logger

[dmlloyd]

The isXxxEnabled check only checks against the log category. If the category is TRACE and the handler is INFO, then isTraceEnabled would still return true.

[johnaohara]

@dmlloyd what is the default log category? I have tried setting quarkus.log.level=INFO but I was still seeing these strack's in the profiling data

[dmlloyd]

Can you share your whole configuration?

[johnaohara]

quarkus.log.level=INFO
quarkus.datasource.url=jdbc:postgresql://localhost/rest-crud
quarkus.datasource.driver=org.postgresql.Driver
quarkus.datasource.username=restcrud
quarkus.datasource.password=restcrud
quarkus.datasource.max-size=8
quarkus.datasource.min-size=2
quarkus.hibernate-orm.database.generation=drop-and-create
quarkus.hibernate-orm.log.sql=false

quarkus.http.worker-threads=8
quarkus.http.io-threads=2

[dmlloyd]

Normally the log level is inherited from enclosing category to enclosed category. However the log configuration that is actually used at run time is an accumulation of log levels set by configuration and by extensions. In particular there is a possibility that some log categories are being overridden for some reason.

Another possibility is that there is simply a bug, in logging or in SVM itself. I'm working on a code change that will allow us to easily examine the complete run time logging configuration. Hopefully it will only take me an hour or two to put it together.

[dmlloyd]

@johnaohara can you build with #2228 included, then set quarkus.log.diagnostic.enable=true, and then hit your native image runner process with a SIGQUIT? It will tell you exactly how every logger and handler in the system is configured.

[johnaohara]

I ran with a build of #2228 and this is the output;

https://gist.github.com/johnaohara/e0877d60118a4393135b1a9eda7cacbd

I also ran a simple byteman rule;

RULE Hibernate logger level
CLASS org.hibernate.loader.entity.CacheEntityLoaderHelper
METHOD convertCacheEntryToEntity
AT ENTRY
IF  true
DO  traceln("traceEnable: " + java.lang.Boolean.toString(CacheEntityLoaderHelper.traceEnabled))
ENDRULE

In JVM mode, the rule logged;

traceEnable: false

In Native mode, the rule logged;

traceEnable: true

[johnaohara]

@dmlloyd Have been debugging another native image issue today, and have logged these exceptions during a native image build;

**** NoSuchMethodException.<init>: java.util.logging.Level.of(java.lang.String)
**** NoSuchMethodException.<init>: java.util.logging.Level.valueOf(java.lang.String)
**** NoSuchMethodException.<init>: java.util.logging.Level.<init>(java.lang.String)
**** NoSuchMethodException.<init>: java.util.logging.Level.parse(java.lang.CharSequence)
**** NoSuchMethodException.<init>: java.util.logging.Level.<init>(java.lang.CharSequence)
**** NoSuchMethodException.<init>: java.util.logging.Level.valueOf(java.lang.CharSequence)
**** NoSuchMethodException.<init>: java.lang.reflect.Proxy.toString()
**** NoSuchMethodException.<init>: java.lang.reflect.Proxy.toString()

When I start the process in JVM mode, I do not see those NoSuchMethodException java.util.logging.* classes

[dmlloyd]

I ran with a build of #2228 and this is the output;

https://gist.github.com/johnaohara/e0877d60118a4393135b1a9eda7cacbd

That's very interesting, especially considering that:

I also ran a simple byteman rule;
[...]
In Native mode, the rule logged;

traceEnable: true

This tells us that isTraceEnabled is not agreeing with what the physical log level actually is. Can you test to see what java.util.logging.Logger.getLogger("org.hibernate.loader.entity.CacheEntityLoaderHelper").getLevel() returns? I'm starting to think that the problem is the caching in org.hibernate.loader.entity.CacheEntityLoaderHelper#traceEnabled. The class initialization time might have changed and the wrong log level might have been cached. /cc @Sanne

[dmlloyd]

@dmlloyd Have been debugging another native image issue today, and have logged these exceptions during a native image build;

**** NoSuchMethodException.<init>: java.util.logging.Level.of(java.lang.String)
**** NoSuchMethodException.<init>: java.util.logging.Level.valueOf(java.lang.String)
**** NoSuchMethodException.<init>: java.util.logging.Level.<init>(java.lang.String)
**** NoSuchMethodException.<init>: java.util.logging.Level.parse(java.lang.CharSequence)
**** NoSuchMethodException.<init>: java.util.logging.Level.<init>(java.lang.CharSequence)
**** NoSuchMethodException.<init>: java.util.logging.Level.valueOf(java.lang.CharSequence)
**** NoSuchMethodException.<init>: java.lang.reflect.Proxy.toString()
**** NoSuchMethodException.<init>: java.lang.reflect.Proxy.toString()

When I start the process in JVM mode, I do not see those NoSuchMethodException java.util.logging.* classes

That's pretty normal I think. Native image mode aggressively initializes classes that might not be initialized in JVM mode, so it's possible that extra probing is happening; based on the methods reported I'd say that it's probably MP-config probing the classes to establish implicit converters. Though the toString one is pretty weird as that method is defined on Object (unless it's looking for one with a different return type, which is possible I guess).

[dmlloyd]

I'm starting to think that the problem is the caching in org.hibernate.loader.entity.CacheEntityLoaderHelper#traceEnabled. The class initialization time might have changed and the wrong log level might have been cached. /cc @Sanne

Just to get into a little more detail here - this field was probably created to avoid repeated calls of isTraceEnabled in the first place. However beyond the initialization time problem we're apparently running into, isTraceEnabled is normally very performant so this kind of optimization should not be necessary. In addition I previously experimented with applying @ForceInline to level checks with seemingly good results, so that might be worth reinstating.

[Sanne]

hi @dmlloyd , allow me to confirm a bit of history. My knowledge might be out of date, happy to change things but I'd be careful with that.

we have witnessed some performance issues withisTraceEnabled in extreme cases; I know it's normally very cheap, but these have been identified by the perf team in the past (@johnaohara but not only, not sure who was involved back then).

The decision back then (maybe it's out of date?) for both the Hibernate and Infinispan project was to not consider "trace" as a level that could be changed at runtime.

Essentially, the alternative in these cases was to just get rid of the logging message altogether - we decided for this tradeoff as they are useful during development.

[dmlloyd]

hi @dmlloyd , allow me to confirm a bit of history. My knowledge might be out of date, happy to change things but I'd be careful with that.

we have witnessed some performance issues withisTraceEnabled in extreme cases; I know it's normally very cheap, but these have been identified by the perf team in the past (@johnaohara but not only, not sure who was involved back then).

The decision back then (maybe it's out of date?) for both the Hibernate and Infinispan project was to not consider "trace" as a level that could be changed at runtime.

Essentially, the alternative in these cases was to just get rid of the logging message altogether - we decided for this tradeoff as they are useful during development.

I'd say it's out of date, probably. The level checks should normally be inlined by JIT as they are monomorphic and below even small thresholds for size; it should boil down to a single volatile field read. In any event, it's definitely a performance problem now, so... :)

[johnaohara]

@Sanne @dmlloyd I currently have a 5.4.2 build with isTraceEnabled() caching removed. I am running a native test atm, which is showing an improvement in throughput. I will run a JVM test comparing 5.4.2 with caching and 5.4.2 without caching. I can also double check that calls to isTraceEnebaled() are being inlined.

[Sanne]

well Quarkus is not the only runtime we have to support, and also Quarkus will need to support other libraries which might want to do similar things, so I don't think "dodging" such a problem by having ORM change its code is the right approach.

it should boil down to a single volatile field read

we know that, still this problem we had wasn't too old, maybe just one year ago, so there's more to it.

Anyhow: this is a widespread practice in several libraries. If we decide it's time to revert such ideas, it's going to take some time to spot all such cases.

[Sanne]

@stalep remembers more details maybe ? ^

[dmlloyd]

well Quarkus is not the only runtime we have to support, and also Quarkus will need to support other libraries which might want to do similar things, so I don't think "dodging" such a problem by having ORM change its code is the right approach.

it should boil down to a single volatile field read

we know that, still this problem we had wasn't too old, maybe just one year ago, so there's more to it.

Maybe. Hopefully John will turn up some more information.

Anyhow: this is a widespread practice in several libraries. If we decide it's time to revert such ideas, it's going to take some time to spot all such cases.

It will have to be, unfortunately. Caching these in static fields will never work in GraalVM due to its class initialization rules. Even if it were moved to runtime init, the log level isn't decided until after logging is initialized, which happens after the configuration is read. So it would still have the same problem in this case, because AFAIK class init isn't lazy even if it's deferred to runtime with GraalVM.

If we want to have some kind of support for constant-folded level checking, we could possibly reestablish the min-level configuration item, whose value could be cached in a static field safely.

[Sanne]

good point re class initialization. I'm happy to merge @johnaohara fixes to ORM upstream, just keep in mind that we'll eventually find many more of such cases (and not exclusive to Hibernate) so if you all find a better solution in the future that would rock.

In particular, we could set Log categories to silent during native-image build?

I know it's not correct in the general sense, but AFAIK all such cases are to disable the lowest levels only so it would be a good help with general perf.

[johnaohara]

Have chatted with Will Reichert on the perf team. Back in 2014, running specj Enterprise 2010, we observed Jfrs where isTraceEnabled accounted for 8.5% of CPU samples. We also observed;

Method Sample Count Percentage(%)
------ -----------: ------------:
org.jboss.logging.JBossLogManagerLogger.translate(Logger$Level) 2,256 1.05%
org.jboss.logging.JBossLogManagerLogger.isEnabled(Logger$Level) 16 0.01%

There were also a large number of calls to org.jboss.logging.JBossLogManagerLogger.translate()

This was the PR that was opened to track the hibernate changes: https://hibernate.atlassian.net/browse/HHH-8942

Unfortunately, we do not have the jfr profiles any longer that showed this issue at the time.

It is probably worth analysing the cost/benefit to directly call isXXXEnabled() under load again.

[stalep]

I'm a bit late to this thread, I remember we added static booleans for logging in hibernate since the .isEnabled did cost a fair bit of cpu. AFAIK I only did it for hot methods, but this is so long ago my memory is hazy...

[johnaohara]

@gsmet are you going to create a PR to upgrade hibernate and link to this issue? thanks

[gsmet]

Yes. I haven’t started the ORM release yet. I have a personal emergency.

I’ll do it tomorrow but sure I will upgrade for 0.16.0.

[Sanne]

Re-opening: #2672 didn't fix the problem, we simply avoid it affecting Hibernate ORM but there's several more libraries (and possibly user code) that could be affected.

[dmlloyd]

Perhaps we need a feature which registers an error during image build if any isXxxEnabled method is called.

[Sanne]

Isn't it very common to invoke such methods? we do it all the time..

• hibernate/hibernate-orm@4be05af

[mkouba]

IMHO these methods should only be used rarely, e.g. to fix some performance issue in a critical path or when it's expensive to create a log message. Because it's error prone - you need to keep those invocations in sync - e.g. isDebug() and debug().

[dmlloyd]

I was thinking only of image build time - during static initialization - but I guess these methods could legitimately be called at that time as well. What we'd have to detect is one of these methods called during static init, whose value was also immediately stored into a final field. Maybe a substrate feature would be more effective - and in this case we could maybe automatically inline these fields...

[stuartwdouglas]

Is this still an issue? It looks like it was solved in #13376

[geoand]

I am pretty sure this has been fixed so I'll close it.