clock: discard monotonic clock component in clock.Now() (#1437)

The dual time measurement is described in
https://go.googlesource.com/proposal/+/master/design/12914-monotonic.md

The fix is to discard hidden monotonic time component of time.Time
by converting to unix time and back.

Reviewed usage of clock.Now() and replaced with timetrack.StartTimer()
when measuring time.

The problem in #1402 was that passage of time was measured using
the monotonic time and not wall clock time. When the computer goes
to sleep, monotonic time is still monotonic while wall clock time makes
a leap when the computer wakes up. This is the behavior that
epoch manager (and most other compontents in Kopia) rely upon.

Fixes #1402

Co-authored-by: Julio Lopez <julio+gh@kasten.io>

.golangci.yml

@@ -13,9 +13,9 @@ linters-settings:
     - ioutil.TempDir # use os.MkdirTemp
     - ioutil.TempFile # use os.CreateTemp
     - ioutil.WriteFile # use os.WriteFile
-    - time.Now # use clock.Now
-    - time.Since # use clock.Since
-    - time.Until # use clock.Until
+    - time.Now # do not use outside of 'clock' and 'timetrack' packages use clock.Now or timetrack.StartTimer
+    - time.Since # use timetrack.Timer.Elapsed()
+    - time.Until # never use this
     - filepath.IsAbs # use ospath.IsAbs which supports windows UNC paths
   gocognit:
     min-complexity: 40

cli/command_logs_session.go

@@ -48,13 +48,13 @@ func (c *logSelectionCriteria) filterLogSessions(allSessions []*logSessionInfo)
 
 	if c.youngerThan > 0 {
 		allSessions = filterLogSessions(allSessions, func(ls *logSessionInfo) bool {
-			return clock.Since(ls.startTime) < c.youngerThan
+			return clock.Now().Sub(ls.startTime) < c.youngerThan
 		})
 	}
 
 	if c.olderThan > 0 {
 		allSessions = filterLogSessions(allSessions, func(ls *logSessionInfo) bool {
-			return clock.Since(ls.startTime) > c.olderThan
+			return clock.Now().Sub(ls.startTime) > c.olderThan
 		})
 	}
 

cli/command_maintenance_info.go

@@ -97,7 +97,7 @@ func (c *commandMaintenanceInfo) displayCycleInfo(cp *maintenance.CycleParams, t
 		c.out.printStdout("  interval: %v\n", cp.Interval)
 
 		if rep.Time().Before(t) {
-			c.out.printStdout("  next run: %v (in %v)\n", formatTimestamp(t), clock.Until(t).Truncate(time.Second))
+			c.out.printStdout("  next run: %v (in %v)\n", formatTimestamp(t), t.Sub(clock.Now()).Truncate(time.Second))
 		} else {
 			c.out.printStdout("  next run: now\n")
 		}

fs/loggingfs/loggingfs.go

@@ -5,7 +5,7 @@
 	"context"
 
 	"github.com/kopia/kopia/fs"
-	"github.com/kopia/kopia/internal/clock"
+	"github.com/kopia/kopia/internal/timetrack"
 )
 
 type loggingOptions struct {
@@ -20,9 +20,9 @@ type loggingDirectory struct {
 }
 
 func (ld *loggingDirectory) Child(ctx context.Context, name string) (fs.Entry, error) {
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 	entry, err := ld.Directory.Child(ctx, name)
-	dt := clock.Since(t0)
+	dt := timer.Elapsed()
 	ld.options.printf(ld.options.prefix+"Child(%v) took %v and returned %v", ld.relativePath, dt, err)
 
 	if err != nil {
@@ -34,9 +34,9 @@ func (ld *loggingDirectory) Child(ctx context.Context, name string) (fs.Entry, e
 }
 
 func (ld *loggingDirectory) Readdir(ctx context.Context) (fs.Entries, error) {
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 	entries, err := ld.Directory.Readdir(ctx)
-	dt := clock.Since(t0)
+	dt := timer.Elapsed()
 	ld.options.printf(ld.options.prefix+"Readdir(%v) took %v and returned %v items", ld.relativePath, dt, len(entries))
 
 	loggingEntries := make(fs.Entries, len(entries))

internal/apiclient/apiclient.go

@@ -11,7 +11,7 @@
 
 	"github.com/pkg/errors"
 
-	"github.com/kopia/kopia/internal/clock"
+	"github.com/kopia/kopia/internal/timetrack"
 	"github.com/kopia/kopia/internal/tlsutil"
 	"github.com/kopia/kopia/repo/logging"
 )
@@ -191,15 +191,16 @@ type loggingTransport struct {
 }
 
 func (t loggingTransport) RoundTrip(req *http.Request) (*http.Response, error) {
-	t0 := clock.Now()
-
+	timer := timetrack.StartTimer()
 	resp, err := t.base.RoundTrip(req)
+	dur := timer.Elapsed()
+
 	if err != nil {
-		log(req.Context()).Debugf("%v %v took %v and failed with %v", req.Method, req.URL, clock.Since(t0), err)
+		log(req.Context()).Debugf("%v %v took %v and failed with %v", req.Method, req.URL, dur, err)
 		return nil, errors.Wrap(err, "round-trip error")
 	}
 
-	log(req.Context()).Debugf("%v %v took %v and returned %v", req.Method, req.URL, clock.Since(t0), resp.Status)
+	log(req.Context()).Debugf("%v %v took %v and returned %v", req.Method, req.URL, dur, resp.Status)
 
 	return resp, nil
 }

internal/blobtesting/cleanup.go

@@ -21,8 +21,10 @@ func CleanupOldData(ctx context.Context, tb testing.TB, st blob.Storage, cleanup
 
 	pq := parallelwork.NewQueue()
 
+	now := clock.Now()
+
 	_ = st.ListBlobs(ctx, "", func(it blob.Metadata) error {
-		age := clock.Since(it.Timestamp)
+		age := now.Sub(it.Timestamp)
 		if age > cleanupAge {
 			pq.EnqueueBack(ctx, func() error {
 				tb.Logf("deleting %v", it.BlobID)

internal/blobtesting/eventually_consistent.go

@@ -75,7 +75,7 @@ type ecCacheEntry struct {
 }
 
 func (e *ecCacheEntry) isValid() bool {
-	return clock.Since(e.accessTime) < ecCacheDuration
+	return clock.Now().Sub(e.accessTime) < ecCacheDuration
 }
 
 type eventuallyConsistentStorage struct {

internal/cache/persistent_lru_cache.go

@@ -11,8 +11,8 @@
 	"github.com/pkg/errors"
 	"go.opencensus.io/stats"
 
-	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/gather"
+	"github.com/kopia/kopia/internal/timetrack"
 	"github.com/kopia/kopia/repo/blob"
 	"github.com/kopia/kopia/repo/logging"
 )
@@ -193,7 +193,7 @@ func (h *contentMetadataHeap) Pop() interface{} {
 }
 
 func (c *PersistentCache) sweepDirectory(ctx context.Context) (err error) {
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 
 	var h contentMetadataHeap
 
@@ -217,7 +217,9 @@ func (c *PersistentCache) sweepDirectory(ctx context.Context) (err error) {
 		return errors.Wrapf(err, "error listing %v", c.description)
 	}
 
-	log(ctx).Debugf("finished sweeping %v in %v and retained %v/%v bytes (%v %%)", c.description, clock.Since(t0), totalRetainedSize, c.maxSizeBytes, 100*totalRetainedSize/c.maxSizeBytes)
+	dur := timer.Elapsed()
+
+	log(ctx).Debugf("finished sweeping %v in %v and retained %v/%v bytes (%v %%)", c.description, dur, totalRetainedSize, c.maxSizeBytes, 100*totalRetainedSize/c.maxSizeBytes)
 
 	return nil
 }

internal/clock/now.go

@@ -1,16 +1,14 @@
-// Package clock provides indirection for accessing current time.
+// Package clock provides indirection for accessing current wall clock time.
+// this is suitable for timestamps and long-term time operations, not short-term time measurements.
 package clock
 
-import (
-	"time"
-)
+import "time"
 
-// Since returns time since the given timestamp.
-func Since(t time.Time) time.Duration {
-	return Now().Sub(t)
-}
-
-// Until returns duration of time between now and a given time.
-func Until(t time.Time) time.Duration {
-	return t.Sub(Now())
+// discardMonotonicTime discards any monotonic time component of time,
+// which behaves incorrectly when the computer goes to sleep and we want to measure durations
+// between points in time.
+//
+// See https://go.googlesource.com/proposal/+/master/design/12914-monotonic.md
+func discardMonotonicTime(t time.Time) time.Time {
+	return time.Unix(0, t.UnixNano())
 }

internal/clock/now_prod.go

@@ -7,5 +7,5 @@
 
 // Now returns current wall clock time.
 func Now() time.Time {
-	return time.Now() // nolint:forbidigo
+	return discardMonotonicTime(time.Now()) // nolint:forbidigo
 }

internal/clock/now_testing.go

@@ -15,7 +15,9 @@
 const refreshServerTimeEvery = 3 * time.Second
 
 // Now is overridable function that returns current wall clock time.
-var Now = time.Now // nolint:forbidigo
+var Now = func() time.Time {
+	return discardMonotonicTime(time.Now()) // nolint:forbidigo
+}
 
 func init() {
 	fakeTimeServer := os.Getenv("KOPIA_FAKE_CLOCK_ENDPOINT")
@@ -71,6 +73,6 @@ func getTimeFromServer(endpoint string) func() time.Time {
 			localTimeOffset = timeInfo.Time.Sub(localTime)
 		}
 
-		return localTime.Add(localTimeOffset)
+		return discardMonotonicTime(localTime.Add(localTimeOffset))
 	}
 }

internal/server/source_manager.go

@@ -126,7 +126,7 @@ func (s *sourceManager) runLocal(ctx context.Context) {
 		var waitTime time.Duration
 
 		if s.nextSnapshotTime != nil {
-			waitTime = clock.Until(*s.nextSnapshotTime)
+			waitTime = s.nextSnapshotTime.Sub(clock.Now())
 		} else {
 			waitTime = oneDay
 		}

internal/timetrack/estimator.go

@@ -39,7 +39,7 @@ func (v Estimator) Estimate(completed, total float64) (Timings, bool) {
 		predictedSeconds := elapsed.Seconds() / completedRatio
 		predictedEndTime := v.startTime.Add(time.Duration(predictedSeconds) * time.Second)
 
-		dt := clock.Until(predictedEndTime).Truncate(time.Second)
+		dt := predictedEndTime.Sub(clock.Now()).Truncate(time.Second)
 		if dt < 0 {
 			dt = 0
 		}

internal/timetrack/timer.go

@@ -0,0 +1,21 @@
+// Package timetrack tracks the progress and estimates completion of a task.
+package timetrack
+
+import (
+	"time"
+)
+
+// Timer measures elapsed time of operations.
+type Timer struct {
+	startTime time.Time
+}
+
+// Elapsed returns time elapsed since the timer was started.
+func (t Timer) Elapsed() time.Duration {
+	return time.Since(t.startTime) // nolint:forbidigo
+}
+
+// StartTimer starts the timer.
+func StartTimer() Timer {
+	return Timer{time.Now()} // nolint:forbidigo
+}

internal/zaplogutil/zaplogutil.go

@@ -17,7 +17,7 @@ type theClock struct{
 func (c theClock) Now() time.Time                         { return clock.Now() }
 func (c theClock) NewTicker(d time.Duration) *time.Ticker { return time.NewTicker(d) }
 
-// Clock isn aimplementation of zapcore.Clock that uses clock.Now().
+// Clock is an implementation of zapcore.Clock that uses clock.Now().
 var Clock zapcore.Clock = theClock{}
 
 // TimezoneAdjust returns zapcore.TimeEncoder that adjusts the time to either UTC or local time before logging.

repo/blob/logging/logging_storage.go

@@ -5,8 +5,8 @@
 	"context"
 	"time"
 
-	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/gather"
+	"github.com/kopia/kopia/internal/timetrack"
 	"github.com/kopia/kopia/repo/blob"
 )
 
@@ -19,9 +19,9 @@ type loggingStorage struct {
 }
 
 func (s *loggingStorage) GetBlob(ctx context.Context, id blob.ID, offset, length int64, output *gather.WriteBuffer) error {
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 	err := s.base.GetBlob(ctx, id, offset, length, output)
-	dt := clock.Since(t0)
+	dt := timer.Elapsed()
 
 	if output.Length() < maxLoggedBlobLength {
 		s.printf(s.prefix+"GetBlob(%q,%v,%v)=(%v, %#v) took %v", id, offset, length, output, err, dt)
@@ -34,9 +34,9 @@ func (s *loggingStorage) GetBlob(ctx context.Context, id blob.ID, offset, length
 }
 
 func (s *loggingStorage) GetMetadata(ctx context.Context, id blob.ID) (blob.Metadata, error) {
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 	result, err := s.base.GetMetadata(ctx, id)
-	dt := clock.Since(t0)
+	dt := timer.Elapsed()
 
 	s.printf(s.prefix+"GetMetadata(%q)=(%v, %#v) took %v", id, result, err, dt)
 
@@ -45,9 +45,9 @@ func (s *loggingStorage) GetMetadata(ctx context.Context, id blob.ID) (blob.Meta
 }
 
 func (s *loggingStorage) PutBlob(ctx context.Context, id blob.ID, data blob.Bytes) error {
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 	err := s.base.PutBlob(ctx, id, data)
-	dt := clock.Since(t0)
+	dt := timer.Elapsed()
 	s.printf(s.prefix+"PutBlob(%q,len=%v)=%#v took %v", id, data.Length(), err, dt)
 
 	// nolint:wrapcheck
@@ -55,9 +55,9 @@ func (s *loggingStorage) PutBlob(ctx context.Context, id blob.ID, data blob.Byte
 }
 
 func (s *loggingStorage) SetTime(ctx context.Context, id blob.ID, t time.Time) error {
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 	err := s.base.SetTime(ctx, id, t)
-	dt := clock.Since(t0)
+	dt := timer.Elapsed()
 	s.printf(s.prefix+"SetTime(%q,%v)=%#v took %v", id, t, err, dt)
 
 	// nolint:wrapcheck
@@ -65,9 +65,9 @@ func (s *loggingStorage) SetTime(ctx context.Context, id blob.ID, t time.Time) e
 }
 
 func (s *loggingStorage) DeleteBlob(ctx context.Context, id blob.ID) error {
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 	err := s.base.DeleteBlob(ctx, id)
-	dt := clock.Since(t0)
+	dt := timer.Elapsed()
 	s.printf(s.prefix+"DeleteBlob(%q)=%#v took %v", id, err, dt)
 
 	// nolint:wrapcheck
@@ -75,22 +75,22 @@ func (s *loggingStorage) DeleteBlob(ctx context.Context, id blob.ID) error {
 }
 
 func (s *loggingStorage) ListBlobs(ctx context.Context, prefix blob.ID, callback func(blob.Metadata) error) error {
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 	cnt := 0
 	err := s.base.ListBlobs(ctx, prefix, func(bi blob.Metadata) error {
 		cnt++
 		return callback(bi)
 	})
-	s.printf(s.prefix+"ListBlobs(%q)=%v returned %v items and took %v", prefix, err, cnt, clock.Since(t0))
+	s.printf(s.prefix+"ListBlobs(%q)=%v returned %v items and took %v", prefix, err, cnt, timer.Elapsed())
 
 	// nolint:wrapcheck
 	return err
 }
 
 func (s *loggingStorage) Close(ctx context.Context) error {
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 	err := s.base.Close(ctx)
-	dt := clock.Since(t0)
+	dt := timer.Elapsed()
 	s.printf(s.prefix+"Close()=%#v took %v", err, dt)
 
 	// nolint:wrapcheck
@@ -106,9 +106,9 @@ func (s *loggingStorage) DisplayName() string {
 }
 
 func (s *loggingStorage) FlushCaches(ctx context.Context) error {
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 	err := s.base.FlushCaches(ctx)
-	dt := clock.Since(t0)
+	dt := timer.Elapsed()
 	s.printf(s.prefix+"FlushCaches()=%#v took %v", err, dt)
 
 	// nolint:wrapcheck

repo/blob/rclone/rclone_storage_test.go

@@ -257,9 +257,10 @@ func cleanupOldData(ctx context.Context, t *testing.T, opt *rclone.Options, clea
 func cleanupAllBlobs(ctx context.Context, t *testing.T, st blob.Storage, cleanupAge time.Duration) {
 	t.Helper()
 
+	now := clock.Now()
+
 	_ = st.ListBlobs(ctx, "", func(it blob.Metadata) error {
-		age := clock.Since(it.Timestamp)
-		if age > cleanupAge {
+		if age := now.Sub(it.Timestamp); age > cleanupAge {
 			if err := st.DeleteBlob(ctx, it.BlobID); err != nil {
 				t.Errorf("warning: unable to delete %q: %v", it.BlobID, err)
 			}

repo/blob/s3/s3_storage_test.go

@@ -21,11 +21,11 @@
 	"github.com/stretchr/testify/require"
 
 	"github.com/kopia/kopia/internal/blobtesting"
-	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/gather"
 	"github.com/kopia/kopia/internal/providervalidation"
 	"github.com/kopia/kopia/internal/testlogging"
 	"github.com/kopia/kopia/internal/testutil"
+	"github.com/kopia/kopia/internal/timetrack"
 	"github.com/kopia/kopia/repo/blob"
 )
 
@@ -205,7 +205,7 @@ func TestInvalidCredsFailsFast(t *testing.T) {
 
 	ctx := testlogging.Context(t)
 
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 
 	_, err := New(ctx, &Options{
 		Endpoint:        minioEndpoint,
@@ -218,7 +218,8 @@ func TestInvalidCredsFailsFast(t *testing.T) {
 	})
 	require.Error(t, err)
 
-	if dt := clock.Since(t0); dt > 10*time.Second {
+	// nolint:forbidigo
+	if dt := timer.Elapsed(); dt > 10*time.Second {
 		t.Fatalf("opening storage took too long, probably due to retries")
 	}
 }

repo/blob/sftp/sftp_storage_test.go

@@ -21,6 +21,7 @@
 	"github.com/kopia/kopia/internal/providervalidation"
 	"github.com/kopia/kopia/internal/testlogging"
 	"github.com/kopia/kopia/internal/testutil"
+	"github.com/kopia/kopia/internal/timetrack"
 	"github.com/kopia/kopia/repo/blob"
 	"github.com/kopia/kopia/repo/blob/sftp"
 )
@@ -250,7 +251,7 @@ func TestInvalidServerFailsFast(t *testing.T) {
 	mustRunCommand(t, "ssh-keygen", "-t", "rsa", "-P", "", "-f", idRSA)
 	os.WriteFile(knownHostsFile, nil, 0o600)
 
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 
 	if _, err := createSFTPStorage(ctx, t, sftp.Options{
 		Path:           "/upload",
@@ -263,7 +264,8 @@ func TestInvalidServerFailsFast(t *testing.T) {
 		t.Fatalf("unexpected success with bad credentials")
 	}
 
-	if dt := clock.Since(t0); dt > 10*time.Second {
+	// nolint:forbidigo
+	if dt := timer.Elapsed(); dt > 10*time.Second {
 		t.Fatalf("opening storage took too long, probably due to retries")
 	}
 }

repo/content/content_manager_indexes.go

@@ -6,8 +6,8 @@
 
 	"github.com/pkg/errors"
 
-	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/gather"
+	"github.com/kopia/kopia/internal/timetrack"
 	"github.com/kopia/kopia/repo/blob"
 )
 
@@ -39,10 +39,10 @@ func (sm *SharedManager) Refresh(ctx context.Context) error {
 
 	sm.indexBlobManager.invalidate(ctx)
 
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 
 	err := sm.loadPackIndexesLocked(ctx)
-	sm.log.Debugf("Refresh completed in %v", clock.Since(t0))
+	sm.log.Debugf("Refresh completed in %v", timer.Elapsed())
 
 	return err
 }

repo/maintenance/maintenance_run.go

@@ -301,7 +301,7 @@ func notRewritingContents(ctx context.Context) {
 }
 
 func notDeletingOrphanedBlobs(ctx context.Context, s *Schedule, safety SafetyParameters) {
-	left := clock.Until(nextBlobDeleteTime(s, safety)).Truncate(time.Second)
+	left := nextBlobDeleteTime(s, safety).Sub(clock.Now()).Truncate(time.Second)
 
 	log(ctx).Infof("Skipping blob deletion because not enough time has passed yet (%v left).", left)
 }

repo/open.go

@@ -307,7 +307,7 @@ func readFormatBlobBytesFromCache(ctx context.Context, cachedFile string, validD
 		return nil, errors.Wrap(err, "unable to open cache file")
 	}
 
-	if clock.Since(cst.ModTime()) > validDuration {
+	if clock.Now().Sub(cst.ModTime()) > validDuration {
 		// got cached file, but it's too old, remove it
 		if err := os.Remove(cachedFile); err != nil {
 			log(ctx).Debugf("unable to remove cache file: %v", err)

tests/end_to_end_test/api_server_repository_test.go

@@ -8,10 +8,10 @@
 	"time"
 
 	"github.com/kopia/kopia/internal/apiclient"
-	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/serverapi"
 	"github.com/kopia/kopia/internal/testlogging"
 	"github.com/kopia/kopia/internal/testutil"
+	"github.com/kopia/kopia/internal/timetrack"
 	"github.com/kopia/kopia/repo"
 	"github.com/kopia/kopia/repo/blob"
 	"github.com/kopia/kopia/tests/clitestutil"
@@ -264,7 +264,7 @@ func testAPIServerRepository(t *testing.T, serverStartArgs []string, useGRPC, al
 	logErrorAndIgnore(t, serverapi.Shutdown(ctx, uiUserCLI))
 
 	// open repository client to a dead server, this should fail quickly instead of retrying forever.
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 
 	repo.OpenAPIServer(ctx, &repo.APIServerInfo{
 		BaseURL:                             sp.baseURL,
@@ -275,7 +275,8 @@ func testAPIServerRepository(t *testing.T, serverStartArgs []string, useGRPC, al
 		Hostname: "bar",
 	}, nil, "baz")
 
-	if dur := clock.Since(t0); dur > 15*time.Second {
+	// nolint:forbidigo
+	if dur := timer.Elapsed(); dur > 15*time.Second {
 		t.Fatalf("failed connection took %v", dur)
 	}
 }

tests/end_to_end_test/snapshot_actions_test.go

@@ -11,8 +11,8 @@
 
 	"github.com/stretchr/testify/require"
 
-	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/testutil"
+	"github.com/kopia/kopia/internal/timetrack"
 	"github.com/kopia/kopia/snapshot"
 	"github.com/kopia/kopia/tests/clitestutil"
 	"github.com/kopia/kopia/tests/testenv"
@@ -94,13 +94,13 @@ func TestSnapshotActionsBeforeSnapshotRoot(t *testing.T) {
 		th+" --exit-code=3 --sleep=30s",
 		"--action-command-mode=async")
 
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 
 	// at this point the data is all cached so this will be quick, definitely less than 30s,
 	// async action failure will not prevent snapshot success.
 	e.RunAndExpectSuccess(t, "snapshot", "create", sharedTestDataDir1)
 
-	if dur := clock.Since(t0); dur > 30*time.Second {
+	if dur := timer.Elapsed(); dur > 30*time.Second {
 		t.Errorf("command did not execute asynchronously (took %v)", dur)
 	}
 
@@ -111,12 +111,11 @@ func TestSnapshotActionsBeforeSnapshotRoot(t *testing.T) {
 		th+" --sleep=30s",
 		"--action-command-timeout=3s")
 
-	t0 = clock.Now()
-
+	timer = timetrack.StartTimer()
 	// the action will be killed after 3s and cause a failure.
 	e.RunAndExpectFailure(t, "snapshot", "create", sharedTestDataDir1)
 
-	if dur := clock.Since(t0); dur > 30*time.Second {
+	if dur := timer.Elapsed(); dur > 30*time.Second {
 		t.Errorf("command did not apply timeout (took %v)", dur)
 	}
 

tests/robustness/engine/engine.go

@@ -129,7 +129,7 @@ func (e *Engine) Shutdown(ctx context.Context) error {
 
 	log.Print(cleanupSummaryBuilder.String())
 
-	e.RunStats.RunTime = clock.Since(e.RunStats.CreationTime)
+	e.RunStats.RunTime = clock.Now().Sub(e.RunStats.CreationTime)
 	e.CumulativeStats.RunTime += e.RunStats.RunTime
 
 	defer e.cleanComponents()

tests/robustness/engine/stats.go

@@ -116,7 +116,7 @@ func (s *ActionStats) AverageRuntime() time.Duration {
 // Record records the current time against the provided start time
 // and updates the stats accordingly.
 func (s *ActionStats) Record(st time.Time, err error) {
-	thisRuntime := clock.Since(st)
+	thisRuntime := clock.Now().Sub(st)
 	s.TotalRuntime += thisRuntime
 
 	if thisRuntime > s.MaxRuntime {
@@ -135,7 +135,7 @@ func (s *ActionStats) Record(st time.Time, err error) {
 }
 
 func (stats *Stats) getLifetimeSeconds() int64 {
-	return durationToSec(clock.Since(stats.CreationTime))
+	return durationToSec(clock.Now().Sub(stats.CreationTime))
 }
 
 func durationToSec(dur time.Duration) int64 {
@@ -155,7 +155,7 @@ func (e *Engine) getTimestampS() int64 {
 }
 
 func (e *Engine) getRuntimeSeconds() int64 {
-	return durationToSec(e.CumulativeStats.RunTime + clock.Since(e.RunStats.CreationTime))
+	return durationToSec(e.CumulativeStats.RunTime + clock.Now().Sub(e.RunStats.CreationTime))
 }
 
 type statsUpdatetype int

tests/robustness/multiclient_test/multiclient_test.go

@@ -14,8 +14,8 @@
 
 	"github.com/stretchr/testify/require"
 
-	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/testlogging"
+	"github.com/kopia/kopia/internal/timetrack"
 	"github.com/kopia/kopia/tests/robustness"
 	"github.com/kopia/kopia/tests/robustness/engine"
 	"github.com/kopia/kopia/tests/robustness/fiofilewriter"
@@ -124,7 +124,7 @@ func TestManySmallFilesAcrossDirecoryTree(t *testing.T) {
 
 func TestRandomizedSmall(t *testing.T) {
 	numClients := 4
-	st := clock.Now()
+	st := timetrack.StartTimer()
 
 	opts := engine.ActionOpts{
 		engine.ActionControlActionKey: map[string]string{
@@ -146,7 +146,8 @@ func TestRandomizedSmall(t *testing.T) {
 		err := tryRestoreIntoDataDirectory(ctx, t)
 		require.NoError(t, err)
 
-		for clock.Since(st) <= *randomizedTestDur {
+		// nolint:forbidigo
+		for st.Elapsed() <= *randomizedTestDur {
 			err := tryRandomAction(ctx, t, opts)
 			require.NoError(t, err)
 		}

tests/robustness/robustness_test/robustness_test.go

@@ -11,8 +11,8 @@
 
 	"github.com/stretchr/testify/require"
 
-	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/testlogging"
+	"github.com/kopia/kopia/internal/timetrack"
 	"github.com/kopia/kopia/tests/robustness"
 	"github.com/kopia/kopia/tests/robustness/engine"
 	"github.com/kopia/kopia/tests/robustness/fiofilewriter"
@@ -95,7 +95,7 @@ func TestManySmallFilesAcrossDirecoryTree(t *testing.T) {
 }
 
 func TestRandomizedSmall(t *testing.T) {
-	st := clock.Now()
+	st := timetrack.StartTimer()
 
 	opts := engine.ActionOpts{
 		engine.ActionControlActionKey: map[string]string{
@@ -114,7 +114,8 @@ func TestRandomizedSmall(t *testing.T) {
 	}
 
 	ctx := testlogging.ContextWithLevel(t, testlogging.LevelInfo)
-	for clock.Since(st) <= *randomizedTestDur {
+
+	for st.Elapsed() <= *randomizedTestDur {
 		err := eng.RandomAction(ctx, opts)
 		if errors.Is(err, robustness.ErrNoOp) {
 			t.Log("Random action resulted in no-op")

tests/testenv/cli_test_env.go

@@ -16,6 +16,7 @@
 
 	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/testutil"
+	"github.com/kopia/kopia/internal/timetrack"
 )
 
 const (
@@ -177,7 +178,7 @@ func (e *CLITest) Run(t *testing.T, expectedError bool, args ...string) (stdout,
 	args = e.cmdArgs(args)
 	t.Logf("running 'kopia %v'", strings.Join(args, " "))
 
-	t0 := clock.Now()
+	timer := timetrack.StartTimer()
 
 	stdoutReader, stderrReader, wait, _ := e.Runner.Start(t, args)
 
@@ -223,7 +224,8 @@ func (e *CLITest) Run(t *testing.T, expectedError bool, args ...string) (stdout,
 		require.NoError(t, gotErr, "unexpected error when running 'kopia %v' (stdout:\n%v\nstderr:\n%v", strings.Join(args, " "), strings.Join(stdout, "\n"), strings.Join(stderr, "\n"))
 	}
 
-	t.Logf("finished in %v: 'kopia %v'", clock.Since(t0).Milliseconds(), strings.Join(args, " "))
+	// nolint:forbidigo
+	t.Logf("finished in %v: 'kopia %v'", timer.Elapsed().Milliseconds(), strings.Join(args, " "))
 
 	return stdout, stderr, gotErr
 }