spike to measure locking time os snapd state file

overlord/state/state.go

@@ -25,6 +25,8 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"os"
+	"runtime"
 	"sort"
 	"strconv"
 	"sync"
@@ -111,6 +113,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
 }
 
 // New returns a new empty state.
@@ -139,6 +143,7 @@ func (s *State) Modified() bool {
 
 // Lock acquires the state lock.
 func (s *State) Lock() {
+	s.lockStart = time.Now().UnixNano() / int64(time.Millisecond)
 	s.mu.Lock()
 	atomic.AddInt32(&s.muC, 1)
 }
@@ -159,6 +164,12 @@ func (s *State) writing() {
 func (s *State) unlock() {
 	atomic.AddInt32(&s.muC, -1)
 	s.mu.Unlock()
+	lockEnd := time.Now().UnixNano() / int64(time.Millisecond)
+	elapsedMilliseconds := lockEnd - s.lockStart
+	if elapsedMilliseconds > 5 {
+		formattedLine := fmt.Sprintf("Elapsed Time: %d milliseconds", elapsedMilliseconds)
+		traceCallers(formattedLine)
+	}
 }
 
 type marshalledState struct {
@@ -248,6 +259,30 @@ func (s *State) Unlocker() (unlock func() (relock func())) {
 	}
 }
 
+func traceCallers(description string) {
+	tmpfile, err := os.OpenFile("/tmp/snapd_lock_traces", os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0600)
+	if err != nil {
+		logger.Panicf("could not open/create log traces file: %v", err)
+	}
+	defer tmpfile.Close()
+
+	pc := make([]uintptr, 10)
+	n := runtime.Callers(0, pc)
+	formattedLine := fmt.Sprintf("###%s\n", description)
+	if _, err = tmpfile.WriteString(formattedLine); err != nil {
+		logger.Panicf("internal error: could not write trace callers header to tmp file: %v", err)
+	}
+	for i := 0; i < n; i++ {
+		f := runtime.FuncForPC(pc[i])
+		file, line := f.FileLine(pc[i])
+		formattedLine = fmt.Sprintf("%s:%d %s\n", file, line, f.Name())
+		if _, err = tmpfile.WriteString(formattedLine); err != nil {
+			logger.Panicf("internal error: could not write trace callers to tmp file: %v", err)
+		}
+	}
+
+}
+
 // Unlock releases the state lock and checkpoints the state.
 // It does not return until the state is correctly checkpointed.
 // After too many unsuccessful checkpoint attempts, it panics.