diff --git a/.github/workflows/test.yaml b/.github/workflows/test.yaml index 34040783595..688506d6df3 100644 --- a/.github/workflows/test.yaml +++ b/.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 } diff --git a/build-aux/snap/snapcraft.yaml b/build-aux/snap/snapcraft.yaml index 6c3a0ee6278..d7d541aa9d3 100644 --- a/build-aux/snap/snapcraft.yaml +++ b/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 ;; diff --git a/osutil/statelock.go b/osutil/statelock.go new file mode 100644 index 00000000000..49b04c179ea --- /dev/null +++ b/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 . + * + */ + +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) + } +} diff --git a/osutil/statelock_fake.go b/osutil/statelock_fake.go new file mode 100644 index 00000000000..1f5bd0c5d04 --- /dev/null +++ b/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 . + * + */ + +package osutil + +func GetLockStart() int64 { + return int64(0) +} + +func MaybeSaveLockTime(lockStart int64) { +} diff --git a/overlord/state/state.go b/overlord/state/state.go index e3ad7e9b744..cb269aea75f 100644 --- a/overlord/state/state.go +++ b/overlord/state/state.go @@ -25,8 +25,6 @@ import ( "errors" "fmt" "io" - "os" - "runtime" "sort" "strconv" "sync" @@ -34,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 @@ -143,7 +142,7 @@ func (s *State) Modified() bool { // Lock acquires the state lock. func (s *State) Lock() { - s.lockStart = time.Now().UnixNano() / int64(time.Millisecond) + s.lockStart = osutil.GetLockStart() s.mu.Lock() atomic.AddInt32(&s.muC, 1) } @@ -164,12 +163,7 @@ 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) - } + osutil.MaybeSaveLockTime(s.lockStart) } type marshalledState struct { @@ -259,30 +253,6 @@ 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. diff --git a/packaging/ubuntu-16.04/rules b/packaging/ubuntu-16.04/rules index 8043be3a64b..b7463140b3f 100755 --- a/packaging/ubuntu-16.04/rules +++ b/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 diff --git a/spread.yaml b/spread.yaml index 1c7e4bccbd1..a5fc4305ea4 100644 --- a/spread.yaml +++ b/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}")' diff --git a/tests/lib/prepare-restore.sh b/tests/lib/prepare-restore.sh index 8d73bea2f81..a5c45214cbf 100755 --- a/tests/lib/prepare-restore.sh +++ b/tests/lib/prepare-restore.sh @@ -697,6 +697,7 @@ prepare_suite_each() { fi if [[ "$variant" = full ]]; then + . "$TESTSLIB"/prepare.sh # shellcheck source=tests/lib/prepare.sh . "$TESTSLIB"/prepare.sh if os.query is-classic; then @@ -704,7 +705,7 @@ prepare_suite_each() { else prepare_each_core fi - + prepare_state_lock "$SPREAD_JOB" fi case "$SPREAD_SYSTEM" in diff --git a/tests/lib/prepare.sh b/tests/lib/prepare.sh index 142d5ada4c4..5ce2bd3362c 100755 --- a/tests/lib/prepare.sh +++ b/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 < "$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 diff --git a/tests/main/snapd-state-lock/task.yaml b/tests/main/snapd-state-lock/task.yaml new file mode 100644 index 00000000000..9a76eff8b3c --- /dev/null +++ b/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 \ No newline at end of file