Just adding SLF4J dependency made my Swing app dead slow. Where to start looking?

Issue

Just adding SLF4J dependency made my Swing app dead slow.

Before proper logging was implemented:

Earlier I was using java.util.Logger to output the logs, and some of them were even using System.out.println.

Getting Log4j2 / Slf4j setup

Then I added log4j2 maven dependencies and log4j2.xml in src/main/resources and then it was not picking up the settings as I was still writing to java.util.Logger.

I found out that I have to get Logger from log4j LogManager, or to make it more configurable get a Logger from slf4j LoggerFactory so that client can plugin any Logger implementation later.

So, I started getting Logger from slf4j LoggerFactory and logging to it. With the log4j2 dependencies in place and log4j2.xml in resources folder, all is well, and only the packages which I want to set to DEBUG level are getting logged.

**The performance issue **

All is well - except for performance! My app uses 125% CPU, and this causes Macbook Pro to start heating. MBP has an issue where once it starts heating kernel_task hits 500% CPU within couple of minutes.

Long story short - once I fixed my logging, my app has become unusable.

Removed even log4j2 from classpath

Not only that, I even removed log4j2 dependencies, and it stopped logging. Slf4j alone remains and I am writing to the Logger which I get from slf4j LoggerFactory. Still my app hits 125% CPU and the MBP kernel_task does the rest to freeze the system.

What could be the problem here? Memory leak in Slf4j? Does Java Swing write too much to Slf4j?

Sequence of trials I am planning next:

1. Upgrade slf4j to latest and greatest version (I can check which one works best with Java 1.8 which the app is using)
2. Avoid slf4j and write directly to Log4j2
3. Revert to java.util.Logger

Update:

This was the log4j2.xml which I have. (But note: I removed log4j2 dependency and nothing is logged now.)

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn" name="tradez" packages="">
    <Appenders>
        <Console name="app_stdout" target="SYSTEM_OUT">
    <!--  PatternLayout pattern="%date{HH:mm:ss,SSS} %t %-5level %class{1.}:%method:: %message %n" / -->
    <PatternLayout pattern="%date %t %-5level %message %n" />
        </Console>
    </Appenders>
    <Loggers>
        <Logger name="net.progressit.tradez" level="debug">
            <AppenderRef ref="app_stdout" />
        </Logger>
        <Root level="info">
            <AppenderRef ref="app_stdout" />
        </Root>
    </Loggers>
</Configuration>

Update 2:

Funnily I get this message from Log4j2 even after I removed Log4j2 dependencies from Maven and cleaned the project. Maybe Slf4j sees my log4j2.xml still hanging around, and prints a customized message for Log4j2?

ERROR StatusLogger Log4j2 could not find a logging implementation

Update 3:

Update 2 is misleading because this is the only logging related item I have in my pom.xml. So, I don't have pure slf4j but rather jog4j-slf4j-impl alone, which is why I get a specific error message.

    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-slf4j-impl</artifactId>
        <version>2.7</version>
    </dependency>

Update 4: Solved!

As suggested by Mark Bramnik I got back to basics and used JVisualVM to debug the app performance.

Found that there was always a thread doing re-layout of components continuously and usually terminating in getFontMetrics. It seems MigLayout layouting never stabilized, and kept relayouting continuously even with no changes to the UI by the program.

So, I just upgraded the dependency from MigLayout 5.2 (2018) to MigLayout 11 (2021/latest) and CPU dropped from 150% to 1.5%

Solution

So you're saying that the Mac Book Pro uses way too much CPU while running the application with logs.

I don't think that adding slf4j/log4j2 alone causes the issues, so it has to do something with your configuration, maybe the configuration of logging appenders, patternts, etc.

The question if pretty general, so here are some ideas that might point in the right direction:

1. Take thread dumps. You might see a lot of threads in the "RUNNABLE" state actually doing something
2. This is a Swing application, so it should have a thread that paints everything and you should do heavy things in the thread that paints stuff (I'm really rusty on Swing, but I still rememeber invokeLater/invokeAndWait APIs. So if you log something and do it wrong (excessive logging, some heavy calculations done when you create a message, a way-to-long string of toString in the object you want to log, etc.) This "rendering" Thread might become busy and the app will be become unresponsive / nothing will render.
3. If you're using slf4j - you can try to configure it with "no-op" implementation (technically, add as a dependency to your build script) instead of actual implementation like log4j2, logback, etc. so that it won't log anything. Why this might be interesting? Because if you're using some kind of a "bad" / "slow" appender implementation - it might this will actually turn it off. Then check the app again: If you see that the issue disappears - this is a wrongly configured appender, but if the app still freezes, this is not related to appenders but rather to some calculations that you do when you print the messages.
4. Check the size of the log file and its content. If it grows way too fast - you might need to reduce your logging messages. Maybe set the default severity level to WARN at least.
5. Try to run the app on another PC/Mac computer - maybe its an issue in your particular computer: stuff like antivirus that tracks the files of logs which are now created.

Answered By - Mark Bramnik