feat: implement JWT caching

[taimoorzaeem]

This should fix #2698

[steve-chavez]

@taimoorzaeem Would it be possible to separate the Server-Timing feature in another PR?

That one could be merged standalone. It would the caching feature easier to review.

[taimoorzaeem]

@taimoorzaeem Would it be possible to separate the Server-Timing feature in another PR?

Yes, that actually would be much better. Let me work on that.

[steve-chavez]

Let's consider warmup (#2937 (comment)) for testing.

I guess first we need two requests and then measure that the third will have lower duration thanks to jwt-caching? Hm, we might need to test this manually first.

[taimoorzaeem]

PGRST_JWT_SECRET="reallyreallyreallyreallyverysafe" PGRST_DB_PLAN_ENABLED="true" PGRST_JWT_CACHING="true" postgrest-with-postgresql-15 postgrest-run

export JWT="eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJleHAiOjk5OTk5OTk5OTksInJvbGUiOiJwb3N0Z3Jlc3RfdGVzdF9hdXRob3IiLCJpZCI6Impkb2UiLCJhdWQiOiJ5b3VyYXVkaW
VuY2UifQ.fJ4tLKSmolWGWehWN20qiU9dMO-WY0RI2VvacL7-ZGo"

$ curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
HTTP/1.1 200 OK
Server-Timing: jwt;dur=495.1

$ curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
HTTP/1.1 200 OK
Server-Timing: jwt;dur=17.7

$ curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
HTTP/1.1 200 OK
Server-Timing: jwt;dur=10.9

@steve-chavez The caching feature is surely working as shown in local testing above. However the same is not the case when I test it with spec-tests. Maybe there is something missing in spec-tests that I wrote?

My guess is that spec-tests resets the AppState after a single request, so that Cache is "reset" after every request.

[steve-chavez]

@taimoorzaeem Around 90% time reduction compared to #2937 (comment) 🎉 🎉

curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
HTTP/1.1 200 OK
Transfer-Encoding: chunked
Date: Tue, 19 Sep 2023 19:53:09 GMT
Server: postgrest/11.2.0 (c5a9ed1)
Content-Range: */*
Content-Location: /authors_only
Content-Type: application/json; charset=utf-8
Server-Timing: jwt;dur=14.1

At startup, sometimes I've gotten higher values than before:

$ curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
Server-Timing: jwt;dur=516.8

$ curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
Server-Timing: jwt;dur=903.6

$ curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
Server-Timing: jwt;dur=402.8

But the next durations are always low (~15), so no problem there.

[steve-chavez]

@taimoorzaeem Really cool feature! Don't forget to add an entry to the CHANGELOG.

[steve-chavez]

My bad, I see the memory test failing. I need to give it another review.

[wolfgangwalther]

Uhm, 7 additional MB for a little token cache?

And it does not happen for the non-RPC requests below?

This is... confusing at least.

[steve-chavez]

Yeah, I don't understand why that happened but it didn't seem that much extra memory to me.

Another thing that's puzzling is that the memory tests don't have the jwt caching enabled.

Maybe the Data.Cache library does some allocation by default?

[steve-chavez]

Just tried postgrest-test-memory locally on 90e3a5e

Running memory usage tests..
not ok 1 - POST /rpc/leak?columns=blob: with a json key of 1M the memory usage(22,978,640 bytes) is more than 16M
ok 2 - POST /leak?columns=blob: with a json key of 1M the memory usage(14,167,624 bytes) is less than 16M
ok 3 - PATCH /leak?id=eq.1&columns=blob: with a json key of 1M the memory usage(14,203,336 bytes) is less than 16M
ok 4 - POST /rpc/leak?columns=blob: with a json key of 10M the memory usage(23,663,344 bytes) is less than 44M
ok 5 - POST /leak?columns=blob: with a json key of 10M the memory usage(23,568,720 bytes) is less than 44M
ok 6 - PATCH /leak?id=eq.1&columns=blob: with a json key of 10M the memory usage(23,610,888 bytes) is less than 44M
ok 7 - POST /rpc/leak?columns=blob: with a json key of 50M the memory usage(65,453,568 bytes) is less than 172M
ok 8 - POST /leak?columns=blob: with a json key of 50M the memory usage(65,355,608 bytes) is less than 172M
ok 9 - PATCH /leak?id=eq.1&columns=blob: with a json key of 50M the memory usage(65,398,104 bytes) is less than 172M
ok 10 - POST /perf_articles?columns=id,body: with a json payload of 32K that has 1000 array values the memory usage(13,176,328 bytes) is less than 14M
ok 11 - POST /perf_articles?columns=id,body: with a json payload of 329K that has 10000 array values the memory usage(13,484,600 bytes) is less than 14M
ok 12 - POST /perf_articles?columns=id,body: with a json payload of 3.4M that has 100000 array values the memory usage(16,688,424 bytes) is less than 24M

Seems the memory increase was not related to this PR

---

Weird, I got it passing now:

Running memory usage tests..
ok 1 - POST /rpc/leak?columns=blob: with a json key of 1M the memory usage(14,258,120 bytes) is less than 16M

[steve-chavez]

Now on a6e3eda, I got 14M too:

Running memory usage tests..
ok 1 - POST /rpc/leak?columns=blob: with a json key of 1M the memory usage(14,271,344 bytes) is less than 23M
ok 2 - POST /leak?columns=blob: with a json key of 1M the memory usage(14,162,648 bytes) is less than 16M
ok 3 - PATCH /leak?id=eq.1&columns=blob: with a json key of 1M the memory usage(14,195,632 bytes) is less than 16M
ok 4 - POST /rpc/leak?columns=blob: with a json key of 10M the memory usage(23,667,280 bytes) is less than 44M
ok 5 - POST /leak?columns=blob: with a json key of 10M the memory usage(23,577,504 bytes) is less than 44M
ok 6 - PATCH /leak?id=eq.1&columns=blob: with a json key of 10M the memory usage(23,613,160 bytes) is less than 44M
ok 7 - POST /rpc/leak?columns=blob: with a json key of 50M the memory usage(65,462,040 bytes) is less than 172M
ok 8 - POST /leak?columns=blob: with a json key of 50M the memory usage(65,358,784 bytes) is less than 172M
ok 9 - PATCH /leak?id=eq.1&columns=blob: with a json key of 50M the memory usage(65,399,112 bytes) is less than 172M
ok 10 - POST /perf_articles?columns=id,body: with a json payload of 32K that has 1000 array values the memory usage(13,169,752 bytes) is less than 14M
ok 11 - POST /perf_articles?columns=id,body: with a json payload of 329K that has 10000 array values the memory usage(13,486,992 bytes) is less than 14M
ok 12 - POST /perf_articles?columns=id,body: with a json payload of 3.4M that has 100000 array values the memory usage(16,699,496 bytes) is less than 24M

And consistenly:

Running memory usage tests..
ok 1 - POST /rpc/leak?columns=blob: with a json key of 1M the memory usage(14,266,608 bytes) is less than 23M

Running memory usage tests..
ok 1 - POST /rpc/leak?columns=blob: with a json key of 1M the memory usage(14,260,440 bytes) is less than 23M

Running memory usage tests..
ok 1 - POST /rpc/leak?columns=blob: with a json key of 1M the memory usage(14,266,984 bytes) is less than 23M

So it seems to be some kinda flakiness on the CI runners.

[steve-chavez]

Just benched jwt caching with this setup (t3a.nano pg + t3a.nano pgrst + m5a.16xlarge k6 client) and this script

req/s
2477.315611/s  no JWT sent              (direct anon request)
1973.09754/s   JWT sent without caching (~20% decrease)
2432.181056/s  JWT sent with caching    (~1% decrease)

With jwt caching Perf is almost as good as with no JWT sent 🎉. So for typical deployments we can say that the perf increase is ~23%.

---

Note: CPU consumption didn't seem to vary that much, during the above load test:

%CPU  %MEM    
148.5   7.6  Without JWT caching
154.8   8.0  With JWT caching

~%6 less CPU usage. I wonder if it's us mostly consuming CPU or the Warp server.