OOM for sysbench select random limits (Hummock read duration seems abnormal)

[lmatz]

Describe the bug

https://buildkite.com/risingwave-test/sysbench/builds/554#018be963-e823-4393-aad6-38255d87bcdd/1121
image is 20231119

https://grafana.test.risingwave-cloud.xyz/d/EpkBw5W4k/risingwave-dev-dashboard?orgId=1&var-datasource=Prometheus:%20test-useast1-eks-a&from=1700429709000&to=1700430303000&var-namespace=sysbench-daily-test-20231119

Dashboard:

The read duration seems abnormal.

The previous tests are all good, e.g. the latest successful one is image 20231116
https://buildkite.com/risingwave-test/sysbench/builds/553#018bd9f0-9c26-4472-a129-e0cb237ecf39

Dashboard:
https://grafana.test.risingwave-cloud.xyz/d/EpkBw5W4k/risingwave-dev-dashboard?from=1700169909000&orgId=1&to=1700171403000&var-datasource=P2453400D1763B4D9&var-namespace=sysbench-daily-test-20231116&var-instance=benchmark-risingwave&var-pod=All&var-component=All&var-table=All

According to https://github.com/risingwavelabs/rw-commits-history#nightly-20231119, it does not seem to be affected by a PR between 20231116 and 20231119.

Error message/log

No response

To Reproduce

No response

Expected behavior

No response

How did you deploy RisingWave?

No response

The version of RisingWave

No response

Additional context

IIUC, we have implemented the mechanism at the executor level to kill a batch query that risks going OOM.
Therefore, OOM is unexpected, although the root cause of OOM is not necessarily this mechanism.

I saw #13132 merged in 20231115, wonder if it may have some impact?

[lmatz]

As the compactor deems itself to have no left work to do, I suppose the LSM tree is in good shape.
If it is in good shape, the read duration should not increase to such extent.

[lmatz]

The sysbench workload is a customed one, see: https://github.com/risingwavelabs/sysbench/blob/master/src/lua/select_random_limits.lua#L26-L31

aka select the same with limit 10 repetitively

[fuyufjh]

Lots of memory hold by Hummock iteration

1700467603-2023-11-20-08-06-42.auto.heap.collapsed.zip

Seems leaks somewhere. This is critical and let’s prioritize it.

Might be related #9732

[lmatz]

4833477 #13444

Since the error is reproducible every time, I suppose it must be some wrong commit between 1116 and 1119?
itertool seems to be the only suspicious one here and need to test it to verify.

Edit:
Nope, all the latest three commits fail with OOM again

test earlier commits and 1116 again

Edit:
Actually, 1115 and 1116 both fail with OOM:
https://buildkite.com/risingwave-test/sysbench/builds/561
https://buildkite.com/risingwave-test/sysbench/builds/560

[lmatz]

We notice that the latest change in our sysbench repo: https://github.com/risingwavelabs/sysbench/commits/master
is two weeks ago, which should not have any effect on 11/19's tests. Otherwise, it should be found out two weeks ago.

also no related commits in kube-bench: https://github.com/risingwavelabs/kube-bench/commits/main in the last two weeks.

neither in risingwave-test: https://github.com/risingwavelabs/risingwave-test/commits/main

[lmatz]

The sysbench CN memory configuration is as such:

In principle, CN should not OOM until 15Gi. But it exceeds 11Gi and then OOM. This is weird. cc: @huangjw806 is trying another new configuration to see if this behavior would be gone or not.

But, we remark that this is a separate issue. It does not explain why the memory usage reaches 11Gi.

Previously, it used only about 6GB at most:

https://grafana.test.risingwave-cloud.xyz/d/EpkBw5W4k/risingwave-dev-dashboard?orgId=1&var-datasource=P2453400D1763B4D9&var-namespace=sysbench-daily-test-20231115&var-instance=benchmark-risingwave&var-pod=All&var-component=All&var-table=All&from=1700080822882&to=1700086015129

[huangjw806]

nightly-20231121

The sysbench 32c64g all pods affinity configuration is as such:

CN still OOM! However, we did not see the mem metric exceeding the limit on grafana. I guess it is because the rapid increase of cn mem caused us to not collect useful metrics.

https://grafana.test.risingwave-cloud.xyz/d/EpkBw5W4k/risingwave-dev-dashboard?orgId=1&var-datasource=P2453400D1763B4D9&var-namespace=jianwei-sysbench-20231121&var-instance=benchmark-risingwave&var-pod=All&var-component=All&var-table=All&from=1700639051172&to=1700640236739

[liurenjie1024]

Lots of memory hold by Hummock iteration

[1700467603-2023-11-20-08-06-42.auto.heap.collapsed.zip](https://github.com/risingwavelabs/risingwave/files/13409769/1700467603-2023-11-20-08-06-42.auto.heap.collapsed.zip)

Seems leaks somewhere. This is critical and let’s prioritize it.

Might be related #9732

How am I supposed to see the flamegraph? Is this a svg?

[fuyufjh]

Lots of memory hold by Hummock iteration

1700467603-2023-11-20-08-06-42.auto.heap.collapsed.zip
Seems leaks somewhere. This is critical and let’s prioritize it.
Might be related #9732

How am I supposed to see the flamegraph? Is this a svg?

Drop the .collapsed file into https://www.speedscope.app/ and click the top-left "Left Heavy" button.

[liurenjie1024]

I agree with @lmatz This more like an environment change rather code change. Same image failed with different schedules.

[huangjw806]

It seems that v1.4.0 does not have this issue.
https://buildkite.com/risingwave-test/sysbench/builds/569

[lmatz]

Actually, I think env and kernel are still both likely to have an issue.

But, we remark that this is a separate issue. It does not explain why the memory usage reaches 11Gi.
Previously, it used only about 6GB at most:

Since the workload is not changed, this behavior is hard to be explained by env but only the kernel.

However, the request 15, limit 11 setting is also concerning and needs to be fixed.

[liurenjie1024]

The latency of succeeded ones are 150+ms:

While it speed up to 5ms for failed ones:

Any changes in storage to speed up this? cc @hzxa21

[liurenjie1024]

I see a lot of errors in failed query:

I think this is reasonable since this may cause a lot scans while frontend is already failed this query.

[liurenjie1024]

Let's wait to see this: https://buildkite.com/risingwave-test/sysbench/builds/572#018bfbef-a682-42d5-bc57-36fad5bce88f

[chenzl25]

It seems it is related to this PR #13132 . It uses a streaming read to prefetch.

[liurenjie1024]

Let's see if this one without config can succeeded. https://buildkite.com/risingwave-test/sysbench/builds/575

[liurenjie1024]

Let's see if this one without config can succeeded. https://buildkite.com/risingwave-test/sysbench/builds/575

It failed.

[hzxa21]

There are still streaming read ops in the last query run.

[liurenjie1024]

There are still streaming read ops in the last query run.

Which one?

[hzxa21]

There are still streaming read ops in the last query run.

Which one?

select_random_limits

There are ~2w connections created:

[liurenjie1024]

https://buildkite.com/risingwave-test/sysbench/builds/576

In this run I've adjusted large_query_memory_usage_mb to 1024, let's see if it can succeeded.

[liurenjie1024]

https://buildkite.com/risingwave-test/sysbench/builds/576

In this run I've adjusted large_query_memory_usage_mb to 1024, let's see if it can succeeded.

Succeeded.