store: sometimes pkg/store.(*indexCache).ensureFits spins forever, blocking other goroutines

[GiedriusS]

Thanos components: improbable/thanos:v0.1.0
Prometheus: prom/prometheus:v2.4.2

What happened

Number of goroutines in Thanos Store instances started growing inexorably. It never came back down and Thanos Store was essentially unresponsive to all queries during this.

What you expected to happen
Goroutine number to stay around the same number i.e. have a low standard deviation, and Thanos Store to be responsive.

How to reproduce it (as minimally and precisely as possible):
To be done. since this is hard to reproduce and depends on the data.

Full logs to relevant components
Thanos Query started timing out:

level=error ts=2018-11-29T13:20:41.368751553Z caller=proxy.go:117 err="fetch series for [{monitor prtoss} {replica a}]: rpc error: code = Canceled desc = context canceled"
level=error ts=2018-11-29T13:20:41.368755808Z caller=proxy.go:117 err="fetch series for [{monitor prtoss} {replica b}]: rpc error: code = Canceled desc = context canceled"
level=error ts=2018-11-29T13:20:41.368808725Z caller=proxy.go:117 err="fetch series for []: rpc error: code = Canceled desc = context canceled"
level=warn ts=2018-11-29T13:20:41.368849077Z caller=proxy.go:126 err="No store matched for this query"
level=error ts=2018-11-29T13:20:41.368848275Z caller=proxy.go:117 err="fetch series for []: rpc error: code = Canceled desc = context canceled"
level=warn ts=2018-11-29T13:20:41.368909531Z caller=proxy.go:126 err="No store matched for this query"
level=error ts=2018-11-29T13:20:41.369833973Z caller=engine.go:499 msg="error expanding series set" err="context canceled"

No more series query processed messages in Thanos Store whatsoever, only Blocks source resolution. Only this one got through somehow in a period of about an hour:

Lap 29 14:07:42 foobar docker[21891]: level=debug ts=2018-11-29T13:07:42.784986336Z caller=bucket.go:802 msg="series query processed" stats="&{blocksQueried:0 postingsTouched:0 postingsTouchedSizeSum:0 postingsFetched:0 postingsFetchedSizeSum:0 postingsFetchCount:0 postingsFetchDurationSum:0 seriesTouched:0 seriesTouchedSizeSum:0 seriesFetched:0 seriesFetchedSizeSum:0 seriesFetchCount:0 seriesFetchDurationSum:0 chunksTouched:0 chunksTouchedSizeSum:0 chunksFetched:0 chunksFetchedSizeSum:0 chunksFetchCount:0 chunksFetchDurationSum:0 getAllDuration:877 mergedSeriesCount:0 mergedChunksCount:0 mergeDuration:1273}"

When something happened but exactly zero data was pulled down so maybe this is a separate issue?

The goroutine dump of Thanos Store at the moment of this freeze:
goroutine_dmp.zip

Notice that exactly one goroutine is stuck in ensureFits and it locks the lock, thus preventing other goroutines from performing their work.

Workaround: increased the index cache significantly and the problem went away. Perhaps this has to do with something that some index cache files are really large:

$ du -t 250M -hs /var/lib/thanos/*/index.cache.json
279M    /var/lib/thanos/01CXD021G0JHNRQWJKVKCHD3QR/index.cache.json
1,6G    /var/lib/thanos/01CXF4WQE8H27NZK0W4VEQB3XP/index.cache.json
1,5G    /var/lib/thanos/01CXFJT3R8J59MD4YC9AC0TPE5/index.cache.json
...

Anything else we need to know
Environment:

• OS: CentOS Linux 7 (Core)
• Kernel: 3.10.0-862.11.6.el7.x86_64
• Docker: 18.03.1-ce, build 9ee9f40
• Memory: 256 GB

[bwplotka]

Are you sure it's spinning forever? When index cache in memory is full (as limited by index cache limit option) it just spinning for every setPosting, setPosting, so it's slow and go routines accumulates.

So it's all about the case of full index cache and how to deal with it. The implementations of LRU is too naive. If it's near full it blocks a lot and removes not aggresively enough. We need to fix this.

Second acceptance criteria to improve this is to also have clear query/way to tell you that you have a traffic that requires bigger cache.

[GiedriusS]

It never got unblocked - I think we have waited for an hour or so. Those two potential solutions sound logical to me however I also think that something like this GiedriusS@621d87d should work in the mean time. @bwplotka what is your opinion about this diff?

[GiedriusS]

Got some time to look at this again and IMHO what had happened is that a huge query came and the results were too big for the index cache to handle - setSeries() was invoked with a slice which exceeds the maximum set amount and thus we couldn't ever ensure that it fitted into the LRU cache. I will cook up some extra unit tests for the index cache to test this hypothesis and I will open up a PR if I am correct.

[bwplotka]

Thanks for looking into it. I think what matters the most is the extension of currnet implementation to handle gracefully or at least be aware of what will happen when cache is:

• too small to fit things needed for single query
• too small to fit things from different queries done in the same time.

It is not easy thing to fix and do unit tests against, but would be super valuable, thanks for helping here!

[bwplotka]

Fix merged.

[bwplotka]

We can repro this again on the version with fix cc @mjd95

[bwplotka]

First thing to test against: size equal to maxSize

[devnev]

Our thanos image is improbable/thanos:master-2019-04-16-f3f0518

Goroutine dump: storegw-0-goroutine.txt

The culprit looks like a single goroutine spinning in ensureFits:

1 @ 0xcfb371 0xe6b48c 0xe6b5ec 0xe77231 0xba6007 0x45cc41
#	0xcfb370	github.com/hashicorp/golang-lru/simplelru.(*LRU).RemoveOldest+0xe0				/go/pkg/mod/github.com/hashicorp/[email protected]/simplelru/lru.go:109
#	0xe6b48b	github.com/improbable-eng/thanos/pkg/store.(*indexCache).ensureFits+0x3b			/go/src/github.com/improbable-eng/thanos/pkg/store/cache.go:131
#	0xe6b5eb	github.com/improbable-eng/thanos/pkg/store.(*indexCache).setPostings+0x11b			/go/src/github.com/improbable-eng/thanos/pkg/store/cache.go:142
#	0xe77230	github.com/improbable-eng/thanos/pkg/store.(*bucketIndexReader).fetchPostings.func3+0x440	/go/src/github.com/improbable-eng/thanos/pkg/store/bucket.go:1460
#	0xba6006	github.com/oklog/run.(*Group).Run.func1+0x26							/go/pkg/mod/github.com/oklog/[email protected]/group.go:38

[GiedriusS]

Weird, I'm on master and I've added some more tests: GiedriusS@42449a8, and they pass without an issue. Could you think of another edge case that we are missing? 😞

[bwplotka]

Interesting thing is that we have 2 replicas, and one was fine, second was deadlocking. This indicates that certain order of requests matters?

[devnev]

Also looks like the thanos_store_index_cache_items_overflowed_total metric isn't being registered.

[bwplotka]

So this still happens (!) However does not affect us much, thanks for our safeguard code we just log error and overflow request if ensureFits loops more than 500 times.

Reopening as this still happens, but is workarounded. Is it simplelru package bug?

cc @mjd95 @devnev

[bwplotka]

We got those logs a lot:

level=error name=simstoregw ts=2019-04-29T12:24:43.387316778Z caller=cache.go:226 msg="LRU has nothing more to evict, but we still cannot allocate the item. Ignoring." maxItemSizeBytes=536870912 maxSizeBytes=1073741824 curSize=1073741770 itemSize=1996 cacheType=Postings

[bwplotka]

It's definitely in near max situation

[bwplotka]

Lol so curSize=1073741770 is clearly lying?

[bwplotka]

Deleted my comments regarding wrong assumption. Was trolled by bucket_e2e & swapping index cache. Fixed that part: #1098

Definitely cannot repro locally / with unit tests yet.