Fix deadlock in messager and health streamer #17230

GuptaManan100 · 2024-11-14T11:50:34Z

Description

This PR fixes the deadlocks in messager and health streamer as pointed out in #17229.

The fix to the deadlock for both the cases was to use two different mutexes. One that only protects against calling setup functions like Open and Close concurrently, and the other one that actually protects the fields. This helps in removing the deadlock since the function that runs on a broadcast from the schema engine would acquire a different mutex than the call to Close.

Related Issue(s)

Fixes Bug Report: Deadlock in messager engine #17229

Checklist

"Backport to:" labels have been added if this change should be back-ported to release branches
If this change is to be back-ported to previous releases, a justification is included in the PR description
Tests were added or are not required
Did the new or modified tests pass consistently locally and on CI?
Documentation was added or is not required

Deployment Notes

Signed-off-by: Manan Gupta <manan@planetscale.com>

vitess-bot · 2024-11-14T11:50:36Z

codecov · 2024-11-14T12:11:37Z

Codecov Report

Attention: Patch coverage is 89.18919% with 4 lines in your changes missing coverage. Please review.

Project coverage is 67.39%. Comparing base (c72bbdc) to head (3901fc2).
Report is 2 commits behind head on main.

Files with missing lines	Patch %	Lines
go/vt/vttablet/tabletserver/health_streamer.go	82.60%	4 Missing ⚠️

Additional details and impacted files

@@           Coverage Diff           @@
##             main   #17230   +/-   ##
=======================================
  Coverage   67.39%   67.39%           
=======================================
  Files        1570     1570           
  Lines      252903   252912    +9     
=======================================
+ Hits       170438   170461   +23     
+ Misses      82465    82451   -14

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

mattlord

Thanks, @GuptaManan100 ! ❤️

mattlord · 2024-11-14T13:56:58Z

go/vt/vttablet/tabletserver/messager/engine_test.go

+
+// TestDeadlockBwCloseAndSchemaChange tests the deadlock observed between Close and schemaChanged
+// functions. More details can be found in the issue https://github.com/vitessio/vitess/issues/17229.
+func TestDeadlockBwCloseAndSchemaChange(t *testing.T) {


I ran this on main in a loop while reviewing the PR. I didn't get any failures:

while true; do go test -v -count 1 -timeout 5s -run ^TestDeadlockBwCloseAndSchemaChange$ vitess.io/vitess/go/vt/vttablet/tabletserver/messager if [[ $? -ne 0 ]]; then say "got one" break fi done

But we already know that it's not easy to trigger and we can logically see how it can happen. Just noting that the test doesn't seem to be as useful as one would hope.

This tracks. I commented on the issue that we haven't seen this in practice, at least that I'm aware of.
#17229 (comment)

Really!? It fails for me -

while true; do go test -v -count 1 -timeout 5s -run ^TestDeadlockBwCloseAndSchemaChange$ vitess.io/vitess/go/vt/vttablet/tabletserver/messager if [[ $? -ne 0 ]]; then say "got one" break fi done === RUN TestDeadlockBwCloseAndSchemaChange --- PASS: TestDeadlockBwCloseAndSchemaChange (0.00s) PASS ok vitess.io/vitess/go/vt/vttablet/tabletserver/messager 0.579s === RUN TestDeadlockBwCloseAndSchemaChange panic: test timed out after 5s running tests: TestDeadlockBwCloseAndSchemaChange (5s) goroutine 66 [running]: testing.(*M).startAlarm.func1() /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/testing/testing.go:2373 +0x30c created by time.goFunc /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/time/sleep.go:215 +0x38 goroutine 1 [chan receive]: testing.(*T).Run(0x140001be820, {0x1012cb3fe?, 0x1400059fb48?}, 0x101ab0970) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/testing/testing.go:1751 +0x328 testing.runTests.func1(0x140001be820) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/testing/testing.go:2168 +0x40 testing.tRunner(0x140001be820, 0x1400059fc68) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/testing/testing.go:1690 +0xe4 testing.runTests(0x140001c7d58, {0x1024c7e00, 0x19, 0x19}, {0xfc00000000000000?, 0xfcaacd9be1871533?, 0x102a6b640?}) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/testing/testing.go:2166 +0x3ac testing.(*M).Run(0x14000342f00) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/testing/testing.go:2034 +0x588 main.main() _testmain.go:93 +0x90 goroutine 35 [select]: github.com/golang/glog.(*fileSink).flushDaemon(0x102a6b6d8) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/github.com/golang/glog@v1.2.3/glog_file.go:352 +0xa4 created by github.com/golang/glog.init.1 in goroutine 1 /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/github.com/golang/glog@v1.2.3/glog_file.go:167 +0x1c8 goroutine 10 [syscall]: os/signal.signal_recv() /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/runtime/sigqueue.go:149 +0x2c os/signal.loop() /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/os/signal/signal_unix.go:23 +0x1c created by os/signal.Notify.func1.1 in goroutine 1 /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/os/signal/signal.go:151 +0x28 goroutine 11 [chan receive]: vitess.io/vitess/go/vt/dbconfigs.init.0.func1() /Users/manangupta/vitess/go/vt/dbconfigs/credentials.go:90 +0x34 created by vitess.io/vitess/go/vt/dbconfigs.init.0 in goroutine 1 /Users/manangupta/vitess/go/vt/dbconfigs/credentials.go:89 +0x164 goroutine 12 [semacquire]: sync.runtime_Semacquire(0x14000663340?) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/runtime/sema.go:71 +0x2c sync.(*WaitGroup).Wait(0x140003b47d0) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/sync/waitgroup.go:118 +0x74 vitess.io/vitess/go/vt/vttablet/tabletserver/messager.TestDeadlockBwCloseAndSchemaChange(0x140001be9c0?) /Users/manangupta/vitess/go/vt/vttablet/tabletserver/messager/engine_test.go:201 +0x110 testing.tRunner(0x140001be9c0, 0x101ab0970) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/testing/testing.go:1690 +0xe4 created by testing.(*T).Run in goroutine 1 /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/testing/testing.go:1743 +0x314 goroutine 13 [select]: vitess.io/vitess/go/stats.(*Rates).track(0x14000465100) /Users/manangupta/vitess/go/stats/rates.go:110 +0xac created by vitess.io/vitess/go/stats.NewRates in goroutine 12 /Users/manangupta/vitess/go/stats/rates.go:97 +0x240 goroutine 14 [select]: vitess.io/vitess/go/stats.(*Rates).track(0x14000465280) /Users/manangupta/vitess/go/stats/rates.go:110 +0xac created by vitess.io/vitess/go/stats.NewRates in goroutine 12 /Users/manangupta/vitess/go/stats/rates.go:97 +0x240 goroutine 15 [sync.Mutex.Lock]: sync.runtime_SemacquireMutex(0x2?, 0x0?, 0x1012d7c7b?) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/runtime/sema.go:95 +0x28 sync.(*Mutex).lockSlow(0x14000410048) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/sync/mutex.go:173 +0x174 sync.(*Mutex).Lock(...) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/sync/mutex.go:92 vitess.io/vitess/go/vt/vttablet/tabletserver/schema.(*Engine).UnregisterNotifier(0x14000410000, {0x10129dacb, 0x8}) /Users/manangupta/vitess/go/vt/vttablet/tabletserver/schema/engine.go:846 +0xc0 vitess.io/vitess/go/vt/vttablet/tabletserver/messager.(*Engine).Close(0x14000061c20) /Users/manangupta/vitess/go/vt/vttablet/tabletserver/messager/engine.go:108 +0x144 vitess.io/vitess/go/vt/vttablet/tabletserver/messager.TestDeadlockBwCloseAndSchemaChange.func1() /Users/manangupta/vitess/go/vt/vttablet/tabletserver/messager/engine_test.go:188 +0x5c created by vitess.io/vitess/go/vt/vttablet/tabletserver/messager.TestDeadlockBwCloseAndSchemaChange in goroutine 12 /Users/manangupta/vitess/go/vt/vttablet/tabletserver/messager/engine_test.go:185 +0xb8 goroutine 16 [sync.Mutex.Lock]: sync.runtime_SemacquireMutex(0x1298a9bf0?, 0x50?, 0x1298a9bf0?) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/runtime/sema.go:95 +0x28 sync.(*Mutex).lockSlow(0x14000061c20) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/sync/mutex.go:173 +0x174 sync.(*Mutex).Lock(...) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.3.darwin-arm64/src/sync/mutex.go:92 vitess.io/vitess/go/vt/vttablet/tabletserver/messager.(*Engine).schemaChanged(0x14000061c20, 0x140001b7dc8?, {0x0, 0x0, 0x0}, {0x0, 0x0, 0x1012570f4?}, {0x0, 0x0, ...}, ...) /Users/manangupta/vitess/go/vt/vttablet/tabletserver/messager/engine.go:152 +0xa8 vitess.io/vitess/go/vt/vttablet/tabletserver/schema.(*Engine).broadcast(0x14000410000, {0x0, 0x0, 0x0}, {0x0, 0x0, 0x0}, {0x0, 0x0, 0x0}, ...) /Users/manangupta/vitess/go/vt/vttablet/tabletserver/schema/engine.go:864 +0x264 vitess.io/vitess/go/vt/vttablet/tabletserver/schema.(*Engine).BroadcastForTesting(0x0?, {0x0?, 0x0?, 0x0?}, {0x0?, 0x0?, 0x0?}, {0x0?, 0x0?, 0x0?}, ...) /Users/manangupta/vitess/go/vt/vttablet/tabletserver/schema/engine.go:872 +0x114 vitess.io/vitess/go/vt/vttablet/tabletserver/messager.TestDeadlockBwCloseAndSchemaChange.func2() /Users/manangupta/vitess/go/vt/vttablet/tabletserver/messager/engine_test.go:196 +0x88 created by vitess.io/vitess/go/vt/vttablet/tabletserver/messager.TestDeadlockBwCloseAndSchemaChange in goroutine 12 /Users/manangupta/vitess/go/vt/vttablet/tabletserver/messager/engine_test.go:193 +0x108 FAIL vitess.io/vitess/go/vt/vttablet/tabletserver/messager 5.648s FAIL

I made sure the test was failing before I added any fixes. After the changes, the test doesn't fail across 1000 or so runs 😄

You can try running this on e525c1a169 commit hash. In this PR I've added the test in one commit, before fixing the issue in the next. So it should be reproducible for you too.

go/vt/vttablet/tabletserver/health_streamer.go

deepthi · 2024-11-14T17:04:21Z

go/vt/vttablet/tabletserver/messager/engine.go

@@ -76,15 +83,12 @@ func NewEngine(tsv TabletService, se *schema.Engine, vs VStreamer) *Engine {
 // Open starts the Engine service.
 func (me *Engine) Open() {
 	me.mu.Lock()
+	defer me.mu.Unlock()


deepthi · 2024-11-14T17:05:23Z

go/vt/vttablet/tabletserver/messager/engine.go

+	me.managersMu.Lock()
+	defer me.managersMu.Unlock()


derekperkins · 2024-11-14T19:12:40Z

For some historical context, when the original code was written, defer still had a somewhat significant penalty, hence the lack of defer mu.Unlock. That was resolved in upstream Go in v1.14.

Signed-off-by: Manan Gupta <manan@planetscale.com>

…17235) Signed-off-by: Manan Gupta <manan@planetscale.com> Co-authored-by: vitess-bot[bot] <108069721+vitess-bot[bot]@users.noreply.github.com>

…17234) Signed-off-by: Manan Gupta <manan@planetscale.com> Co-authored-by: Manan Gupta <35839558+GuptaManan100@users.noreply.github.com> Co-authored-by: Manan Gupta <manan@planetscale.com>

…17233) Signed-off-by: Manan Gupta <manan@planetscale.com> Co-authored-by: Manan Gupta <35839558+GuptaManan100@users.noreply.github.com> Co-authored-by: Manan Gupta <manan@planetscale.com>

Signed-off-by: Manan Gupta <manan@planetscale.com> Signed-off-by: Renan Rangel <rrangel@slack-corp.com>

GuptaManan100 added 4 commits November 14, 2024 16:37

test: add a test for the deadlock seen

e525c1a

Signed-off-by: Manan Gupta <manan@planetscale.com>

feat: fix the deadlock in messager engine

6a79ff9

Signed-off-by: Manan Gupta <manan@planetscale.com>

test: add a deadlock test for health streamer

b136ca6

Signed-off-by: Manan Gupta <manan@planetscale.com>

feat: fix health streamer deadlock

c676499

Signed-off-by: Manan Gupta <manan@planetscale.com>

GuptaManan100 added Type: Bug Component: VTTablet labels Nov 14, 2024

GuptaManan100 requested review from mattlord, rohit-nayak-ps, derekperkins, harshit-gangal, systay, shlomi-noach and timvaillancourt as code owners November 14, 2024 11:50

github-actions bot added this to the v22.0.0 milestone Nov 14, 2024

mattlord approved these changes Nov 14, 2024

View reviewed changes

deepthi approved these changes Nov 14, 2024

View reviewed changes

go/vt/vttablet/tabletserver/health_streamer.go Show resolved Hide resolved

deepthi added the Do Not Merge label Nov 14, 2024

deepthi reviewed Nov 14, 2024

View reviewed changes

go/vt/vttablet/tabletserver/messager/engine.go

Comment on lines +109 to +110

me.managersMu.Lock()

defer me.managersMu.Unlock()

Copy link

Member

deepthi Nov 14, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍

derekperkins approved these changes Nov 14, 2024

View reviewed changes

feat: address review comments

3901fc2

Signed-off-by: Manan Gupta <manan@planetscale.com>

GuptaManan100 added Backport to: release-19.0 Needs to be back ported to release-19.0 Backport to: release-20.0 Needs to be backport to release-20.0 Backport to: release-21.0 Needs to be backport to release-21.0 and removed Do Not Merge labels Nov 15, 2024

GuptaManan100 merged commit 9fdfdb9 into vitessio:main Nov 15, 2024
102 checks passed

GuptaManan100 deleted the messager-deadlock branch November 15, 2024 04:38

This was referenced Nov 15, 2024

[release-19.0] Fix deadlock in messager and health streamer (#17230) #17233

Merged

[release-20.0] Fix deadlock in messager and health streamer (#17230) #17234

Merged

vitess-bot pushed a commit that referenced this pull request Nov 15, 2024

Fix deadlock in messager and health streamer (#17230)

8c6d94e

Signed-off-by: Manan Gupta <manan@planetscale.com>

vitess-bot bot mentioned this pull request Nov 15, 2024

[release-21.0] Fix deadlock in messager and health streamer (#17230) #17235

Merged

GuptaManan100 added a commit that referenced this pull request Nov 15, 2024

Fix deadlock in messager and health streamer (#17230)

eace5a2

Signed-off-by: Manan Gupta <manan@planetscale.com>

GuptaManan100 added a commit that referenced this pull request Nov 15, 2024

Fix deadlock in messager and health streamer (#17230)

5e14251

Signed-off-by: Manan Gupta <manan@planetscale.com>

GuptaManan100 mentioned this pull request Nov 20, 2024

Fix potential deadlock in health streamer #17261

Merged

5 tasks

rvrangel pushed a commit to rvrangel/vitess that referenced this pull request Nov 21, 2024

Fix deadlock in messager and health streamer (vitessio#17230)

c289b9c

Signed-off-by: Manan Gupta <manan@planetscale.com> Signed-off-by: Renan Rangel <rrangel@slack-corp.com>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix deadlock in messager and health streamer #17230

Fix deadlock in messager and health streamer #17230

GuptaManan100 commented Nov 14, 2024

vitess-bot bot commented Nov 14, 2024

codecov bot commented Nov 14, 2024 •

edited

Loading

mattlord left a comment

mattlord Nov 14, 2024

derekperkins Nov 14, 2024

GuptaManan100 Nov 15, 2024

GuptaManan100 Nov 15, 2024

GuptaManan100 Nov 15, 2024

deepthi Nov 14, 2024

deepthi Nov 14, 2024

derekperkins commented Nov 14, 2024 •

edited

Loading

Fix deadlock in messager and health streamer #17230

Fix deadlock in messager and health streamer #17230

Conversation

GuptaManan100 commented Nov 14, 2024

Description

Related Issue(s)

Checklist

Deployment Notes

vitess-bot bot commented Nov 14, 2024

Review Checklist

General

Tests

Documentation

New flags

If a workflow is added or modified:

Backward compatibility

codecov bot commented Nov 14, 2024 • edited Loading

Codecov Report

mattlord left a comment

Choose a reason for hiding this comment

mattlord Nov 14, 2024

Choose a reason for hiding this comment

derekperkins Nov 14, 2024

Choose a reason for hiding this comment

GuptaManan100 Nov 15, 2024

Choose a reason for hiding this comment

GuptaManan100 Nov 15, 2024

Choose a reason for hiding this comment

GuptaManan100 Nov 15, 2024

Choose a reason for hiding this comment

deepthi Nov 14, 2024

Choose a reason for hiding this comment

deepthi Nov 14, 2024

Choose a reason for hiding this comment

derekperkins commented Nov 14, 2024 • edited Loading

codecov bot commented Nov 14, 2024 •

edited

Loading

derekperkins commented Nov 14, 2024 •

edited

Loading