From 5711f0e38c69ddbbfb5604a44a5098a6a04d7dcb Mon Sep 17 00:00:00 2001 From: Riccardo Manfrin <3090891+riccardomanfrin@users.noreply.github.com> Date: Mon, 29 Jun 2026 11:02:02 +0200 Subject: [PATCH] [client] add per-phase timing metrics for sync processing (#6533) * Adds metrics sync phases time split to monitor costs * Address review fixes * Increment README.md with description on usage with debug bundles --- client/internal/engine.go | 119 +++++--- client/internal/metrics/influxdb.go | 24 ++ client/internal/metrics/infra/README.md | 69 ++++- .../dashboards/json/netbird-sync-phases.json | 259 ++++++++++++++++++ client/internal/metrics/infra/ingest/main.go | 13 + client/internal/metrics/metrics.go | 15 + client/internal/metrics/push_test.go | 3 + 7 files changed, 468 insertions(+), 34 deletions(-) create mode 100644 client/internal/metrics/infra/grafana/provisioning/dashboards/json/netbird-sync-phases.json diff --git a/client/internal/engine.go b/client/internal/engine.go index e7f1c0501..f7c7e1862 100644 --- a/client/internal/engine.go +++ b/client/internal/engine.go @@ -895,6 +895,16 @@ func (e *Engine) handleAutoUpdateVersion(autoUpdateSettings *mgmProto.AutoUpdate e.updateManager.SetVersion(autoUpdateSettings.Version, autoUpdateSettings.AlwaysUpdate) } +// phase times a sync sub-phase: it returns a function that records the elapsed +// duration when called. Starting the timer at the call site keeps inter-phase +// glue code out of the measurement. +func (e *Engine) phase(name string) func() { + start := time.Now() + return func() { + e.clientMetrics.RecordSyncPhase(e.ctx, name, time.Since(start)) + } +} + func (e *Engine) handleSync(update *mgmProto.SyncResponse) error { started := time.Now() defer func() { @@ -914,7 +924,10 @@ func (e *Engine) handleSync(update *mgmProto.SyncResponse) error { e.handleAutoUpdateVersion(update.NetworkMap.PeerConfig.AutoUpdate) } - if err := e.updateNetbirdConfig(update.GetNetbirdConfig()); err != nil { + done := e.phase("netbird_config") + err := e.updateNetbirdConfig(update.GetNetbirdConfig()) + done() + if err != nil { return err } @@ -928,11 +941,16 @@ func (e *Engine) handleSync(update *mgmProto.SyncResponse) error { return nil } - if err := e.updateChecksIfNew(update.Checks); err != nil { + done = e.phase("checks") + err = e.updateChecksIfNew(update.Checks) + done() + if err != nil { return err } + done = e.phase("persist") e.persistSyncResponse(update) + done() // only apply new changes and ignore old ones if err := e.updateNetworkMap(nm); err != nil { @@ -1371,13 +1389,16 @@ func (e *Engine) updateNetworkMap(networkMap *mgmProto.NetworkMap) error { dnsConfig := toDNSConfig(protoDNSConfig, e.wgInterface.Address()) + done := e.phase("dns_server") if err := e.dnsServer.UpdateDNSServer(serial, dnsConfig); err != nil { log.Errorf("failed to update dns server, err: %v", err) } + done() e.routeManager.SetDNSForwarderPort(dnsConfig.ForwarderPort) // apply routes first, route related actions might depend on routing being enabled + done = e.phase("routes_classify") routes := toRoutes(networkMap.GetRoutes()) serverRoutes, clientRoutes := e.routeManager.ClassifyRoutes(routes) @@ -1386,29 +1407,60 @@ func (e *Engine) updateNetworkMap(networkMap *mgmProto.NetworkMap) error { e.connMgr.UpdateRouteHAMap(clientRoutes) log.Debugf("updated lazy connection manager with %d HA groups", len(clientRoutes)) } + done() + done = e.phase("routes_apply") dnsRouteFeatureFlag := toDNSFeatureFlag(networkMap) if err := e.routeManager.UpdateRoutes(serial, serverRoutes, clientRoutes, dnsRouteFeatureFlag); err != nil { log.Errorf("failed to update routes: %v", err) } + done() + done = e.phase("filtering") if e.acl != nil { e.acl.ApplyFiltering(networkMap, dnsRouteFeatureFlag) } + done() + done = e.phase("dns_forwarder") fwdEntries := toRouteDomains(e.config.WgPrivateKey.PublicKey().String(), routes) e.updateDNSForwarder(dnsRouteFeatureFlag, fwdEntries) + done() // Ingress forward rules + done = e.phase("forward_rules") forwardingRules, err := e.updateForwardRules(networkMap.GetForwardingRules()) if err != nil { log.Errorf("failed to update forward rules, err: %v", err) } + done() log.Debugf("got peers update from Management Service, total peers to connect to = %d", len(networkMap.GetRemotePeers())) + done = e.phase("offline_peers") e.updateOfflinePeers(networkMap.GetOfflinePeers()) + done() + remotePeers, err := e.reconcilePeers(networkMap) + if err != nil { + return err + } + + // must set the exclude list after the peers are added. Without it the manager can not figure out the peers parameters from the store + done = e.phase("lazy_exclude") + excludedLazyPeers := e.toExcludedLazyPeers(forwardingRules, remotePeers) + e.connMgr.SetExcludeList(e.ctx, excludedLazyPeers) + done() + + e.networkSerial = serial + + return nil +} + +// reconcilePeers applies the remote peer list from the network map (removing, +// modifying and adding peers, then updating SSH config) and returns the remote +// peers with our own peer filtered out, for use by later sync steps. +func (e *Engine) reconcilePeers(networkMap *mgmProto.NetworkMap) ([]*mgmProto.RemotePeerConfig, error) { // Filter out own peer from the remote peers list localPubKey := e.config.WgPrivateKey.PublicKey().String() remotePeers := make([]*mgmProto.RemotePeerConfig, 0, len(networkMap.GetRemotePeers())) @@ -1423,42 +1475,43 @@ func (e *Engine) updateNetworkMap(networkMap *mgmProto.NetworkMap) error { err := e.removeAllPeers() e.statusRecorder.FinishPeerListModifications() if err != nil { - return err + return nil, err } - } else { - err := e.removePeers(remotePeers) - if err != nil { - return err - } - - err = e.modifyPeers(remotePeers) - if err != nil { - return err - } - - err = e.addNewPeers(remotePeers) - if err != nil { - return err - } - - e.statusRecorder.FinishPeerListModifications() - - e.updatePeerSSHHostKeys(remotePeers) - - if err := e.updateSSHClientConfig(remotePeers); err != nil { - log.Warnf("failed to update SSH client config: %v", err) - } - - e.updateSSHServerAuth(networkMap.GetSshAuth()) + return remotePeers, nil } - // must set the exclude list after the peers are added. Without it the manager can not figure out the peers parameters from the store - excludedLazyPeers := e.toExcludedLazyPeers(forwardingRules, remotePeers) - e.connMgr.SetExcludeList(e.ctx, excludedLazyPeers) + done := e.phase("removed_peers") + err := e.removePeers(remotePeers) + done() + if err != nil { + return nil, err + } - e.networkSerial = serial + done = e.phase("modified_peers") + err = e.modifyPeers(remotePeers) + done() + if err != nil { + return nil, err + } - return nil + done = e.phase("added_peers") + err = e.addNewPeers(remotePeers) + done() + if err != nil { + return nil, err + } + + e.statusRecorder.FinishPeerListModifications() + + e.updatePeerSSHHostKeys(remotePeers) + + if err := e.updateSSHClientConfig(remotePeers); err != nil { + log.Warnf("failed to update SSH client config: %v", err) + } + + e.updateSSHServerAuth(networkMap.GetSshAuth()) + + return remotePeers, nil } func toDNSFeatureFlag(networkMap *mgmProto.NetworkMap) bool { diff --git a/client/internal/metrics/influxdb.go b/client/internal/metrics/influxdb.go index 531f6a986..4ba14bf44 100644 --- a/client/internal/metrics/influxdb.go +++ b/client/internal/metrics/influxdb.go @@ -120,6 +120,30 @@ func (m *influxDBMetrics) RecordSyncDuration(_ context.Context, agentInfo AgentI m.trimLocked() } +func (m *influxDBMetrics) RecordSyncPhase(_ context.Context, agentInfo AgentInfo, phase string, duration time.Duration) { + tags := fmt.Sprintf("deployment_type=%s,version=%s,os=%s,arch=%s,peer_id=%s,phase=%s", + agentInfo.DeploymentType.String(), + agentInfo.Version, + agentInfo.OS, + agentInfo.Arch, + agentInfo.peerID, + phase, + ) + + m.mu.Lock() + defer m.mu.Unlock() + + m.samples = append(m.samples, influxSample{ + measurement: "netbird_sync_phase", + tags: tags, + fields: map[string]float64{ + "duration_seconds": duration.Seconds(), + }, + timestamp: time.Now(), + }) + m.trimLocked() +} + func (m *influxDBMetrics) RecordLoginDuration(_ context.Context, agentInfo AgentInfo, duration time.Duration, success bool) { result := "success" if !success { diff --git a/client/internal/metrics/infra/README.md b/client/internal/metrics/infra/README.md index 5a93dbd87..7941a30cf 100644 --- a/client/internal/metrics/infra/README.md +++ b/client/internal/metrics/infra/README.md @@ -78,6 +78,25 @@ Tags: - `os`: Operating system (linux, darwin, windows, android, ios, etc.) - `arch`: CPU architecture (amd64, arm64, etc.) +### Sync Phase Timing + +Measurement: `netbird_sync_phase` + +Breaks down where time goes inside a single sync, so the total `netbird_sync` duration can be attributed to the sub-step that dominates. + +| Field | Description | +|-------|-------------| +| `duration_seconds` | Time spent in one sub-phase of sync processing | + +Tags: +- `phase`: the sub-phase — `netbird_config`, `checks`, `persist`, `dns_server`, `routes_classify`, `routes_apply`, `filtering`, `dns_forwarder`, `forward_rules`, `offline_peers`, `removed_peers`, `modified_peers`, `added_peers`, `lazy_exclude` +- `deployment_type`: "cloud" | "selfhosted" | "unknown" +- `version`: NetBird version string +- `os`: Operating system (linux, darwin, windows, android, ios, etc.) +- `arch`: CPU architecture (amd64, arm64, etc.) + +**Note:** this is wall-time per phase — it includes both CPU work and time spent waiting on locks. A slow phase points to *where* the time goes, not *why*; pair it with lock-wait metrics to tell contention apart from real work. + ### Login Duration Measurement: `netbird_login` @@ -191,4 +210,52 @@ docker compose exec influxdb influx query \ # Check ingest server health curl http://localhost:8087/health -``` \ No newline at end of file +``` + +## Analyzing a Debug Bundle + +Metrics collection is always on, so every debug bundle ships a `metrics.txt` in InfluxDB line protocol — a timestamped time series of all recorded events (sync durations, sync phases, connection stages, login). You can replay it into the local stack and graph it, without a running client. + +The bundle's `metrics.txt` is a rolling window (capped at 5 days / ~20k samples, see [Buffer Limits](#buffer-limits)). For a connection incident the relevant window is short (connection setup is seconds), so a bundle captured during the issue is enough. + +### 1. Start the stack + +```bash +# From this directory (client/internal/metrics/infra) +INFLUXDB_ADMIN_TOKEN=admin123 INFLUXDB_ADMIN_PASSWORD=admin123 GRAFANA_ADMIN_PASSWORD=admin123 \ + docker compose up -d +``` + +(`admin123` are throwaway local credentials — fine for offline analysis.) + +### 2. Clear any previous data + +So you only see this bundle: + +```bash +docker exec influxdb influx delete --org netbird --bucket metrics --token admin123 \ + --start 1970-01-01T00:00:00Z --stop 2100-01-01T00:00:00Z +``` + +### 3. Import the bundle's metrics.txt + +InfluxDB is not exposed on the host, so import inside the container: + +```bash +docker cp /path/to/bundle/metrics.txt influxdb:/tmp/m.txt +docker exec influxdb influx write --org netbird --bucket metrics --precision ns \ + --token admin123 --file /tmp/m.txt +``` + +Re-importing the same file is idempotent (same measurement+tags+timestamp overwrites). + +### 4. View the dashboards + +Grafana on http://localhost:3001 (login `admin` / `admin123`), datasource pre-provisioned: + +- **Where sync time goes:** http://localhost:3001/d/netbird-sync-phases/netbird-sync-phases-where-time-goes +- **General client metrics:** http://localhost:3001/d/netbird-influxdb-metrics + +**Set the time range** to cover the bundle's timestamps (e.g. "Last 7 days" or an absolute range matching when the bundle was taken) — with the default short range the panels look empty. + +Bundles are distinguishable by the `version` tag; add a tag at import time (e.g. `sed 's/^netbird_\([a-z_]*\),/netbird_\1,bundle=mycase,/' metrics.txt`) if you want to compare several side by side. \ No newline at end of file diff --git a/client/internal/metrics/infra/grafana/provisioning/dashboards/json/netbird-sync-phases.json b/client/internal/metrics/infra/grafana/provisioning/dashboards/json/netbird-sync-phases.json new file mode 100644 index 000000000..69dbac0ae --- /dev/null +++ b/client/internal/metrics/infra/grafana/provisioning/dashboards/json/netbird-sync-phases.json @@ -0,0 +1,259 @@ +{ + "annotations": { + "list": [] + }, + "editable": true, + "fiscalYearStartMonth": 0, + "graphTooltip": 1, + "links": [], + "refresh": "", + "schemaVersion": 39, + "tags": [ + "netbird", + "sync" + ], + "templating": { + "list": [ + { + "current": { + "text": "All", + "value": "$__all" + }, + "datasource": { + "type": "influxdb", + "uid": "influxdb" + }, + "definition": "import \"influxdata/influxdb/schema\"\nschema.tagValues(bucket: \"metrics\", tag: \"version\")", + "includeAll": true, + "label": "version", + "multi": true, + "name": "version", + "query": "import \"influxdata/influxdb/schema\"\nschema.tagValues(bucket: \"metrics\", tag: \"version\")", + "refresh": 2, + "type": "query", + "allValue": ".*" + } + ] + }, + "time": { + "from": "now-2d", + "to": "now" + }, + "timepicker": {}, + "timezone": "", + "title": "NetBird Sync Phases (where time goes)", + "uid": "netbird-sync-phases", + "version": 1, + "panels": [ + { + "id": 1, + "title": "Time per phase over time (stacked, ms)", + "type": "timeseries", + "datasource": { + "type": "influxdb", + "uid": "influxdb" + }, + "gridPos": { + "h": 10, + "w": 24, + "x": 0, + "y": 0 + }, + "fieldConfig": { + "defaults": { + "unit": "ms", + "custom": { + "drawStyle": "bars", + "stacking": { + "mode": "normal", + "group": "A" + }, + "fillOpacity": 80, + "lineWidth": 0 + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "calcs": [ + "max", + "mean" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "influxdb", + "uid": "influxdb" + }, + "query": "from(bucket: \"metrics\")\n |> range(start: v.timeRangeStart, stop: v.timeRangeStop)\n |> filter(fn: (r) => r._measurement == \"netbird_sync_phase\" and r._field == \"duration_seconds\")\n |> filter(fn: (r) => r.version =~ /${version:regex}/)\n |> map(fn: (r) => ({ r with _value: r._value * 1000.0 }))\n |> keep(columns: [\"_time\", \"_value\", \"phase\"])\n |> group(columns: [\"phase\"])" + } + ] + }, + { + "id": 2, + "title": "p95 per phase (ms)", + "type": "bargauge", + "datasource": { + "type": "influxdb", + "uid": "influxdb" + }, + "gridPos": { + "h": 11, + "w": 12, + "x": 0, + "y": 10 + }, + "fieldConfig": { + "defaults": { + "unit": "ms", + "color": { + "mode": "continuous-GrYlRd" + } + }, + "overrides": [] + }, + "options": { + "displayMode": "gradient", + "orientation": "horizontal", + "reduceOptions": { + "calcs": [ + "lastNotNull" + ], + "fields": "", + "values": false + }, + "showUnfilled": true + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "influxdb", + "uid": "influxdb" + }, + "query": "from(bucket: \"metrics\")\n |> range(start: v.timeRangeStart, stop: v.timeRangeStop)\n |> filter(fn: (r) => r._measurement == \"netbird_sync_phase\" and r._field == \"duration_seconds\")\n |> filter(fn: (r) => r.version =~ /${version:regex}/)\n |> map(fn: (r) => ({ r with _value: r._value * 1000.0 }))\n |> group(columns: [\"phase\"])\n |> quantile(q: 0.95)\n |> group()\n |> sort(columns: [\"_value\"], desc: true)" + } + ] + }, + { + "id": 3, + "title": "Per-phase stats (ms): mean / p95 / max", + "type": "table", + "datasource": { + "type": "influxdb", + "uid": "influxdb" + }, + "gridPos": { + "h": 11, + "w": 12, + "x": 12, + "y": 10 + }, + "fieldConfig": { + "defaults": { + "unit": "ms" + }, + "overrides": [] + }, + "options": { + "showHeader": true, + "sortBy": [ + { + "displayName": "max", + "desc": true + } + ] + }, + "transformations": [ + { + "id": "merge", + "options": {} + } + ], + "targets": [ + { + "refId": "mean", + "datasource": { + "type": "influxdb", + "uid": "influxdb" + }, + "query": "from(bucket: \"metrics\")\n |> range(start: v.timeRangeStart, stop: v.timeRangeStop)\n |> filter(fn: (r) => r._measurement == \"netbird_sync_phase\" and r._field == \"duration_seconds\")\n |> filter(fn: (r) => r.version =~ /${version:regex}/)\n |> map(fn: (r) => ({ r with _value: r._value * 1000.0 }))\n |> group(columns: [\"phase\"])\n |> mean()\n |> group()\n |> keep(columns: [\"phase\", \"_value\"])\n |> rename(columns: {_value: \"mean\"})" + }, + { + "refId": "p95", + "datasource": { + "type": "influxdb", + "uid": "influxdb" + }, + "query": "from(bucket: \"metrics\")\n |> range(start: v.timeRangeStart, stop: v.timeRangeStop)\n |> filter(fn: (r) => r._measurement == \"netbird_sync_phase\" and r._field == \"duration_seconds\")\n |> filter(fn: (r) => r.version =~ /${version:regex}/)\n |> map(fn: (r) => ({ r with _value: r._value * 1000.0 }))\n |> group(columns: [\"phase\"])\n |> quantile(q: 0.95)\n |> group()\n |> keep(columns: [\"phase\", \"_value\"])\n |> rename(columns: {_value: \"p95\"})" + }, + { + "refId": "max", + "datasource": { + "type": "influxdb", + "uid": "influxdb" + }, + "query": "from(bucket: \"metrics\")\n |> range(start: v.timeRangeStart, stop: v.timeRangeStop)\n |> filter(fn: (r) => r._measurement == \"netbird_sync_phase\" and r._field == \"duration_seconds\")\n |> filter(fn: (r) => r.version =~ /${version:regex}/)\n |> map(fn: (r) => ({ r with _value: r._value * 1000.0 }))\n |> group(columns: [\"phase\"])\n |> max()\n |> group()\n |> keep(columns: [\"phase\", \"_value\"])\n |> rename(columns: {_value: \"max\"})" + } + ] + }, + { + "id": 4, + "title": "Total sync duration (netbird_sync, ms) \u2014 reference", + "type": "timeseries", + "datasource": { + "type": "influxdb", + "uid": "influxdb" + }, + "gridPos": { + "h": 8, + "w": 24, + "x": 0, + "y": 21 + }, + "fieldConfig": { + "defaults": { + "unit": "ms", + "custom": { + "drawStyle": "points", + "pointSize": 5 + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "calcs": [ + "max", + "mean" + ] + }, + "tooltip": { + "mode": "single" + } + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "influxdb", + "uid": "influxdb" + }, + "query": "from(bucket: \"metrics\")\n |> range(start: v.timeRangeStart, stop: v.timeRangeStop)\n |> filter(fn: (r) => r._measurement == \"netbird_sync\" and r._field == \"duration_seconds\")\n |> filter(fn: (r) => r.version =~ /${version:regex}/)\n |> map(fn: (r) => ({ r with _value: r._value * 1000.0 }))\n |> keep(columns: [\"_time\", \"_value\", \"version\"])\n |> group(columns: [\"version\"])" + } + ] + } + ] +} \ No newline at end of file diff --git a/client/internal/metrics/infra/ingest/main.go b/client/internal/metrics/infra/ingest/main.go index a5031a873..623a17e4d 100644 --- a/client/internal/metrics/infra/ingest/main.go +++ b/client/internal/metrics/infra/ingest/main.go @@ -59,6 +59,19 @@ var allowedMeasurements = map[string]measurementSpec{ "peer_id": true, }, }, + "netbird_sync_phase": { + allowedFields: map[string]bool{ + "duration_seconds": true, + }, + allowedTags: map[string]bool{ + "deployment_type": true, + "version": true, + "os": true, + "arch": true, + "peer_id": true, + "phase": true, + }, + }, "netbird_login": { allowedFields: map[string]bool{ "duration_seconds": true, diff --git a/client/internal/metrics/metrics.go b/client/internal/metrics/metrics.go index 4ebb43496..f18082995 100644 --- a/client/internal/metrics/metrics.go +++ b/client/internal/metrics/metrics.go @@ -56,6 +56,9 @@ type metricsImplementation interface { // RecordSyncDuration records how long it took to process a sync message RecordSyncDuration(ctx context.Context, agentInfo AgentInfo, duration time.Duration) + // RecordSyncPhase records how long a single sub-phase of sync processing took + RecordSyncPhase(ctx context.Context, agentInfo AgentInfo, phase string, duration time.Duration) + // RecordLoginDuration records how long the login to management took RecordLoginDuration(ctx context.Context, agentInfo AgentInfo, duration time.Duration, success bool) @@ -127,6 +130,18 @@ func (c *ClientMetrics) RecordSyncDuration(ctx context.Context, duration time.Du c.impl.RecordSyncDuration(ctx, agentInfo, duration) } +// RecordSyncPhase records the duration of a single sub-phase of sync processing +func (c *ClientMetrics) RecordSyncPhase(ctx context.Context, phase string, duration time.Duration) { + if c == nil { + return + } + c.mu.RLock() + agentInfo := c.agentInfo + c.mu.RUnlock() + + c.impl.RecordSyncPhase(ctx, agentInfo, phase, duration) +} + // RecordLoginDuration records how long the login to management server took func (c *ClientMetrics) RecordLoginDuration(ctx context.Context, duration time.Duration, success bool) { if c == nil { diff --git a/client/internal/metrics/push_test.go b/client/internal/metrics/push_test.go index 20a509da1..43c1b2c06 100644 --- a/client/internal/metrics/push_test.go +++ b/client/internal/metrics/push_test.go @@ -70,6 +70,9 @@ func (m *mockMetrics) RecordConnectionStages(_ context.Context, _ AgentInfo, _ s func (m *mockMetrics) RecordSyncDuration(_ context.Context, _ AgentInfo, _ time.Duration) { } +func (m *mockMetrics) RecordSyncPhase(_ context.Context, _ AgentInfo, _ string, _ time.Duration) { +} + func (m *mockMetrics) RecordLoginDuration(_ context.Context, _ AgentInfo, _ time.Duration, _ bool) { }