Benchmarking performance regression from v13 to v16

[steve-chavez]

Had some suspicion of notable perf drop on latest versions (#4702 (comment)) so I ran this on postgrest-benchmark:

$ nix-shell
# uses the default t3a.nano
$ postgrest-bench-vary-pgrst postgrest-bench-k6-vary-vus k6/GETSingleJWT.js 2m > results.jsonl # takes a long time
$ python3 scripts/generate_report.py < results.jsonl

This produces:

Version	VUs	http_reqs (req/s)	p50	p90	p95
v13.0.0	10	1998.22	4.63ms	6.58ms	7.28ms
v13.0.0	50	1643.57	29.93ms	33.96ms	35.44ms
v13.0.0	100	1602.02	61.85ms	67.24ms	68.85ms
v13.0.1	10	1940.93	4.77ms	6.79ms	7.49ms
v13.0.1	50	1582.33	31.07ms	35.44ms	37.01ms
v13.0.1	100	1505.11	65.87ms	71.82ms	73.67ms
v13.0.2	10	1831.68	5.06ms	7.28ms	8.11ms
v13.0.2	50	1557.07	31.50ms	36.22ms	37.90ms
v13.0.2	100	1509.36	65.47ms	71.86ms	74.04ms
v13.0.3	10	1761.91	5.25ms	7.62ms	8.49ms
v13.0.3	50	1630.67	30.24ms	33.98ms	35.34ms
v13.0.3	100	1591.78	62.22ms	67.57ms	69.15ms
v13.0.4	10	1916.74	4.85ms	6.90ms	7.66ms
v13.0.4	50	1639.89	29.94ms	34.03ms	35.56ms
v13.0.4	100	1537.3	64.32ms	70.51ms	72.52ms
v13.0.5	10	1883.89	4.92ms	7.04ms	7.81ms
v13.0.5	50	1664.32	29.56ms	33.40ms	34.87ms
v13.0.5	100	1536.53	64.34ms	70.54ms	73.16ms
v13.0.6	10	1767.58	5.22ms	7.60ms	8.49ms
v13.0.6	50	1624.74	30.19ms	34.45ms	36.06ms
v13.0.6	100	1425.57	68.29ms	78.84ms	83.62ms
v13.0.7	10	1831.25	5.05ms	7.27ms	8.10ms
v13.0.7	50	1600.78	30.56ms	35.75ms	37.52ms
v13.0.7	100	1474.97	66.88ms	74.00ms	76.51ms
v13.0.8	10	1873.26	4.95ms	7.09ms	7.87ms
v13.0.8	50	1581.81	31.10ms	35.63ms	37.22ms
v13.0.8	100	1534.05	64.67ms	70.54ms	72.51ms
v14.0	10	2130.81	4.33ms	6.13ms	6.79ms
v14.0	50	1850.4	26.59ms	29.62ms	30.79ms
v14.0	100	1754.5	56.35ms	61.70ms	63.62ms
v14.1	10	2014.82	4.57ms	6.56ms	7.32ms
v14.1	50	1785.55	27.55ms	30.72ms	32.03ms
v14.1	100	1605.74	60.87ms	69.38ms	73.44ms
v14.2	10	2079.51	4.43ms	6.33ms	7.02ms
v14.2	50	1886.88	26.07ms	28.71ms	29.76ms
v14.2	100	1698.95	58.10ms	64.08ms	66.36ms
v14.3	10	2123.06	4.36ms	6.17ms	6.84ms
v14.3	50	1924.92	25.63ms	28.07ms	28.96ms
v14.3	100	1762.35	56.05ms	61.13ms	62.74ms
v14.4	10	2110.08	4.38ms	6.20ms	6.85ms
v14.4	50	1929.84	25.52ms	28.17ms	29.14ms
v14.4	100	1736.59	56.96ms	62.33ms	64.01ms
v14.5	10	2116.97	4.36ms	6.15ms	6.82ms
v14.5	50	1975.25	24.98ms	27.28ms	28.14ms
v14.5	100	1689.42	58.30ms	64.64ms	67.07ms
v14.6	10	2005.93	4.59ms	6.64ms	7.40ms
v14.6	50	1687.42	28.82ms	33.41ms	35.91ms
v14.6	100	1537.94	63.25ms	72.99ms	79.34ms
v14.7	10	2161.18	4.27ms	6.04ms	6.70ms
v14.7	50	1857.16	26.49ms	29.47ms	30.55ms
v14.7	100	1795.31	55.03ms	60.16ms	61.87ms
v14.8	10	2250.52	4.10ms	5.72ms	6.30ms
v14.8	50	1888.42	26.10ms	28.80ms	29.73ms
v14.8	100	1823.04	54.23ms	58.85ms	60.24ms
v14.9	10	2123.57	4.33ms	6.18ms	6.86ms
v14.9	50	1875.93	26.21ms	29.01ms	30.16ms
v14.9	100	1778.19	55.53ms	59.96ms	61.45ms
v14.10	10	2107.96	4.38ms	6.21ms	6.87ms
v14.10	50	1940.09	25.44ms	27.90ms	28.79ms
v14.10	100	1750.26	56.58ms	61.53ms	63.10ms
v14.11	10	2063.86	4.46ms	6.36ms	7.06ms
v14.11	50	1867.71	26.40ms	29.01ms	29.95ms
v14.11	100	1770.25	55.80ms	60.55ms	62.01ms
v14.12	10	2136.02	4.33ms	6.08ms	6.72ms
v14.12	50	1984.25	24.87ms	27.07ms	27.88ms
v14.12	100	1800.41	54.78ms	60.26ms	62.01ms
v14.13	10	2203.78	4.20ms	5.87ms	6.45ms
v14.13	50	1916.36	25.76ms	28.07ms	28.94ms
v14.13	100	1738.71	56.89ms	61.80ms	63.37ms
v14.14	10	2179.81	4.24ms	5.99ms	6.61ms
v14.14	50	1881.68	26.21ms	28.80ms	29.87ms
v14.14	100	1709.95	57.99ms	62.68ms	64.27ms
v14.15	10	2037.41	4.55ms	6.44ms	7.07ms
v14.15	50	1826.13	27.01ms	29.81ms	30.85ms
v14.15	100	1716.48	57.64ms	63.18ms	64.95ms
v14.16	10	2168.36	4.28ms	5.96ms	6.54ms
v14.16	50	1809.38	27.18ms	30.52ms	31.75ms
v14.16	100	1733.13	57.02ms	62.43ms	64.27ms
v14.17	10	2133.2	4.34ms	6.09ms	6.68ms
v14.17	50	1862.9	26.49ms	29.21ms	30.25ms
v14.17	100	1750.71	56.45ms	61.19ms	62.59ms
v16.0	10	2059.55	4.52ms	6.35ms	6.98ms
v16.0	50	1871.52	26.33ms	29.04ms	30.05ms
v16.0	100	1767.22	55.86ms	61.15ms	62.88ms
v16.1	10	2115.61	4.40ms	6.10ms	6.68ms
v16.1	50	1872.3	26.29ms	29.32ms	30.42ms
v16.1	100	1696.53	58.22ms	64.25ms	66.15ms
v16.2	10	2033.65	4.57ms	6.43ms	7.06ms
v16.2	50	1850.56	26.65ms	29.28ms	30.27ms
v16.2	100	1730.56	57.04ms	63.06ms	65.11ms

[wolfgangwalther]

So the answer is "no regression"?

[steve-chavez]

Yeah, but only for reads + JWT validation. Will rerun to include other types of loadtests.

[mkleczek]

I am somewhat suspicious of these results and postgrest-benchmark in general:

1. 100 VUs is... small? (ie. only 100 concurrent requests). The problem is that such low level of concurrency does not exercise potential lock contention and interaction between large number of threads and GC, etc.
2. I am pretty sure postgrest-benchmark is missing larger payload tests (ie. large PATCH requests or RPCs taking large JSON as argument).

I performed 3k VUs tests with mixed load of small and large requests/responses and I did find significant regression in 16.x.

[wolfgangwalther]

Or in other words: When the bottleneck is the DB connection (which it apparently was, at some point) it makes zero sense to keep scaling the VUs to add more load - it won't raise the throughput at all, since the pool size is fixed.

[mkleczek]

See also: https://grafana.com/docs/k6/latest/using-k6/scenarios/concepts/arrival-rate-vu-allocation/

From that page further down:

Though it seems convenient, you should avoid using maxVUs in most cases. Allocating VUs has CPU and memory costs, and allocating VUs as the test runs can overload the load generator and skew results.

I made sure load injector machine was big enough not to be the bottleneck. It took some time and several rounds to eliminate this kind of external factors.

I'm skeptical.

We should try to reproduce these results with fixed VUs. Then minimize the reproducer to take less time/resources. Then run it in a bisect to see which commit exactly caused this.

@wolfgangwalther - I made sure the only difference between the runs was PostgREST version. I also performed several different runs as I was really surprised with the results (didn't expect any 16.x regression). The results were consistent.

I understand the skepticism and happy to share the scripts so that you can reproduce the results yourself.
I was heavily using ChatGPT in this case, though, as the whole work was on a tight schedule.

[mkleczek]

Or in other words: When the bottleneck is the DB connection (which it apparently was, at some point) it makes zero sense to keep scaling the VUs to add more load - it won't raise the throughput at all, since the pool size is fixed.

Funny thing is that it wasn't and it is a hint to look for bottlenecks: db-pool-waiters value was high even though there were available connections.

[steve-chavez]

While benching on big EC2 instances, I've also noticed that we're not able to saturate the available pg connections.

I think we should add a metric that gives us the exact queue latency, the current pgrst-db-pool-waiting doesn't really tells us if the pool has overhead due to thread contention or some other cause.

Will open an issue.

[wolfgangwalther]

#5227 (reply in thread) is technically a violation of our AI policy, because the data has been generated with the assistance of an LLM.

Since we only have a claim about a loss of performance, but nothing to reproduce it in conformance with out contribution guidelines, there is nothing to do for us on this thread right now.

[steve-chavez]

The above only benched one k6/GETSingleJWT.js script across versions. I've now ran all k6 scripts and shared the full results on: PostgREST/postgrest-benchmark#6

For me one thing is clear, the OPTIONSUniqueJWT.svg is the most useful test to detect the regression mentioned on #4702 (comment), which can be clearly seen on the produced svg, there's a perf drop starting from v14.15 due to the upgraded warp.

[wolfgangwalther]

v16.0 already doesn't have it.

[steve-chavez]

v16.0 already doesn't have it.

Sorry I don't get it 😕 . On the graphic it shows that v16 still has a perf drop compared to v14.14.

[wolfgangwalther]

It also shows a small improvement from 14.17 to 16.0, though.

My best guess is: The performance regression is caused by both jose-jwt and warp. The one with jose-jwt was fixed again with v16, the other was not.

[steve-chavez]

Another thing that comes to mind is why do we validate the JWT on an OPTIONS request?

Looking at the code OPTIONS does reply with different metadata depending on the schema cache:

postgrest/test/spec/Feature/OptionsSpec.hs

Lines 13 to 17 in 297542d

	context "a table" $ do
	it "includes read/write methods for writeable table" $ do
	r <- request methodOptions "/items" [] ""
	liftIO $ do
	simpleHeaders r `shouldSatisfy` matchHeader "Allow" "OPTIONS,GET,HEAD,POST,PUT,PATCH,DELETE"

And those types of non-CORS requests are logged:

postgrest/test/io/test_log.py

Lines 593 to 621 in 297542d

	def test_options_request_logs_but_cors_preflight_does_not(defaultenv):
	"Plain OPTIONS requests should be logged, but CORS preflight requests should not."
	env = {
	**defaultenv,
	"PGRST_LOG_LEVEL": "info",
	"PGRST_SERVER_CORS_ALLOWED_ORIGINS": "http://example.com",
	}
	preflight_headers = {
	"Origin": "http://example.com",
	"Access-Control-Request-Method": "POST",
	"Access-Control-Request-Headers": "Content-Type",
	}
	with run(env=env) as postgrest:
	response = postgrest.session.options("/projects")
	assert response.status_code == 200
	response = postgrest.session.options("/projects", headers=preflight_headers)
	assert response.status_code == 200
	assert response.headers["Access-Control-Allow-Origin"] == "http://example.com"
	output = drain_stdout(postgrest)
	assert len(output) == 1
	assert re.match(
	r'- - postgrest_test_anonymous \[.+\] "OPTIONS /projects HTTP/1.1" 200 \d+ "" "python-requests/.+"',
	output[0],
	)

So since they're logged we need the role info to show on the apache log format.

🤔 But all of this seems of dubious value to me, I remember a long time ago we even had a response body for OPTIONS (dropped afterwards) but that was before OpenAPI. I think we can evaluate dropping all this extra OPTIONS features if it causes some maintenance problem.

[wolfgangwalther]

I don't think the performance problem here is "options requests are slower", but rather that options requests are the only requests which show the degraded performance. Which in turn just means, as rightfully mentioned by Michal earlier, that the performance regression is only relevant for requests which don't hit the database - and possibly just dont't matter.

So I don't see how the fact whether options requests have their JWT checked or not is any relevant. It is certainly helpful for testing (see JWT loadtest) - and in the absence of really good arguments, I don't see why there would need to be an artificial difference made between options requests and other requests.