Bug Report: JDK 17 apps start a lot slower than other LTS in Payara Micro / FISH-6432

[CarlosMOGoncalves]

Description

---

Hello everyone.

I'm not quite sure this is a bug per se, but it certainly needs looking at.

I am trying out JDK 17 on Payara Platform, both Server and Micro. My goal is to upgrade several applications from JDK 8 straight to JDK 17.

The moment I have made the (small) changes in the pom.xml in order to compile the code to JDK 17 and actually ran it in a Payara Micro uberJAR I found out that the JDK 17 app starts a lot slower.

In my particular case, it will take somewhere from 50% up to almost 100% more time. Let's say 10 seconds on JDK 8 up to 18s on JDK 17. And it is not even a particularly large or complex app.

This happens only with JDK 17 and not with JDK 11 (I also tried it out in order to check whether this was 17 specific).

The issue seems to be connected with a large increase in the Class Scanning phase of deployment and, I suspect, with the ASM library.

Expected Outcome

Well, I expected JDK 17 apps to actually start faster that with JDK 8, but at least it should be as fast as with JDK 8.

Current Outcome

Currently, any application ran in JDK 17 will take longer to be deployed. This increase in time is directly proportional to the number of dependencies the app has, as well as the size, in classes, that those dependencies package.

In order to get some more info I have used the deployment trace feature that @pdudits has written about in an unrelated post on your forum (thanks Patrick, I needed it for something else, but it was really useful here).

This is what I have found out:

In JDK 8 This is a trimmed down actual example of an app being deployed on Payara Micro. You are likely familiar with this, it shows some phases of deployment. In here, for example the CREATE_DEPLOYMENT_CONTEXT Full takes around 6 seconds.

null    20777                                                                         
OPENING_ARCHIVE    12                                                                 
...            
SWITCH_VERSIONS    0                                                                  
CREATE_DEPLOYMENT_CONTEXT   Full    6147                                                 
CLASS_SCANNING  ROOT    1417                                                            
CLEANUP generated    4                                                                 
PREPARE ServerConfig    9                                                              
...  

In JDK 11 The very same app takes roughy the same time (in this case, a further one second can be caused by anything, subsequent deployments took around the same as JDK 8)

null    23471
OPENING_ARCHIVE    16
...            
SWITCH_VERSIONS    0                                                                  
CREATE_DEPLOYMENT_CONTEXT   Full    7782
CLASS_SCANNING  ROOT    1490
CLEANUP generated    5                                                                 
PREPARE ServerConfig    17                                                              
...  

In JDK 17 This is where it gets rough, the total deployment time went up some full 15 seconds from JDK 8 on the very same app. However, it clearly shows where it is taking the lion share of the difference.

null    35019
OPENING_ARCHIVE    6
...            
SWITCH_VERSIONS    0                                                                  
CREATE_DEPLOYMENT_CONTEXT   Full    16554 
CLASS_SCANNING  ROOT    1370
CLEANUP generated    11                                                                 
PREPARE ServerConfig    7                                                              
...  

We can now see that the deployment context is taking almost 3 times longer (6147 to 16554ms).

In order to have a clearer picture of what is happening, I have increased the logging detail and dug into the code. This is what I have found:

On the DeployCommand.class we have a line that scans for deployable types (DeployCommand::515)

  String transformNS = System.getProperty(TRANSFORM_NAMESPACE);
  Types types = deployment.getDeployableTypes(deploymentContext);

Which then builds a Parser on ApplicationLifecycle::721 which in turn will scan the entire archive on Parse.parse(). This parser will use an Executor Service, which in my machine uses 3 threads to process (I haven't checked where it is created, so it might have different specs depending on the machine). This executor will be in charge of running the tasks wich call doJob()

 Future<Result> future = es.submit(new Callable<Result>() {
  @Override
  public Result call() throws Exception {
      try {
          if (logger.isLoggable(Level.FINE)) {
              logger.log(Level.FINE, "elected file " + source.getURI().getPath());
          }
          if (logger.isLoggable(Level.FINE)) {
              context.logger.log(Level.FINE, "started working at " + System.currentTimeMillis() + "in "
                      + this + " on " + source.getURI().getPath());
          }
          doJob(source, doneHook);

          return new Result(source.getURI().getPath(), null);
      } catch (Exception e) {
          logger.log(Level.SEVERE, "Exception while parsing file " + source.getURI(), e);
          return new Result(source.getURI().getPath(), e);
      }
  }
});

doJob will define the action the task takes when scanning the archives. When parsing, it will either handleJar or handleEntry - ReadableArchiveScannerAdapter.onSelectedEntries() handleJar will try to find a sub archive and handleEntry will actually parse each class it finds. And here is where the issue seems to lie - when visiting the class using the ClassReader.

if (context.archiveSelector == null || context.archiveSelector.selects(adapter)) {
      final URI uri = adapter.getURI();
      if (logger.isLoggable(Level.FINE)) {
          logger.log(Level.FINE, "Parsing file {0}", uri.getPath());
      }

      adapter.onSelectedEntries(
              new ArchiveAdapter.Selector() {
                  @Override
                  public boolean isSelected(ArchiveAdapter.Entry entry) {
                      return entry.name.endsWith(".class");
                  }
              },
              new ArchiveAdapter.EntryTask() {
                  @Override
                  public void on(ArchiveAdapter.Entry entry, InputStream is) throws IOException {
                      if (logger.isLoggable(Level.FINER)) {
                          logger.log(Level.FINER, "Parsing class " + entry.name);
                      }
                      try {
                          ClassReader cr = new ClassReader(is);
                          cr.accept(context.getClassVisitor(uri, entry.name, true), ClassReader.SKIP_DEBUG);
                      } catch (Throwable e) {
                          logger.log(Level.SEVERE, "Exception while visiting " + entry.name
                                  + " of size " + entry.size, e);
                      }
                  }
              },
              logger
      );
      saveResult(uri, context.getTypes());
  }

Somehow, on JDK 17, this parsing step of each class will take a lot longer that its JDK 8 or even JDK 17 counterpart. I suspect it has something to do with ASM's ClassReader taking longer to visit a JDK 17 compiled class than a JDK 8, though I am still not quite sure. In order to try to figure it further I tried replacing the asm jars with more recent ones (9.2 and 9.3) to see if it would improve the performance, but it did not have any effect - all in all, it took roughly the same time.

In here you can see a comparison of timings between JDK 8 class scanning and JDK 17. This was taken straight from the logs, by increasing the detail of javax.enterprise.system.tools.deployment.common.level=FINE. I then parsed the logs myself in order to keep only the actual message with the timings taken.

In JDK 8

Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/SparseBitSet-1.2.jar at 1655999640729 in 8 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/annotations-13.0.jar at 1655999636128 in 14 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/annotations-2.17.151.jar at 1655999636129 in 8 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/apache-client-2.17.151.jar at 1655999636168 in 17 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/arns-2.17.151.jar at 1655999636158 in 7 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/auth-2.17.151.jar at 1655999636199 in 34 ms
...
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/guava-31.1-jre.jar at 1655999638215 in 637 ms
...
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/poi-5.2.1.jar at 1655999639565 in 500 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/poi-ooxml-5.2.1.jar at 1655999639354 in 285 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/poi-ooxml-full-5.2.1.jar at 1655999641178 in 2077 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/poi-ooxml-lite-5.2.1.jar at 1655999640460 in 1097 ms

Notice that some smaller JARs are quickly parsed, but larger ones like Guava (637 ms) or POI (500ms) take way longer.

In JDK 17

Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/SparseBitSet-1.2.jar at 1655999365239 in 17 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/annotations-13.0.jar at 1655999350385 in 37 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/annotations-2.17.151.jar at 1655999350369 in 16 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/apache-client-2.17.151.jar at 1655999350435 in 57 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/arns-2.17.151.jar at 1655999350405 in 14 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/auth-2.17.151.jar at 1655999350548 in 136 ms
...
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/guava-31.1-jre.jar at 1655999356041 in 2740 ms
...
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/poi-5.2.1.jar at 1655999361284 in 2355 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/poi-ooxml-5.2.1.jar at 1655999360269 in 1311 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/poi-ooxml-full-5.2.1.jar at 1655999366223 in 7105 ms
Finished parsing /C:/Users/carlos.manuel/modules/fc-maintenance/domain/applications/ROOT/WEB-INF/lib/poi-ooxml-lite-5.2.1.jar at 1655999363844 in 3571 ms

All dependencies are taking longer, with the difference being even worse on the larger JARs. Here Guava (2740 ms) and POI (2355 ms) really paint the picture.

When we take the added times of each dependency - even with multiple threads parsing - we can see how this takes way longer on JDK 17. This particular app has around 117 dependencies, which is a relatively fair number of dependencies. Larger apps will take longer on the same machine.

Steps to reproduce

I have prepared a sample application that runs in Payara Micro. It can be found here

This app does nothing. It has a Jakarta REST endpoint but that is just for show. What it does have are some dependencies. Not too many, just enough to test the point.

1. Checkout the project
2. It has 3 branches: master, jdk11 and jdk8
3. As you can excpect each of those really are not that different from each other, they just set the version of JDK for the maven compiler plugin. It was just to test faster. master has JDK 17 as default.
4. run mvn clean install with a matching JDK version on your system
5. run mvn payara-micro:start . This will start the microbundle
6. Log level is quite detailed for deployment classes
7. In the end, you will also see the deployment trace being printed on console. I have activated it on the bundle goal of the Payara micro plugin configuration. You can see it in the pom.xml
8. Repeat with other branches for comparison
9. If you want you can keep adding other dependencies just to watch it degrade

Final notes

1. That app has a rather simple setup. In all other applications I have (and which my company uses in production) I actually have a permanent domain dir. This means everytime I deploy a new version of the app on my environment it will first redeploy (there should probably be a config to avoid this) the older version that is kept on the domain dir and only after that it will deploy the current one - this means it also doubles the time to deploy it, which means it is even worse on JDK 17.

2. My laptop is a fairly potent one, so I don't expect that to make a difference on hardware. I have left it on the envirnoment in any case.

3. I am not entirely sure that the CLASS_SCANNING span in deployment tracing is registering the right value. I think it is registering it too soon, because it should be closer to the total time it spends on CREATE_DEPLOYMENT_CONTEXT, since this is the part that is taking too long. Or I might have just missed the point by far :D

4. It might be possible to speed this up just by adding more threads to the Executor Service pool. If the issue really lies on ASM, then just adding more threads might do the trick.

5. I have here, in attachment, the full deployment traces of the app using JDK 8, 11 and 17. It might be useful to you. Maintenance_Corretto_JDK8.txt Maintenance_Corretto_JDK11.txt Maintenance_Corretto_JDK17.txt

Environment

• Distribution: Server Full Profile / Server Web Profile / Micro Community 5.2022.2
• JDK Version: Corretto JDK 8 / Corretto JDK 17
• Operating System: Windows 10
• Laptop: HP EliteBook 840 G7 8-core i7

[JamesHillyard]

Hi @CarlosMOGoncalves,

Thank you for the very detailed analysis, compiled results and reproducer - It's much appreciated! I agree there is definitely not a hardware limitation here as I was able to observe the same performance hit on an i5-12600k and very fast NVMe storage.

I have been able to validate your claims using Zulu JDK 8 / 11 / 17 observing between 60% - 70% increased deployment times on JDK 17 over JDK 8 using Windows 10.

When using Ubuntu 20.04.3 LTS, I observed almost no increase in deployment time on JDK 17 over JDK 8, where a few deployments were slightly faster on JDK 17.

We agree this should be looked into and therefore have raised this issue with the development team with the JIRA FISH-6432.

Thank you again for the detailed report, James

[CarlosMOGoncalves]

Hello @JamesHillyard ,

Thanks for checking it out. I never got to try it with a Linux distribution as all our development environment are Windows. Clearly there is something fishy here when running on Windows, which now I am very curious about.

However, I now have a delicate question for you: since we are fast approaching the final Payara 5 Community release, is is possble that any fix for this matter could make it into it?

Because otherwise this would only make it into Payara 6 and, although I plan on upgrading ASAP, it would also leave JDK 17 support on 5 a bit troublesome.

Thanks

[JamesHillyard]

Hi @CarlosMOGoncalves,

We can't guarantee the fix will be ready in time for the final community release, however we would like to include it in Payara Community.

If the fix is ready after the final release, it will be available in Payara 5 Enterprise, which would be recommended if you, or anyone else, wishes to continue using Payara 5 after the final Community release.

We hope you understand, James

[CarlosMOGoncalves]

Hello James,

I perfectly understand it and I know this issue probably came a bit "at the last minute". I really hope you make it so that I can avoid the overhead of moving all codebase to the jakarta namespace as well as to JDK 17 in one go on Payara 6.

Thanks all

[mkarg]

@JamesHillyard Any news for us? :-)

[JamesHillyard]

Hi @CarlosMOGoncalves and @mkarg,

Our development team has been looking into this recently, and it appears this issue is significantly deeper than first meets the eye. We are continuing to work on this, and your patience in the meantime is much appreciated.

Thanks, James

[CarlosMOGoncalves]

Hello @JamesHillyard ,

Thanks for the update. I have to admit that I am very much looking forward for this matter to be worked on because I really want to jump to JDK 17, but I suspected that it could be something tricky as soon as it became clear it was a difference from OS to OS.

I would be very glad if you could keep us updated on this matter.

[CarlosMOGoncalves]

Hello @JamesHillyard ,

I have just noticed that the latest release for Payara Community seems to have included a fix for this matter, although I haven't tested it myself.

Can you provide some information of what and why was happening? And why creating that file to read the canonical name was bottlenecking the whole deploy business on JDK 12 and above? This is merely for my own curiosity's sake 😄

Also, I noticed it was merged into Payara 5... however, we are past the final release for Payara 5 Community. Is there any change, even if just extraordinarily, that you could consider releasing it, as a final treat for the users, because of the impact it has on Windows users?

Regardless of that, thank you for this fix!

[ettaramesh]

We are seeing similar issue with Payara 6.2024.2 (Full) and Zulu Open JDK 17. The deployment with 6.2023.2 and Zulu open jdk 11 used take around 90 Seconds to deploy, but now with Payara 6.2024.2 and JDK 17 takes around 300 seconds. Are there are any configurations to tweak to get the deployment faster?