15

I have a strange behaviour on our spring boot application:

  • Frontend/Client - angular 6
  • Backend - spring boot - spring MVC - embedded tomcat - Linux

After restarting the backend the first calls to a controller needs about 5 seconds, the following same request only takes 50ms. This is reproducible in 90% of the cases, sometimes even the first call is fast.

I am sure, the problem is on the server not on the client. On the browser, I see the TTFB time (time to the first byte) is increasing to 5 seconds. The following requests only need 10ms for TTFB.

With monitoring tools on the server (app dynamics) i can collect such slow server calls and on the call graph i can see that:

org.apache.catalina.webresources.JarWarResourceSet:getArchiveEntries:117

needs 4916ms. So here is my bottleneck, I think. But I don't know how to fix it.

What i have already tryed:

  • Switched from hikaricp to apache tomcat jdbc connection pool
  • Ugraded spring boot from 2.0.0 to 2.0.5
  • Upgraded java to 1.8.0_181
  • Propertie spring.jpa.tomcat.testOnBorrow = true
  • Propertie spring.jpa.tomcat.validationQuery = select 1

Everything without influence to the server delay.

Update

The time is lost cause the war file is scanned multiple times.

org.apache.catalina.webresources.CachedResource.validateResource is checking if we have a war file (isPackedWarFile) and this check return false. Even though it is a war file. For this misbehave I have a workaround. I set tomcat.resource.cache-tt to a high value.

But now org.apache.catalina.webresources.Cache.getResource has a noCache method. And in this method class and jar files are excluded from caching. And this is the reason why the war file is scanned again.

Scanning the whole war file takes roughly 5 seconds. And this break is a stop the world break. And this scanning is absolutely needless cause the war file is not exploded and so its contents can not be changed.

Update

If I put the war file into a tomcat installation everything is fast. The embedded tomcat is the problem.

Arpit Sharma
  • 900
  • 5
  • 11
tomas
  • 830
  • 3
  • 8
  • 25
  • Similarly, in an installed Tomcat, we have found that `` can make a big difference. Clearly resource scanning directly within a `.war` is inefficient compared to an expanded directory. I can believe that scanning the indexes of jar files in `WEB-INF/lib` would be more work when they are themselves archived. – df778899 Oct 09 '18 at 21:12
  • What about the other flavours of spring boot web server - jetty and undertow? – ThomasRS Oct 14 '18 at 21:16
  • I need AJP support from the server. I think jetty has dropped his AJP support. Not sure about undertow. Anyway i want to use tomecat. – tomas Oct 15 '18 at 07:59

4 Answers4

4

I suppose you already did, but if you haven't, take a look at https://cwiki.apache.org/confluence/display/TOMCAT/HowTo+FasterStartUp and implement the fixes suggested there.

For disabling scanning with embedded tomcat, there is a suggestion in the comments here https://github.com/spring-projects/spring-boot/issues/1610

If none of the above suggestions helps you fix the delay, a possible workaround would be making that first request at server start-up (and triggering the delay from there).

@SpringBootApplication
public class Application implements CommandLineRunner {

    @Autowired
    private RestTemplate template;

    public static void main (String args[]){
        SpringApplication.run(Application.class, args);
    }

    @Override
    public void run(String... strings) throws Exception {
        // do an initial request from here to trigger scanning the war
        template.exchange(...);
    }

}

In this way, your client will no longer experience the 5s delay. I am aware this is a hack, so if you find a cleaner way to do it use that instead.

balsick
  • 1,099
  • 1
  • 10
  • 23
  • Hope at least the hack will help you :) –  Oct 15 '18 at 08:21
  • I've now given up deployment as fat jar. When I deploy my application into a tomact it runs perfectly. – tomas Oct 22 '18 at 09:42
  • seems like the first url has moved to https://cwiki.apache.org/confluence/display/TOMCAT/HowTo+FasterStartUp for those interested – ajax992 May 07 '20 at 21:14
1

I was facing similar issue of high CPU usage and delay in response. org.apache.catalina.webresources.JarWarResourceSet:getArchiveEntries was taking around 5 sec while scanning war file.During scanning, no requests were served.

I have updated Spring boot version from 1.4.2.RELEASE to 1.5.12.RELEASE, which resolved this issue. Indeed, It seems issue was with embedded Tomcat which got fixed in later versions.

Rigel1121
  • 2,022
  • 1
  • 17
  • 24
Naveen Katiyar
  • 33
  • 4
  • 1
    I am using Spring boot 2 (2.0.5). This version includes an embedded tomcat in version 8.5.34. And here the problem is still existing. – tomas Oct 22 '18 at 09:40
  • @tomas Do you mind sharing if you were able to get past this issue and how? – dev_in_prog Mar 13 '20 at 05:57
  • i am also facing this issue. checked locally with jvisual vm and sampler the time is consumed in org.apache.catalina.webresources.JarWarResourceSet:getArchiveEntries. moving to jar is not an option for me. any other ideas. – arvin_v_s Jul 13 '21 at 13:52
1

Using an executable JAR file (instead of a WAR) to run with embedded Tomcat solved the issue for me. This is the recommended way to speed up resource loading from executable archives.

  1. you can have one Spring Boot project and deploy to both JAR or WAR,
  2. I had to switch from WAR to JAR to have better performance and had an issue when using JSP taglibs in freemarker. This is a way to solve that issue when using JSP taglibs.
rochb
  • 2,249
  • 18
  • 26
  • thanks for your reply. i'm pretty sure i tried both a jar and a war deployment back then. and both had this performance problem. – tomas Sep 06 '19 at 09:45
  • I went from WAR to JAR and I do not have the performance issue anymore as explained here: https://github.com/spring-projects/spring-boot/issues/16471 – rochb Sep 09 '19 at 14:01
0

What you're describing is the typical effect of a reboot on an infrastructyure which uses heavy DB connection pooling.

  • first request: open the physical connection (100ms to 2-3 secs), do some inizialization (depends on DB), perform SQL (vary per query), return to pool (<1ms)
  • second request: extract from pool (<1ms), perform SQL (vary per query), return to pool (<1ms)

based on your data my best guess is that the first two steps are slow and untile the DB pool is warmed up you'll experience some very slow queries. Potential improvements are:

  • configure a warm-up period during which the pool performs self-init while Tomcat is not yet responding
  • check on the DB side what's being done at connection creation and on the app side if/which config you have to setup the connection
Simone Avogadro
  • 789
  • 8
  • 23
  • This was also my first thoughts. But the connection pool is not the problem. With performance profiling i could find that it is the scanning of the WAR file. – tomas Oct 15 '18 at 14:16
  • if you're sure about that then I suggest you look into Antivirus (well known hog when opening wars and examining bytecode) and containerization (which sometimes have some weirs side effect on I/O). The first (antivirus) can be easily be checked by disabling it. The second (containerization) is usually way less trivial because of the many differences involved in running containerized vs. non containerized apps, there you should look for specific stackoverflow questions. – Simone Avogadro Oct 16 '18 at 18:19