several second delay before "The features are already installed, so no action is needed."

[covener]

Using the CORS OL guide, and even substituting 3.6.1 LMP in the finish/pom.xml, I have two systems where around 10 seconds elapses before the last message on every subsequent run of mvn liberty:dev

[INFO] Running liberty:install-feature
[INFO] CWWKM2102I: Using artifact based assembly archive : io.openliberty:openliberty-kernel:null:22.0.0.6:zip.
[INFO] CWWKM2102I: Using installDirectory : /home/covener/SRC/guide-cors/finish/target/liberty/wlp.
[INFO] CWWKM2102I: Using serverName : defaultServer.
[INFO] CWWKM2102I: Using serverDirectory : /home/covener/SRC/guide-cors/finish/target/liberty/wlp/usr/servers/defaultServer.
[INFO] Parsing the server file for features and includes: defaultServer/server.xml
[INFO] Parsing the server file for features and includes: defaultServer/configDropins/overrides/liberty-plugin-variable-config.xml
[INFO] Installing features: [jsonb-2.0, restfulws-3.0]

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

https://github.com/openliberty/guide-cors.git

[cherylking]

I think we need to determine where the delay is coming from exactly. If one tries to install features directly on Liberty (not through Liberty Maven plugin) that are already installed, do we see a similar delay?

If we need to avoid calling Liberty to install features in this scenario, the only option seems to be to keep a cache of already installed features. The problem I see with that is that the cache could easily become inaccurate if any other processes interact with the Liberty server outside of LMP. Also, do we want to avoid the very first attempt of installing features when the target Liberty server is openliberty-runtime and presumably has all the features? Could the list of features from server.xml include a WebSphere Liberty feature, or a user feature (could detect this one and still install it)?

[scottkurz]

I stepped through a simple scenario in the debugger: LMP dev mode, 5 features, OL only.

It seems pretty clear to me that this is the line to investigate in InstallKernelMap.singleFileResolve():

      resolveResult = resolver.resolveAsSet((Collection<String>) data.get(InstallConstants.FEATURES_TO_RESOLVE));

the stack at this point is:

InstallKernelMap.singleFileResolve() line: 931	
InstallKernelMap.get(Object) line: 270	
InstallMap.get(Object) line: 273	
InstallFeatureSupport$InstallFeatureMojoUtil(InstallFeatureUtil).installFeatures(boolean, List<String>) line: 593	
InstallFeatureMojo.installFeatures() line: 99	
InstallFeatureMojo.doExecute() line: 70	
InstallFeatureMojo(MojoSupport).execute() line: 122	
DefaultBuildPluginManager.executeMojo(MavenSession, MojoExecution) line: 137	
MojoExecutor.executeMojo(Plugin, String, Xpp3Dom, MojoExecutor$ExecutionEnvironment) line: 120	
DevMojo(StartDebugMojoSupport).runLibertyMojo(String, Xpp3Dom) line: 363	
DevMojo(StartDebugMojoSupport).runLibertyMojoInstallFeature(MojoExecutor$Element, File, String) line: 348	
DevMojo.runLibertyMojoInstallFeature(MojoExecutor$Element, File, String) line: 1911	
DevMojo.doExecute() line: 1331	
DevMojo(MojoSupport).execute() line: 122	
DefaultBuildPluginManager.executeMojo(MavenSession, MojoExecution) line: 137	

One thing to keep in mind is that 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 already loaded the map class via reflection at this point and the slow part is calling this resolver.resolveAsSet(..) method. But I don't really know JVM internals to 100% rule that out as relevant.

[scottkurz]

Opened OpenLiberty/open-liberty#24592 to track from the runtime perspective. Guess we can still leave this open for now.

[scottkurz]

This issue was addressed via #1646 and the conclusion is here: #1646 (comment)