Waiting for server respnse耗時過長原因排查及解決

更新時間：2023年05月24日 09:03:00 作者：iiopsd

這篇文章主要給大家介紹了關于Waiting for server respnse耗時過長原因排查及解決的相關資料,文中將解決的辦法介紹的非常詳細,對大家的學習或者工作具有一定的參考學習價值,需要的朋友可以參考下

背景

開發(fā)了一個導入接口，測試過程中發(fā)現導入壓縮包24M時，耗時50多秒。覺得這個時間太長了，可能存在問題，于是開始了漫長的排查之旅。

查看接口時間

通過Chrome DevTools 查看接口請求信息，發(fā)現接口時間主要消耗在發(fā)送數據（Request sent）和等待服務器響應（Waiting for server respnse）兩部分。

Request sent：平均在31s

Waiting for server respnse：平均18s

Request sent時間屬于正常偏慢，因為發(fā)送數據受網絡上行帶寬限制，暫時也沒辦法做太大的優(yōu)化。
Waiting for server respnse時間有很大的問題，因為接口中只做了簡單的操作，復雜的數據處理都是異步執(zhí)行的，所以問題應該在服務端。

排查接口問題

懷疑是接口請求問題后，就使用arthas trace 查看接口詳細耗時。

docker exec -it xxx java -jar /arthas/arthas-boot.jar
[INFO] arthas-boot version: 3.5.1
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.
* [1]: 10 org.springframework.boot.loader.JarLauncher

[INFO] arthas home: /opt/arthas
[INFO] Try to attach process 10
[INFO] Attach process 10 success.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.                           
 /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'                          
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.                          
|  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |                         
`--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'                          
                                                                                

wiki       https://arthas.aliyun.com/doc                                        
tutorials  https://arthas.aliyun.com/doc/arthas-tutorials.html                  
version    3.5.1                                                                
main_class                                                                      
pid        10                                                                   
time       2022-11-23 19:07:06                                                  

[arthas@10]$ trace xxx.XXXController test  -n 5 --skipJDKMethod false 
Press Q or Ctrl+C to abort.
Affect(class count: 2 , method count: 2) cost in 601 ms, listenerId: 1
`---ts=2022-11-24 13:44:28;thread_name=http-nio-9001-exec-17;id=bd;is_daemon=true;priority=5;TCCL=org.xxx.xxxClassLoader@300aa927
    `---[211.492528ms] xxx.XXXController$$EnhancerBySpringCGLIB$$103cd3e4:test()
        `---[166.654272ms] org.xxx.MethodInterceptor:intercept() #57
            `---[102.043649ms] com.xxx.XXXController:test()
                +---[101.125313ms] com.xxx.XXXService:importUser() #359
                `---[0.754306ms] com.xxx.XXXBuilder:success() #57

根據arthas trace日志顯示，接口耗時在200ms左右，這才是符合預期的時間。沒有找到具體問題，只能代碼走查一遍。接口邏輯其實很清晰，先校驗文件格式大小，然后創(chuàng)建異步任務（插入一條數據），最后執(zhí)行異步任務。因為有異步任務，所以整個接口耗時應該最多幾百毫秒，初步判斷arthas trace的結果正確合理。

排查網關問題

既然接口實現沒有問題，那就往上游排查，查看網關是否存在問題。查看網關接口請求和返回時間和剛才arthas trace時間相差無幾，排除了網關的問題。

排查SLB問題

網關沒問題只能在往上排查問題，測試了另一個環(huán)境B發(fā)現是相對正常的，Waiting for server respnse 時間在600ms左右。

對比討論了下兩個環(huán)境的差異，發(fā)現有問題的環(huán)境A相比正常的環(huán)境B多了一層SLB負載均衡，懷疑可能是這個問題。網上查了相關資料，也沒有顯示SLB有出現過這種情況。

于是讓運維先關閉SLB負載均衡驗證一下情況，修改SLB配置后需要一小會才能生效，結果顯示關掉SLB接口請求時間還是有問題，因此也不是SLB的問題，于是只是剩下Nginx了。

排查Nginx問題

排查了一下午沒有結果，然后就先去吃飯休息，踢踢桌面足球放松一下。

放松回來后，開始排查了Nginx配置，嘗試重啟ng，修改buffer大小都無濟于事。掃到ng配置的時候發(fā)現ng做了一次負載均衡，而且服務器地址配置的是公網ip，猜測可能是這個問題，死馬當成活馬醫(yī)，隨便試試看。修改為內網地址，然后重啟ng后驗證發(fā)現正常了。就這樣正常了?；舜蟀胩鞎r間，總算解決了。后來復盤討論猜測，應該是ng接收到文件后，通過負載均衡走公網ip轉了一圈回來導致Waiting for server respnse 耗時過長。

一不小心就有坑。