Title
w
williamdclt
10/12/2022, 11:00 AMIt suspect there's a memory leak in SpiceDB. My pods are regularly restarting (36 times in 5d18h), with memory going very high pretty quickly. That only started happening since I upgraded to v1.13.0
For info, my
resourceresources:
requests:
cpu: 500m
memory: 1Gi
limits:
cpu: 1000m
memory: 2GiExtended graph.
- First yellowish zone is v1.11.0
- Purpleish zone is v1.12.0
- Second yellowish zone is v1.13.0 (same zone as the purpleish zone of the first screenshot above, confusingly)
v
vroldanbet
10/12/2022, 11:11 AMmaybe potentially related to the new way to compute cache size using percentages? By default it uses a 75% of available memory to the container. A way to determine if that was the contributing factor would be to change from the default 75% to a static memory value
It could be that perhaps the newly introduced library is not respecting cgroup limits
cc @jzelinskie
(could be totally unrelated to the new percentage-based cache sizes, but it's worth ruling it out with the exercise outlined above)
w
williamdclt
10/12/2022, 11:25 AMI'm happy to try it: could you suggest a reasonable static memory value here?
v
vroldanbet
10/12/2022, 11:27 AMwell I'd say set it to 75% of the resource request, that'd me 750mib?
v
vad
10/12/2022, 1:06 PM@vroldanbet are you talking about
--dispatch-cluster-cache-max-cost--dispatch-cache-max-costv
vroldanbet
10/12/2022, 1:07 PMactually both.
v
vad
10/12/2022, 1:08 PMwe're experiencing memory issues too, but I don't know if related to latest version, since we just enabled spice in production (for a small feature, we'd like to expand usage too)
v
vroldanbet
10/12/2022, 1:08 PMdid you experience memory issues after setting those 2 flags?
any chances you can get a pprof dump?
v
vad
10/12/2022, 1:09 PMno, those flags are not set, but as I wrote earlier at every restart I get different values. Even with small values like:
it ends up OOMing
go_memstats_mallocs_total{job="spicedb-production-metrics"} - go_memstats_frees_total{job="spicedb-production-metrics"}v
vroldanbet
10/12/2022, 1:11 PMit's expected you get different values, since the percentage of free memory in the machine would vary each time spicedb starts up
v
vad
10/12/2022, 1:11 PM(memory request is 1GB)
v
vroldanbet
10/12/2022, 1:11 PM👀
v
vad
10/12/2022, 1:12 PMyes but should always be at least 1GB -> thus 70% ~ 700MB
v
vroldanbet
10/12/2022, 1:12 PMis that running in your machine or in prod? I experienced something similar in my machine. Maybe the library we are using is not reliable
v
vad
10/12/2022, 1:13 PMprod
v
vroldanbet
10/12/2022, 1:13 PMso in that graph request and limit is 1GB, correct?
v
vad
10/12/2022, 1:14 PMlet me check the limit, I thought it was not set, it could be an error in the chart
but yes, request is 1GB
v
vroldanbet
10/12/2022, 1:15 PMand the logs above, showing relatively low cache allocations, is also from prod right?
I certainly wouldn't expect those numbers. It's similar to what I observed, but in my local machine
the only alternative I can think of right now is to set those manually and make sure they fit within the request
manually as in with actual sizes instead of percentages, the flag should support both
v
vad
10/12/2022, 1:16 PMyes, they are from production.
I confirm limit is 1GB, my bad
v
vroldanbet
10/12/2022, 1:16 PM@jzelinskie can follow up, Im actually OoO but just in front of the computer because I got paged 😅
v
vad
10/12/2022, 1:18 PMI'll set them rn, but I don't expect it to improve, because even now we're going way above those values
j
jzelinskie
10/12/2022, 3:21 PMthe percentage actually checks free memory and does (free mem * 0.70) * $YOUR_PERCENTAGE
it's confusing, but this is so that other things can consume some amount of memory without the cache having eaten up everything
We're looking into to seeing if there could be another cause to the misaligned memory usage though, since that should put you safely below your target and not above it
v
vad
10/13/2022, 10:04 AM@jzelinskie have you seen the chart about allocs? does it say something? 😄
w
williamdclt
10/13/2022, 10:58 AMJust tried setting a static
--dispatch-cache-max-cost750MiB(I don't enable the dispatch cluster, so didn't set
--dispatch-cluster-cache-max-costa heap dump for your eyes
Interestingly the dump talks about "882.57MB total", not >3GB 🤔
> (I don't enable the dispatch cluster, so didn't set --dispatch-cluster-cache-max-cost)
I set it for peace of mind: didn't change anything either 🙂
v
vad
10/13/2022, 1:06 PMi set them to 200MB/200MB, still growing (slowing, not many requests, as I mentioned before)
j
jzelinskie
10/13/2022, 2:36 PMOk I'm going to try and reproduce this today
w
williamdclt
10/13/2022, 3:26 PMIt's impacting response time and availability pretty negatively, I'll rollback to v1.12.0 in the meanwhile!
j
jzelinskie
10/14/2022, 3:36 PMI suspect our cost estimates for item sizes going into the cache are substantially off such that the cache in reality is growing beyond what it's intended
I'm experimenting with how we store and estimate items in our cache so that they are no longer estimates.
v
vad
10/15/2022, 7:05 PM@jzelinskie if you add metrics (estimates vs real, where real could be optional?) we could report what we see
j
jzelinskie
10/17/2022, 3:26 PMRather I have a PR that just gets rid of any guess-work we were doing.
You might be able to cherrypick it onto v1.13
v
vad
10/18/2022, 2:58 PM@jzelinskie I'm running 1.13.0 patched with your PR. I'll wait till tomorrow to be sure but apparently it's 😍
j
jzelinskie
10/18/2022, 2:59 PMnice! glad to hear that so far
v
vad
10/19/2022, 11:54 AMannotation where PR was applied
v
vroldanbet
10/19/2022, 11:57 AMdo you have cache metrics enabled? Would be useful to see if evictions are happening based on the cache size selected on startup
v
vad
10/19/2022, 2:27 PM@vroldanbet can you tell me which (prometheus) metric exactly?
v
vroldanbet
10/19/2022, 2:30 PMsure! you need 2 flags enabled, because these are "ristretto" (the caching library we use) specific metrics, which are not enabled by default:
-
dispatch-cache-metricsdispatch-cluster-cache-metricsspicedb_dispatch_client_cost_added_bytes
spicedb_dispatch_client_cost_evicted_bytes
spicedb_dispatch_cost_added_bytes
spicedb_dispatch_cost_evicted_bytesv
vad
10/19/2022, 2:43 PMthey're all 0, they're probably not enabled. Let me check
I've just deployed spice with these metrics enabled. Traffic is already going down for today (TZ is EU/Rome), we can have more information tomorrow
v
vroldanbet
10/19/2022, 2:51 PMthanks for looking into this!
v
vad
10/19/2022, 2:57 PM@vroldanbet thank you and @jzelinskie for the support!
v
vroldanbet
10/19/2022, 2:58 PMno problem! it's jimmy who deserve all the credit here! ✨
j
jzelinskie
10/19/2022, 3:35 PM@vad would it be possible to get a similar graph for your cpu performance?
v
vad
10/20/2022, 7:44 AM@jzelinskie
v
vroldanbet
10/20/2022, 7:46 AMmind marking when did the cache-fix got deployed?
I believe Jimmy wanted to check if extra CPU incurred was relevant, and it appears it is not.
How many pods are y'all running?
v
vad
10/20/2022, 7:50 AMsure. I can post p50 and p90 too, they look relevant
v
vroldanbet
10/20/2022, 7:50 AMwhat is this snapshot, avg?
when I say relevant, I mean that it does not look like there is an appreciable increase in CPU use. And even if there was, SpiceDB is still fundamentally I/O bound and trading some CPU seemed like a reasonable choice here to better control memory management
v
vad
10/20/2022, 8:20 AM(ATM only a couple of features with low usage have ACL managed with spice). Yes, I agree that CPU usage has not changed in any relevant way.
Here CPU with annotation:
p50 and p90:
it looks like there's a modest increase in p90
v
vroldanbet
10/20/2022, 8:29 AMit seems like your workload always shows that pattern around 8:00am in your TZ. At first glance it would seem so, but perhaps early to drag conclusions - workload could have changed. Maybe try to correlate with traffic?
v
vad
10/20/2022, 9:09 AMno traffic on weekends, working days are quite similar:
evicted are still 0
max costs are 200MB/200MB
v
vroldanbet
10/21/2022, 3:13 PMnice looking good, presumably there is not enough load to apply pressure to the cache
j
jzelinskie
10/21/2022, 4:11 PMfantastic
v
vad
11/03/2022, 7:42 AMeven if the memory has improved a lot, I think there's still something not working properly.
- In the last hours we went over the 200MB limit we set, and we still see no evitions.
- Total memory usage is 675MB. It's growing faster than caches. It was ~400MB when caches were ~100MB each, thus ~200MB overhead. With caches ~200MB each it's ~675MB, thus 375MB overhead. Memory usage is basically double the amount of memory reserved for cache.
j
jzelinskie
11/03/2022, 3:12 PMCan you run a heap profile on a SpiceDB instance? There could be something else outside of the cache consuming memory, so I'd like to confirm that.
v
vad
11/03/2022, 3:36 PM(update: evictions started at 209MB 🙏 )
@jzelinskie can I send it privately somehow?
j
jzelinskie
11/03/2022, 3:47 PMyeah if you DM me a https://pprof.me link that should be private
Looks like there could be a big LookupResources request in flight
going to dig a bit deeper if i can
v
vad
11/03/2022, 4:47 PMI would't say there's a big one, of this resource type we have at most ~200 resources per user AFAIK. Could it be there's a leak of "LookupResources objects" ?
as you can see in the above chart, it takes days to reach this point
j
jzelinskie
11/03/2022, 5:16 PMyeah, that's quite possible
v
vad
11/04/2022, 8:30 AMand then suddenly it oomed
j
jzelinskie
11/04/2022, 3:07 PMCan y'all try the latest v1.14 release? I just want to make sure you have all the latest changes to LookUpResources internals
v
vad
11/05/2022, 8:31 PMI'll try next week ASAP, thank you
j
jzelinskie
11/05/2022, 8:32 PMThere have been lots of changes there for performance and to support caveats, so I'd like to make sure things are reproducible
Check out the GitHub release notes for how to upgrade with zero downtime
v
vad
11/08/2022, 4:34 PMwe're now running 1.14.1. Let's wait for memory to increase
j
jzelinskie
11/09/2022, 4:19 PMHow's it been going?
v
vad
11/10/2022, 8:23 AMit's apparently the same, but let me collect data 1 more day
I need to decrease cache size even more in order to be able to make a statement
an update: with 1.14.1 memory seems to be quite stable 🎉 there could still be a small leak but way less important. I'm collecting evidence
v
vroldanbet
11/15/2022, 3:51 PMdid you guys reduce the memory request/limits to put some pressure on the memory?
v
vad
11/15/2022, 3:59 PMwe reduced cache size (in MB), do you think I should decrease even the pod req/limits?
v
vroldanbet
11/15/2022, 4:02 PMwell ideally you don't need to resource to reducing the cache size and the default establishes sensible values. I was referring to the kube requests/limits in order to accelerate the leak and make it evident waiting less time (it it still exists)
v
vad
11/16/2022, 10:48 AMthe current situation is much better than before. However, I would expect memory usage to go back to the same value every night (when there's no traffic), as soon as evictions starts kicking in. We observed an increase of ~20MB between the last two nights instead.
v
vroldanbet
11/16/2022, 10:50 AMhrm, shouldn't eviction kick-in when there is memory pressure? If I understand correctly, y'all set a lower cache size compared to the actual memory available to the process, right?
so I guess that's why eviction is kicking in, even thought there is still memory left
while that works, it does not fully utilize the memory available to the process
If I may, I'd suggest adding a line denoting the cache size the first panel, so it's easier to map evictions to crossing that threshold
v
vad
11/16/2022, 1:32 PMcache limit is 20MB BTW. I'm aware it's not an optimal setting, it's just for "debugging"
v
vroldanbet
11/16/2022, 2:02 PMoh ok!
a
AlexB
12/22/2022, 3:31 PMHey everyone, we started to see quite a lot of out-of-memory kills of our spicedb pods recently (as the number of the relationships has grown from ~7K to ~11K, but maybe due to some other reason that we're missing)
we tried setting --dispatch-cluster-cache-max-cost and --dispatch-cache-max-cost to specific values (700MiB and 300MiB respectively out of 1280Mi configured as the pods' resource request) as it was suggested here but didn't see any improvement
we started to experience these problems with 1.14.1, then upgraded to 1.15.0 which made no difference
is there anything else that we could try doing?
v
vroldanbet
12/22/2022, 5:54 PMwhat version are you currently running?
a
AlexB
12/27/2022, 9:26 AMwe're running 1.15.0
v
vroldanbet
12/27/2022, 9:27 AMare there any chances you guys can provide us with your schema to see if we can reproduce it? cc @jzelinskie who's been looking into the leak
a
AlexB
01/04/2023, 5:21 PMhey @vroldanbet and @jzelinskie , we'll have to obfuscate our schema a little to be able to share but we can do that, I can send it to you in DM
it's pretty complex though, so I'm not sure how feasible it would be to make any use of it
I can also share some heap profiles and any other metrics if it helps
one observation - when our kubernetes metrics show that a spicedb pod uses ~1 GB of memory, the heap profile shows less than 500MB
j
Joey
01/04/2023, 6:27 PMwhat does
psj
jzelinskie
01/04/2023, 6:32 PMcan you share a heap profile?
go tool pprof http://$SPICEDB_URL:$METRICS_PORT/debug/pprof/heapa
AlexB
01/04/2023, 9:42 PM/ # ps -o pid,user,vsz,rss,comm
PID USER VSZ RSS COMMAND
1 65532 1.7g 1.1g spicedbj
Joey
01/04/2023, 9:47 PMthanks
a
AlexB
01/04/2023, 9:54 PMmemory usage in the heap profile (Memory In-Use Bytes, Cumulative), ps (the rss column) and in kubernetes metrics seem to match actually
but the svg generated with
go tool pprofwebShowing nodes accounting for 443.62MB 92.88% of 477.64MB totalj
Joey
01/04/2023, 9:54 PM[spicedb] github.com/authzed/spicedb/internal/namespace.(*ReachabilityGraph).collectEntrypointsI'll investigate tomorrow to make sure we're not somehow keeping that graph around once its done being used
a
AlexB
01/10/2023, 10:56 PMhey everybody, I was wondering if there are any updates regarding the suspected memory leak
as far as I can see, our heap profile at the link above got overwritten by something else, but I can upload a new one if needed
we keep seeing oom kills quite frequently - typically a couple of time a day
j
Joey
01/10/2023, 11:00 PMwe found a deadlock in the LookupResources code and just merged a fix for it: https://github.com/authzed/spicedb/pull/1086
however, we aren't 100% certain that is the root cause of the memory issues
if you can get us another profile too, it can't hurt
a
AlexB
01/19/2023, 10:17 PMHi everybody, we're still suffering memory leak issues
here's some more observations:
ps -o pid,user,vsz,rss,comm
PID USER VSZ RSS COMMAND
1 65532 3.0g 1.4g spicedbps -o pid,user,vsz,rss,comm
PID USER VSZ RSS COMMAND
1 65532 3.0g 2.2g spicedbj
Joey
01/19/2023, 10:20 PM@jzelinskie ^
@AlexB on v1.16?
v1.16 has a fix for what we believe was causing the reachability graph to not be GCed
that fix linked above ^
j
jzelinskie
01/19/2023, 10:26 PMfrom your graph -- the fix joey is mentioning removes errgroup and uses a different primitive for scheduling reachableresources dispatches
a
AlexB
01/19/2023, 10:29 PMhmm... I checked what's included in v1.16 and I thought the fix linked above wasn't there and based on that we decided not to upgrade just yet
j
Joey
01/19/2023, 10:30 PMah
might be v1.16.1
j
jzelinskie
01/19/2023, 10:30 PMj
Joey
01/19/2023, 10:31 PMyeah, sorry
I thought it merged earlier than it did
a
AlexB
01/19/2023, 10:34 PMthanks a lot 👍, we'll give it a try
j
Joey
01/19/2023, 10:36 PMthanks for the report
it was incredibly helpful to narrow it down
p
pdow
01/25/2023, 2:28 PMFYI @Joey - we are still seeing the same issues after upgrading. We have a relatively small DB and have been giving our pods more and more memory, but invariably spicedb eventually eats all of it after some time and use. The pattern seems to be that we do some writes to the db, and after we start doing reads on it it looks like spicedb starts populating caches but never stops growing them. In case it helps: we are not using ZedTokens and querying with the fully consistent setting (the response times on this are perfectly fine for our use case when spicedb is operating normally). Based on our observations, the latest release did not fix or mitigate the memory leak issues.
v
vroldanbet
01/25/2023, 2:31 PMIs this with 1.16.1? would you mind getting another heap profile and sharing with us? 🙏🏻
p
pdow
01/25/2023, 2:43 PMYes, latest version - we'll try to get something to you soon. Since the behaviour does not seem to have changed, I expect it might look similar to the profiles from before
The pod just got killed a little while ago so we might have to wait a little for the issue to re-occur (typically happens a couple of times per day)
a
AlexB
01/25/2023, 2:48 PMhere's a heap profile https://pprof.me/de52332/
and ps output for the same pod
PID USER VSZ RSS COMMAND
1 65532 6.3g 4.6g spicedbp
pdow
01/25/2023, 2:54 PMNote that the ps output shows 4.6g, while the heap memory-in-use bytes only show up as 2.8GB in the profile - we're not sure where the rest of that comes from
j
Joey
01/25/2023, 3:18 PMthe ristretto cache holds memory in a different way
but that is expected
it looks like gRPC is still holding references to the streams, for some reaswon
reason*
I'll investigate today
p
pdow
01/25/2023, 3:43 PMClient-side we are using the asyncio python library. Roughly following the README page for that, we have a setup that just creates one client object for the app, which we keep re-using. I am quite sure we consume the streams from e.g. ReadRelationships fully, so there shouldn't be a reason for the client to keep such streams open, for instance. But there's no context management going on anywhere as of now, not sure if that's normal for this client. We're considering trying an experiment where we just destroy and re-create this client object every few hundred/thousand requests or so to see if that changes anything - do you have any reason to believe this could help?
j
Joey
01/25/2023, 3:47 PMI don't believe a client change is necessary, no
it may help in convincing gRPC to clear the streams
but that's not something we'd want to encourage, ideally
it appears others are having similar issues with gRPC streams
@pdow do you happen to have a QA or stage env that you can reproduce the problem in?
if you do, and you want to try a fix: https://github.com/authzed/spicedb/pull/1119
p
pdow
01/26/2023, 12:40 PMWe're giving this a try, thanks @Joey
a
AlexB
01/26/2023, 2:56 PMwe built and deployed a version from main (i.e. without the PR linked above) and our problems are gone
when we return to 1.16.1 the memory issues are back
is this this PR https://github.com/authzed/spicedb/pull/1110 that solves the problem?
yep, we built from the previous commit in main and can immediately see the problem again
v
vroldanbet
01/26/2023, 3:04 PMit does not necessarily mean there is no leak. What that PR is doing is eagerly evicting data from the cache that is 2x out of the quantization window and therefore unlikely to be reused
what could be happening is that the grow will be slower moving forward. Or it could be also that there was never any leak, but SpiceDB does not properly compute the size of the cache entries and more entries are being added when there is no capacity left
a
AlexB
01/26/2023, 3:13 PMare there any cache configuration options that we can experiment with to check the latter hypothesis?
the very first thing that we tried was tuning --dispatch-cluster-cache-max-cost and --dispatch-cache-max-cost but to no effect
v
vroldanbet
01/26/2023, 3:14 PMyou could disable the cache entirely
it may be worth just testing this PR for a bit but I'm not convinced this solves the problem. It's eagerly evicting data from the cache that is likely to be unused.
- if the leak does not happen anymore, then we know it's related to the cache
- if it happens but is happening slower than before, then it means the leak is elsewhere, and that PR didn't really fix it
j
Joey
01/26/2023, 3:34 PMWe know part of the issue is related to reachable resources, which the quantization PR does not address
@pdow @AlexB let me know if you can try the timeouts PR itself, instead of just
mainthe overall memory usage should still be higher, but the memory profile should show the leak removed
a
AlexB
01/26/2023, 3:51 PM@Joey , yes, we will try it
j
Joey
01/26/2023, 3:51 PMthanks
@AlexB any updates?
@AlexB we've merged that PR into HEAD, alongside the cache improvements
a
AlexB
02/07/2023, 10:39 AMhey @Joey , sorry, I was off last week, our team did some quick tests using that PR but we didn't collect enough data to come to any conclusion and then we had (due to some internal reasons) to switch back to 1.16.1
we'll try to do more tests this week
here's how things look for us in terms of memory usage after switching to a build from the main branch
and here's what we have in prod where we use 1.16.1
v
vroldanbet
02/09/2023, 10:05 AMlooks promising! The fix should have been released now as part of 1.16.2