Skip to content

Commit ad1c795

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 d8a12af commit ad1c795

16 files changed

+132
-0
lines changed

‎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
·

‎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
│ │
@@ -411,6 +417,7 @@ quality of service: regular
411417
│ │ regions: <hidden>
412418
│ │ actual row count: 1
413419
│ │ vectorized batch count: 0
420+
│ │ execution time: 0µs
414421
│ │ estimated row count: 0 (missing stats)
415422
│ │ from: xy
416423
│ │
@@ -420,6 +427,7 @@ quality of service: regular
420427
│ │ regions: <hidden>
421428
│ │ actual row count: 1
422429
│ │ vectorized batch count: 0
430+
│ │ execution time: 0µs
423431
│ │ label: buffer 1
424432
│ │
425433
│ └── • filter
@@ -428,6 +436,7 @@ quality of service: regular
428436
│ │ regions: <hidden>
429437
│ │ actual row count: 1
430438
│ │ vectorized batch count: 0
439+
│ │ execution time: 0µs
431440
│ │ estimated row count: 10 (missing stats)
432441
│ │ filter: y = 2
433442
│ │
@@ -478,6 +487,7 @@ quality of service: regular
478487
regions: <hidden>
479488
actual row count: 1
480489
vectorized batch count: 0
490+
execution time: 0µs
481491
estimated row count: 1
482492
label: buffer 1000000
483493

@@ -683,6 +693,7 @@ quality of service: regular
683693
│ │ regions: <hidden>
684694
│ │ actual row count: 1
685695
│ │ vectorized batch count: 0
696+
│ │ execution time: 0µs
686697
│ │ estimated row count: 0 (missing stats)
687698
│ │ table: parent
688699
│ │ set: k
@@ -693,6 +704,7 @@ quality of service: regular
693704
│ │ regions: <hidden>
694705
│ │ actual row count: 0
695706
│ │ vectorized batch count: 0
707+
│ │ execution time: 0µs
696708
│ │ label: buffer 1
697709
│ │
698710
│ └── • render
@@ -755,6 +767,7 @@ quality of service: regular
755767
│ │ regions: <hidden>
756768
│ │ actual row count: 1
757769
│ │ vectorized batch count: 0
770+
│ │ execution time: 0µs
758771
│ │ estimated row count: 0 (missing stats)
759772
│ │ table: parent
760773
│ │ set: k
@@ -765,6 +778,7 @@ quality of service: regular
765778
│ │ regions: <hidden>
766779
│ │ actual row count: 1
767780
│ │ vectorized batch count: 0
781+
│ │ execution time: 0µs
768782
│ │ label: buffer 1
769783
│ │
770784
│ └── • render
@@ -805,6 +819,7 @@ quality of service: regular
805819
│ │ regions: <hidden>
806820
│ │ actual row count: 0
807821
│ │ vectorized batch count: 0
822+
│ │ execution time: 0µs
808823
│ │ estimated row count: 0 (missing stats)
809824
│ │ table: child
810825
│ │ set: fk
@@ -818,6 +833,7 @@ quality of service: regular
818833
│ │ regions: <hidden>
819834
│ │ actual row count: 1
820835
│ │ vectorized batch count: 0
836+
│ │ execution time: 0µs
821837
│ │ label: buffer 1
822838
│ │
823839
│ └── • filter
@@ -826,6 +842,7 @@ quality of service: regular
826842
│ │ regions: <hidden>
827843
│ │ actual row count: 1
828844
│ │ vectorized batch count: 0
845+
│ │ execution time: 0µs
829846
│ │ estimated row count: 3 (missing stats)
830847
│ │ filter: f IS DISTINCT FROM NULL
831848
│ │
@@ -865,6 +882,7 @@ quality of service: regular
865882
│ │ regions: <hidden>
866883
│ │ actual row count: 1
867884
│ │ vectorized batch count: 0
885+
│ │ execution time: 0µs
868886
│ │ estimated max memory allocated: 0 B
869887
│ │ estimated max sql temp disk usage: 0 B
870888
│ │ estimated row count: 3 (missing stats)
@@ -896,6 +914,7 @@ quality of service: regular
896914
│ │ regions: <hidden>
897915
│ │ actual row count: 1
898916
│ │ vectorized batch count: 0
917+
│ │ execution time: 0µs
899918
│ │ estimated row count: 0
900919
│ │ filter: k IS DISTINCT FROM k_new
901920
│ │
@@ -905,6 +924,7 @@ quality of service: regular
905924
│ regions: <hidden>
906925
│ actual row count: 1
907926
│ vectorized batch count: 0
927+
│ execution time: 0µs
908928
│ estimated row count: 1
909929
│ label: buffer 1000000
910930
│
@@ -916,6 +936,7 @@ quality of service: regular
916936
│ │ regions: <hidden>
917937
│ │ actual row count: 0
918938
│ │ vectorized batch count: 0
939+
│ │ execution time: 0µs
919940
│ │
920941
│ └── • lookup join (anti)
921942
│ │ columns: (fk_new)
@@ -930,6 +951,7 @@ quality of service: regular
930951
│ │ KV pairs read: 2
931952
│ │ KV bytes read: 8 B
932953
│ │ KV gRPC calls: 1
954+
│ │ execution time: 0µs
933955
│ │ estimated max memory allocated: 0 B
934956
│ │ MVCC step count (ext/int): 0/0
935957
│ │ MVCC seek count (ext/int): 0/0
@@ -944,6 +966,7 @@ quality of service: regular
944966
│ │ regions: <hidden>
945967
│ │ actual row count: 1
946968
│ │ vectorized batch count: 0
969+
│ │ execution time: 0µs
947970
│ │ estimated row count: 3 (missing stats)
948971
│ │ filter: fk_new IS NOT NULL
949972
│ │
@@ -956,6 +979,7 @@ quality of service: regular
956979
│ regions: <hidden>
957980
│ actual row count: 1
958981
│ vectorized batch count: 0
982+
│ execution time: 0µs
959983
│ estimated row count: 3 (missing stats)
960984
│ label: buffer 1
961985
│
@@ -990,6 +1014,7 @@ quality of service: regular
9901014
regions: <hidden>
9911015
actual row count: 1
9921016
vectorized batch count: 0
1017+
execution time: 0µs
9931018
estimated row count: 1
9941019
label: buffer 1000000
9951020

@@ -1024,6 +1049,7 @@ quality of service: regular
10241049
│ regions: <hidden>
10251050
│ actual row count: 1
10261051
│ vectorized batch count: 0
1052+
│ execution time: 0µs
10271053
│ estimated row count: 0 (missing stats)
10281054
│ from: parent
10291055
│ spans: /2/0
@@ -1040,6 +1066,7 @@ quality of service: regular
10401066
│ │ regions: <hidden>
10411067
│ │ actual row count: 0
10421068
│ │ vectorized batch count: 0
1069+
│ │ execution time: 0µs
10431070
│ │ estimated row count: 0 (missing stats)
10441071
│ │ from: child
10451072
│ │
@@ -1052,6 +1079,7 @@ quality of service: regular
10521079
│ │ regions: <hidden>
10531080
│ │ actual row count: 1
10541081
│ │ vectorized batch count: 0
1082+
│ │ execution time: 0µs
10551083
│ │ label: buffer 1
10561084
│ │
10571085
│ └── • filter
@@ -1060,6 +1088,7 @@ quality of service: regular
10601088
│ │ regions: <hidden>
10611089
│ │ actual row count: 1
10621090
│ │ vectorized batch count: 0
1091+
│ │ execution time: 0µs
10631092
│ │ estimated row count: 10 (missing stats)
10641093
│ │ filter: f IS DISTINCT FROM NULL
10651094
│ │
@@ -1090,6 +1119,7 @@ quality of service: regular
10901119
│ │ regions: <hidden>
10911120
│ │ actual row count: 1
10921121
│ │ vectorized batch count: 0
1122+
│ │ execution time: 0µs
10931123
│ │ estimated row count: 10 (missing stats)
10941124
│ │ filter: fk = 2
10951125
│ │
@@ -1140,6 +1170,7 @@ quality of service: regular
11401170
regions: <hidden>
11411171
actual row count: 1
11421172
vectorized batch count: 0
1173+
execution time: 0µs
11431174
estimated row count: 1
11441175
label: buffer 1000000
11451176

‎pkg/sql/instrumentation.go

+1
Original file line numberDiff line numberDiff line change
@@ -1060,6 +1060,7 @@ func (m execNodeTraceMetadata) annotateExplain(
10601060
nodeStats.SeekCount.MaybeAdd(stats.KV.NumInterfaceSeeks)
10611061
nodeStats.InternalSeekCount.MaybeAdd(stats.KV.NumInternalSeeks)
10621062
nodeStats.VectorizedBatchCount.MaybeAdd(stats.Output.NumBatches)
1063+
nodeStats.ExecTime.MaybeAdd(stats.Exec.ExecTime)
10631064
nodeStats.MaxAllocatedMem.MaybeAdd(stats.Exec.MaxAllocatedMem)
10641065
nodeStats.MaxAllocatedDisk.MaybeAdd(stats.Exec.MaxAllocatedDisk)
10651066
if noMutations && !makeDeterministic {

‎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
·

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

+11
Original file line numberDiff line numberDiff line change
@@ -1062,12 +1062,14 @@ quality of service: regular
10621062
│ │ sql nodes: <hidden>
10631063
│ │ regions: <hidden>
10641064
│ │ actual row count: 1
1065+
│ │ execution time: 0µs
10651066
│ │ from: loop_a
10661067
│ │
10671068
│ └── • buffer
10681069
│ │ sql nodes: <hidden>
10691070
│ │ regions: <hidden>
10701071
│ │ actual row count: 1
1072+
│ │ execution time: 0µs
10711073
│ │ label: buffer 1
10721074
│ │
10731075
│ └── • scan
@@ -1095,18 +1097,21 @@ quality of service: regular
10951097
│ │ sql nodes: <hidden>
10961098
│ │ regions: <hidden>
10971099
│ │ actual row count: 0
1100+
│ │ execution time: 0µs
10981101
│ │ from: loop_b
10991102
│ │
11001103
│ └── • buffer
11011104
│ │ sql nodes: <hidden>
11021105
│ │ regions: <hidden>
11031106
│ │ actual row count: 1
1107+
│ │ execution time: 0µs
11041108
│ │ label: buffer 1
11051109
│ │
11061110
│ └── • hash join (semi)
11071111
│ │ sql nodes: <hidden>
11081112
│ │ regions: <hidden>
11091113
│ │ actual row count: 1
1114+
│ │ execution time: 0µs
11101115
│ │ estimated max memory allocated: 0 B
11111116
│ │ estimated max sql temp disk usage: 0 B
11121117
│ │ equality: (cascade_delete) = (id)
@@ -1131,6 +1136,7 @@ quality of service: regular
11311136
│ sql nodes: <hidden>
11321137
│ regions: <hidden>
11331138
│ actual row count: 1
1139+
│ execution time: 0µs
11341140
│ estimated row count: 1
11351141
│ label: buffer 1000000
11361142
│
@@ -1143,12 +1149,14 @@ quality of service: regular
11431149
│ │ sql nodes: <hidden>
11441150
│ │ regions: <hidden>
11451151
│ │ actual row count: 0
1152+
│ │ execution time: 0µs
11461153
│ │ from: loop_a
11471154
│ │
11481155
│ └── • buffer
11491156
│ │ sql nodes: <hidden>
11501157
│ │ regions: <hidden>
11511158
│ │ actual row count: 1
1159+
│ │ execution time: 0µs
11521160
│ │ label: buffer 1
11531161
│ │
11541162
│ └── • lookup join
@@ -1162,6 +1170,7 @@ quality of service: regular
11621170
│ │ KV pairs read: 2
11631171
│ │ KV bytes read: 8 B
11641172
│ │ KV gRPC calls: 1
1173+
│ │ execution time: 0µs
11651174
│ │ estimated max memory allocated: 0 B
11661175
│ │ table: loop_a@loop_a_cascade_delete_idx
11671176
│ │ equality: (id) = (cascade_delete)
@@ -1170,6 +1179,7 @@ quality of service: regular
11701179
│ │ sql nodes: <hidden>
11711180
│ │ regions: <hidden>
11721181
│ │ actual row count: 1
1182+
│ │ execution time: 0µs
11731183
│ │ estimated max memory allocated: 0 B
11741184
│ │ estimated max sql temp disk usage: 0 B
11751185
│ │ estimated row count: 1
@@ -1179,6 +1189,7 @@ quality of service: regular
11791189
│ sql nodes: <hidden>
11801190
│ regions: <hidden>
11811191
│ actual row count: 1
1192+
│ execution time: 0µs
11821193
│ estimated row count: 1
11831194
│ label: buffer 1000000
11841195
│

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

+2
Original file line numberDiff line numberDiff line change
@@ -69,6 +69,7 @@ quality of service: regular
6969
│ sql nodes: <hidden>
7070
│ regions: <hidden>
7171
│ actual row count: 1
72+
│ execution time: 0µs
7273
│
7374
└── • scan
7475
sql nodes: <hidden>
@@ -108,6 +109,7 @@ quality of service: regular
108109
│ sql nodes: <hidden>
109110
│ regions: <hidden>
110111
│ actual row count: 5
112+
│ execution time: 0µs
111113
│ estimated max memory allocated: 0 B
112114
│ estimated max sql temp disk usage: 0 B
113115
│ equality: (k) = (k)

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

+1
Original file line numberDiff line numberDiff line change
@@ -2254,6 +2254,7 @@ quality of service: regular
22542254
sql nodes: <hidden>
22552255
regions: <hidden>
22562256
actual row count: 1
2257+
execution time: 0µs
22572258
size: 1 column, 1 row
22582259

22592260
# Tests for EXPLAIN (OPT, MEMO).

0 commit comments

Comments
 (0)