[bugfix] scheduler: Gracefully shutdown querier when using query-scheduler #7735

liguozhong · 2022-11-21T12:58:12Z

What this PR does / why we need it:
Gracefully shutdown querier when using query-scheduler
This PR is an attempt to fix a bug that my loki cluster is unavailable for logql. The source code and ideas are from mimir of LGTM. Thanks mimir and pr author @pracucci

Which issue(s) this PR fixes:
Fixes #7722

Special notes for your reviewer:
mimir PR
grafana/mimir#1756
grafana/mimir#1767

Checklist

Reviewed the CONTRIBUTING.md guide
Documentation added
Tests updated
CHANGELOG.md updated
Changes that require user attention or interaction to upgrade are documented in docs/sources/upgrading/_index.md

grafanabot · 2022-11-21T13:04:16Z

./tools/diff_coverage.sh ../loki-target-branch/test_results.txt test_results.txt ingester,distributor,querier,querier/queryrange,iter,storage,chunkenc,logql,loki

Change in test coverage per package. Green indicates 0 or positive change, red indicates that test coverage for a package fell.

+           ingester	0%
+        distributor	0%
+            querier	0%
+ querier/queryrange	0.1%
+               iter	0%
+            storage	0%
+           chunkenc	0%
+              logql	0%
+               loki	0%

grafanabot · 2022-11-22T05:36:35Z

./tools/diff_coverage.sh ../loki-target-branch/test_results.txt test_results.txt ingester,distributor,querier,querier/queryrange,iter,storage,chunkenc,logql,loki

Change in test coverage per package. Green indicates 0 or positive change, red indicates that test coverage for a package fell.

+           ingester	0%
+        distributor	0%
+            querier	0%
- querier/queryrange	-0.1%
+               iter	0%
+            storage	0%
+           chunkenc	0%
+              logql	0%
+               loki	0%

jeschkies

This is great work but I need to understand the synchronization of inflightQuery a little better.

How do you feel about using a WaitGroup instead. This would also avoid using a busy loop. A mutex would be easier to reason about as well.

pkg/querier/worker/scheduler_processor.go

jeschkies · 2022-11-22T10:52:07Z

pkg/querier/worker/scheduler_processor.go


-			sp.metrics.inflightRequests.Dec()


Where did this go?

Hi, this was my mistake, I simply ‘copied’ scheduler mimir's code to loki, ignoring the inflightRequests metrics.
I have submitted a commit which fixes this issue.

jeschkies · 2022-11-22T10:54:21Z

pkg/querier/worker/util.go

+		case <-workerCtx.Done():
+			level.Debug(logger).Log("msg", "querier worker context has been canceled, waiting until there's no inflight query")
+
+			for inflightQuery.Load() {


What happens when the query is never processed? Also, isn't there a potential race condition between testing the flag and setting it in the querier loop? It could be false here but then the next query is received.

https://github.com/grafana/mimir/blob/main/pkg/querier/worker/util.go

This util.go is completely copied from mimir. I will deploy this PR to my loki cluster and run it for a while to verify whether this PR will cause unexpected race risks.

Hm. We somehow need to document this. I'll try to find the original author.

Also, isn't there a potential race condition between testing the flag and setting it in the querier loop? It could be false here but then the next query is received.

When the querier shutdowns it's expected to cancel the context and so the call to request, err := c.Recv() (done in schedulerProcessor.querierLoop()) to return error because of the canceled context (I mean the querier context, not the query execution context).

Is there a race? Yes, there's a race between the call to c.Recv() and the sequent call to inflightQuery.Store(true), but the time window is very short and we ignored it in Mimir (all in all we want to gracefully handle the 99.9% of cases).

What happens when the query is never processed?

Can you elaborate this?

I was wondering if we can end up in a state were the query is inflight but we shut down. I guess it times out.

I think that race condition still exists (I found it very hard to guarantee to never happen) but in practice should be very unlikely.

@liguozhong would you mind add a small comment summarizing Marco's answer?

Co-authored-by: Karsten Jeschkies <k@jeschkies.xyz>

… into scheduler-deadlock

grafanabot · 2022-11-23T06:20:57Z

./tools/diff_coverage.sh ../loki-target-branch/test_results.txt test_results.txt ingester,distributor,querier,querier/queryrange,iter,storage,chunkenc,logql,loki

Change in test coverage per package. Green indicates 0 or positive change, red indicates that test coverage for a package fell.

+           ingester	0%
+        distributor	0%
+            querier	0%
+ querier/queryrange	0%
+               iter	0%
+            storage	0%
+           chunkenc	0%
+              logql	0%
+               loki	0%

liguozhong · 2022-11-23T06:34:40Z

How do you feel about using a WaitGroup instead. This would also avoid using a busy loop. A mutex would be easier to reason about as well.

hi， Thanks for your timely review. this pr is really important to me .I've been trying to fix #7722 for 18 days.

I prefer to keep the current code, which will make loki and mimir use the same scheduler code, even if there is a problem with this code, it can be fixed together with the mimir community.

dannykopping · 2022-11-24T15:45:18Z

@jeschkies can you take another pass at this pls?

liguozhong · 2022-11-25T07:17:04Z

Good news, I deployed this PR to my loki cluster and Fixes #7722.

At present, the recording rule has been running stably for 1 day. This PR seems to be useful.

jeschkies

Thanks for you hard work and patience. Could you add a comment on the possible race condition.

jeschkies · 2022-11-29T16:11:00Z

pkg/querier/worker/util.go

+		case <-workerCtx.Done():
+			level.Debug(logger).Log("msg", "querier worker context has been canceled, waiting until there's no inflight query")
+
+			for inflightQuery.Load() {


@liguozhong would you mind add a small comment summarizing Marco's answer?

grafanabot · 2022-11-30T06:27:09Z

./tools/diff_coverage.sh ../loki-target-branch/test_results.txt test_results.txt ingester,distributor,querier,querier/queryrange,iter,storage,chunkenc,logql,loki

Change in test coverage per package. Green indicates 0 or positive change, red indicates that test coverage for a package fell.

+           ingester	0%
+        distributor	0%
+            querier	0%
+ querier/queryrange	0%
+               iter	0%
+            storage	0%
+           chunkenc	0%
+              logql	0%
+               loki	0%

liguozhong · 2022-11-30T06:27:12Z

Thanks for you hard work and patience. Could you add a comment on the possible race condition.

done

grafanabot · 2022-11-30T06:46:19Z

./tools/diff_coverage.sh ../loki-target-branch/test_results.txt test_results.txt ingester,distributor,querier,querier/queryrange,iter,storage,chunkenc,logql,loki

Change in test coverage per package. Green indicates 0 or positive change, red indicates that test coverage for a package fell.

+           ingester	0%
+        distributor	0%
+            querier	0%
+ querier/queryrange	0%
+               iter	0%
+            storage	0%
+           chunkenc	0%
+              logql	0%
+               loki	0%

Gracefully shutdown querier when using query-scheduler

230f81e

liguozhong requested a review from a team as a code owner November 21, 2022 12:58

pull-request-size bot added the size/XL label Nov 21, 2022

Merge branch 'main' into scheduler-deadlock

c212eec

jeschkies requested changes Nov 22, 2022

View reviewed changes

liguozhong and others added 3 commits November 23, 2022 14:11

Update pkg/querier/worker/scheduler_processor.go

2cfd17b

Co-authored-by: Karsten Jeschkies <k@jeschkies.xyz>

rollback inflightRequests metrics code

4618cce

Merge branch 'scheduler-deadlock' of https://github.com/liguozhong/loki…

f43b887

… into scheduler-deadlock

jeschkies approved these changes Nov 29, 2022

View reviewed changes

add a small comment summarizing Marco's answer?

5c62622

Merge branch 'main' into scheduler-deadlock

5e9c382

jeschkies merged commit 63a57c7 into grafana:main Dec 1, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[bugfix] scheduler: Gracefully shutdown querier when using query-scheduler #7735

[bugfix] scheduler: Gracefully shutdown querier when using query-scheduler #7735

liguozhong commented Nov 21, 2022

grafanabot commented Nov 21, 2022

grafanabot commented Nov 22, 2022

jeschkies left a comment •

edited

Loading

jeschkies Nov 22, 2022

liguozhong Nov 23, 2022

jeschkies Nov 22, 2022

liguozhong Nov 23, 2022

jeschkies Nov 29, 2022

pracucci Nov 29, 2022

pracucci Nov 29, 2022

jeschkies Nov 29, 2022

pracucci Nov 29, 2022

jeschkies Nov 29, 2022

grafanabot commented Nov 23, 2022

liguozhong commented Nov 23, 2022 •

edited

Loading

dannykopping commented Nov 24, 2022

liguozhong commented Nov 25, 2022

jeschkies left a comment

jeschkies Nov 29, 2022

grafanabot commented Nov 30, 2022

liguozhong commented Nov 30, 2022

grafanabot commented Nov 30, 2022

[bugfix] scheduler: Gracefully shutdown querier when using query-scheduler #7735

[bugfix] scheduler: Gracefully shutdown querier when using query-scheduler #7735

Conversation

liguozhong commented Nov 21, 2022

grafanabot commented Nov 21, 2022

grafanabot commented Nov 22, 2022

jeschkies left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

grafanabot commented Nov 23, 2022

liguozhong commented Nov 23, 2022 • edited Loading

dannykopping commented Nov 24, 2022

liguozhong commented Nov 25, 2022

jeschkies left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

grafanabot commented Nov 30, 2022

liguozhong commented Nov 30, 2022

grafanabot commented Nov 30, 2022

jeschkies left a comment •

edited

Loading

liguozhong commented Nov 23, 2022 •

edited

Loading