Skip to content

Commit 365dfa4

Browse files
DrewKimballDrewKimball
committed
sql: fix flake in EXPLAIN ANALYZE contention time stats
We recently added latch wait time to the cumulative contention time reported for plan nodes that perform KV operations (#113649). This is causing a few `EXPLAIN ANALYZE` tests to flake because mutation operators in particular only report the contention time metric if it is nonzero. Latch wait time is more likely to be nonzero than lock wait time in response to load on the node, so sensitive tests are now occasionally failing. This commit fixes the flake by always reporting the contention time metrics for mutation operators just like the read-only operators that report similar metrics (e.g. Scan, LookupJoin etc.). The reporting is also restricted to `planNodeToRowSource` instances that wrap a mutation to avoid polluting the explain output for other `planNode` types. Fixes #143406 Fixes #143453 Release note: None
1 parent fd2f8d1 commit 365dfa4

File tree

8 files changed

+78
-6
lines changed

8 files changed

+78
-6
lines changed

‎pkg/ccl/logictestccl/testdata/logic_test/triggers_explain‎

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -124,6 +124,9 @@ quality of service: regular
124124
│ regions: <hidden>
125125
│ actual row count: 0
126126
│ vectorized batch count: 0
127+
│ KV contention time: 0µs
128+
│ KV lock wait time: 0µs
129+
│ KV latch wait time: 0µs
127130
│ estimated row count: 0 (missing stats)
128131
│ table: xy
129132
│ set: x, y
@@ -340,6 +343,9 @@ quality of service: regular
340343
│ │ regions: <hidden>
341344
│ │ actual row count: 0
342345
│ │ vectorized batch count: 0
346+
│ │ KV contention time: 0µs
347+
│ │ KV lock wait time: 0µs
348+
│ │ KV latch wait time: 0µs
343349
│ │ estimated row count: 0 (missing stats)
344350
│ │ from: xy
345351
│ │
@@ -416,6 +422,9 @@ quality of service: regular
416422
│ │ regions: <hidden>
417423
│ │ actual row count: 1
418424
│ │ vectorized batch count: 0
425+
│ │ KV contention time: 0µs
426+
│ │ KV lock wait time: 0µs
427+
│ │ KV latch wait time: 0µs
419428
│ │ estimated row count: 0 (missing stats)
420429
│ │ from: xy
421430
│ │
@@ -690,6 +699,9 @@ quality of service: regular
690699
│ │ regions: <hidden>
691700
│ │ actual row count: 0
692701
│ │ vectorized batch count: 0
702+
│ │ KV contention time: 0µs
703+
│ │ KV lock wait time: 0µs
704+
│ │ KV latch wait time: 0µs
693705
│ │ estimated row count: 0 (missing stats)
694706
│ │ table: parent
695707
│ │ set: k
@@ -765,6 +777,9 @@ quality of service: regular
765777
│ │ regions: <hidden>
766778
│ │ actual row count: 1
767779
│ │ vectorized batch count: 0
780+
│ │ KV contention time: 0µs
781+
│ │ KV lock wait time: 0µs
782+
│ │ KV latch wait time: 0µs
768783
│ │ estimated row count: 0 (missing stats)
769784
│ │ table: parent
770785
│ │ set: k
@@ -817,6 +832,9 @@ quality of service: regular
817832
│ │ regions: <hidden>
818833
│ │ actual row count: 0
819834
│ │ vectorized batch count: 0
835+
│ │ KV contention time: 0µs
836+
│ │ KV lock wait time: 0µs
837+
│ │ KV latch wait time: 0µs
820838
│ │ estimated row count: 0 (missing stats)
821839
│ │ table: child
822840
│ │ set: fk
@@ -1039,6 +1057,9 @@ quality of service: regular
10391057
│ regions: <hidden>
10401058
│ actual row count: 1
10411059
│ vectorized batch count: 0
1060+
│ KV contention time: 0µs
1061+
│ KV lock wait time: 0µs
1062+
│ KV latch wait time: 0µs
10421063
│ estimated row count: 0 (missing stats)
10431064
│ from: parent
10441065
│ spans: /2/0
@@ -1055,6 +1076,9 @@ quality of service: regular
10551076
│ │ regions: <hidden>
10561077
│ │ actual row count: 0
10571078
│ │ vectorized batch count: 0
1079+
│ │ KV contention time: 0µs
1080+
│ │ KV lock wait time: 0µs
1081+
│ │ KV latch wait time: 0µs
10581082
│ │ estimated row count: 0 (missing stats)
10591083
│ │ from: child
10601084
│ │

‎pkg/sql/opt/exec/execbuilder/testdata/cascade‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1084,6 +1084,9 @@ quality of service: regular
10841084
│ │ sql nodes: <hidden>
10851085
│ │ regions: <hidden>
10861086
│ │ actual row count: 1
1087+
│ │ KV contention time: 0µs
1088+
│ │ KV lock wait time: 0µs
1089+
│ │ KV latch wait time: 0µs
10871090
│ │ from: loop_a
10881091
│ │
10891092
│ └── • buffer
@@ -1120,6 +1123,9 @@ quality of service: regular
11201123
│ │ sql nodes: <hidden>
11211124
│ │ regions: <hidden>
11221125
│ │ actual row count: 0
1126+
│ │ KV contention time: 0µs
1127+
│ │ KV lock wait time: 0µs
1128+
│ │ KV latch wait time: 0µs
11231129
│ │ from: loop_b
11241130
│ │
11251131
│ └── • buffer
@@ -1169,6 +1175,9 @@ quality of service: regular
11691175
│ │ sql nodes: <hidden>
11701176
│ │ regions: <hidden>
11711177
│ │ actual row count: 0
1178+
│ │ KV contention time: 0µs
1179+
│ │ KV lock wait time: 0µs
1180+
│ │ KV latch wait time: 0µs
11721181
│ │ from: loop_a
11731182
│ │
11741183
│ └── • buffer
@@ -1494,6 +1503,9 @@ quality of service: regular
14941503
│ │ sql nodes: <hidden>
14951504
│ │ regions: <hidden>
14961505
│ │ actual row count: 0
1506+
│ │ KV contention time: 0µs
1507+
│ │ KV lock wait time: 0µs
1508+
│ │ KV latch wait time: 0µs
14971509
│ │ from: p138974
14981510
│ │
14991511
│ └── • buffer

‎pkg/sql/opt/exec/execbuilder/testdata/delete‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -493,6 +493,9 @@ quality of service: regular
493493
│ sql nodes: <hidden>
494494
│ regions: <hidden>
495495
│ actual row count: 0
496+
│ KV contention time: 0µs
497+
│ KV lock wait time: 0µs
498+
│ KV latch wait time: 0µs
496499
│ from: t137352
497500
│ auto commit
498501
│
@@ -556,6 +559,9 @@ quality of service: regular
556559
│ sql nodes: <hidden>
557560
│ regions: <hidden>
558561
│ actual row count: 0
562+
│ KV contention time: 0µs
563+
│ KV lock wait time: 0µs
564+
│ KV latch wait time: 0µs
559565
│ from: t137352
560566
│ auto commit
561567
│

‎pkg/sql/opt/exec/execbuilder/testdata/explain_analyze_plans‎

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -407,6 +407,9 @@ quality of service: regular
407407
│ │ sql nodes: <hidden>
408408
│ │ regions: <hidden>
409409
│ │ actual row count: 1
410+
│ │ KV contention time: 0µs
411+
│ │ KV lock wait time: 0µs
412+
│ │ KV latch wait time: 0µs
410413
│ │ into: child(c, p)
411414
│ │
412415
│ └── • buffer
@@ -490,5 +493,5 @@ quality of service: regular
490493
label: buffer 1
491494
·
492495
Diagram 1 (subquery): https://cockroachdb.github.io/distsqlplan/decode.html#eJysU9Fu2jAUfd9XWPcJJCMSqkmTn9pRJqHSUAFFmiaEXOc2tUjszL4ZsIrP2g_sy6YkTQel7VZteQB878n14Zx77sF_TUHAMJoOJjM2jGZjpu50GrP52eh6MGWtkLPWdDAa9Gcs06aVt9mnyfiS5dKhoXYbOBgbYyQz9CC-QAgc3sOCQ-6sQu-tK8v3FWgYb0AEHLTJCyrLCw7KOgRxD6QpRRAQ2Y7Nuz3gECNJnVZDcYOqIG0NI52hYMHPHx443EhSd-iZLSgvSLAAODi7_l0IYbHjUJ8e7vMkEwRxskdweA6it-N7HMPXOc7kTYoTlDG6bnDItJbltP5a5ivcAoe-TYvMeMFy4DDNZfmzAxxGOtPESsUu5qy83AtmHo4OE21LIKGnunTw3y_mTFlDaI5luZiz1KoVW0tNx51Ss-dblXQxKhtjLBpaN1tCzxzKWLAP7GNdTCZXfaZkmvpHXC61a3Cle5fzfp95wpwpWxhiLdxQVxtqCxZUotUAxNVLgExuWIaZdVsm09QqSSWtoOLwD86HT5wP3uL8WZI4TCRZ1w0PjT-LPi-j8WwZXY9GrdOwzMX_39reE-7hAfc_JGuCPrfG4wHvl24KntzUCXcLDhgnWMfZ28IpvHJWVdj6OK4GVYUYPdXdk_owNE3Lk0OZPUq_Pyl8dVLvDZN6r04KjifJSgAwSGvrVmVM0Kjto2lN_Tg4MXp0Wqb6uzz2unmt8tehQv2tyVbTagLW9OqQNd0MvZfJASD4yx3a16dy7za166WOQUDw8HSe-WgeKF-QiS9XaHpn15VYs21eLsCtTD1yuJQrPEdCl2mjPWkFglyBu927XwEAAP__fX8Rfg==
493-
Diagram 2 (main-query): https://cockroachdb.github.io/distsqlplan/decode.html#eJy0ksGK2zAQhu99CjGnBLTE8t50K90UDLtJSdJeiilaeZyIypIrjZotwY_VF-iTFdu77dZ0AzmsDoL5JX3zIeYE8ZsFCcVqu9zsWLHarZk-GFuxT29vPy63bCY4m22Xt8t3O9YYN2vn7P1mfcdaFdDRfA4cnK9wpRqMID-DgJJDG7zGGH3oo9NwoageQGYcjGsT9XHJQfuAIE9AhiyCBOu1suy7sgkjyxYZcKiQlLEDGR9QJzLeMTINSpb9-hmBw70ifcDIfKI2kWT9q-CPfwMBZcdhrB4bR1J7BCmemRY3ILOOXyp7n-oaAxML8dqy-URWXC6rfXLE8kX-2q7XE9f8EtcNxta7iP9IvtQpm3S6El3JAas9jqMXfQoaPwSvh7tjuR5AQ1BhpPFUjEXhno4iBVTNn7l4ThJnSfnLJDEl5WdJ1-ecSg619ccvpgIJ2eO6-s_2tKB_oPax_-ztwR8H7O5H239VrWxEDnfqK94gYWiMM5GMBkkhYde9-R0AAP__XNhbxw==
496+
Diagram 2 (main-query): https://cockroachdb.github.io/distsqlplan/decode.html#eJy0ksFqGzEQhu99imFOMSh4tbnpVhoXTBK72K4vxRRFO7ZFtNJWmq1TzD5WX6BPVnY3aRMnMRhaHQQzv_TP9wvtMX1zqHA8mY9mCxhPFlMwW-sKWL6__jyaw5kUcDYfXY8-LKC0_qwawMfZ9AYqHcnzYIACfShooktKqL6gxJXAKgZDKYXYtvbdgXFxjyoTaH1Vc9teCTQhEqo9smVHqNAFox18166mBNkwQ4EFsbauc6Z7MjXb4IFtSQqyXz8TCrzVbLaUINRc1aygvRXD7m9D4qoR2FcPgxPrDaGST0jHl6iyRpwKe1uv1xRBDuX_hs0PYOXpsCbUniEf5s9Zr5ZggmfyL3mvluCCuYOdtvxSacO8Iv377BcH2fNTss8oVcEnehb6rUnZwaRz2awEUrGh_iunUEdDn2Iw3dm-nHZGXaOgxL0q-2LsH6XEkXT55589dZJHnfK3neShU37U6eIY00rg2oXdV1ugwuxhnb-yPS5sL-hNah97vg27znbxo2qfaq1dIoE3-o4uiSmW1tvE1qDiWFPTvPsdAAD__2nHd8M=
494497
Diagram 3 (postquery): https://cockroachdb.github.io/distsqlplan/decode.html#eJy0lMFu8jgQx-_7FKM5geSKBHpY-dQupVJaChVQLitUuclAvTh21nYEqOKx9gX2yVZOoFtoYbef9OUAmvH4n99M_vYbuj8VckwG495oAslgMoT0VaoMptf9p94YGjGDxrjX73UnkEvdKJpwOxo-QCEsad9sIkNtMhqInBzy3zHGGcPCmpScMzak3qqCJFsjjxhKXZQ-pGcMU2MJ-Rt66RUhR2VSocClQsNLOZ-ThagVIcOMvJCqkh-WnsNVGxnSmtLSS6PBy5w4RH__5ZDhi_DpKzkwpS9CbdhvzerfRIyzLcM62nE4LxaEPP4Antwgj7bs_7PfSuXJkm3Fh8B1nsNVDMkYBsMJDJ76_Z_C3z7ij7_Df2ekHpHIyLbahx1MNgVx6PduJ3A9mCRwN0wGyLA2wFX991wsaYMM-8YsywL-MFKD0aFrZNg1qsy141DgjgFCR6GVfey8UOpwEPdTCOyOg47r0NJCmqDjyfk6dbwjNdqT_jzV-ykoky5hJaT_vBJG_vVSNfmMUpNRVvPeT-Fl48mBJZFx-BV-q5OL0WMXUqGUe68rhLT7ujDTh2m3C85TAakptYcGrX1Lat_kO5_XBUTLUwUnPJOLNeSUG7sBocIh8oE2qtD-00_RST91jvzU_o6f6rNM1hoLcl4PMm51Dq31o2fgNPPlEXPnO8wjcoXRjg4gT70pOnrTRbydMaRsQfWl50xpU3q0Jq1q63BYCVWJjJyvV-M6SPR-yXlLIn-_gj4qxWeV2qeV4mOl9lmlzmml9rFS56zS5bnuZgznyqyeZYYco91z8cXP_sGwQSxc-GzjV7OqZMMN5ZDPhXLE8EEs6YY82Vxq6bxMkXtb0nb7yz8BAAD__8zCQBU=

‎pkg/sql/opt/exec/execbuilder/testdata/unique‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -620,6 +620,9 @@ quality of service: regular
620620
│ │ sql nodes: <hidden>
621621
│ │ regions: <hidden>
622622
│ │ actual row count: 2
623+
│ │ KV contention time: 0µs
624+
│ │ KV lock wait time: 0µs
625+
│ │ KV latch wait time: 0µs
623626
│ │ into: uniq_fk_parent(a, b, c, rowid)
624627
│ │
625628
│ └── • buffer
@@ -742,6 +745,9 @@ quality of service: regular
742745
│ │ sql nodes: <hidden>
743746
│ │ regions: <hidden>
744747
│ │ actual row count: 2
748+
│ │ KV contention time: 0µs
749+
│ │ KV lock wait time: 0µs
750+
│ │ KV latch wait time: 0µs
745751
│ │ into: uniq_fk_child(a, b, c, rowid)
746752
│ │
747753
│ └── • buffer
@@ -2632,6 +2638,9 @@ quality of service: regular
26322638
│ │ sql nodes: <hidden>
26332639
│ │ regions: <hidden>
26342640
│ │ actual row count: 2
2641+
│ │ KV contention time: 0µs
2642+
│ │ KV lock wait time: 0µs
2643+
│ │ KV latch wait time: 0µs
26352644
│ │ table: uniq_fk_parent
26362645
│ │ set: c
26372646
│ │
@@ -2671,6 +2680,9 @@ quality of service: regular
26712680
│ │ │ sql nodes: <hidden>
26722681
│ │ │ regions: <hidden>
26732682
│ │ │ actual row count: 0
2683+
│ │ │ KV contention time: 0µs
2684+
│ │ │ KV lock wait time: 0µs
2685+
│ │ │ KV latch wait time: 0µs
26742686
│ │ │ table: uniq_fk_child
26752687
│ │ │ set: b, c
26762688
│ │ │

‎pkg/sql/opt/exec/execbuilder/testdata/update‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1014,6 +1014,9 @@ quality of service: regular
10141014
│ sql nodes: <hidden>
10151015
│ regions: <hidden>
10161016
│ actual row count: 0
1017+
│ KV contention time: 0µs
1018+
│ KV lock wait time: 0µs
1019+
│ KV latch wait time: 0µs
10171020
│ table: t137352
10181021
│ set: a, b
10191022
│ auto commit
@@ -1082,6 +1085,9 @@ quality of service: regular
10821085
│ sql nodes: <hidden>
10831086
│ regions: <hidden>
10841087
│ actual row count: 0
1088+
│ KV contention time: 0µs
1089+
│ KV lock wait time: 0µs
1090+
│ KV latch wait time: 0µs
10851091
│ table: t137352
10861092
│ set: a, b
10871093
│ auto commit
@@ -1170,6 +1176,9 @@ quality of service: regular
11701176
│ sql nodes: <hidden>
11711177
│ regions: <hidden>
11721178
│ actual row count: 1
1179+
│ KV contention time: 0µs
1180+
│ KV lock wait time: 0µs
1181+
│ KV latch wait time: 0µs
11731182
│ table: t137352
11741183
│ set: a, b
11751184
│ auto commit
@@ -1254,6 +1263,9 @@ quality of service: regular
12541263
│ sql nodes: <hidden>
12551264
│ regions: <hidden>
12561265
│ actual row count: 0
1266+
│ KV contention time: 0µs
1267+
│ KV lock wait time: 0µs
1268+
│ KV latch wait time: 0µs
12571269
│ table: t137352
12581270
│ set: a, b
12591271
│ auto commit

‎pkg/sql/opt/exec/execbuilder/testdata/upsert‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1183,6 +1183,9 @@ quality of service: regular
11831183
│ sql nodes: <hidden>
11841184
│ regions: <hidden>
11851185
│ actual row count: 1
1186+
│ KV contention time: 0µs
1187+
│ KV lock wait time: 0µs
1188+
│ KV latch wait time: 0µs
11861189
│ into: t137352(k, a, b)
11871190
│ auto commit
11881191
│ arbiter indexes: t137352_pkey
@@ -1255,6 +1258,9 @@ quality of service: regular
12551258
│ sql nodes: <hidden>
12561259
│ regions: <hidden>
12571260
│ actual row count: 1
1261+
│ KV contention time: 0µs
1262+
│ KV lock wait time: 0µs
1263+
│ KV latch wait time: 0µs
12581264
│ into: t137352(k, a, b)
12591265
│ auto commit
12601266
│ arbiter indexes: t137352_a_key

‎pkg/sql/plan_node_to_row_source.go‎

Lines changed: 2 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -263,11 +263,8 @@ func (p *planNodeToRowSource) trailingMetaCallback() []execinfrapb.ProducerMetad
263263

264264
// execStatsForTrace implements ProcessorBase.ExecStatsForTrace.
265265
func (p *planNodeToRowSource) execStatsForTrace() *execinfrapb.ComponentStats {
266-
// Propagate contention time and RUs from IO requests.
267-
if p.contentionEventsListener.GetContentionTime() == 0 &&
268-
p.contentionEventsListener.GetLockWaitTime() == 0 &&
269-
p.contentionEventsListener.GetLatchWaitTime() == 0 &&
270-
p.tenantConsumptionListener.GetConsumedRU() == 0 {
266+
// Propagate contention time and RUs from IO requests for mutations.
267+
if _, ok := p.node.(mutationPlanNode); !ok {
271268
return nil
272269
}
273270
return &execinfrapb.ComponentStats{

0 commit comments

Comments
 (0)