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 <[email protected]>

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 1 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/[email protected]/src/testing/testing.go:2373 +0x30c created by time.goFunc /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/[email protected]/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/[email protected]/src/testing/testing.go:1751 +0x328 testing.runTests.func1(0x140001be820) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/[email protected]/src/testing/testing.go:2168 +0x40 testing.tRunner(0x140001be820, 0x1400059fc68) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/[email protected]/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/[email protected]/src/testing/testing.go:2166 +0x3ac testing.(*M).Run(0x14000342f00) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/[email protected]/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/[email protected]/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/[email protected]/glog_file.go:167 +0x1c8 goroutine 10 [syscall]: os/signal.signal_recv() /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/[email protected]/src/runtime/sigqueue.go:149 +0x2c os/signal.loop() /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/[email protected]/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/[email protected]/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/[email protected]/src/runtime/sema.go:71 +0x2c sync.(*WaitGroup).Wait(0x140003b47d0) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/src/runtime/sema.go:95 +0x28 sync.(*Mutex).lockSlow(0x14000410048) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/[email protected]/src/sync/mutex.go:173 +0x174 sync.(*Mutex).Lock(...) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/[email protected]/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/[email protected]/src/runtime/sema.go:95 +0x28 sync.(*Mutex).lockSlow(0x14000061c20) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/[email protected]/src/sync/mutex.go:173 +0x174 sync.(*Mutex).Lock(...) /Users/manangupta/.gvm/pkgsets/go1.23.0/global/pkg/mod/golang.org/[email protected]/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 <[email protected]>

GuptaManan100 added 4 commits November 14, 2024 16:37

test: add a test for the deadlock seen

e525c1a

Signed-off-by: Manan Gupta <[email protected]>

feat: fix the deadlock in messager engine

6a79ff9

Signed-off-by: Manan Gupta <[email protected]>

test: add a deadlock test for health streamer

b136ca6

Signed-off-by: Manan Gupta <[email protected]>

feat: fix health streamer deadlock

c676499

Signed-off-by: Manan Gupta <[email protected]>

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 <[email protected]>

GuptaManan100 removed the Do Not Merge label Nov 15, 2024

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

Are you sure you want to change the base?

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