Nginx の背後にある高速な SSD サーバーでホストされている ASP.NET Core アプリがあり、データベースは同じサーバーでホストされている MySql です。私は非常に奇妙な行動を経験しています。
下記は用例です。そのため、数字は API への呼び出しを表し、応答時間が発生します。内部アーキテクチャに問題があると思ったので、コントローラーの先頭に日時オブジェクトがあり、最後にタイムスパンを測定します。次のようなものです。
[HttpGet("/api/surveys/")]
public async Task<IActionResult> GetRecentSurveys()
{
var enter = DateTime.Now;
var recentSurveys = await context.Surveys.OrderByDescending(d => d.Date).Take(20).Include(x => x.Client).ToListAsync();
var resource = mapper.Map<IEnumerable<Survey>, IEnumerable<SurveyResource>>(recentSurveys);
var exit = DateTime.Now;
TimeSpan time = exit - enter;
return Ok(resource.Count() + " Time taken: "+ time.Seconds+ " sec " + time.Milliseconds + " ms ");
}
だからここに私が得るものがあります（アプリはサーバー上にあり、高速の100mbpsネットワーク上にあるローカルマシンから呼び出しています）：
デプロイ API アドレス 1 の直後に行われた呼び出し
1) 4.879 秒 2) 262 ミリ秒 3) 10 ミリ秒 4) 14 ミリ秒 5) 7 ミリ秒 6) 7 ミリ秒 7) 8 ミリ秒
API アドレス 2 8) 523ms 9) 16ms 10) 6ms 11) 7ms 12) 5ms
ご覧のとおり、最初の API への最初の呼び出しに最も時間がかかり、その後、時間は最小の 7 ミリ秒に短縮されます。別の API エンドポイントに切り替えると、開始時にほぼ同じ結果が得られますが、少し高速ですが、あとがきの動作はまったく同じですが、約 10 ミリ秒の応答時間で安定します。
誰もこの問題を経験したことがありますか? ユーザーが行う前に最初の呼び出しを行うための可能な回避策を聞きましたが、おそらくタイムアウト後にこの動作が返されると思われますが、これは醜いように聞こえますか? カーテンの後ろで実際に何が起こっているかを確認するにはどうすればよいですか?
この問題に本当に悩まされています。アプリは非常にうまく機能しますが、これは本当に苦痛です。前もって感謝します！これに関する有益な情報を本当に感謝します。
更新だから、Linux マシンのシステム ログを調査したところ、次のような結果が得られました。
//this is what I get after I run systemctl restart backend
//backend is the backend.dll of my ASP.NET Core app
Dec 5 12:54:34 yzapplications systemd[1]: Started Boat Inspector Backend.
Dec 5 12:54:40 yzapplications dotnet[14069]: Hosting environment: Production
Dec 5 12:54:40 yzapplications dotnet[14069]: Content root path: /var/www/asp/boat
Dec 5 12:54:40 yzapplications dotnet[14069]: Now listening on: http://localhost:5000
Dec 5 12:54:40 yzapplications dotnet[14069]: Application started. Press Ctrl+C to shut down.
Dec 5 12:54:56 yzapplications kernel: [6136322.314602] [UFW BLOCK] IN=ens18 OUT= MAC=00:50:56:00:2a:04:84:c1:c1:14:1a:1f:08:00 SRC=145.239.43.246 DST=138.201.204.243 LEN=40 TOS=0x00 PREC=0x00 TTL=244 ID=47548 PROTO=TCP SPT=13158 DPT=3361 WINDOW=1024 RES=0x00 SYN URGP=0
Dec 5 12:55:05 yzapplications kernel: [6136332.110161] [UFW BLOCK] IN=ens18 OUT= MAC=00:50:56:00:2a:04:84:c1:c1:14:1a:1f:08:00 SRC=145.239.43.246 DST=138.201.204.243 LEN=40 TOS=0x00 PREC=0x00 TTL=245 ID=9990 PROTO=TCP SPT=17564 DPT=1775 WINDOW=1024 RES=0x00 SYN URGP=0
//so here comes the first request
Dec 5 12:55:07 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
Dec 5 12:55:07 yzapplications dotnet[14069]: Request starting HTTP/1.1 GET http://webanatom.com/api/surveys application/json
Dec 5 12:55:08 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
Dec 5 12:55:08 yzapplications dotnet[14069]: Executing action method backend.Controllers.SurveyController.GetRecentSurveys (Backend) with arguments ((null)) - ModelState is Valid
Dec 5 12:55:13 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Mvc.Internal.ObjectResultExecutor[1]
Dec 5 12:55:13 yzapplications dotnet[14069]: Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
Dec 5 12:55:14 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
Dec 5 12:55:14 yzapplications dotnet[14069]: Executed action backend.Controllers.SurveyController.GetRecentSurveys (Backend) in 6116.2843ms
Dec 5 12:55:14 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
Dec 5 12:55:14 yzapplications dotnet[14069]: Request finished in 7283.3191ms 200 text/plain; charset=utf-8
// so it took 7283 ms
Dec 5 12:55:25 yzapplications kernel: [6136351.176905] [UFW BLOCK] IN=ens18 OUT= MAC=00:50:56:00:2a:04:84:c1:c1:14:1a:1f:08:00 SRC=188.166.18.231 DST=138.201.204.243 LEN=40 TOS=0x00 PREC=0x00 TTL=247 ID=62427 PROTO=TCP SPT=58647 DPT=1027 WINDOW=1024 RES=0x00 SYN URGP=0
Dec 5 12:55:46 yzapplications kernel: [6136373.008361] [UFW BLOCK] IN=ens18 OUT= MAC=00:50:56:00:2a:04:84:c1:c1:14:1a:1f:08:00 SRC=145.239.43.246 DST=138.201.204.243 LEN=40 TOS=0x00 PREC=0x00 TTL=245 ID=52844 PROTO=TCP SPT=18094 DPT=16287 WINDOW=1024 RES=0x00 SYN URGP=0
//here comes the second one
Dec 5 12:55:59 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
Dec 5 12:55:59 yzapplications dotnet[14069]: Request starting HTTP/1.1 GET http://webanatom.com/api/surveys application/json
Dec 5 12:55:59 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
Dec 5 12:55:59 yzapplications dotnet[14069]: Executing action method backend.Controllers.SurveyController.GetRecentSurveys (Backend) with arguments ((null)) - ModelState is Valid
Dec 5 12:55:59 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Mvc.Internal.ObjectResultExecutor[1]
Dec 5 12:55:59 yzapplications dotnet[14069]: Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
Dec 5 12:55:59 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
Dec 5 12:55:59 yzapplications dotnet[14069]: Executed action backend.Controllers.SurveyController.GetRecentSurveys (Backend) in 80.8676ms
Dec 5 12:55:59 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
Dec 5 12:55:59 yzapplications dotnet[14069]: Request finished in 86.3561ms 200 text/plain; charset=utf-8
//and the second one tool 86ms!!!! Why?
//next one
Dec 5 12:56:01 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
Dec 5 12:56:01 yzapplications dotnet[14069]: Request starting HTTP/1.1 GET http://webanatom.com/api/surveys application/json
Dec 5 12:56:01 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
Dec 5 12:56:01 yzapplications dotnet[14069]: Executing action method backend.Controllers.SurveyController.GetRecentSurveys (Backend) with arguments ((null)) - ModelState is Valid
Dec 5 12:56:01 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Mvc.Internal.ObjectResultExecutor[1]
Dec 5 12:56:01 yzapplications dotnet[14069]: Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
Dec 5 12:56:01 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
Dec 5 12:56:01 yzapplications dotnet[14069]: Executed action backend.Controllers.SurveyController.GetRecentSurveys (Backend) in 32.0372ms
Dec 5 12:56:01 yzapplications dotnet[14069]: #033[40m#033[32minfo#033[39m#033[22m#033[49m: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
Dec 5 12:56:01 yzapplications dotnet[14069]: Request finished in 32.8292ms 200 text/plain; charset=utf-8
// 32 ms