Reduce XML classes in native image when using Logback

[sdeleuze]

As discussed with @wilkinsona, in an empty Spring Boot application with just spring-boot-starter compiled to native, the only place where XML parsing is reachable is ch.qos.logback.core.joran.GenericXMLConfigurator#doConfigure. The impact on the footprint and compile time is quite significant (as usual with XML on native images).

On my Linux machine, the RSS memory after startup is 36.58M when XML is reachable and 34.15M without (difference of 2.43M or 6.64%). You can see the impressive diff of the 675 additional classes included in the native image in this gist.

To track how it is reachable, I compile the native image with a META-INF/native-image/native-image.properties with Args = -H:ReportAnalysisForbiddenType=ch.qos.logback.core.joran.event.SaxEventRecorder and it gives me the following stacktrace:

Fatal error: com.oracle.graal.pointsto.util.AnalysisError$ParsingError: Error encountered while parsing ch.qos.logback.core.joran.GenericXMLConfigurator.populateSaxEventRecorder(org.xml.sax.InputSource) 
Parsing context:
   at ch.qos.logback.core.joran.GenericXMLConfigurator.populateSaxEventRecorder(GenericXMLConfigurator.java:177)
   at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:159)
   at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:122)
   at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:65)
   at org.springframework.boot.logging.logback.LogbackLoggingSystem.configureByResourceUrl(LogbackLoggingSystem.java:260)
   at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:237)
   at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:80)
   at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:60)
   at org.springframework.boot.context.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:332)
   at org.springframework.boot.context.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:298)
   at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:246)
   at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:223)

Sadly, GenericXMLConfigurator#doConfigure is final so we can't override it in a proper way, so to make the XML parsing not reachable for testing purpose, I used this substitution:

@TargetClass(className = "ch.qos.logback.core.joran.GenericXMLConfigurator")
final class Target_GenericXmlConfigurator {

	@Substitute
	public final void doConfigure(URL url) throws JoranException {
	}
}

I don't expect this to be fixable before Spring Boot 3.0 GA, but maybe we could do something about it in 3.0.x. We could potentially raise a related issue on Logback side to see if there is a possibility to make this method non final, or to ask a refactoring that would allow us to make the XML parsing not reachable on native image (either out of the box or via an override on Boot side).

[wilkinsona]

We can avoid this specific path with a small change to LogbackLoggingSystem:

diff --git a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/LogbackLoggingSystem.java b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/LogbackLoggingSystem.java
index 3cd3c241f7..63c8e85af3 100644
--- a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/LogbackLoggingSystem.java
+++ b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/LogbackLoggingSystem.java
@@ -55,6 +55,7 @@ import org.springframework.boot.logging.LoggingInitializationContext;
 import org.springframework.boot.logging.LoggingSystem;
 import org.springframework.boot.logging.LoggingSystemFactory;
 import org.springframework.boot.logging.LoggingSystemProperties;
+import org.springframework.core.NativeDetector;
 import org.springframework.core.Ordered;
 import org.springframework.core.annotation.Order;
 import org.springframework.core.env.ConfigurableEnvironment;
@@ -228,6 +229,9 @@ public class LogbackLoggingSystem extends AbstractLoggingSystem implements BeanF
        @Override
        protected void loadConfiguration(LoggingInitializationContext initializationContext, String location,
                        LogFile logFile) {
+               if (NativeDetector.inNativeImage()) {
+                       throw new IllegalStateException("Loading configuration in a native image is not supported.");
+               }
                if (initializationContext != null) {
                        applySystemProperties(initializationContext.getEnvironment(), logFile);
                }

Unfortunately, that just moves us onto the next one:

Fatal error: com.oracle.graal.pointsto.util.AnalysisError$ParsingError: Error encountered while parsing ch.qos.logback.core.joran.GenericXMLConfigurator.populateSaxEventRecorder(org.xml.sax.InputSource) 
Parsing context:
   at ch.qos.logback.core.joran.GenericXMLConfigurator.populateSaxEventRecorder(GenericXMLConfigurator.java:177)
   at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:159)
   at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:122)
   at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:65)
   at ch.qos.logback.classic.joran.ReconfigureOnChangeTask.performXMLConfiguration(ReconfigureOnChangeTask.java:113)
   at ch.qos.logback.classic.joran.ReconfigureOnChangeTask.run(ReconfigureOnChangeTask.java:73)
   at java.lang.Shutdown.runHooks(Shutdown.java:130)
   at java.lang.Shutdown.shutdown(Shutdown.java:185)
   at com.oracle.svm.core.jdk.RuntimeSupport.shutdown(RuntimeSupport.java:154)

I can't see a way to avoid this in Boot without some changes to Logback.

[sdeleuze]

Yeah, I reached the same conclusion. Maybe we could mark this issue as blocked and we raise a related issue or PR on Logback side to discuss the possible options?

[wilkinsona]

Sounds good to me.

[philwebb]

@sdeleuze Did a Logback issue get raised for this?

[sdeleuze]

Thanks for the reminder, I have created https://jira.qos.ch/browse/LOGBACK-1717.

[ceki]

@sdeleuze Unfortunately, we had a server failure involving data loss. I have recreated issue LOGBACK-1717 by hand. If you wish to follow this item, you may need to sign in anew at jira.qos.ch.

On the bright side, this item is at the top of my to-do list.

[sdeleuze]

@ceki Thanks I will, feel free to reach me for feedback if needed, we can even plan a call if that can help.