Feature resolver processing is too slow when used from Liberty Maven Plugin feature install, for already-installed features

[scottkurz]

Describe the bug

First, calling this a "bug" is subjective but read on.

When using Liberty Maven Plugin "dev mode", most of the startup sequence is pretty quick and not much longer than the startup of the Liberty server started within..... EXCEPT that is, for the feature install.

Using the timing of the liberty-maven-plugin console log messages as a close-enough proxy for the feature install execution time, when installing these features:

[INFO] Installing features: [mpconfig-2.0, mpmetrics-3.0, mphealth-3.1, cdi-2.0, jaxrs-2.1]

it takes about 45 seconds for the features to install initially. That's fine. Not trying to raise a concern when the features actually need to be installed upon the first time dev mode starts after Liberty is installed.

However, it takes about 15 seconds to get through this step every time dev mode is started after the first. From the user perspective, a noticeable delay "installing features x,y,z" that have already been installed starts to get annoying and makes the whole dev mode experience less pleasant.

Call stack details

By running dev mode in a Java debugger (e.g. mvnDebug liberty:dev) I narrowed down the routine taking a long time to the FeatureResolverImpl.processRoots() call within this call stack:

FeatureResolverImpl.processRoots(Collection<String>, Set<String>, SelectionContext) line: 305    
FeatureResolverImpl.processCurrentPermutation(Collection<String>, Set<String>, SelectionContext) line: 296    
FeatureResolverImpl.doResolveFeatures(Collection<String>, Set<String>, SelectionContext) line: 259    
FeatureResolverImpl.resolveFeatures(Repository, Collection<ProvisioningFeatureDefinition>, Collection<String>, Set<String>, Set<String>, EnumSet<ProcessType>) line: 182    
FeatureResolverImpl.resolveFeatures(Repository, Collection<ProvisioningFeatureDefinition>, Collection<String>, Set<String>, boolean) line: 114    
RepositoryResolver.resolveFeatures(ResolutionMode) line: 468    
RepositoryResolver.resolve(Collection<String>, ResolutionMode) line: 364    
RepositoryResolver.resolveAsSet(Collection<String>) line: 351    
InstallKernelMap.singleFileResolve() line: 929    
InstallKernelMap.get(Object) line: 273    
InstallMap.get(Object) line: 275    
InstallFeatureSupport$InstallFeatureMojoUtil(InstallFeatureUtil).installFeatures(boolean, List<String>) line: 593    
InstallFeatureMojo.installFeatures() line: 99    
InstallFeatureMojo.doExecute() line: 70    

NOTE: We are using a bit of an unusual approach in using reflection to load the runtime classes from the plugin, (to avoid a dependency). To me it looks like that probably isn't a factor... we have already loaded the map class via reflection at this point and the slow part is calling this FeatureResolverImpl.processRoots(..) method. But I don't really know 100% I can rule that out as relevant so mentioning.

Steps to Reproduce

1. git clone git@github.com:OpenLiberty/devfile-stack-intro.git; cd devfile-stack-intro
2. mvn liberty:dev # run dev mode & wait for full startup,
3. Kill mvn & Liberty server: Ctrl+C, e.g.
4. mvn liberty:dev # run dev mode again
5. With a stopwatch/clock/etc. observe the time it takes from when this line is output in the console:

   [INFO] Installing features: [mpconfig-2.0, mpmetrics-3.0, mphealth-3.1, cdi-2.0, jaxrs-2.1]

to when this line is displayed:

[INFO] The features are already installed, so no action is needed.

For me, on Win 11, running with Semeru Java 17, it seems to average around 15 seconds, (after the features have been installed).

Diagnostic information:

• OpenLiberty Version: 23.0.0.1
• Java Version: openjdk version "17.0.3" 2022-04-19 IBM Semeru Runtime Open Edition 17.0.3.0 (build 17.0.3+7) Eclipse OpenJ9 VM 17.0.3.0 (build openj9-0.32.0, JRE 17 Windows 11 amd64-64-Bit Compressed References 20220422_155 (JIT enabled, AOT enabled) OpenJ9 - 9a84ec34e OMR - ab24b6666 JCL - dc07fd49b92 based on jdk-17.0.3+7)
  • Affected feature(s), server.xml: See recreate proj: https://github.com/OpenLiberty/devfile-stack-intro

Additional context

It is also worth considering how we might address this from the Liberty Maven Plugin layer, and we're also exploring that in these issues: https://github.com/OpenLiberty/ci.maven/issues/1557 https://github.com/OpenLiberty/ci.maven/issues/1646

though this still seemed like a valid issue to open at least from the runtime perspective.

[yeekangc]

Cc @jhanders34

[Azquelt]

The stack you highlight shows that the slow part is running FeatureResolverImpl.resolveFeatures (and children). This is the entry point to the kernel feature resolver which is the same code that runs at server startup to decide which features should be enabled.

I believe (though you might want to check with the kernel team) that, due to the way tolerates is specified, there's no way of determining whether all the required features are installed without calling this method or duplicating the logic of the feature resolver.

It would probably be good if we can run this through a profiler to check that the problem isn't in KernelResolverEsa, KernelResolverRepository or KernelResolverRequirement which are the objects which install passes through to FeatureResolverImpl.

[scottkurz]

Did something change in 23.0.0.3?

Noticing the performance has improved substantially and consistently for me using the latest runtime version of 23.0.0.3. Real time for mvn liberty:install-feature drops from about 15s to 7-8s. Wondering if others see similar results.

[scottkurz]

I think with 23.0.0.8 we have a noticeable improvement in performance of mvn liberty:install-feature when the feature set is already installed. Not sure my data is organized enough to bother including... but I'm seeing 7-9s going down to 2-3s, for what that's worth. Closing this issue then.