Framework: ConnectorTracker.getLogger() should be cached

[vtuonone]

Vaadin version 7.7.12

ConnectorTracker.getLogger() is called quite often and at least in WildFly Logger.getLogger(String) call is quite slow.

Some other frameworks have also notified that there is this problem in JBoss logmanager and caching the loggers is way to go.
https://developer.jboss.org/thread/224138
https://issues.jboss.org/browse/AS7-6583

Current implementation is also against what you suggest Advanced-logging

[Legioth]

There's a difference between what's safe in an application and what's safe in a reusable library. See e.g.
https://wiki.apache.org/commons/Logging/StaticLog and https://github.com/vaadin/framework/issues/2092.

[vtuonone]

Hmm I see the point why it is not final static but why it is not a normal field?
private transient Logger logger=Logger.getLogger(...);
For example in Table logger is defined that way.
What is the difference?

[Legioth]

An instance field should be safe from the shared classloader issue, at the expense of slightly higher memory consumption and some additional code complexity.

From this follows the obvious question on whether that technique should be applied to all framework classes that use loggers, or only some specific classes, and in that case what kind of heuristic to use for determining which approach to use where.

[stale[bot]]

Hello there!

It looks like this issue hasn't progressed lately. There are so many issues that we just can't deal them all within a reasonable timeframe.

There are a couple of things you could help to get things rolling on this issue (this is an automated message, so expect that some of these are already in use):

• Check if the issue is still valid for the latest version. There are dozens of duplicates in our issue tracker, so it is possible that the issue is already tackled. If it appears to be fixed, close the issue, otherwise report to the issue that it is still valid.
• Provide more details how to reproduce the issue.
• Explain why it is important to get this issue fixed and politely draw others attention to it e.g. via the forum or social media.
• Add a reduced test case about the issue, so it is easier for somebody to start working on a solution.
• Try fixing the issue yourself and create a pull request that contains the test case and/or a fix for it. Handling the pull requests is the top priority for the core team.
• If the issue is clearly a bug, use the Warranty in your Vaadin subscription to raise its priority.

Thanks again for your contributions! Even though we haven't been able to get this issue fixed, we hope you to report your findings and enhancement ideas in the future too!

[pm-finamis]

We have a scenario with many GUI updates, it seems that repetitive execution of getLogger() adds 200% of performance overhead. After patching the ConnectorTracker to reuse a logger instance the problem vanished. I would strongly vote for fixing this issue. Thank you.

[Legioth]

I guess that in most cases, the overhead of getLogger() is quite small compared to the overhead of actually logging anything. What's special about ConnectorTracker is that it has several quite commonly called snippets that do if (getLogger().isLoggable(Level.FINE)).

Just caching that boolean might be easy enough with the benefit that it can be done really easily without having to take any classloader or serialization gotchas into account.

[pm-finamis]

FYI This is the output from profiler.

[Legioth]

I see. If I read that chart correctly, getLogger() contributes to 9 / 446 ms, i.e. around 2% of the total time spent. Would be a good target to optimize, but still not an absolutely critical issue.

The methods that are marked to be calling getLogger() also correlate well with my hypothesis that it's the getLogger().isLoggable(Level.FINE) checks that are happening even though there isn't any actual logging going on. Changing the implementation to cache that boolean should be quite straightforward.

[pm-finamis]

Sorry, the profiler is using some mixture of regional settings, it is 9 thousand ms. It means that out of 9266 millis spent on java.util.logging.Logger.getLogger(), 9216ms were spent on calls initiated from ConnectorTracker.markDirty().

[Legioth]

I see.

I've created https://github.com/vaadin/framework/pull/11664 that caches the isLoggable status.

[pm-finamis]

Thank you