Skip to content

Commit c5bb92c

Browse files
yuzefovichyuzefovich
committed
explain: show "execution time" on EXPLAIN ANALYZE output
We've been tracking "execution time" statistic for most operators (except for vectorized KV-reading ones which get separate "KV time" stat) for many years now, but for some reason we only reported it on the DistSQL diagram. This commit fixes that oversight so that the stat is now included on `EXPLAIN ANALYZE` output when available. Release note (sql change): New statistic `execution time` is now reported on EXPLAIN ANALYZE output for most operators. It was previously only available on the DistSQL diagrams (included in `EXPLAIN ANALYZE (DISTSQL)` output).
1 parent e113b11 commit c5bb92c

19 files changed

+164
-0
lines changed

Diff for: ‎pkg/ccl/logictestccl/testdata/logic_test/explain_call_plpgsql

+2
Original file line numberDiff line numberDiff line change
@@ -155,6 +155,7 @@ quality of service: regular
155155
sql nodes: <hidden>
156156
regions: <hidden>
157157
actual row count: 0
158+
execution time: 0µs
158159
estimated row count: 0
159160
procedure: foo(3)
160161

@@ -177,6 +178,7 @@ quality of service: regular
177178
sql nodes: <hidden>
178179
regions: <hidden>
179180
actual row count: 0
181+
execution time: 0µs
180182
estimated row count: 0
181183
procedure: foo(3)
182184
·

Diff for: ‎pkg/ccl/logictestccl/testdata/logic_test/triggers_explain

+31
Original file line numberDiff line numberDiff line change
@@ -124,6 +124,7 @@ quality of service: regular
124124
│ regions: <hidden>
125125
│ actual row count: 1
126126
│ vectorized batch count: 0
127+
│ execution time: 0µs
127128
│ estimated row count: 0 (missing stats)
128129
│ table: xy
129130
│ set: x, y
@@ -146,6 +147,7 @@ quality of service: regular
146147
│ regions: <hidden>
147148
│ actual row count: 0
148149
│ vectorized batch count: 0
150+
│ execution time: 0µs
149151
│ estimated row count: 10 (missing stats)
150152
│ filter: f IS DISTINCT FROM NULL
151153
│
@@ -182,6 +184,7 @@ quality of service: regular
182184
│ regions: <hidden>
183185
│ actual row count: 0
184186
│ vectorized batch count: 0
187+
│ execution time: 0µs
185188
│ estimated row count: 10 (missing stats)
186189
│ filter: y = 2
187190
│
@@ -338,6 +341,7 @@ quality of service: regular
338341
│ │ regions: <hidden>
339342
│ │ actual row count: 1
340343
│ │ vectorized batch count: 0
344+
│ │ execution time: 0µs
341345
│ │ estimated row count: 0 (missing stats)
342346
│ │ from: xy
343347
│ │
@@ -347,6 +351,7 @@ quality of service: regular
347351
│ │ regions: <hidden>
348352
│ │ actual row count: 0
349353
│ │ vectorized batch count: 0
354+
│ │ execution time: 0µs
350355
│ │ label: buffer 1
351356
│ │
352357
│ └── • filter
@@ -355,6 +360,7 @@ quality of service: regular
355360
│ │ regions: <hidden>
356361
│ │ actual row count: 0
357362
│ │ vectorized batch count: 0
363+
│ │ execution time: 0µs
358364
│ │ estimated row count: 10 (missing stats)
359365
│ │ filter: y = 2
360366
│ │
@@ -412,6 +418,7 @@ quality of service: regular
412418
│ │ regions: <hidden>
413419
│ │ actual row count: 1
414420
│ │ vectorized batch count: 0
421+
│ │ execution time: 0µs
415422
│ │ estimated row count: 0 (missing stats)
416423
│ │ from: xy
417424
│ │
@@ -421,6 +428,7 @@ quality of service: regular
421428
│ │ regions: <hidden>
422429
│ │ actual row count: 1
423430
│ │ vectorized batch count: 0
431+
│ │ execution time: 0µs
424432
│ │ label: buffer 1
425433
│ │
426434
│ └── • filter
@@ -429,6 +437,7 @@ quality of service: regular
429437
│ │ regions: <hidden>
430438
│ │ actual row count: 1
431439
│ │ vectorized batch count: 0
440+
│ │ execution time: 0µs
432441
│ │ estimated row count: 10 (missing stats)
433442
│ │ filter: y = 2
434443
│ │
@@ -479,6 +488,7 @@ quality of service: regular
479488
regions: <hidden>
480489
actual row count: 1
481490
vectorized batch count: 0
491+
execution time: 0µs
482492
estimated row count: 1
483493
label: buffer 1000000
484494

@@ -684,6 +694,7 @@ quality of service: regular
684694
│ │ regions: <hidden>
685695
│ │ actual row count: 1
686696
│ │ vectorized batch count: 0
697+
│ │ execution time: 0µs
687698
│ │ estimated row count: 0 (missing stats)
688699
│ │ table: parent
689700
│ │ set: k
@@ -694,6 +705,7 @@ quality of service: regular
694705
│ │ regions: <hidden>
695706
│ │ actual row count: 0
696707
│ │ vectorized batch count: 0
708+
│ │ execution time: 0µs
697709
│ │ label: buffer 1
698710
│ │
699711
│ └── • render
@@ -757,6 +769,7 @@ quality of service: regular
757769
│ │ regions: <hidden>
758770
│ │ actual row count: 1
759771
│ │ vectorized batch count: 0
772+
│ │ execution time: 0µs
760773
│ │ estimated row count: 0 (missing stats)
761774
│ │ table: parent
762775
│ │ set: k
@@ -767,6 +780,7 @@ quality of service: regular
767780
│ │ regions: <hidden>
768781
│ │ actual row count: 1
769782
│ │ vectorized batch count: 0
783+
│ │ execution time: 0µs
770784
│ │ label: buffer 1
771785
│ │
772786
│ └── • render
@@ -807,6 +821,7 @@ quality of service: regular
807821
│ │ regions: <hidden>
808822
│ │ actual row count: 0
809823
│ │ vectorized batch count: 0
824+
│ │ execution time: 0µs
810825
│ │ estimated row count: 0 (missing stats)
811826
│ │ table: child
812827
│ │ set: fk
@@ -820,6 +835,7 @@ quality of service: regular
820835
│ │ regions: <hidden>
821836
│ │ actual row count: 1
822837
│ │ vectorized batch count: 0
838+
│ │ execution time: 0µs
823839
│ │ label: buffer 1
824840
│ │
825841
│ └── • filter
@@ -828,6 +844,7 @@ quality of service: regular
828844
│ │ regions: <hidden>
829845
│ │ actual row count: 1
830846
│ │ vectorized batch count: 0
847+
│ │ execution time: 0µs
831848
│ │ estimated row count: 3 (missing stats)
832849
│ │ filter: f IS DISTINCT FROM NULL
833850
│ │
@@ -867,6 +884,7 @@ quality of service: regular
867884
│ │ regions: <hidden>
868885
│ │ actual row count: 1
869886
│ │ vectorized batch count: 0
887+
│ │ execution time: 0µs
870888
│ │ estimated max memory allocated: 0 B
871889
│ │ estimated row count: 3 (missing stats)
872890
│ │ equality: (fk) = (k)
@@ -897,6 +915,7 @@ quality of service: regular
897915
│ │ regions: <hidden>
898916
│ │ actual row count: 1
899917
│ │ vectorized batch count: 0
918+
│ │ execution time: 0µs
900919
│ │ estimated row count: 0
901920
│ │ filter: k IS DISTINCT FROM k_new
902921
│ │
@@ -906,6 +925,7 @@ quality of service: regular
906925
│ regions: <hidden>
907926
│ actual row count: 1
908927
│ vectorized batch count: 0
928+
│ execution time: 0µs
909929
│ estimated row count: 1
910930
│ label: buffer 1000000
911931
│
@@ -917,6 +937,7 @@ quality of service: regular
917937
│ │ regions: <hidden>
918938
│ │ actual row count: 0
919939
│ │ vectorized batch count: 0
940+
│ │ execution time: 0µs
920941
│ │
921942
│ └── • lookup join (anti)
922943
│ │ columns: (fk_new)
@@ -931,6 +952,7 @@ quality of service: regular
931952
│ │ KV pairs read: 2
932953
│ │ KV bytes read: 8 B
933954
│ │ KV gRPC calls: 1
955+
│ │ execution time: 0µs
934956
│ │ estimated max memory allocated: 0 B
935957
│ │ MVCC step count (ext/int): 0/0
936958
│ │ MVCC seek count (ext/int): 0/0
@@ -945,6 +967,7 @@ quality of service: regular
945967
│ │ regions: <hidden>
946968
│ │ actual row count: 1
947969
│ │ vectorized batch count: 0
970+
│ │ execution time: 0µs
948971
│ │ estimated row count: 3 (missing stats)
949972
│ │ filter: fk_new IS NOT NULL
950973
│ │
@@ -957,6 +980,7 @@ quality of service: regular
957980
│ regions: <hidden>
958981
│ actual row count: 1
959982
│ vectorized batch count: 0
983+
│ execution time: 0µs
960984
│ estimated row count: 3 (missing stats)
961985
│ label: buffer 1
962986
│
@@ -991,6 +1015,7 @@ quality of service: regular
9911015
regions: <hidden>
9921016
actual row count: 1
9931017
vectorized batch count: 0
1018+
execution time: 0µs
9941019
estimated row count: 1
9951020
label: buffer 1000000
9961021

@@ -1025,6 +1050,7 @@ quality of service: regular
10251050
│ regions: <hidden>
10261051
│ actual row count: 1
10271052
│ vectorized batch count: 0
1053+
│ execution time: 0µs
10281054
│ estimated row count: 0 (missing stats)
10291055
│ from: parent
10301056
│ spans: /2/0
@@ -1041,6 +1067,7 @@ quality of service: regular
10411067
│ │ regions: <hidden>
10421068
│ │ actual row count: 0
10431069
│ │ vectorized batch count: 0
1070+
│ │ execution time: 0µs
10441071
│ │ estimated row count: 0 (missing stats)
10451072
│ │ from: child
10461073
│ │
@@ -1053,6 +1080,7 @@ quality of service: regular
10531080
│ │ regions: <hidden>
10541081
│ │ actual row count: 1
10551082
│ │ vectorized batch count: 0
1083+
│ │ execution time: 0µs
10561084
│ │ label: buffer 1
10571085
│ │
10581086
│ └── • filter
@@ -1061,6 +1089,7 @@ quality of service: regular
10611089
│ │ regions: <hidden>
10621090
│ │ actual row count: 1
10631091
│ │ vectorized batch count: 0
1092+
│ │ execution time: 0µs
10641093
│ │ estimated row count: 10 (missing stats)
10651094
│ │ filter: f IS DISTINCT FROM NULL
10661095
│ │
@@ -1091,6 +1120,7 @@ quality of service: regular
10911120
│ │ regions: <hidden>
10921121
│ │ actual row count: 1
10931122
│ │ vectorized batch count: 0
1123+
│ │ execution time: 0µs
10941124
│ │ estimated row count: 10 (missing stats)
10951125
│ │ filter: fk = 2
10961126
│ │
@@ -1141,6 +1171,7 @@ quality of service: regular
11411171
regions: <hidden>
11421172
actual row count: 1
11431173
vectorized batch count: 0
1174+
execution time: 0µs
11441175
estimated row count: 1
11451176
label: buffer 1000000
11461177

Diff for: ‎pkg/sql/instrumentation.go

+1
Original file line numberDiff line numberDiff line change
@@ -1067,6 +1067,7 @@ func (m execNodeTraceMetadata) annotateExplain(
10671067
nodeStats.SeekCount.MaybeAdd(stats.KV.NumInterfaceSeeks)
10681068
nodeStats.InternalSeekCount.MaybeAdd(stats.KV.NumInternalSeeks)
10691069
nodeStats.VectorizedBatchCount.MaybeAdd(stats.Output.NumBatches)
1070+
nodeStats.ExecTime.MaybeAdd(stats.Exec.ExecTime)
10701071
nodeStats.MaxAllocatedMem.MaybeAdd(stats.Exec.MaxAllocatedMem)
10711072
nodeStats.MaxAllocatedDisk.MaybeAdd(stats.Exec.MaxAllocatedDisk)
10721073
if noMutations && !makeDeterministic {

Diff for: ‎pkg/sql/opt/exec/execbuilder/testdata/call

+2
Original file line numberDiff line numberDiff line change
@@ -149,6 +149,7 @@ quality of service: regular
149149
sql nodes: <hidden>
150150
regions: <hidden>
151151
actual row count: 0
152+
execution time: 0µs
152153
estimated row count: 0
153154
procedure: foo(3)
154155

@@ -171,6 +172,7 @@ quality of service: regular
171172
sql nodes: <hidden>
172173
regions: <hidden>
173174
actual row count: 0
175+
execution time: 0µs
174176
estimated row count: 0
175177
procedure: foo(3)
176178
·

Diff for: ‎pkg/sql/opt/exec/execbuilder/testdata/cascade

+14
Original file line numberDiff line numberDiff line change
@@ -1067,12 +1067,14 @@ quality of service: regular
10671067
│ │ sql nodes: <hidden>
10681068
│ │ regions: <hidden>
10691069
│ │ actual row count: 1
1070+
│ │ execution time: 0µs
10701071
│ │ from: loop_a
10711072
│ │
10721073
│ └── • buffer
10731074
│ │ sql nodes: <hidden>
10741075
│ │ regions: <hidden>
10751076
│ │ actual row count: 1
1077+
│ │ execution time: 0µs
10761078
│ │ label: buffer 1
10771079
│ │
10781080
│ └── • scan
@@ -1101,18 +1103,21 @@ quality of service: regular
11011103
│ │ sql nodes: <hidden>
11021104
│ │ regions: <hidden>
11031105
│ │ actual row count: 0
1106+
│ │ execution time: 0µs
11041107
│ │ from: loop_b
11051108
│ │
11061109
│ └── • buffer
11071110
│ │ sql nodes: <hidden>
11081111
│ │ regions: <hidden>
11091112
│ │ actual row count: 1
1113+
│ │ execution time: 0µs
11101114
│ │ label: buffer 1
11111115
│ │
11121116
│ └── • hash join (semi)
11131117
│ │ sql nodes: <hidden>
11141118
│ │ regions: <hidden>
11151119
│ │ actual row count: 1
1120+
│ │ execution time: 0µs
11161121
│ │ estimated max memory allocated: 0 B
11171122
│ │ equality: (cascade_delete) = (id)
11181123
│ │
@@ -1136,6 +1141,7 @@ quality of service: regular
11361141
│ sql nodes: <hidden>
11371142
│ regions: <hidden>
11381143
│ actual row count: 1
1144+
│ execution time: 0µs
11391145
│ estimated row count: 1
11401146
│ label: buffer 1000000
11411147
│
@@ -1148,12 +1154,14 @@ quality of service: regular
11481154
│ │ sql nodes: <hidden>
11491155
│ │ regions: <hidden>
11501156
│ │ actual row count: 0
1157+
│ │ execution time: 0µs
11511158
│ │ from: loop_a
11521159
│ │
11531160
│ └── • buffer
11541161
│ │ sql nodes: <hidden>
11551162
│ │ regions: <hidden>
11561163
│ │ actual row count: 1
1164+
│ │ execution time: 0µs
11571165
│ │ label: buffer 1
11581166
│ │
11591167
│ └── • lookup join
@@ -1167,6 +1175,7 @@ quality of service: regular
11671175
│ │ KV pairs read: 2
11681176
│ │ KV bytes read: 8 B
11691177
│ │ KV gRPC calls: 1
1178+
│ │ execution time: 0µs
11701179
│ │ estimated max memory allocated: 0 B
11711180
│ │ table: loop_a@loop_a_cascade_delete_idx
11721181
│ │ equality: (id) = (cascade_delete)
@@ -1175,6 +1184,7 @@ quality of service: regular
11751184
│ │ sql nodes: <hidden>
11761185
│ │ regions: <hidden>
11771186
│ │ actual row count: 1
1187+
│ │ execution time: 0µs
11781188
│ │ estimated max memory allocated: 0 B
11791189
│ │ estimated row count: 1
11801190
│ │ distinct on: id
@@ -1183,6 +1193,7 @@ quality of service: regular
11831193
│ sql nodes: <hidden>
11841194
│ regions: <hidden>
11851195
│ actual row count: 1
1196+
│ execution time: 0µs
11861197
│ estimated row count: 1
11871198
│ label: buffer 1000000
11881199
│
@@ -1471,18 +1482,21 @@ quality of service: regular
14711482
│ │ sql nodes: <hidden>
14721483
│ │ regions: <hidden>
14731484
│ │ actual row count: 1
1485+
│ │ execution time: 0µs
14741486
│ │ from: p138974
14751487
│ │
14761488
│ └── • buffer
14771489
│ │ sql nodes: <hidden>
14781490
│ │ regions: <hidden>
14791491
│ │ actual row count: 0
1492+
│ │ execution time: 0µs
14801493
│ │ label: buffer 1
14811494
│ │
14821495
│ └── • filter
14831496
│ │ sql nodes: <hidden>
14841497
│ │ regions: <hidden>
14851498
│ │ actual row count: 0
1499+
│ │ execution time: 0µs
14861500
│ │ filter: v = 1
14871501
│ │
14881502
│ └── • scan

0 commit comments

Comments
 (0)