ITADN

sql,obs: crdb_contention_activity records at most one sample for a long-blocked waiter

#173845Openangles-n-daemons 创建于 2 天前
C-bugA-sql-observabilityT-observabilityO-agent
**Describe the problem** The `information_schema.crdb_contention_activity` view (added by the open `contention-activity-view` PR, cockroachlabs/cockroach#3470) surfaces **at most one — often zero — row for a request blocked on a contended lock**, regardless of how long it waits. In a demo, a reader blocked for minutes produced a single sample. **Root cause** A request blocked on a lock held by a live transaction is recorded in ASH as `work_event = 'LockWait'` — the event the view filters on, and the only one carrying the `range_id`/`table_id`/`index_id`/`blocking_stmt_fingerprint_id` labels — **only for the initial liveness-push delay (~100ms)**. It then escalates to synchronously pushing the lock holder's transaction and, for the *entire remaining wait*, is sampled as `TxnPushWait`, which the view neither matches (`work_event IN ('LatchWait','LockWait')`) nor labels (`labels ? 'range_id'`). Mechanically, the push runs on the waiter's own goroutine (`intentresolver.MaybePushTransactions` → `db.Run`), so `maybeInterceptReq` registers `TxnPushWait` on top of the still-present `LockWait` on that goroutine's work-state stack, and the sampler only reads the top of the stack. **To Reproduce** 1. Single-node cluster; `SET CLUSTER SETTING obs.ash.labels.enabled = true`, `obs.ash.labels.kv_sync_wait.enabled = true`, `obs.ash.sample_interval = '1s'`. 2. Session A: `BEGIN; UPDATE t SET v=v+1 WHERE k=1;` (hold, don't commit). 3. Session B: `SELECT * FROM t WHERE k=1 FOR UPDATE;` (blocks). 4. While B is blocked (verified via `crdb_internal.cluster_locks`), query `crdb_internal.cluster_active_session_history` for `work_event='LockWait'`. At 1s sampling: 0 `LockWait` samples over a 90s block. At 10ms sampling over an ~8s block, on the same goroutine: | work_event | samples | carry `range_id` | |---|---|---| | LockWait | 10 | 10 | | TxnPushWait | 782 | 0 | | TxnQueryWait | 782 | 0 | **Expected behavior** A request blocked on a lock for its whole wait should be represented in `crdb_contention_activity` for the duration of the wait, not by a single transient sample. **Fix options** - **Option A (recommended, less invasive): don't let a lock-wait-nested push mask the `LockWait`.** In `maybeInterceptReq`, if the current goroutine already holds a `WorkLock`/`LockWait` state, skip registering the nested `TxnPushWait`. The labeled `LockWait` stays top-of-stack for the whole wait and the view works unchanged. Tradeoff: lock-driven pushes no longer appear as `TxnPushWait`. - **Option B: label the push.** Attach the contention labels to `TxnPushWait`/`TxnQueryWait` and add them to the view filter. More invasive — the push batch is re-stamped as the `WORKLOAD_ID_INTENT_RESOLUTION` *system* workload and coalesces multiple pushees, so there is no single lock identity at the push site. **Caveats** - Topology (predicted, not yet verified): in a multi-node cluster where the pushee's txn-record range is remote, the waiter's goroutine stays in `LockWait` for the whole wait (the push is an RPC; `TxnPushWait` appears on the remote node). So this is likely a single-node / co-located-range artifact — common in demos and small clusters. - Test gap: the PR's logictest inserts synthetic ASH rows with labels; it never drives the real lock-wait → work-state path, so it cannot catch this. Epic CRDB-65143
1 条评论