tests: measure state lock

.github/workflows/test.yaml

@@ -195,6 +195,7 @@ jobs:
           - { go-build-tags: withbootassetstesting, skip-coverage: false, snapd-debug: false, go-test-race: false}
           - { go-build-tags: nosecboot,             skip-coverage: false, snapd-debug: false, go-test-race: false}
           - { go-build-tags: faultinject,           skip-coverage: false, snapd-debug: false, go-test-race: false}
+          - { go-build-tags: statelock,             skip-coverage: false, snapd-debug: false, go-test-race: false}
           - { go-build-tags: snapdusergo,           skip-coverage: false, snapd-debug: false, go-test-race: false}
           - { go-build-tags: "",                    skip-coverage: true,  snapd-debug: false, go-test-race: true }
 

build-aux/snap/snapcraft.yaml

@@ -355,14 +355,14 @@ parts:
             TAGS+=(nomanagers)
             case "${VERSION}" in
               1337.*)
-                TAGS+=(withtestkeys faultinject)
+                TAGS+=(withtestkeys faultinject statelock)
                 ;;
             esac
             ;;
           *)
             case "${VERSION}" in
               1337.*)
-                TAGS+=(withtestkeys withbootassetstesting faultinject)
+                TAGS+=(withtestkeys withbootassetstesting faultinject statelock)
                 ;;
             esac
             ;;

osutil/statelock.go

@@ -0,0 +1,83 @@
+// -*- Mode: Go; indent-tabs-mode: t -*-
+//go:build statelock
+
+/*
+ * Copyright (C) 2021 Canonical Ltd
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License version 3 as
+ * published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ */
+
+package osutil
+
+import (
+	"fmt"
+	"os"
+	"runtime"
+	"time"
+)
+
+func traceCallers(description string) {
+	lockfilePath := os.Getenv("SNAPD_STATE_LOCK_FILE")
+	if lockfilePath == "" {
+		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)
+	if err != nil {
+		fmt.Fprintf(os.Stderr, "could not open/create log traces file: %v", err)
+		return
+	}
+	defer lockfile.Close()
+
+	pc := make([]uintptr, 10)
+	n := runtime.Callers(0, pc)
+	formattedLine := fmt.Sprintf("##%s\n", description)
+	if _, err = lockfile.WriteString(formattedLine); err != nil {
+		fmt.Fprintf(os.Stderr, "internal error: could not write trace callers header to tmp file: %v", err)
+		return
+	}
+	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 = lockfile.WriteString(formattedLine); err != nil {
+			fmt.Fprintf(os.Stderr, "internal error: could not write trace callers to tmp file: %v", err)
+			return
+		}
+	}
+}
+
+func GetLockStart() int64 {
+	return time.Now().UnixNano() / int64(time.Millisecond)
+}
+
+// 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)
+
+	if !GetenvBool("SNAPPY_TESTING") {
+		return
+	}
+	threshold := GetenvInt64("SNAPD_STATE_LOCK_THRESHOLD_MS")
+	if threshold <= 0 {
+		return
+	}
+
+	elapsedMilliseconds := lockEnd - lockStart
+	if elapsedMilliseconds > threshold {
+		formattedLine := fmt.Sprintf("Elapsed Time: %d milliseconds", elapsedMilliseconds)
+		traceCallers(formattedLine)
+	}
+}

osutil/statelock_fake.go

@@ -0,0 +1,28 @@
+// -*- Mode: Go; indent-tabs-mode: t -*-
+//go:build !statelock
+
+/*
+ * Copyright (C) 2021 Canonical Ltd
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License version 3 as
+ * published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ */
+
+package osutil
+
+func GetLockStart() int64 {
+	return int64(0)
+}
+
+func MaybeSaveLockTime(lockStart int64) {
+}

overlord/state/state.go

@@ -32,6 +32,7 @@ import (
 	"time"
 
 	"github.com/snapcore/snapd/logger"
+	"github.com/snapcore/snapd/osutil"
 )
 
 // A Backend is used by State to checkpoint on every unlock operation
@@ -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
 }
 
 // New returns a new empty state.
@@ -139,6 +142,7 @@ func (s *State) Modified() bool {
 
 // Lock acquires the state lock.
 func (s *State) Lock() {
+	s.lockStart = osutil.GetLockStart()
 	s.mu.Lock()
 	atomic.AddInt32(&s.muC, 1)
 }
@@ -159,6 +163,7 @@ func (s *State) writing() {
 func (s *State) unlock() {
 	atomic.AddInt32(&s.muC, -1)
 	s.mu.Unlock()
+	osutil.MaybeSaveLockTime(s.lockStart)
 }
 
 type marshalledState struct {

packaging/ubuntu-16.04/rules

@@ -103,8 +103,8 @@ _SNAP_TAGS=
 # check if we need to include the testkeys in the binary
 ifneq (,$(filter testkeys,$(DEB_BUILD_OPTIONS)))
   # if enabled also enable bootloader assets testing and fault injection
-	_TAGS := withtestkeys,withbootassetstesting,faultinject
-	_SNAP_TAGS := nomanagers,withtestkeys,faultinject
+	_TAGS := withtestkeys,withbootassetstesting,faultinject,statelock
+	_SNAP_TAGS := nomanagers,withtestkeys,faultinject,statelock
 else
 	_SNAP_TAGS=nomanagers
 endif

spread.yaml

@@ -84,6 +84,8 @@ environment:
     SNAPD_DEB_FROM_REPO: '$(HOST: echo "${SPREAD_SNAPD_DEB_FROM_REPO:-true}")'
     # Directory where the built snapd snaps and other assets are stored
     SNAPD_WORK_DIR: '$(HOST: echo "${SPREAD_SNAPD_WORK_DIR:-/var/tmp/work-dir}")'
+    # Threshold used to determine which stake locks have to be collected during runtime
+    SNAPD_STATE_LOCK_THRESHOLD_MS: '$(HOST: echo "${SPREAD_SNAPD_STATE_LOCK_THRESHOLD_MS:-0}")'
 
     # Directory where the nested images and test assets are stored
     NESTED_WORK_DIR: '$(HOST: echo "${NESTED_WORK_DIR:-/var/tmp/work-dir}")'

tests/lib/prepare-restore.sh

@@ -697,14 +697,16 @@ prepare_suite_each() {
     fi
 
     if [[ "$variant" = full ]]; then
+        # shellcheck source=tests/lib/prepare.sh
+        . "$TESTSLIB"/prepare.sh
         # shellcheck source=tests/lib/prepare.sh
         . "$TESTSLIB"/prepare.sh
         if os.query is-classic; then
             prepare_each_classic
         else
             prepare_each_core
         fi
-
+        prepare_state_lock "$SPREAD_JOB"
     fi
 
     case "$SPREAD_SYSTEM" in

tests/lib/prepare.sh

@@ -460,6 +460,7 @@ prepare_classic() {
         fi
 
         prepare_reexec_override
+        prepare_state_lock "SNAPD PROJECT"
         prepare_memory_limit_override
         disable_refreshes
 
@@ -1520,6 +1521,37 @@ EOF
     rm -rf "$UNPACK_DIR"
 }
 
+prepare_state_lock(){
+    TAG=$1
+    CONF_FILE="/etc/systemd/system/snapd.service.d/state-lock.conf"
+    LOCKS_FILE="$TESTSTMP"/snapd_lock_traces
+    RESTART=false
+
+    if [ "$SNAPD_STATE_LOCK_THRESHOLD_MS" -gt 0 ]; then
+        echo "###START: $TAG" >> "$LOCKS_FILE"
+
+        # Generate the config file when it does not exist and when the threshold has changed different
+        if ! [ -f "$CONF_FILE" ] || ! grep -q "SNAPD_STATE_LOCK_THRESHOLD_MS=$SNAPD_STATE_LOCK_THRESHOLD_MS" < "$CONF_FILE"; then
+            echo "Prepare snapd for getting state lock time"
+            cat <<EOF > "$CONF_FILE"
+[Service]
+Environment=SNAPPY_TESTING=1 SNAPD_STATE_LOCK_THRESHOLD_MS="$SNAPD_STATE_LOCK_THRESHOLD_MS" SNAPD_STATE_LOCK_FILE="$LOCKS_FILE"
+EOF
+            RESTART=true
+        fi
+    elif [ -f "$CONF_FILE" ]; then
+        rm -f "$CONF_FILE"
+        RESTART=true
+    fi
+
+    if [ "$RESTART" = "true" ]; then
+        # the service setting may have changed in the service so we need
+        # to ensure snapd is reloaded
+        systemctl daemon-reload
+        systemctl restart snapd
+    fi
+}
+
 # prepare_ubuntu_core will prepare ubuntu-core 16+
 prepare_ubuntu_core() {
     # we are still a "classic" image, prepare the surgery
@@ -1633,6 +1665,7 @@ prepare_ubuntu_core() {
         # or restore will break
         remove_disabled_snaps
         prepare_memory_limit_override
+        prepare_state_lock "SNAPD PROJECT"
         setup_experimental_features
         systemctl stop snapd.service snapd.socket
         save_snapd_state

tests/main/snapd-state-lock/task.yaml

@@ -0,0 +1,16 @@
+summary: smoke test used to retrieve the lock state times
+
+details: |
+    Test used to collect artifacts
+
+priority: -1
+
+artifacts: 
+  - snapd_lock_traces
+
+execute: |
+  if [ -f "$TESTSTMP"/snapd_lock_traces ]; then
+    cp -f "$TESTSTMP"/snapd_lock_traces .
+  else
+    touch snapd_lock_traces
+  fi