kv/concurrency: misleading duration of contention events with txn pushes

[yuzefovich]

Here (internal slack) is a stmt bundle in which we have a case when the total execution time of subquery 1 was 1.9s yet we reported 28s of contention. This is due to the read in that subquery being repeatedly pushed, so we produced multiple contention events with constantly increasing duration, here is a subset (edited to remove possible PII):

"structuredRecords": [
    {
        "time": "2023-03-05T08:02:20.763129115Z",
        "payload": {
            "@type": "type.googleapis.com/cockroach.roachpb.ContentionEvent",
            "duration": "0.056493704s"
        }
    },
    {
        "time": "2023-03-05T08:02:20.823929395Z",
        "payload": {
            "@type": "type.googleapis.com/cockroach.roachpb.ContentionEvent",
            "duration": "0.117294565s"
        }
    },
    {
        "time": "2023-03-05T08:02:20.921669801Z",
        "payload": {
            "@type": "type.googleapis.com/cockroach.roachpb.ContentionEvent",
            "duration": "0.215034456s"
        }
    },
...

Notably, all these events occurred when performing the same read, but the duration keeps on increasing (due to the read being pushed many times AFAIU), until the last event records the actual contention of 1.88s.

SQL treats all of these events as separate, so it aggregates them here

cockroach/pkg/sql/execstats/stats.go

Line 38 in 2853470

func GetCumulativeContentionTime(

I believe it's a bug in the KV layer where we should be producing the contention events such that their duration doesn't include the duration of contention of previously reported events.

Jira issue: CRDB-25078

[blathers-crl]

Hi @nvanbenschoten, please add branch-* labels to identify which branch(es) this release-blocker affects.

_{🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is dev-inf.}

[nvanbenschoten]

I think this was broken by 70ef641.

Before that change, we would reset the clock on each contention event 70ef641#diff-b2445fe50a89171ab341cf76c645ef668d8dcccd14143b7c96d07d8b52047941L902. These events were emitted on every new (key, txn) pair.

Now, we reset it whenever we wait on a new key:

cockroach/pkg/kv/kvserver/concurrency/lock_table.go

Line 1762 in 77029b1

g.mu.curLockWaitStart = clock.PhysicalTime()

This means that we may emit multiple contention events on the same key but for different lock holder txns without resetting the timer.