Occasional ~4-second wait when using API

[markkuleinio]

When calling /api/ (or any other API paths for that matter), I experience occasional ~4-second wait before the response is sent.

• Happens with gunicorn and uWSGI
• Verified with tcpdump that the problem is inside the application stack (= request goes to 8001/tcp - or whatever port is WSGI using - but the response comes out late)
• There is no worker restart happening when the wait happens
• According to top -d 1, there is generally nobody on the CPU while the wait is happening (occasionally gunicorn/uwsgi is spending lots of CPU during the waits, but not always), and there are gigabytes of free memory (currently tested with t3.medium and t3.large EC2 instance sizes)
• I'm now testing with NetBox 3.7.0 (but this looks the same I'm experiencing with 3.3.8 as well, on another server+db)

Interesting detail:

• Capturing 5432/tcp (Postgres) as well, using Amazon RDS for PostgreSQL (deployed in the same VPC)
• API calls normally cause database traffic
• BUT while the wait happens, there is no database traffic while waiting
• AND the next packets in the db connection after the wait are SYN-SYN+ACK-ACK, meaning that there is a new database connection when the wait is released.

Example:

1. Started tcpdump on 5432/tcp
2. Sent /api/ (with token)
3. No database traffic packets captured yet
4. Waiting for that ~4 seconds to pass
5. Response is received, and in the database traffic there is a new TCP session and traffic (none of the other database TCP sessions were communicating so it was this specific database session that fetched the API response)

--> Something in the NetBox instance made it wait for ~4 seconds and then open a new database connection to get the requested data.

When capturing over longer period of time and repeating the API call, it can be seen that a new database TCP connection is quite rare (outside of this wait issue), and that when the wait happens, the previous TCP connections (that were used for the previous API calls) still seem to be there = they were recently used and nobody sent any session-terminating packets on them, but NetBox somehow didn't use the existing database connections but opted to wait and then opened a new database connection to serve the API call.

I have to say that this doesn't look load-dependent: any call can be delayed, independent of the time since previous call or other activity on the system.

CONN_MAX_AGE is currently the default (300), the value doesn't seem to affect this.

What do you suggest to improve the situation?

The RDS database is Postgres 13.10, the NetBox EC2 instance (Debian 12) has:

ii  libpq-dev      15.5-0+deb12u1 amd64        header files for libpq5 (PostgreSQL library)
ii  libpq5:amd64   15.5-0+deb12u1 amd64        PostgreSQL C client library

Example of a testing script to see the waits happen:

#!/bin/bash
while true; do
    date
    echo -n Requesting...
    curl -s -H "Authorization: token MYTOKEN" https://mynetbox.example.com/api/ -s > /dev/null
    echo ok
    sleep 0.1
done

When running watch -n 1 "ss -nt | grep 5432 | sort | nl" at the same time it can also be seen that a new database connection is opened after each wait, up to 10 connections (I don't know where that max is coming from).

I have read https://docs.djangoproject.com/en/4.2/ref/settings/#databases (and about the persistent database connections), didn't see any help there.

When running the testing script, within a minute there will be one or more waits.

[markkuleinio]

Observation: If I leave out the token from the testing script, calling /api/:

• there isn't continous database traffic anymore while testing (I guess that's expected since there is no token to verify)
• the ~4-second waits are still happening occasionally (actually looks like 5 seconds now)
• new database connection is not opened when the wait expires
• EXCEPT that sometimes a new database connection is still opened when the wait expires.

Next, Redis connections, from the capture:

• Every second there are requests related to scheduled things, looks legitime (3 x ZRANGEBYSCORE, 1 x MULTI EXPIRE)
• My /api/ call causes "GET :1:config" and "GET :1:config_version" calls (with responses)
• When the API call is waiting, there is no Redis call for config or config_version yet (= if capture is started and then testing script is started, if the very first test goes to wait, then there is no config+config_version calls yet in the capture)
• Sometimes a new Redis connection is established just about the same time the wait is happening: (1) new TCP session is established, (2) one more config+config_version request pair comes in and they go to that new TCP session, (3) then wait starts.
• (Btw, while establishing the Redis TCP connection there is "ERR unknown subcommand 'SETINFO'. Try CLIENT HELP." error, but the CLIENT SETINFO LIB-NAME redis-py command seems to be available from 7.2.0 only)

Any ideas from these symptoms?

This is running redis-server 7.0.11-1+deb12u1 (but again, this wait problem also occurs on older system that has 6.0.16-1+deb11u2).

[markkuleinio]

Looks like I managed to explain all this (unless I find something new later...). Two issues:

1. DNS (it's always DNS, right?). The DNS resolver operated by the local service provider just has some resolving issues every now and then (= request takes ~4 seconds to resolve), and that messed up some of my observations. (In my captures I managed to miss that not all wait cases were responses delayed by the server, sometimes it was the request that was delayed)
2. Starting a new NetBox WSGI worker (process or thread) takes like 4 seconds, and all workers then start their own database connections. Since the HTTP requests are not necessarily evenly spread out to all the worker processes+threads, the ~4-second delays can be experienced after relatively long time after restarting NetBox, depending on the number of processes+threads and how the first requests have been distributed to the workers.

When using uWSGI, after adding thunder-lock = true the requests seem to distribute very evenly to the workers. Without it some of the workers got much more requests than others. I don't claim to understand all of its meaning though...