Found there is a randomly slow response(NOT the first request) when running .NET5 container on AWS ECS Fargate, and I have no idea why it happened and how to resolve it. Usually it responses under 50ms, but sometimes it's 600+ms to almost 2 seconds, 30X~100X slower.
Actually I deployed 2 projects with same settings, both have same problem. I tried update AddDbContext() to AddDbContextPool() to enable context pooling, but does not fix the problem, and it acts even a bit slower(~10ms slower). I thought DbContextPooling should perform better?
Environment
- .NET5 webapi project with EF Core 5.0.11 (
Npgsql.EntityFrameworkCore.PostgreSQLpackage) - Project published as self-contained, docker image:
mcr.microsoft.com/dotnet/runtime-deps:5.0-alpine - Container run on AWS ECS (Fargate, running in private subnet with NAT gateway & ALB)
- Cloudflare name service & CDN (CNAME point to ALB, proxied)
- AWS RDS (PostgreSQL, single AZ,
db.t3.micro) - AWS Elasticsearch service for collecting log (using
Serilogpackage, logging to console and a sidecar AWS Firelens container to deliver logs to ES, docker image:aws-for-fluent-bit:latest) - A .NET5 worker service (deployed as windows service, standalone, outside of AWS network) to access api once a minute (2 GET, do calculation, then 2 POST)
ECS service utilizations
- CPU: max 0.7%, avg. 0.2x%
- Memory: around 15%
RDS service utilizations
- CPU: max 4.5%, avg. 3.x%
- Freeable Memory: around 320MB
Request logs from WebAPI
Since the editor wouldn't let me post full logs, I cut some off, actually there are 4 requests every minute.
Dec 1, 2021 @ 20:05:39.975 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint2}" responded 200 in 5.4110 ms
Dec 1, 2021 @ 20:05:39.996 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint3}" responded 200 in 4.3331 ms
Dec 1, 2021 @ 20:05:40.074 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "POST" "{endpoint4}" responded 200 in 8.5302 ms
Dec 1, 2021 @ 20:05:40.107 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "POST" "{endpoint1}" responded 200 in 6.7933 ms
Dec 1, 2021 @ 20:06:40.703 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint2}" responded 200 in 6.3423 ms
Dec 1, 2021 @ 20:06:44.150 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint3}" responded 200 in 3460.4096 ms
Dec 1, 2021 @ 20:06:44.227 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "POST" "{endpoint4}" responded 200 in 8.6665 ms
Dec 1, 2021 @ 20:06:44.831 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "POST" "{endpoint1}" responded 200 in 593.9562 ms
** from here I update AddDbContext() to AddDbContextPool()
so the next 4 lines are the first request after new container deployed, which is acceptable **
Dec 1, 2021 @ 20:08:48.023 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint2}" responded 200 in 857.7578 ms
Dec 1, 2021 @ 20:08:48.024 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint3}" responded 200 in 865.1430 ms
Dec 1, 2021 @ 20:08:48.156 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "POST" "{endpoint1}" responded 200 in 24.1025 ms
Dec 1, 2021 @ 20:08:48.159 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "POST" "{endpoint4}" responded 200 in 22.9004 ms
Dec 1, 2021 @ 20:32:04.517 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint3}" responded 200 in 34.9491 ms
Dec 1, 2021 @ 20:32:04.528 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint2}" responded 200 in 32.3778 ms
Dec 1, 2021 @ 20:32:04.620 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "POST" "{endpoint1}" responded 200 in 20.8825 ms
Dec 1, 2021 @ 20:32:04.636 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "POST" "{endpoint4}" responded 200 in 20.4790 ms
Dec 1, 2021 @ 20:33:05.013 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint2}" responded 200 in 25.3981 ms
Dec 1, 2021 @ 20:33:05.042 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint3}" responded 200 in 23.8576 ms
Dec 1, 2021 @ 20:33:06.026 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "POST" "{endpoint1}" responded 200 in 899.0295 ms
Dec 1, 2021 @ 20:33:06.028 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "POST" "{endpoint4}" responded 200 in 901.7089 ms
This is my first project using docker, AWS ECS and RDS, any suggestions or guides are appreciate.
Edit: 2021/12/04
- Checked Fargate instance running in same region & AZ as RDS instance.
- Update Serilog to asynchronous
Serilog.Sinks.Async, no help.
Edit: 2021/12/05
- Tried remove JWT authentication, no help.
- Tried run api on local machine & worker(api caller) on laptop, the unexpected latency still happends, around 30X slower, the deployed AWS Fargate instance is around 100X.
Edit: 2021/12/06
- Tried running worker to call 'static' endpoint only, seems it's more like EFCore or PostgreSQL problem. Logs as below.
[11:42:37 INF] Anonymous from ::1 http localhost:5000 GET /environment responded 200 in 0.8511 ms
[11:43:37 INF] Anonymous from ::1 http localhost:5000 GET /environment responded 200 in 1.1113 ms
[11:44:38 INF] Anonymous from ::1 http localhost:5000 GET /environment responded 200 in 1.2851 ms
[11:45:38 INF] Anonymous from ::1 http localhost:5000 GET /environment responded 200 in 0.5541 ms
[11:46:38 INF] Anonymous from ::1 http localhost:5000 GET /environment responded 200 in 1.7339 ms
[11:47:38 INF] Anonymous from ::1 http localhost:5000 GET /environment responded 200 in 1.0749 ms
[11:48:38 INF] Anonymous from ::1 http localhost:5000 GET /environment responded 200 in 1.2822 ms
[11:49:39 INF] Anonymous from ::1 http localhost:5000 GET /environment responded 200 in 5.0458 ms
[11:50:39 INF] Anonymous from ::1 http localhost:5000 GET /environment responded 200 in 1.2989 ms
[11:51:39 INF] Anonymous from ::1 http localhost:5000 GET /environment responded 200 in 1.0595 ms
[11:52:40 INF] Anonymous from ::1 http localhost:5000 GET /environment responded 200 in 1.0484 ms
[11:53:40 INF] Anonymous from ::1 http localhost:5000 GET /environment responded 200 in 1.5287 ms
[11:54:40 INF] Anonymous from ::1 http localhost:5000 GET /environment responded 200 in 0.8633 ms
[11:55:40 INF] Anonymous from ::1 http localhost:5000 GET /environment responded 200 in 2.6060 ms
- Tried switch
gcServeroff, no help. - Increased RDS size from
db.t3.microtodb.t4g.medium, unexpected latency still exists, but not as often. Since this api is only for private use, will downgrade todb.t4g.smalland keep monitoring.
Edit: 2021/12/07
- Tried call endpoint without accessing db from AWS instance, can almost confirm it's either EFCore or RDS. Logs as below.
Dec 7, 2021 @ 18:04:13.592 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1681 ms
Dec 7, 2021 @ 18:03:13.236 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1622 ms
Dec 7, 2021 @ 18:02:12.882 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1604 ms
Dec 7, 2021 @ 18:01:12.541 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1722 ms
Dec 7, 2021 @ 18:00:12.165 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1591 ms
Dec 7, 2021 @ 17:59:11.791 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1554 ms
Dec 7, 2021 @ 17:58:11.414 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1654 ms
Dec 7, 2021 @ 17:57:11.026 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1727 ms
Dec 7, 2021 @ 17:56:10.554 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1746 ms
Dec 7, 2021 @ 17:55:10.001 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1697 ms
Dec 7, 2021 @ 17:54:09.474 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1734 ms
Dec 7, 2021 @ 17:53:08.994 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1621 ms
Dec 7, 2021 @ 17:52:08.546 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1744 ms
Dec 7, 2021 @ 17:51:08.176 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.2123 ms
Dec 7, 2021 @ 17:50:07.814 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1793 ms
Dec 7, 2021 @ 17:49:07.430 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1588 ms
Dec 7, 2021 @ 17:48:07.043 Information "{worker}" from "{remote_ip}" "http" "{mydomain.com}" "GET" "{endpoint_without_db_access}" responded 200 in 0.1696 ms
Edit: 2022/01/15
After weeks talking to AWS support, my guess is the ECS Fargate is just not for a latency-sensitive project. They did help a lot, checked my network settings, RDS instance, and the instance fargate deployed on, and they said the Fargate instances are for "General purpose" which means there are no latency guarantees. So, if you have a latency-sensitive project and you'd like to run it on ECS, then you might wanna choose EC2 instances instead.
Actually, I have another project also running on ECS Fargate, and I don't see this problem there, my best guess is, it actually depends on which machine your fargate instance assigned to, may or may not bump into inconsistance latency.