I have an ASP.NET Core app hosted behind Nginx on a good fast SSD server and database is MySql hosted on the same server. I am experiencing very weird behaviour.
Here are some examples. So the number represents a call to the API and then there is a response time. I thought I have some inside architecture problem so I have a date time object in the beginning of the controller and in the end where and then I measure the timespan, something like this:
[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 ");
}
So here is what I get (app is on server I am calling from local machine which is on a fast 100mbps network):
calls made straight after deployment api adress 1
1) 4.879 sec 2) 262 ms 3) 10ms 4) 14ms 5) 7ms 6) 7 ms 7) 8 ms
api adres 2 8) 523ms 9) 16ms 10) 6ms 11) 7ms 12) 5ms
As we can see the initial call to the first API takes the longest time and then the time decreases to a minimum of 7ms. If I switch to another API enpoint I get almost the same on start however it is a bit faster but the afterwords behavoiur is exactly the same except for it stabilizes to around 10ms response time much quicker.
Has anyone ever experinced this matter? I heard possible workarounds as to make initial call before user does but I suspect this behavoiur will return maybe after some timeout and this does sound a but ugly? How can I see what is actually happening behind the curtains?
Really stuck with this issue, app works quite well but this is just a real pain. Thanks in advance! Would really appreciate any helpfull info on this.
UPDATE So I have investigated into system logs on my Linux machine and here is what I get.
//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