tests: measure state lock #14874

sergiocazzolato · 2024-12-18T02:34:17Z

This change allows to collect the time the snapd state file is locked. To collect the results it is required to include the test snapd-state-lock and make sure just 1 worker is used.

SPREAD_SNAPD_STATE_LOCK_THRESHOLD_MS=15 SPREAD_USE_SNAPD_SNAP_URL= SPREAD_USE_PREBUILT_SNAPD_SNAP=false ./run-spread -artifacts .artifacts google:ubuntu-22.04-64:tests/main/snapd-state-lock google:ubuntu-22.04-64:tests/smoke/

this is an example of the smoke suite with threshold=15ms: https://paste.ubuntu.com/p/vkcMdcGTnM/
this is an example of the smoke suite with threshold=100ms: https://paste.ubuntu.com/p/XTn8jZ62pJ/

pedronis

question

pedronis · 2024-12-20T13:15:19Z

overlord/state/state.go

@@ -139,6 +142,7 @@ func (s *State) Modified() bool {

 // Lock acquires the state lock.
 func (s *State) Lock() {
+	s.lockStart = osutil.GetLockStart()


shouldn't this be done with the lock taken? otherwise just the tentative themselves to lock will race/dirty lockStart

right, I'll update this

sergiocazzolato · 2025-01-06T14:04:46Z

These are the times after the fix proposed by @pedronis

lock-times-smoke.txt

I see it locks about 820ms when the snapd daemon is started (this happens in all the tests)

pedronis · 2025-01-06T17:16:25Z

overlord/state/state.go

@@ -159,6 +163,7 @@ func (s *State) writing() {
 func (s *State) unlock() {
 	atomic.AddInt32(&s.muC, -1)
 	s.mu.Unlock()
+	osutil.MaybeSaveLockTime(s.lockStart)


this only needs to happen with the lock taken I think

This may be ok to do with the state lock released if we flock the log file. With the state lock held, there would likely be no contention for flock on the log file. OTOH with the lock released, we'd rely on flock to serialize writes, but this would not keep the state lock unnecessarily held.

FWIW, unlocking may reschedule, so assuming we use flock for serializing writes, the timing may end up being incorrect given that the time is captured inside MaybeSaveLockTime(). The end time will likely need to be captured like so:

lockEnd := time.Now() s.mu.Unlock() osutil.MaybeSaveLockTime(s.lockStart, lockEnd)

note, I missed that s.lockStart is used after releasing the lock, it should ofc be read into a variable before the lock is released

sergiocazzolato · 2025-01-06T19:36:53Z

@pedronis This is the result of the main suite 145 tests (using a machine with 2 cores and threshold of 800ms),
https://pastebin.canonical.com/p/Km4DrSskYD/

I see some worst times doing:
github.com/snapcore/snapd/daemon.(*Daemon).Start
github.com/snapcore/snapd/overlord/assertstate.doValidateSnap

should we specially test those cases?

bboozzoo · 2025-01-07T15:00:15Z

osutil/statelock.go

+	defer lockfile.Close()
+
+	pc := make([]uintptr, 10)
+	n := runtime.Callers(0, pc)


skip should likely be set to 2, to skip traceCallers and MaybeSaveLockTime

bboozzoo · 2025-01-07T15:28:54Z

osutil/statelock.go

+	for i := 0; i < n; i++ {
+		f := runtime.FuncForPC(pc[i])
+		file, line := f.FileLine(pc[i])


per docs of https://pkg.go.dev/runtime?utm_source=godoc#Callers, this should use runtime.CallersFrames()

bboozzoo · 2025-01-07T15:34:33Z

osutil/statelock.go

+// MaybeSaveLockTime allows to save lock times when this overpass the threshold
+// defined by through the SNAPD_STATE_LOCK_THRESHOLD_MS environment settings.
+func MaybeSaveLockTime(lockStart int64) {
+	lockEnd := time.Now().UnixNano() / int64(time.Millisecond)


this can prob be done after both getenvs

bboozzoo · 2025-01-07T15:39:26Z

overlord/state/state.go

@@ -159,6 +163,7 @@ func (s *State) writing() {
 func (s *State) unlock() {
 	atomic.AddInt32(&s.muC, -1)
 	s.mu.Unlock()
+	osutil.MaybeSaveLockTime(s.lockStart)


This may be ok to do with the state lock released if we flock the log file. With the state lock held, there would likely be no contention for flock on the log file. OTOH with the lock released, we'd rely on flock to serialize writes, but this would not keep the state lock unnecessarily held.

FWIW, unlocking may reschedule, so assuming we use flock for serializing writes, the timing may end up being incorrect given that the time is captured inside MaybeSaveLockTime(). The end time will likely need to be captured like so:

lockEnd := time.Now() s.mu.Unlock() osutil.MaybeSaveLockTime(s.lockStart, lockEnd)

bboozzoo · 2025-01-07T15:43:25Z

osutil/statelock.go

+		fmt.Fprintf(os.Stderr, "could not retrieve log file, SNAPD_STATE_LOCK_FILE env var required")
+	}
+
+	lockfile, err := os.OpenFile(lockfilePath, os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0600)


this could flock the file after opening it, so that we serialize the writes but the state lock could be unlocked earlier

bboozzoo · 2025-01-07T15:45:06Z

osutil/statelock.go

+		f := runtime.FuncForPC(pc[i])
+		file, line := f.FileLine(pc[i])
+		formattedLine = fmt.Sprintf("%s:%d %s\n", file, line, f.Name())
+		if _, err = lockfile.WriteString(formattedLine); err != nil {


I wonder if we could maybe use runtime.Profile to achieve the same thing but do it in more standard way.

bboozzoo · 2025-01-07T15:47:47Z

osutil/statelock.go

+)
+
+func traceCallers(description string) {
+	lockfilePath := os.Getenv("SNAPD_STATE_LOCK_FILE")


I'd avoid using lock* in the name, to not confuse future self or other readers that this is not a lock file, but a file with log of state lock times (and their context). So maybe logFilePath.

bboozzoo · 2025-01-07T15:48:15Z

osutil/statelock.go

+	if threshold <= 0 {
+		return
+	}
+


"SNAPD_STATE_LOCK_FILE" could be tested here

bboozzoo · 2025-01-07T15:57:38Z

overlord/state/state.go

@@ -111,6 +112,8 @@ type State struct {
 	// task/changes observing
 	taskHandlers   map[int]func(t *Task, old, new Status) (remove bool)
 	changeHandlers map[int]func(chg *Change, old, new Status)
+
+	lockStart int64


Suggested change

lockStart int64

lockWait int64

lockStart int64

bboozzoo · 2025-01-07T15:58:49Z

overlord/state/state.go

 	s.mu.Lock()
 	atomic.AddInt32(&s.muC, 1)
+	s.lockStart = osutil.GetLockStart()


Suggested change

s.mu.Lock()

atomic.AddInt32(&s.muC, 1)

s.lockStart = osutil.GetLockStart()

lockWait := osutil.LockTimestamp()

s.mu.Lock()

atomic.AddInt32(&s.muC, 1)

s.lockStart = osutil.LockTimestamp()

s.lockWait = lockWait

bboozzoo · 2025-01-07T15:59:37Z

osutil/statelock.go

+
+// MaybeSaveLockTime allows to save lock times when this overpass the threshold
+// defined by through the SNAPD_STATE_LOCK_THRESHOLD_MS environment settings.
+func MaybeSaveLockTime(lockStart int64) {


Suggested change

func MaybeSaveLockTime(lockStart int64) {

func MaybeSaveLockTime(lockWait, lockStart, lockEnd int64) {

bboozzoo · 2025-01-07T16:00:58Z

overlord/state/state.go

 	s.mu.Unlock()
+	osutil.MaybeSaveLockTime(s.lockStart)


Suggested change

s.mu.Unlock()

osutil.MaybeSaveLockTime(s.lockStart)

lockWait, lockStart := s.lockWait, s.lockStart

s.lockWait, s.lockStart = 0, 0

s.mu.Unlock()

osutil.MaybeSaveLockTime(lockWait, lockStart)

bboozzoo · 2025-01-07T16:01:31Z

overlord/state/state.go

@@ -159,6 +163,7 @@ func (s *State) writing() {
 func (s *State) unlock() {
 	atomic.AddInt32(&s.muC, -1)
 	s.mu.Unlock()
+	osutil.MaybeSaveLockTime(s.lockStart)


note, I missed that s.lockStart is used after releasing the lock, it should ofc be read into a variable before the lock is released

bboozzoo · 2025-01-07T16:04:13Z

osutil/statelock.go

+	elapsedMilliseconds := lockEnd - lockStart
+	if elapsedMilliseconds > threshold {
+		formattedLine := fmt.Sprintf("Elapsed Time: %d milliseconds", elapsedMilliseconds)
+		traceCallers(formattedLine)
+	}


Suggested change

elapsedMilliseconds := lockEnd - lockStart

if elapsedMilliseconds > threshold {

formattedLine := fmt.Sprintf("Elapsed Time: %d milliseconds", elapsedMilliseconds)

traceCallers(formattedLine)

}

heldMs := lockEnd - lockStart

waitedMs := lockStart - lockWait

if heldMs > threshold || waitedMs > threshold {

formattedLine := fmt.Sprintf("waited %d ms held", waitedMs, heldMs)

traceCallers(formattedLine)

}

This will prevent raises.

codecov · 2025-01-08T04:21:51Z

Codecov Report

Attention: Patch coverage is 54.54545% with 5 lines in your changes missing coverage. Please review.

Project coverage is 78.22%. Comparing base (24a0034) to head (af6f416).
Report is 88 commits behind head on master.

Files with missing lines	Patch %	Lines
osutil/statelock_fake.go	0.00%	3 Missing ⚠️
osutil/flock.go	0.00%	2 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##           master   #14874      +/-   ##
==========================================
+ Coverage   78.20%   78.22%   +0.01%     
==========================================
  Files        1151     1154       +3     
  Lines      151396   152804    +1408     
==========================================
+ Hits       118402   119528    +1126     
- Misses      25662    25895     +233     
- Partials     7332     7381      +49

Flag	Coverage Δ
unittests	`78.22% <54.54%> (+0.01%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

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

sergiocazzolato marked this pull request as draft December 18, 2024 02:34

sergiocazzolato requested a review from pedronis December 18, 2024 02:34

sergiocazzolato added 3 commits December 18, 2024 14:38

spike to measure locking time os snapd state file

6b28c3a

Changes required to collect the state locks for the whole run

6b3d5b8

fix shellcheck error

f46e537

sergiocazzolato force-pushed the tests-measure-state-lock branch from 0d1c64f to f46e537 Compare December 18, 2024 17:40

sergiocazzolato added the Needs Samuele review Needs a review from Samuele before it can land label Dec 19, 2024

sergiocazzolato requested a review from maykathm December 19, 2024 16:51

sergiocazzolato marked this pull request as ready for review December 19, 2024 16:51

pedronis reviewed Dec 20, 2024

View reviewed changes

pedronis requested a review from bboozzoo December 20, 2024 14:03

measure the lock time after the lock is done

30de5db

pedronis self-requested a review January 6, 2025 15:54

pedronis reviewed Jan 6, 2025

View reviewed changes

bboozzoo reviewed Jan 7, 2025

View reviewed changes

sergiocazzolato added 2 commits January 7, 2025 13:10

Save unlock times before the unlock

42430f7

This will prevent raises.

Added wait time and several improvements

af6f416

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

tests: measure state lock #14874

tests: measure state lock #14874

sergiocazzolato commented Dec 18, 2024 •

edited

Loading

pedronis left a comment

pedronis Dec 20, 2024

sergiocazzolato Jan 6, 2025

sergiocazzolato commented Jan 6, 2025 •

edited

Loading

pedronis Jan 6, 2025

bboozzoo Jan 7, 2025

bboozzoo Jan 7, 2025

sergiocazzolato Jan 7, 2025

sergiocazzolato commented Jan 6, 2025 •

edited

Loading

bboozzoo Jan 7, 2025

sergiocazzolato Jan 7, 2025

bboozzoo Jan 7, 2025

bboozzoo Jan 7, 2025

bboozzoo Jan 7, 2025

bboozzoo Jan 7, 2025

bboozzoo Jan 7, 2025

bboozzoo Jan 7, 2025

bboozzoo Jan 7, 2025

bboozzoo Jan 7, 2025

bboozzoo Jan 7, 2025

bboozzoo Jan 7, 2025

bboozzoo Jan 7, 2025

bboozzoo Jan 7, 2025

bboozzoo Jan 7, 2025

codecov bot commented Jan 8, 2025

	func MaybeSaveLockTime(lockStart int64) {
	func MaybeSaveLockTime(lockWait, lockStart, lockEnd int64) {

tests: measure state lock #14874

Are you sure you want to change the base?

tests: measure state lock #14874

Conversation

sergiocazzolato commented Dec 18, 2024 • edited Loading

pedronis left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sergiocazzolato commented Jan 6, 2025 • 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

sergiocazzolato commented Jan 6, 2025 • 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

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

codecov bot commented Jan 8, 2025

Codecov Report

sergiocazzolato commented Dec 18, 2024 •

edited

Loading

sergiocazzolato commented Jan 6, 2025 •

edited

Loading

sergiocazzolato commented Jan 6, 2025 •

edited

Loading