我注意到我的 SpringBoot 微服务有一些奇怪的行为。我正在使用 spring mvc、springboot 3.3.3 和 Java 21。
考虑控制器中的以下代码(用
@RestController
和 lombok 的 @Slf4j
注释):
@GetMapping("/test/{id}")
public void getTest(@PathVariable Integer id) {
log.info("get test: {}", id);
}
@DeleteMapping("/test/{id}")
public void deleteTest(@PathVariable Integer id) throws InterruptedException {
TimeUnit.SECONDS.sleep(10);
log.info("delete test: {}", id);
}
@GetMapping("/test/{id}/something")
public void getTestSomething(@PathVariable Integer id) throws InterruptedException {
TimeUnit.SECONDS.sleep(10);
log.info("get test something: {}", id);
}
如果我在 10 秒内点击
DELETE /test/3
,然后点击 GET /test/3
,则 GET
将等待,直到 DELETE
请求返回。但是,如果我先点击GET /test/3/something
,然后点击GET /test/3
,它就不会等待。后者是我期望两者的行为。
此外,如果我为
DELETE
和第一个 GET
执行不同的 id,则 GET
将不会等待。例如,DELETE /test/4
后跟 GET /test/3
另一个有趣的观察是,如果我不使用传入的路径变量,例如只是不要记录它或将其传递给任何东西,它不会等待。如果路径未指定路径变量并且相等,情况也是如此。例如:
GET /test
和删除 /test
此外,如果我包含
@RequestParameter
,则不会出现等待问题。例如。 GET /test/3?key=value
我观察到的奇怪的等待行为是否在意料之中?还是我发现了一些奇怪的错误?
demo
├── pom.xml
├── src
│ └── main
│ ├── java
│ │ └── com
│ │ └── example
│ │ ├── DemoApplication.java
│ │ └── HelloController.java
│ └── resources
│ ├── application.properties
│ └── logback.xml
├── test1.sh
├── test2.sh
├── test3.sh
├── test4.sh
├── test5.sh
├── test6.sh
└── test-main.sh
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns="http://maven.apache.org/POM/4.0.0"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>3.3.3</version>
<relativePath/> <!-- lookup parent from repository -->
</parent>
<groupId>com.example</groupId>
<artifactId>demo</artifactId>
<version>0.0.1-SNAPSHOT</version>
<name>demo</name>
<description>Demo project for Spring Boot</description>
<properties>
<maven.compiler.source>17</maven.compiler.source>
<maven.compiler.target>17</maven.compiler.target>
<project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
<project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
</properties>
<dependencies>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-logging</artifactId>
</dependency>
<dependency>
<groupId>org.projectlombok</groupId>
<artifactId>lombok</artifactId>
</dependency>
</dependencies>
<build>
<finalName>app</finalName>
<plugins>
<plugin>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-maven-plugin</artifactId>
</plugin>
</plugins>
</build>
</project>
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="Console" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d [%thread] %-5level %-50logger{40} - %msg%n</pattern>
</encoder>
</appender>
<appender name="RollingFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>app.log</file>
<encoder>
<pattern>%d [%thread] %-5level %-50logger{40} - %msg%n</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>app-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<maxFileSize>1MB</maxFileSize>
<maxHistory>30</maxHistory>
<totalSizeCap>10MB</totalSizeCap>
<cleanHistoryOnStart>true</cleanHistoryOnStart>
</rollingPolicy>
</appender>
<root level="INFO">
<appender-ref ref="Console" />
<appender-ref ref="RollingFile" />
</root>
</configuration>
package com.example;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
@SpringBootApplication
public class DemoApplication {
public static void main(String[] args) {
SpringApplication.run(DemoApplication.class, args);
}
}
我将方法的返回值改为String,返回对应的日期和时间。
package com.example;
import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.*;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
import java.util.Calendar;
import java.util.concurrent.TimeUnit;
@Slf4j
@RestController
public class HelloController {
@GetMapping("/test/{id}")
public String getTest(@PathVariable Integer id) {
log.info("get test: {}", id);
LocalDateTime now = LocalDateTime.now();
DateTimeFormatter formatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS");
String formattedDateTime = now.format(formatter);
return formattedDateTime + "\t" + "get test: "+ id + "\n";
}
@DeleteMapping("/test/{id}")
public String deleteTest(@PathVariable Integer id) throws InterruptedException {
log.info("entry delete test: {}", id);
TimeUnit.SECONDS.sleep(10);
log.info("delete test: {}", id);
LocalDateTime now = LocalDateTime.now();
DateTimeFormatter formatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS");
String formattedDateTime = now.format(formatter);
return formattedDateTime + "\t" + "delete test: "+ id + "\n";
}
@GetMapping("/test/{id}/something")
public String getTestSomething(@PathVariable Integer id) throws InterruptedException {
log.info("entry get test something: {}", id);
TimeUnit.SECONDS.sleep(10);
log.info("get test something: {}", id);
LocalDateTime now = LocalDateTime.now();
DateTimeFormatter formatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS");
String formattedDateTime = now.format(formatter);
return formattedDateTime + "\t" + "get test something: "+ id +"\n";
}
}
test-main.sh 调用 test1.sh、test2.sh、test3.sh、test4.sh、test5.sh、test6.sh
test1.sh(test4.sh)调用
getTest
test2.sh(test5.sh)调用
deleteTest
test3.sh(test6.sh)调用
getTestSomething
#!/bin/bash
echo "TEST MAIN START"
start_time0=$(date +%s)
for i in {1..6}; do
./test${i}.sh &
done
wait
end_time0=$(date +%s)
elapsed_time0=$((end_time0 - start_time0))
echo "TEST MAIN - Elapsed time: $elapsed_time0 seconds"
#!/bin/bash
echo "TEST 1 START"
start_time1=$(date +%s)
for i in {1..100}; do
curl -X GET "http://localhost:8080/test/${i}" &
done
wait
end_time1=$(date +%s)
elapsed_time1=$((end_time1 - start_time1))
echo "TEST 1 - Elapsed time: $elapsed_time1 seconds"
#!/bin/bash
echo "TEST 2 START"
start_time2=$(date +%s)
for i in {1..100}; do
curl -X DELETE "http://localhost:8080/test/${i}" &
done
wait
end_time2=$(date +%s)
elapsed_time2=$((end_time2 - start_time2))
echo "TEST 2 - Elapsed time: $elapsed_time2 seconds"
#!/bin/bash
echo "TEST 3 START"
start_time3=$(date +%s)
for i in {1..100}; do
curl -X GET "http://localhost:8080/test/${i}/something" &
done
wait
end_time3=$(date +%s)
elapsed_time3=$((end_time3 - start_time3))
echo "TEST 3 - Elapsed time: $elapsed_time3 seconds"
#!/bin/bash
echo "TEST 4 START"
start_time4=$(date +%s)
for i in {1..100}; do
curl -X GET "http://localhost:8080/test/${i}" &
done
wait
end_time4=$(date +%s)
elapsed_time4=$((end_time4 - start_time4))
echo "TEST 4 - Elapsed time: $elapsed_time4 seconds"
#!/bin/bash
echo "TEST 5 START"
start_time5=$(date +%s)
for i in {1..100}; do
curl -X DELETE "http://localhost:8080/test/${i}" &
done
wait
end_time5=$(date +%s)
elapsed_time5=$((end_time5 - start_time5))
echo "TEST 5 - Elapsed time: $elapsed_time5 seconds"
#!/bin/bash
echo "TEST 6 START"
start_time6=$(date +%s)
for i in {1..100}; do
curl -X GET "http://localhost:8080/test/${i}/something" &
done
wait
end_time6=$(date +%s)
elapsed_time6=$((end_time6 - start_time6))
echo "TEST 6 - Elapsed time: $elapsed_time6 seconds"
mvn clean package
java -jar target/app.jar
test-main.sh
你可以数一下,
getTest
传入参数id从1到100,每个数字调用2次(test1.sh,test4.sh)
deleteTest
传入参数id从1到100,每个数字调用2次(test2.sh,test5.sh)
getTestSomething
传入参数id从1到100,每个数字调用2次(test3.sh,test6.sh)
TEST MAIN START
TEST 3 START
TEST 2 START
TEST 1 START
TEST 4 START
TEST 5 START
TEST 6 START
2024-09-26 20:05:44.372 get test: 67
2024-09-26 20:05:44.371 get test: 100
2024-09-26 20:05:44.345 get test: 90
2024-09-26 20:05:44.371 get test: 42
...
2024-09-26 20:05:44.762 get test: 76
2024-09-26 20:05:44.765 get test: 41
2024-09-26 20:05:44.769 get test: 31
2024-09-26 20:05:54.344 delete test: 72
2024-09-26 20:05:54.344 delete test: 46
2024-09-26 20:05:54.346 get test something: 43
2024-09-26 20:05:54.346 delete test: 77
2024-09-26 20:05:54.344 delete test: 1
...
2024-09-26 20:06:04.763 delete test: 19
2024-09-26 20:06:04.765 get test something: 27
2024-09-26 20:06:04.765 get test something: 29
2024-09-26 20:06:04.765 delete test: 25
2024-09-26 20:06:04.764 get test something: 95
TEST 5 - Elapsed time: 21 seconds
TEST 6 - Elapsed time: 21 seconds
TEST 2 - Elapsed time: 21 seconds
2024-09-26 20:06:04.780 get test something: 3
TEST 3 - Elapsed time: 21 seconds
TEST MAIN - Elapsed time: 21 seconds
您可以像
http-nio-8080-exec-XX
一样检查app.log中的http-nio-8080-exec-36
来查看已处理的线程。
...
2024-09-26 20:05:44,340 [http-nio-8080-exec-36] INFO com.example.HelloController - get test: 54
2024-09-26 20:05:44,342 [http-nio-8080-exec-47] INFO com.example.HelloController - entry delete test: 46
2024-09-26 20:05:44,342 [http-nio-8080-exec-12] INFO com.example.HelloController - entry delete test: 1
2024-09-26 20:05:44,342 [http-nio-8080-exec-51] INFO com.example.HelloController - entry delete test: 72
2024-09-26 20:05:44,343 [http-nio-8080-exec-46] INFO com.example.HelloController - get test: 64
2024-09-26 20:05:44,640 [http-nio-8080-exec-111] INFO com.example.HelloController - entry get test something: 94
2024-09-26 20:05:44,652 [http-nio-8080-exec-109] INFO com.example.HelloController - get test: 16
...
2024-09-26 20:05:44,728 [http-nio-8080-exec-174] INFO com.example.HelloController - entry get test something: 86
2024-09-26 20:05:44,728 [http-nio-8080-exec-168] INFO com.example.HelloController - get test: 21
2024-09-26 20:05:44,729 [http-nio-8080-exec-158] INFO com.example.HelloController - entry get test something: 44
2024-09-26 20:05:44,729 [http-nio-8080-exec-165] INFO com.example.HelloController - entry delete test: 88
2024-09-26 20:05:44,725 [http-nio-8080-exec-148] INFO com.example.HelloController - entry get test something: 41
2024-09-26 20:05:44,727 [http-nio-8080-exec-160] INFO com.example.HelloController - get test: 51
...
2024-09-26 20:05:54,638 [http-nio-8080-exec-107] INFO com.example.HelloController - entry delete test: 89
2024-09-26 20:05:54,640 [http-nio-8080-exec-105] INFO com.example.HelloController - get test something: 93
2024-09-26 20:05:54,642 [http-nio-8080-exec-111] INFO com.example.HelloController - get test something: 94
2024-09-26 20:05:54,643 [http-nio-8080-exec-104] INFO com.example.HelloController - get test: 58
...
2024-09-26 20:05:54,707 [http-nio-8080-exec-139] INFO com.example.HelloController - delete test: 46
2024-09-26 20:05:54,708 [http-nio-8080-exec-153] INFO com.example.HelloController - get test: 47
2024-09-26 20:05:54,709 [http-nio-8080-exec-124] INFO com.example.HelloController - entry delete test: 57
2024-09-26 20:05:54,692 [http-nio-8080-exec-130] INFO com.example.HelloController - delete test: 97
2024-09-26 20:05:54,692 [http-nio-8080-exec-141] INFO com.example.HelloController - get test something: 83
2024-09-26 20:05:54,693 [http-nio-8080-exec-122] INFO com.example.HelloController - get test something: 100
2024-09-26 20:05:54,693 [http-nio-8080-exec-127] INFO com.example.HelloController - entry delete test: 26
2024-09-26 20:05:54,710 [http-nio-8080-exec-156] INFO com.example.HelloController - get test something: 90
2024-09-26 20:05:54,710 [http-nio-8080-exec-153] INFO com.example.HelloController - entry get test something: 76
2024-09-26 20:05:54,711 [http-nio-8080-exec-162] INFO com.example.HelloController - delete test: 99
2024-09-26 20:05:54,712 [http-nio-8080-exec-156] INFO com.example.HelloController - get test: 49
2024-09-26 20:05:54,712 [http-nio-8080-exec-122] INFO com.example.HelloController - entry delete test: 43
2024-09-26 20:05:54,712 [http-nio-8080-exec-162] INFO com.example.HelloController - get test: 9
2024-09-26 20:05:54,693 [http-nio-8080-exec-136] INFO com.example.HelloController - get test something: 42
2024-09-26 20:05:54,693 [http-nio-8080-exec-116] INFO com.example.HelloController - entry delete test: 64
2024-09-26 20:05:54,693 [http-nio-8080-exec-123] INFO com.example.HelloController - delete test: 12
2024-09-26 20:05:54,713 [http-nio-8080-exec-147] INFO com.example.HelloController - get test something: 64
...
2024-09-26 20:05:54,724 [http-nio-8080-exec-138] INFO com.example.HelloController - entry get test something: 28
2024-09-26 20:05:54,724 [http-nio-8080-exec-166] INFO com.example.HelloController - entry delete test: 86
2024-09-26 20:05:54,695 [http-nio-8080-exec-144] INFO com.example.HelloController - get test something: 30
2024-09-26 20:05:54,696 [http-nio-8080-exec-143] INFO com.example.HelloController - delete test: 48
2024-09-26 20:05:54,697 [http-nio-8080-exec-149] INFO com.example.HelloController - delete test: 17
2024-09-26 20:05:54,726 [http-nio-8080-exec-170] INFO com.example.HelloController - get test something: 85
2024-09-26 20:05:54,727 [http-nio-8080-exec-146] INFO com.example.HelloController - get test something: 50
2024-09-26 20:05:54,727 [http-nio-8080-exec-149] INFO com.example.HelloController - get test: 36
2024-09-26 20:05:54,697 [http-nio-8080-exec-135] INFO com.example.HelloController - get test something: 18
2024-09-26 20:05:54,728 [http-nio-8080-exec-170] INFO com.example.HelloController - get test: 97
2024-09-26 20:05:54,728 [http-nio-8080-exec-173] INFO com.example.HelloController - delete test: 74
2024-09-26 20:05:54,728 [http-nio-8080-exec-159] INFO com.example.HelloController - delete test: 75
2024-09-26 20:05:54,729 [http-nio-8080-exec-142] INFO com.example.HelloController - entry get test something: 71
2024-09-26 20:05:54,732 [http-nio-8080-exec-159] INFO com.example.HelloController - get test: 75
2024-09-26 20:05:54,732 [http-nio-8080-exec-143] INFO com.example.HelloController - entry delete test: 35
2024-09-26 20:05:54,732 [http-nio-8080-exec-135] INFO com.example.HelloController - entry get test something: 30
2024-09-26 20:05:54,697 [http-nio-8080-exec-114] INFO com.example.HelloController - get test: 46
2024-09-26 20:05:54,732 [http-nio-8080-exec-146] INFO com.example.HelloController - entry get test something: 16
2024-09-26 20:05:54,698 [http-nio-8080-exec-152] INFO com.example.HelloController - get test something: 4
2024-09-26 20:05:54,733 [http-nio-8080-exec-169] INFO com.example.HelloController - get test something: 93
2024-09-26 20:05:54,707 [http-nio-8080-exec-154] INFO com.example.HelloController - get test: 46
2024-09-26 20:05:54,734 [http-nio-8080-exec-114] INFO com.example.HelloController - get test: 81
2024-09-26 20:05:54,710 [http-nio-8080-exec-139] INFO com.example.HelloController - get test: 84
2024-09-26 20:05:54,735 [http-nio-8080-exec-168] INFO com.example.HelloController - get test something: 52
2024-09-26 20:05:54,712 [http-nio-8080-exec-141] INFO com.example.HelloController - entry get test something: 81
2024-09-26 20:05:54,735 [http-nio-8080-exec-114] INFO com.example.HelloController - entry get test something: 49
2024-09-26 20:05:54,735 [http-nio-8080-exec-176] INFO com.example.HelloController - get test something: 76
2024-09-26 20:05:54,735 [http-nio-8080-exec-177] INFO com.example.HelloController - delete test: 9
2024-09-26 20:05:54,735 [http-nio-8080-exec-139] INFO com.example.HelloController - get test: 57
2024-09-26 20:05:54,735 [http-nio-8080-exec-154] INFO com.example.HelloController - entry delete test: 69
2024-09-26 20:05:54,712 [http-nio-8080-exec-130] INFO com.example.HelloController - entry get test something: 97
2024-09-26 20:05:54,736 [http-nio-8080-exec-152] INFO com.example.HelloController - get test: 30
2024-09-26 20:05:54,736 [http-nio-8080-exec-155] INFO com.example.HelloController - delete test: 74
2024-09-26 20:05:54,736 [http-nio-8080-exec-151] INFO com.example.HelloController - get test something: 27
2024-09-26 20:05:54,737 [http-nio-8080-exec-176] INFO com.example.HelloController - get test: 62
2024-09-26 20:05:54,737 [http-nio-8080-exec-180] INFO com.example.HelloController - delete test: 71
2024-09-26 20:05:54,738 [http-nio-8080-exec-155] INFO com.example.HelloController - entry delete test: 87
2024-09-26 20:05:54,738 [http-nio-8080-exec-172] INFO com.example.HelloController - delete test: 87
2024-09-26 20:05:54,739 [http-nio-8080-exec-181] INFO com.example.HelloController - get test something: 6
2024-09-26 20:05:54,739 [http-nio-8080-exec-184] INFO com.example.HelloController - delete test: 65
2024-09-26 20:05:54,739 [http-nio-8080-exec-182] INFO com.example.HelloController - delete test: 70
2024-09-26 20:05:54,740 [http-nio-8080-exec-185] INFO com.example.HelloController - delete test: 53
2024-09-26 20:05:54,740 [http-nio-8080-exec-182] INFO com.example.HelloController - get test: 28
2024-09-26 20:05:54,741 [http-nio-8080-exec-178] INFO com.example.HelloController - delete test: 98
2024-09-26 20:05:54,741 [http-nio-8080-exec-188] INFO com.example.HelloController - delete test: 50
2024-09-26 20:05:54,742 [http-nio-8080-exec-163] INFO com.example.HelloController - delete test: 66
2024-09-26 20:05:54,742 [http-nio-8080-exec-151] INFO com.example.HelloController - entry get test something: 69
2024-09-26 20:05:54,742 [http-nio-8080-exec-182] INFO com.example.HelloController - entry get test something: 23
2024-09-26 20:05:54,742 [http-nio-8080-exec-180] INFO com.example.HelloController - get test: 49
2024-09-26 20:05:54,743 [http-nio-8080-exec-163] INFO com.example.HelloController - entry get test something: 68
2024-09-26 20:05:54,743 [http-nio-8080-exec-187] INFO com.example.HelloController - delete test: 82
2024-09-26 20:05:54,743 [http-nio-8080-exec-177] INFO com.example.HelloController - entry delete test: 62
2024-09-26 20:05:54,745 [http-nio-8080-exec-181] INFO com.example.HelloController - entry get test something: 34
2024-09-26 20:05:54,714 [http-nio-8080-exec-162] INFO com.example.HelloController - entry get test something: 67
2024-09-26 20:05:54,720 [http-nio-8080-exec-136] INFO com.example.HelloController - entry get test something: 72
2024-09-26 20:05:54,730 [http-nio-8080-exec-158] INFO com.example.HelloController - get test something: 44
2024-09-26 20:05:54,730 [http-nio-8080-exec-165] INFO com.example.HelloController - delete test: 88
2024-09-26 20:05:54,747 [http-nio-8080-exec-195] INFO com.example.HelloController - get test something: 17
2024-09-26 20:05:54,747 [http-nio-8080-exec-196] INFO com.example.HelloController - delete test: 68
2024-09-26 20:05:54,747 [http-nio-8080-exec-165] INFO com.example.HelloController - entry get test something: 48
2024-09-26 20:05:54,747 [http-nio-8080-exec-158] INFO com.example.HelloController - entry get test something: 86
2024-09-26 20:05:54,730 [http-nio-8080-exec-173] INFO com.example.HelloController - entry delete test: 33
2024-09-26 20:05:54,730 [http-nio-8080-exec-148] INFO com.example.HelloController - get test something: 41
2024-09-26 20:05:54,730 [http-nio-8080-exec-144] INFO com.example.HelloController - get test: 38
2024-09-26 20:05:54,748 [http-nio-8080-exec-195] INFO com.example.HelloController - entry get test something: 87
2024-09-26 20:05:54,749 [http-nio-8080-exec-148] INFO com.example.HelloController - entry delete test: 33
2024-09-26 20:05:54,749 [http-nio-8080-exec-196] INFO com.example.HelloController - get test: 43
2024-09-26 20:05:54,730 [http-nio-8080-exec-150] INFO com.example.HelloController - get test: 89
2024-09-26 20:05:54,730 [http-nio-8080-exec-170] INFO com.example.HelloController - entry get test something: 15
2024-09-26 20:05:54,724 [http-nio-8080-exec-132] INFO com.example.HelloController - entry get test something: 47
2024-09-26 20:05:54,731 [http-nio-8080-exec-161] INFO com.example.HelloController - delete test: 90
2024-09-26 20:05:54,751 [http-nio-8080-exec-196] INFO com.example.HelloController - get test: 70
2024-09-26 20:05:54,751 [http-nio-8080-exec-150] INFO com.example.HelloController - entry get test something: 19
2024-09-26 20:05:54,731 [http-nio-8080-exec-160] INFO com.example.HelloController - get test something: 53
2024-09-26 20:05:54,731 [http-nio-8080-exec-145] INFO com.example.HelloController - entry delete test: 58
2024-09-26 20:06:04,763 [http-nio-8080-exec-161] INFO com.example.HelloController - get test something: 27
2024-09-26 20:06:04,765 [http-nio-8080-exec-168] INFO com.example.HelloController - delete test: 25
2024-09-26 20:06:04,765 [http-nio-8080-exec-186] INFO com.example.HelloController - get test something: 29
2024-09-26 20:06:04,780 [http-nio-8080-exec-192] INFO com.example.HelloController - get test something: 3
我不明白有什么问题?