Spring boot - strange long response time for the first request of several ones

user_1150133 0
Viewed 8477

My teammates are developing a REST API using Spring Boot + PostgreSQL + Redis + Kafka, etc., while I'm making a monitoring tool using Prometheus, Grafana, and so on, to monitor that API.

This API provides four endpoints. Let's call them A,B,C and D.

I wanted to collect metrices of "approximate response time of each API endpoint". So I wrote simple scripts(Bash and Perl) that measure elapsed time taken to call each endpoint using curl. And then I registered the scripts using crontab to execute them once every minutes.

# get response time
curl -XGET -s -w "\\n%{http_code}\\n%{time_total}\\n" "http://for.example/A" | tail -n 1 >> log_A
curl -XGET -s -w "\\n%{http_code}\\n%{time_total}\\n" "http://for.example/B" | tail -n 1 >> log_B
...

The result is, as you see below, somewhat strange:

graph of response times

It took about 100ms to call one endpoint and took just a few milliseconds to call the others.

I looked into it and found that the first call of each cron job took much longer. That is, if I measured A,B,C,then D, A took 100ms. If I measured B,C,D, then A, B took 100ms. Next three endpoints response very soon. In the figure, I modified the sequence and I could see it affected the result immediately.

I am suspecting connection between Spring boot application and database(or redis, or kafka?) is disconnected due to expiration, so it takes time to reconnect first. But I think one minute is too short for any configuration to expire any connection. Anyway, from what point do I have to start?

Any advice would be appreciated.

Edit:

After writing this post, I launched a very simple Spring Boot REST API app, whose code came from Spring boot guide doc( https://spring.io/guides/gs/rest-service ), not using DB nor any external things. It takes only 4ms to curl this API always. So I suspect the external things more.

If you need to see configurations about Spring boot application. Here is pom.xml and application.yaml:

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
  xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
  <parent>
    <groupId>com.company</groupId>
    <artifactId>sylphid</artifactId>
    <version>0.1.0</version>
  </parent>
  <modelVersion>4.0.0</modelVersion>

  <artifactId>personal</artifactId>
  <version>0.3.0</version>

  <dependencies>
    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-data-jpa</artifactId>
    </dependency>
    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-web</artifactId>
    </dependency>
    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-cache</artifactId>
    </dependency>

    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-batch</artifactId>
    </dependency>
    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-data-redis</artifactId>
    </dependency>
    <!-- kafka -->
    <dependency>
      <groupId>org.springframework.kafka</groupId>
      <artifactId>spring-kafka</artifactId>
      <version>${spring-kafka.version}</version>
    </dependency>

    <dependency>
      <groupId>io.springfox</groupId>
      <artifactId>springfox-swagger2</artifactId>
      <version>${swagger.version}</version>
    </dependency>
    <dependency>
      <groupId>io.springfox</groupId>
      <artifactId>springfox-swagger-ui</artifactId>
      <version>${swagger.version}</version>
    </dependency>

    <!-- https://mvnrepository.com/artifact/io.springfox/springfox-spi -->
    <dependency>
      <groupId>io.springfox</groupId>
      <artifactId>springfox-spi</artifactId>
      <version>${swagger.version}</version>
    </dependency>
    <!-- https://mvnrepository.com/artifact/io.springfox/springfox-spring-web -->
    <dependency>
      <groupId>io.springfox</groupId>
      <artifactId>springfox-spring-web</artifactId>
      <version>${swagger.version}</version>
    </dependency>
    <dependency>
      <groupId>org.postgresql</groupId>
      <artifactId>postgresql</artifactId>
      <scope>runtime</scope>
    </dependency>
    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-test</artifactId>
      <scope>test</scope>
    </dependency>
  </dependencies>

  <build>
    <resources>
      <resource>
        <directory>src/main/resources</directory>
        <filtering>false</filtering>
      </resource>
    </resources>

    <finalName>personal</finalName>
    <plugins>
      <plugin>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-maven-plugin</artifactId>
      </plugin>
      <plugin>
        <groupId>io.fabric8</groupId>
        <artifactId>docker-maven-plugin</artifactId>
        <version>0.21.0</version>
        <configuration>
          <images>
            <image>
              <name>sylphid/${project.build.finalName}</name>
              <build>
                <from>openjdk:8u162-jdk</from>
                <entryPoint>java -Dspring.profiles.active=docker -jar /application/${project.build.finalName}.jar</entryPoint>
                <assembly>
                  <basedir>/application</basedir>
                  <descriptorRef>artifact</descriptorRef>
                  <inline>
                    <id>assembly</id>
                    <files>
                      <file>
                        <source>target/${project.build.finalName}.jar</source>
                      </file>
                    </files>
                  </inline>
                </assembly>
                <tags>
                  <tag>latest</tag>
                  <tag>${project.version}</tag>
                </tags>
                <ports>
                  <port>8080</port>
                </ports>
              </build>
              <run>
                <namingStrategy>alias</namingStrategy>
              </run>
              <alias>${project.build.finalName}</alias>
            </image>
          </images>
        </configuration>
      </plugin>
    </plugins>
  </build>

  <repositories>
    <repository>
      <id>spring-snapshots</id>
      <name>Spring Snapshots</name>
      <url>https://repo.spring.io/snapshot</url>
      <snapshots>
        <enabled>true</enabled>
      </snapshots>
    </repository>
    <repository>
      <id>spring-milestones</id>
      <name>Spring Milestones</name>
      <url>https://repo.spring.io/milestone</url>
      <snapshots>
        <enabled>false</enabled>
      </snapshots>
    </repository>
    <repository>
      <id>sonatype-nexus-snapshots</id>
      <name>Sonatype Nexus Snapshots</name>
      <url>https://oss.sonatype.org/content/repositories/snapshots/</url>
      <snapshots>
        <enabled>true</enabled>
      </snapshots>
      <releases>
        <enabled>false</enabled>
      </releases>
    </repository>
  </repositories>

</project>

spring:
  profiles: allnative
  application:
    name: personal
  jpa:
    database-platform: org.hibernate.dialect.PostgreSQL9Dialect
    properties:
      hibernate:
        temp.use_jdbc_metadata_defaults: false
        show_sql: false
        format_sql: false
        use_sql_comments: false
    hibernate:
      ddl-auto: update
  datasource:
    driver-class-name: org.postgresql.Driver
    url: jdbc:postgresql://127.0.0.1:5432/sylphid
    username: postgres
  batch:
    initialize-schema: always
  cache:
    type: redis
    redis:
      key-prefix: sylphid_
      time-to-live: 60m
  redis:
    host: 127.0.0.1
    port: 6379
  kafka:
      bootstrap-servers: 127.0.0.1:9092
      consumer:
        auto-offset-reset: earliest
        group-id: bookclub
server:
  port: 13480

app:
  topic:
    selection: bookclub.selection

management:
  endpoints:
    web:
      exposure:
        include: "*"
  endpoint:
    health:
      show-details: always
logging:
  file: allnative.log

Edit(2):

I was calling curl for each endpoint without any delay:

curl endpointA; curl endpointB; curl endpointC; curl endpointD
( almost 60 seconds interval before next cronjob )
curl endpointA; curl endpointB; curl endpointC; curl endpointD
...

Yesterday I tried to insert some delay between each curl executions, guessing "the interval between the last request and current request affects the response time of current request". (like... a human worker may fall asleep if nobody asks him to do something for a long time. When someone calls for him, he needs some more time to wake up. If someone else calls for him while he is awake, he can do the second job faster.)

When I inserted more than 2 seconds delay, I could see another endpoint began to be slow. When I inserted 10 seconds delay:

curl endpointA; sleep 10; curl endpointB; sleep 10;...
( about 20 seconds interval, because crontab still executes every minutes )
curl endpointA; sleep 10; curl endpointB; sleep 10;...

Here is the result. Every endpoints began to response after around 100ms.

enter image description here

Edit(3)

As a new attempt, I tried to use Jetty as embedded server instead of Tomcat. The result was somewhat impressive. Application using Jetty showed very stable response times for almost every measurement. Even Jetty showed long response time(about 300ms or so) sometimes, but they were very rare cases.

enter image description here

I have been observing two testsets(Tomcat and Jetty) for a few hours, and I'm going to observe one or more days. If this result goes on, I'll plan to tell my teammates about this and suggest to change the embedded server to Jetty.

However, if Tomcat is the cause of trouble, I have no idea why the simple Spring Boot app from the official guide does not show such a symptom.

grafana apache-kafka spring-boot redis
1 Answers

That's a very interesting test. Your stack is complex, and I understand the need of performance in this case.

Concerning the difference of performance between Tomcat/Jetty. May I suggest you to try an integration test with a MockMvc (see the get started )

I know how much is hard to split test between OPS infrastructures and DEV framework, but with SpringBoot you can test and display the execution performance with a unit test.

Iterate a call to one on your API any time you want and add a StopWatch around the execution. 

@RunWith(SpringRunner.class)
@SpringBootTest
@AutoConfigureMockMvc
public class ApplicationTest {
      private final static Logger LOGGER = LoggerFactory.getLogger(ApplicationTest .class);
  @Autowired
  private MockMvc mockMvc;

  @Test
  public void shouldReturnDefaultMessage() throws Exception {
    StopWatch stopWatch = new StopWatch("Testing REST API performances");

    for(int i=1; i<=5; i<++) {
      stopWatch.start("Test iteration " + i);
      this.mockMvc.perform(get("/")).andDo(print()).andExpect(status().isOk())
            .andExpect(content().string(containsString("Hello World")));
      stopWatch.stop();
    }
    // Print the result
    LOGGER.info(stopWatch.prettyPrint());
  }
}

This test should bring to light the performance issue should be the init of the rest controller.

Locally I have also a latency at the first call.

StopWatch 'Testing REST API performances': running time (millis) = 806

  • 00510ms 063 % Test iteration 1
  • 00072ms 009 % Test iteration 2
  • 00080ms 010 % Test iteration 3
  • 00071ms 009 % Test iteration 4
  • 00073ms 009 % Test iteration 5

As you can see the first call take a long time.

Hope I my answer will help you to have reach you performance expected and help you in your choice.

user_90998640
Related