From 672eec804371fe574e5fe4eb3f08ba9d3ead20aa Mon Sep 17 00:00:00 2001 From: Ashish Sharda Date: Sat, 7 Mar 2026 15:15:29 -0500 Subject: [PATCH 1/3] scd: reduce subscription lock scope and add lock diagnostics --- docs/operations/performances.md | 21 ++++++++ pkg/scd/operational_intents_handler.go | 4 +- pkg/scd/repos/repos.go | 2 +- pkg/scd/store/datastore/subscriptions.go | 61 ++++++++++++++++++++++-- 4 files changed, 80 insertions(+), 8 deletions(-) diff --git a/docs/operations/performances.md b/docs/operations/performances.md index 4f1d9b791..c8e050d4b 100644 --- a/docs/operations/performances.md +++ b/docs/operations/performances.md @@ -28,3 +28,24 @@ All graphs have been generated with the [loadtest present in the monitoring repo ![](../assets/perfs_scd_lock_notoverlapping.png) *Non-overlapping requests. Notice the reduction of performance on the right, with a single lock.* + +## SCD lock diagnostics logs + +To help diagnose latency spikes (for example as discussed in [#1311](https://github.com/interuss/dss/issues/1311)), the SCD subscription lock path emits targeted warning logs when a lock query looks expensive. + +The warning is emitted only when one of the following thresholds is met: +* Lock query duration is greater than or equal to `500ms` +* Number of matched/locked rows is greater than or equal to `1000` + +The log message is `SCD lock query diagnostics` and includes: +* `global_lock`: Whether global lock mode is enabled for this query +* `duration`: Time spent executing the lock query +* `matched_rows`: Number of rows matched by the lock query +* `cell_count`: Number of S2 cells in the request +* `explicit_subscription_id_count`: Number of explicitly provided subscription IDs + +Failed lock queries also emit warnings with timing and context: +* `SCD global lock query failed` +* `SCD subscription lock query failed` + +These diagnostics are intended to keep normal logs low-noise while surfacing lock contention or unexpectedly large lock scopes. diff --git a/pkg/scd/operational_intents_handler.go b/pkg/scd/operational_intents_handler.go index d0b416689..f439a02ba 100644 --- a/pkg/scd/operational_intents_handler.go +++ b/pkg/scd/operational_intents_handler.go @@ -108,7 +108,7 @@ func (a *Server) DeleteOperationalIntentReference(ctx context.Context, req *rest subscriptionIds = append(subscriptionIds, *old.SubscriptionID) } - err = r.LockSubscriptionsOnCells(ctx, old.Cells, subscriptionIds) + err = r.LockSubscriptionsOnCells(ctx, old.Cells, subscriptionIds, old.StartTime, old.EndTime) if err != nil { return stacktrace.Propagate(err, "Unable to acquire lock") } @@ -853,7 +853,7 @@ func (a *Server) upsertOperationalIntentReference(ctx context.Context, now time. subscriptionIds = append(subscriptionIds, validParams.subscriptionID) } - err = r.LockSubscriptionsOnCells(ctx, validParams.cells, subscriptionIds) + err = r.LockSubscriptionsOnCells(ctx, validParams.cells, subscriptionIds, validParams.uExtent.StartTime, validParams.uExtent.EndTime) if err != nil { return stacktrace.Propagate(err, "Unable to acquire lock") } diff --git a/pkg/scd/repos/repos.go b/pkg/scd/repos/repos.go index b33f1dbd7..46bd0ecbc 100644 --- a/pkg/scd/repos/repos.go +++ b/pkg/scd/repos/repos.go @@ -59,7 +59,7 @@ type Subscription interface { IncrementNotificationIndices(ctx context.Context, subscriptionIds []dssmodels.ID) ([]int, error) // LockSubscriptionsOnCells locks the subscriptions of interest on specific cells and, optionnaly, specific subscriptions via their IDs - LockSubscriptionsOnCells(ctx context.Context, cells s2.CellUnion, subscriptionIds []dssmodels.ID) error + LockSubscriptionsOnCells(ctx context.Context, cells s2.CellUnion, subscriptionIds []dssmodels.ID, startTime *time.Time, endTime *time.Time) error // ListExpiredSubscriptions lists all subscriptions older than the threshold. // Their age is determined by their end time, or by their update time if they do not have an end time. diff --git a/pkg/scd/store/datastore/subscriptions.go b/pkg/scd/store/datastore/subscriptions.go index 6b4c73088..9e92b729e 100644 --- a/pkg/scd/store/datastore/subscriptions.go +++ b/pkg/scd/store/datastore/subscriptions.go @@ -6,10 +6,12 @@ import ( "strings" "time" + "github.com/interuss/dss/pkg/logging" dssmodels "github.com/interuss/dss/pkg/models" scdmodels "github.com/interuss/dss/pkg/scd/models" dsssql "github.com/interuss/dss/pkg/sql" "github.com/interuss/stacktrace" + "go.uber.org/zap" "github.com/golang/geo/s2" ) @@ -20,6 +22,12 @@ var ( subscriptionFieldsWithoutPrefix string ) +const ( + // These thresholds keep lock diagnostics low-noise in production while still surfacing likely bottlenecks. + lockQuerySlowThreshold = 500 * time.Millisecond + lockQueryLargeRowCount = 1000 +) + // TODO Update database schema and fields below. func init() { subscriptionFieldsWithIndices[0] = "id" @@ -378,7 +386,8 @@ func (c *repo) IncrementNotificationIndices(ctx context.Context, subscriptionIds return orderedIndices, nil } -func (c *repo) LockSubscriptionsOnCells(ctx context.Context, cells s2.CellUnion, subscriptionIds []dssmodels.ID) error { +func (c *repo) LockSubscriptionsOnCells(ctx context.Context, cells s2.CellUnion, subscriptionIds []dssmodels.ID, startTime *time.Time, endTime *time.Time) error { + logger := logging.WithValuesFromContext(ctx, logging.Logger) if c.globalLock { @@ -391,11 +400,28 @@ func (c *repo) LockSubscriptionsOnCells(ctx context.Context, cells s2.CellUnion, // Notice that this requieres key entries to be present to work. const query = `SELECT key FROM scd_locks WHERE key = 0 FOR UPDATE` - _, err := c.q.Exec(ctx, query) + start := time.Now() + result, err := c.q.Exec(ctx, query) + duration := time.Since(start) if err != nil { + logger.Warn("SCD global lock query failed", + zap.Duration("duration", duration), + zap.Error(err), + ) return stacktrace.Propagate(err, "Error in query: %s", query) } + matchedRows := int(result.RowsAffected()) + if duration >= lockQuerySlowThreshold || matchedRows >= lockQueryLargeRowCount { + logger.Warn("SCD lock query diagnostics", + zap.Bool("global_lock", true), + zap.Duration("duration", duration), + zap.Int("matched_rows", matchedRows), + zap.Int("cell_count", len(cells)), + zap.Int("explicit_subscription_id_count", len(subscriptionIds)), + ) + } + return nil } @@ -406,8 +432,14 @@ func (c *repo) LockSubscriptionsOnCells(ctx context.Context, cells s2.CellUnion, FROM scd_subscriptions WHERE - cells && $1 - OR + ( + cells && $1 + AND + COALESCE(starts_at <= $4, true) + AND + COALESCE(ends_at >= $3, true) + ) + OR id = ANY($2) FOR UPDATE ` @@ -417,11 +449,30 @@ func (c *repo) LockSubscriptionsOnCells(ctx context.Context, cells s2.CellUnion, ids[i] = id.String() } - _, err := c.q.Exec(ctx, query, dsssql.CellUnionToCellIds(cells), ids) + start := time.Now() + result, err := c.q.Exec(ctx, query, dsssql.CellUnionToCellIds(cells), ids, startTime, endTime) + duration := time.Since(start) if err != nil { + logger.Warn("SCD subscription lock query failed", + zap.Duration("duration", duration), + zap.Int("cell_count", len(cells)), + zap.Int("explicit_subscription_id_count", len(subscriptionIds)), + zap.Error(err), + ) return stacktrace.Propagate(err, "Error in query: %s", query) } + matchedRows := int(result.RowsAffected()) + if duration >= lockQuerySlowThreshold || matchedRows >= lockQueryLargeRowCount { + logger.Warn("SCD lock query diagnostics", + zap.Bool("global_lock", false), + zap.Duration("duration", duration), + zap.Int("matched_rows", matchedRows), + zap.Int("cell_count", len(cells)), + zap.Int("explicit_subscription_id_count", len(subscriptionIds)), + ) + } + return nil } From 590c4fe822cd03da5500ea63295bbb67b367d365 Mon Sep 17 00:00:00 2001 From: Ashish Sharda Date: Sat, 14 Mar 2026 23:03:46 -0400 Subject: [PATCH 2/3] scd: tune lock diagnostics threshold and message --- docs/operations/performances.md | 7 ++----- pkg/scd/store/datastore/subscriptions.go | 19 +++++++------------ 2 files changed, 9 insertions(+), 17 deletions(-) diff --git a/docs/operations/performances.md b/docs/operations/performances.md index c8e050d4b..aeaf4cf7e 100644 --- a/docs/operations/performances.md +++ b/docs/operations/performances.md @@ -33,14 +33,11 @@ All graphs have been generated with the [loadtest present in the monitoring repo To help diagnose latency spikes (for example as discussed in [#1311](https://github.com/interuss/dss/issues/1311)), the SCD subscription lock path emits targeted warning logs when a lock query looks expensive. -The warning is emitted only when one of the following thresholds is met: -* Lock query duration is greater than or equal to `500ms` -* Number of matched/locked rows is greater than or equal to `1000` +The warning is emitted when lock query duration is greater than or equal to `4s`. -The log message is `SCD lock query diagnostics` and includes: +The log message is `Expensive SCD lock detected` and includes: * `global_lock`: Whether global lock mode is enabled for this query * `duration`: Time spent executing the lock query -* `matched_rows`: Number of rows matched by the lock query * `cell_count`: Number of S2 cells in the request * `explicit_subscription_id_count`: Number of explicitly provided subscription IDs diff --git a/pkg/scd/store/datastore/subscriptions.go b/pkg/scd/store/datastore/subscriptions.go index 9e92b729e..3817dd142 100644 --- a/pkg/scd/store/datastore/subscriptions.go +++ b/pkg/scd/store/datastore/subscriptions.go @@ -24,8 +24,7 @@ var ( const ( // These thresholds keep lock diagnostics low-noise in production while still surfacing likely bottlenecks. - lockQuerySlowThreshold = 500 * time.Millisecond - lockQueryLargeRowCount = 1000 + lockQuerySlowThreshold = 4 * time.Second ) // TODO Update database schema and fields below. @@ -401,7 +400,7 @@ func (c *repo) LockSubscriptionsOnCells(ctx context.Context, cells s2.CellUnion, const query = `SELECT key FROM scd_locks WHERE key = 0 FOR UPDATE` start := time.Now() - result, err := c.q.Exec(ctx, query) + _, err := c.q.Exec(ctx, query) duration := time.Since(start) if err != nil { logger.Warn("SCD global lock query failed", @@ -411,12 +410,10 @@ func (c *repo) LockSubscriptionsOnCells(ctx context.Context, cells s2.CellUnion, return stacktrace.Propagate(err, "Error in query: %s", query) } - matchedRows := int(result.RowsAffected()) - if duration >= lockQuerySlowThreshold || matchedRows >= lockQueryLargeRowCount { - logger.Warn("SCD lock query diagnostics", + if duration >= lockQuerySlowThreshold { + logger.Warn("Expensive SCD lock detected", zap.Bool("global_lock", true), zap.Duration("duration", duration), - zap.Int("matched_rows", matchedRows), zap.Int("cell_count", len(cells)), zap.Int("explicit_subscription_id_count", len(subscriptionIds)), ) @@ -450,7 +447,7 @@ func (c *repo) LockSubscriptionsOnCells(ctx context.Context, cells s2.CellUnion, } start := time.Now() - result, err := c.q.Exec(ctx, query, dsssql.CellUnionToCellIds(cells), ids, startTime, endTime) + _, err := c.q.Exec(ctx, query, dsssql.CellUnionToCellIds(cells), ids, startTime, endTime) duration := time.Since(start) if err != nil { logger.Warn("SCD subscription lock query failed", @@ -462,12 +459,10 @@ func (c *repo) LockSubscriptionsOnCells(ctx context.Context, cells s2.CellUnion, return stacktrace.Propagate(err, "Error in query: %s", query) } - matchedRows := int(result.RowsAffected()) - if duration >= lockQuerySlowThreshold || matchedRows >= lockQueryLargeRowCount { - logger.Warn("SCD lock query diagnostics", + if duration >= lockQuerySlowThreshold { + logger.Warn("Expensive SCD lock detected", zap.Bool("global_lock", false), zap.Duration("duration", duration), - zap.Int("matched_rows", matchedRows), zap.Int("cell_count", len(cells)), zap.Int("explicit_subscription_id_count", len(subscriptionIds)), ) From a0f3a9331bce09d6e14c7184b9fc69f7de4695fb Mon Sep 17 00:00:00 2001 From: Ashish Sharda Date: Mon, 16 Mar 2026 05:43:52 -0400 Subject: [PATCH 3/3] Fix comment grammar in subscriptions.go --- pkg/scd/store/datastore/subscriptions.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pkg/scd/store/datastore/subscriptions.go b/pkg/scd/store/datastore/subscriptions.go index 3817dd142..335cb0c06 100644 --- a/pkg/scd/store/datastore/subscriptions.go +++ b/pkg/scd/store/datastore/subscriptions.go @@ -23,7 +23,7 @@ var ( ) const ( - // These thresholds keep lock diagnostics low-noise in production while still surfacing likely bottlenecks. + // This threshold keep lock diagnostics low-noise in production while still surfacing likely bottlenecks. lockQuerySlowThreshold = 4 * time.Second )