all: Add Prometheus-style metrics to expose some internal performance counters (fixes #5175) (#9003)

lib/model/folder.go

@@ -137,6 +137,9 @@ func newFolder(model *model, fset *db.FileSet, ignores *ignore.Matcher, cfg conf
 	f.pullPause = f.pullBasePause()
 	f.pullFailTimer = time.NewTimer(0)
 	<-f.pullFailTimer.C
+
+	registerFolderMetrics(f.ID)
+
 	return f
 }
 
@@ -459,6 +462,11 @@ func (f *folder) scanSubdirs(subDirs []string) error {
 	}
 	defer f.ioLimiter.Give(1)
 
+	metricFolderScans.WithLabelValues(f.ID).Inc()
+	ctx, cancel := context.WithCancel(f.ctx)
+	defer cancel()
+	go addTimeUntilCancelled(ctx, metricFolderScanSeconds.WithLabelValues(f.ID))
+
 	for i := range subDirs {
 		sub := osutil.NativeFilename(subDirs[i])
 

lib/model/folder_sendrecv.go

@@ -8,6 +8,7 @@ package model
 
 import (
 	"bytes"
+	"context"
 	"errors"
 	"fmt"
 	"io"
@@ -162,11 +163,12 @@ func (f *sendReceiveFolder) pull() (bool, error) {
 
 	scanChan := make(chan string)
 	go f.pullScannerRoutine(scanChan)
+	defer close(scanChan)
 
-	defer func() {
-		close(scanChan)
-		f.setState(FolderIdle)
-	}()
+	metricFolderPulls.WithLabelValues(f.ID).Inc()
+	ctx, cancel := context.WithCancel(f.ctx)
+	defer cancel()
+	go addTimeUntilCancelled(ctx, metricFolderPullSeconds.WithLabelValues(f.ID))
 
 	changed := 0
 
@@ -573,9 +575,9 @@ func (f *sendReceiveFolder) handleDir(file protocol.FileInfo, snap *db.Snapshot,
 		})
 	}()
 
-	mode := fs.FileMode(file.Permissions & 0777)
+	mode := fs.FileMode(file.Permissions & 0o777)
 	if f.IgnorePerms || file.NoPermissions {
-		mode = 0777
+		mode = 0o777
 	}
 
 	if shouldDebug() {
@@ -705,7 +707,7 @@ func (f *sendReceiveFolder) checkParent(file string, scanChan chan<- string) boo
 		return true
 	}
 	l.Debugf("%v creating parent directory of %v", f, file)
-	if err := f.mtimefs.MkdirAll(parent, 0755); err != nil {
+	if err := f.mtimefs.MkdirAll(parent, 0o755); err != nil {
 		f.newPullError(file, fmt.Errorf("creating parent dir: %w", err))
 		return false
 	}
@@ -1136,12 +1138,12 @@ func (f *sendReceiveFolder) handleFile(file protocol.FileInfo, snap *db.Snapshot
 func (f *sendReceiveFolder) reuseBlocks(blocks []protocol.BlockInfo, reused []int, file protocol.FileInfo, tempName string) ([]protocol.BlockInfo, []int) {
 	// Check for an old temporary file which might have some blocks we could
 	// reuse.
-	tempBlocks, err := scanner.HashFile(f.ctx, f.mtimefs, tempName, file.BlockSize(), nil, false)
+	tempBlocks, err := scanner.HashFile(f.ctx, f.ID, f.mtimefs, tempName, file.BlockSize(), nil, false)
 	if err != nil {
 		var caseErr *fs.ErrCaseConflict
 		if errors.As(err, &caseErr) {
 			if rerr := f.mtimefs.Rename(caseErr.Real, tempName); rerr == nil {
-				tempBlocks, err = scanner.HashFile(f.ctx, f.mtimefs, tempName, file.BlockSize(), nil, false)
+				tempBlocks, err = scanner.HashFile(f.ctx, f.ID, f.mtimefs, tempName, file.BlockSize(), nil, false)
 			}
 		}
 	}
@@ -1235,7 +1237,7 @@ func (f *sendReceiveFolder) shortcutFile(file protocol.FileInfo, dbUpdateChan ch
 	f.queue.Done(file.Name)
 
 	if !f.IgnorePerms && !file.NoPermissions {
-		if err = f.mtimefs.Chmod(file.Name, fs.FileMode(file.Permissions&0777)); err != nil {
+		if err = f.mtimefs.Chmod(file.Name, fs.FileMode(file.Permissions&0o777)); err != nil {
 			f.newPullError(file.Name, fmt.Errorf("shortcut file (setting permissions): %w", err))
 			return
 		}
@@ -1249,7 +1251,7 @@ func (f *sendReceiveFolder) shortcutFile(file protocol.FileInfo, dbUpdateChan ch
 	// Still need to re-write the trailer with the new encrypted fileinfo.
 	if f.Type == config.FolderTypeReceiveEncrypted {
 		err = inWritableDir(func(path string) error {
-			fd, err := f.mtimefs.OpenFile(path, fs.OptReadWrite, 0666)
+			fd, err := f.mtimefs.OpenFile(path, fs.OptReadWrite, 0o666)
 			if err != nil {
 				return err
 			}
@@ -1329,7 +1331,7 @@ func (f *sendReceiveFolder) copierRoutine(in <-chan copyBlocksState, pullChan ch
 				// block of all zeroes, so then we should not skip it.
 
 				// Pretend we copied it.
-				state.copiedFromOrigin()
+				state.skippedSparseBlock(block.Size)
 				state.copyDone(block)
 				continue
 			}
@@ -1348,9 +1350,9 @@ func (f *sendReceiveFolder) copierRoutine(in <-chan copyBlocksState, pullChan ch
 						state.fail(fmt.Errorf("dst write: %w", err))
 					}
 					if offset == block.Offset {
-						state.copiedFromOrigin()
+						state.copiedFromOrigin(block.Size)
 					} else {
-						state.copiedFromOriginShifted()
+						state.copiedFromOriginShifted(block.Size)
 					}
 
 					return false
@@ -1398,7 +1400,9 @@ func (f *sendReceiveFolder) copierRoutine(in <-chan copyBlocksState, pullChan ch
 						state.fail(fmt.Errorf("dst write: %w", err))
 					}
 					if path == state.file.Name {
-						state.copiedFromOrigin()
+						state.copiedFromOrigin(block.Size)
+					} else {
+						state.copiedFromElsewhere(block.Size)
 					}
 					return true
 				})
@@ -1608,7 +1612,7 @@ loop:
 func (f *sendReceiveFolder) performFinish(file, curFile protocol.FileInfo, hasCurFile bool, tempName string, snap *db.Snapshot, dbUpdateChan chan<- dbUpdateJob, scanChan chan<- string) error {
 	// Set the correct permission bits on the new file
 	if !f.IgnorePerms && !file.NoPermissions {
-		if err := f.mtimefs.Chmod(tempName, fs.FileMode(file.Permissions&0777)); err != nil {
+		if err := f.mtimefs.Chmod(tempName, fs.FileMode(file.Permissions&0o777)); err != nil {
 			return fmt.Errorf("setting permissions: %w", err)
 		}
 	}

lib/model/folder_sendrecv_test.go

@@ -299,7 +299,7 @@ func TestCopierFinder(t *testing.T) {
 	}
 
 	// Verify that the fetched blocks have actually been written to the temp file
-	blks, err := scanner.HashFile(context.TODO(), f.Filesystem(nil), tempFile, protocol.MinBlockSize, nil, false)
+	blks, err := scanner.HashFile(context.TODO(), f.ID, f.Filesystem(nil), tempFile, protocol.MinBlockSize, nil, false)
 	if err != nil {
 		t.Log(err)
 	}

lib/model/folder_summary.go

@@ -396,6 +396,24 @@ func (c *folderSummaryService) sendSummary(ctx context.Context, folder string) {
 		Summary: data,
 	})
 
+	metricFolderSummary.WithLabelValues(folder, metricScopeGlobal, metricTypeFiles).Set(float64(data.GlobalFiles))
+	metricFolderSummary.WithLabelValues(folder, metricScopeGlobal, metricTypeDirectories).Set(float64(data.GlobalDirectories))
+	metricFolderSummary.WithLabelValues(folder, metricScopeGlobal, metricTypeSymlinks).Set(float64(data.GlobalSymlinks))
+	metricFolderSummary.WithLabelValues(folder, metricScopeGlobal, metricTypeDeleted).Set(float64(data.GlobalDeleted))
+	metricFolderSummary.WithLabelValues(folder, metricScopeGlobal, metricTypeBytes).Set(float64(data.GlobalBytes))
+
+	metricFolderSummary.WithLabelValues(folder, metricScopeLocal, metricTypeFiles).Set(float64(data.LocalFiles))
+	metricFolderSummary.WithLabelValues(folder, metricScopeLocal, metricTypeDirectories).Set(float64(data.LocalDirectories))
+	metricFolderSummary.WithLabelValues(folder, metricScopeLocal, metricTypeSymlinks).Set(float64(data.LocalSymlinks))
+	metricFolderSummary.WithLabelValues(folder, metricScopeLocal, metricTypeDeleted).Set(float64(data.LocalDeleted))
+	metricFolderSummary.WithLabelValues(folder, metricScopeLocal, metricTypeBytes).Set(float64(data.LocalBytes))
+
+	metricFolderSummary.WithLabelValues(folder, metricScopeNeed, metricTypeFiles).Set(float64(data.NeedFiles))
+	metricFolderSummary.WithLabelValues(folder, metricScopeNeed, metricTypeDirectories).Set(float64(data.NeedDirectories))
+	metricFolderSummary.WithLabelValues(folder, metricScopeNeed, metricTypeSymlinks).Set(float64(data.NeedSymlinks))
+	metricFolderSummary.WithLabelValues(folder, metricScopeNeed, metricTypeDeleted).Set(float64(data.NeedDeletes))
+	metricFolderSummary.WithLabelValues(folder, metricScopeNeed, metricTypeBytes).Set(float64(data.NeedBytes))
+
 	for _, devCfg := range c.cfg.Folders()[folder].Devices {
 		select {
 		case <-ctx.Done():

lib/model/folderstate.go

@@ -111,6 +111,10 @@ func (s *stateTracker) setState(newState folderState) {
 		return
 	}
 
+	defer func() {
+		metricFolderState.WithLabelValues(s.folderID).Set(float64(s.current))
+	}()
+
 	/* This should hold later...
 	if s.current != FolderIdle && (newState == FolderScanning || newState == FolderSyncing) {
 		panic("illegal state transition " + s.current.String() + " -> " + newState.String())
@@ -148,6 +152,10 @@ func (s *stateTracker) setError(err error) {
 	s.mut.Lock()
 	defer s.mut.Unlock()
 
+	defer func() {
+		metricFolderState.WithLabelValues(s.folderID).Set(float64(s.current))
+	}()
+
 	eventData := map[string]interface{}{
 		"folder": s.folderID,
 		"from":   s.current.String(),

lib/model/metrics.go

@@ -0,0 +1,93 @@
+// Copyright (C) 2023 The Syncthing Authors.
+//
+// This Source Code Form is subject to the terms of the Mozilla Public
+// License, v. 2.0. If a copy of the MPL was not distributed with this file,
+// You can obtain one at https://mozilla.org/MPL/2.0/.
+
+package model
+
+import (
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/promauto"
+)
+
+var (
+	metricFolderState = promauto.NewGaugeVec(prometheus.GaugeOpts{
+		Namespace: "syncthing",
+		Subsystem: "model",
+		Name:      "folder_state",
+		Help:      "Current folder state",
+	}, []string{"folder"})
+	metricFolderSummary = promauto.NewGaugeVec(prometheus.GaugeOpts{
+		Namespace: "syncthing",
+		Subsystem: "model",
+		Name:      "folder_summary",
+		Help:      "Current folder summary data (counts for global/local/need files/directories/symlinks/deleted/bytes)",
+	}, []string{"folder", "scope", "type"})
+
+	metricFolderPulls = promauto.NewCounterVec(prometheus.CounterOpts{
+		Namespace: "syncthing",
+		Subsystem: "model",
+		Name:      "folder_pulls_total",
+		Help:      "Total number of folder pull iterations, per folder ID",
+	}, []string{"folder"})
+	metricFolderPullSeconds = promauto.NewCounterVec(prometheus.CounterOpts{
+		Namespace: "syncthing",
+		Subsystem: "model",
+		Name:      "folder_pull_seconds_total",
+		Help:      "Total time spent in folder pull iterations, per folder ID",
+	}, []string{"folder"})
+
+	metricFolderScans = promauto.NewCounterVec(prometheus.CounterOpts{
+		Namespace: "syncthing",
+		Subsystem: "model",
+		Name:      "folder_scans_total",
+		Help:      "Total number of folder scan iterations, per folder ID",
+	}, []string{"folder"})
+	metricFolderScanSeconds = promauto.NewCounterVec(prometheus.CounterOpts{
+		Namespace: "syncthing",
+		Subsystem: "model",
+		Name:      "folder_scan_seconds_total",
+		Help:      "Total time spent in folder scan iterations, per folder ID",
+	}, []string{"folder"})
+
+	metricFolderProcessedBytesTotal = promauto.NewCounterVec(prometheus.CounterOpts{
+		Namespace: "syncthing",
+		Subsystem: "model",
+		Name:      "folder_processed_bytes_total",
+		Help:      "Total amount of data processed during folder syncing, per folder ID and data source (network/local_origin/local_other/local_shifted/skipped)",
+	}, []string{"folder", "source"})
+)
+
+const (
+	metricSourceNetwork      = "network"       // from the network
+	metricSourceLocalOrigin  = "local_origin"  // from the existing version of the local file
+	metricSourceLocalOther   = "local_other"   // from a different local file
+	metricSourceLocalShifted = "local_shifted" // from the existing version of the local file, rolling hash shifted
+	metricSourceSkipped      = "skipped"       // block of all zeroes, invented out of thin air
+
+	metricScopeGlobal = "global"
+	metricScopeLocal  = "local"
+	metricScopeNeed   = "need"
+
+	metricTypeFiles       = "files"
+	metricTypeDirectories = "directories"
+	metricTypeSymlinks    = "symlinks"
+	metricTypeDeleted     = "deleted"
+	metricTypeBytes       = "bytes"
+)
+
+func registerFolderMetrics(folderID string) {
+	// Register metrics for this folder, so that counters are present even
+	// when zero.
+	metricFolderState.WithLabelValues(folderID)
+	metricFolderPulls.WithLabelValues(folderID)
+	metricFolderPullSeconds.WithLabelValues(folderID)
+	metricFolderScans.WithLabelValues(folderID)
+	metricFolderScanSeconds.WithLabelValues(folderID)
+	metricFolderProcessedBytesTotal.WithLabelValues(folderID, metricSourceNetwork)
+	metricFolderProcessedBytesTotal.WithLabelValues(folderID, metricSourceLocalOrigin)
+	metricFolderProcessedBytesTotal.WithLabelValues(folderID, metricSourceLocalOther)
+	metricFolderProcessedBytesTotal.WithLabelValues(folderID, metricSourceLocalShifted)
+	metricFolderProcessedBytesTotal.WithLabelValues(folderID, metricSourceSkipped)
+}

lib/model/progressemitter_test.go

@@ -91,7 +91,7 @@ func TestProgressEmitter(t *testing.T) {
 	expectEvent(w, t, 1)
 	expectTimeout(w, t)
 
-	s.copiedFromOrigin()
+	s.copiedFromOrigin(1)
 
 	expectEvent(w, t, 1)
 	expectTimeout(w, t)

lib/model/sharedpullerstate.go

@@ -152,11 +152,11 @@ func (s *sharedPullerState) tempFileInWritableDir(_ string) error {
 	// permissions will be set to the final value later, but in the meantime
 	// we don't want to have a temporary file with looser permissions than
 	// the final outcome.
-	mode := fs.FileMode(s.file.Permissions) | 0600
+	mode := fs.FileMode(s.file.Permissions) | 0o600
 	if s.ignorePerms {
 		// When ignorePerms is set we use a very permissive mode and let the
 		// system umask filter it.
-		mode = 0666
+		mode = 0o666
 	}
 
 	// Attempt to create the temp file
@@ -261,19 +261,34 @@ func (s *sharedPullerState) copyDone(block protocol.BlockInfo) {
 	s.mut.Unlock()
 }
 
-func (s *sharedPullerState) copiedFromOrigin() {
+func (s *sharedPullerState) copiedFromOrigin(bytes int) {
 	s.mut.Lock()
 	s.copyOrigin++
 	s.updated = time.Now()
 	s.mut.Unlock()
+	metricFolderProcessedBytesTotal.WithLabelValues(s.folder, metricSourceLocalOrigin).Add(float64(bytes))
 }
 
-func (s *sharedPullerState) copiedFromOriginShifted() {
+func (s *sharedPullerState) copiedFromElsewhere(bytes int) {
+	metricFolderProcessedBytesTotal.WithLabelValues(s.folder, metricSourceLocalOther).Add(float64(bytes))
+}
+
+func (s *sharedPullerState) skippedSparseBlock(bytes int) {
+	// pretend we copied it, historical
+	s.mut.Lock()
+	s.copyOrigin++
+	s.updated = time.Now()
+	s.mut.Unlock()
+	metricFolderProcessedBytesTotal.WithLabelValues(s.folder, metricSourceSkipped).Add(float64(bytes))
+}
+
+func (s *sharedPullerState) copiedFromOriginShifted(bytes int) {
 	s.mut.Lock()
 	s.copyOrigin++
 	s.copyOriginShifted++
 	s.updated = time.Now()
 	s.mut.Unlock()
+	metricFolderProcessedBytesTotal.WithLabelValues(s.folder, metricSourceLocalShifted).Add(float64(bytes))
 }
 
 func (s *sharedPullerState) pullStarted() {
@@ -295,6 +310,7 @@ func (s *sharedPullerState) pullDone(block protocol.BlockInfo) {
 	s.availableUpdated = time.Now()
 	l.Debugln("sharedPullerState", s.folder, s.file.Name, "pullNeeded done ->", s.pullNeeded)
 	s.mut.Unlock()
+	metricFolderProcessedBytesTotal.WithLabelValues(s.folder, metricSourceNetwork).Add(float64(block.Size))
 }
 
 // finalClose atomically closes and returns closed status of a file. A true

lib/model/util.go

@@ -7,6 +7,7 @@
 package model
 
 import (
+	"context"
 	"errors"
 	"fmt"
 	"path/filepath"
@@ -14,6 +15,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/prometheus/client_golang/prometheus"
 	"github.com/syncthing/syncthing/lib/events"
 	"github.com/syncthing/syncthing/lib/fs"
 	"github.com/syncthing/syncthing/lib/ur"
@@ -117,11 +119,11 @@ func inWritableDir(fn func(string) error, targetFs fs.Filesystem, path string, i
 
 	const permBits = fs.ModePerm | fs.ModeSetuid | fs.ModeSetgid | fs.ModeSticky
 	var parentErr error
-	if mode := info.Mode() & permBits; mode&0200 == 0 {
+	if mode := info.Mode() & permBits; mode&0o200 == 0 {
 		// A non-writeable directory (for this user; we assume that's the
 		// relevant part). Temporarily change the mode so we can delete the
 		// file or directory inside it.
-		parentErr = targetFs.Chmod(dir, mode|0700)
+		parentErr = targetFs.Chmod(dir, mode|0o700)
 		if parentErr != nil {
 			l.Debugf("Failed to make parent directory writable: %v", parentErr)
 		} else {
@@ -148,3 +150,27 @@ func inWritableDir(fn func(string) error, targetFs fs.Filesystem, path string, i
 	}
 	return err
 }
+
+// addTimeUntilCancelled adds time to the counter for the duration of the
+// Context. We do this piecemeal so that polling the counter during a long
+// operation shows a relevant value, instead of the counter just increasing
+// by a large amount at the end of the operation.
+func addTimeUntilCancelled(ctx context.Context, counter prometheus.Counter) {
+	t0 := time.Now()
+	defer func() {
+		counter.Add(time.Since(t0).Seconds())
+	}()
+
+	ticker := time.NewTicker(time.Second)
+	defer ticker.Stop()
+
+	for {
+		select {
+		case t := <-ticker.C:
+			counter.Add(t.Sub(t0).Seconds())
+			t0 = t
+		case <-ctx.Done():
+			return
+		}
+	}
+}