From 0f563dd734d13380272b7db19bb5655e62bb02fa Mon Sep 17 00:00:00 2001 From: Yahor Yuzefovich Date: Wed, 5 Oct 2022 19:18:09 -0700 Subject: [PATCH] execinfra: remove possible logging for each output row of processors MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This commit removes possible logging (hidden behind level 3 verbosity) for each row that flows through `ProcessRowHelper` (which effectively all processors use). The verbosity check itself has non-trivial performance cost in this case. I think it's ok to remove it given that this logging was commented out until ea559dfe0ba57259ca71d3c8ca1de6388954ea73, and I don't recall ever having a desire to see all of the rows. ``` name old time/op new time/op delta Noop/cols=1-24 907µs ± 0% 749µs ± 0% -17.43% (p=0.000 n=9+9) Noop/cols=2-24 906µs ± 0% 748µs ± 0% -17.44% (p=0.000 n=9+10) Noop/cols=4-24 908µs ± 0% 748µs ± 0% -17.64% (p=0.000 n=10+9) Noop/cols=16-24 908µs ± 0% 749µs ± 0% -17.57% (p=0.000 n=10+10) Noop/cols=256-24 911µs ± 0% 751µs ± 0% -17.50% (p=0.000 n=10+10) name old speed new speed delta Noop/cols=1-24 578MB/s ± 0% 700MB/s ± 0% +21.12% (p=0.000 n=9+9) Noop/cols=2-24 1.16GB/s ± 0% 1.40GB/s ± 0% +21.13% (p=0.000 n=9+10) Noop/cols=4-24 2.31GB/s ± 0% 2.80GB/s ± 0% +21.41% (p=0.000 n=10+9) Noop/cols=16-24 9.24GB/s ± 0% 11.20GB/s ± 0% +21.32% (p=0.000 n=10+10) Noop/cols=256-24 147GB/s ± 0% 179GB/s ± 0% +21.22% (p=0.000 n=10+10) name old alloc/op new alloc/op delta Noop/cols=1-24 1.45kB ± 0% 1.45kB ± 0% -0.07% (p=0.000 n=10+10) Noop/cols=2-24 1.46kB ± 0% 1.46kB ± 0% -0.07% (p=0.000 n=10+9) Noop/cols=4-24 1.47kB ± 0% 1.47kB ± 0% -0.07% (p=0.000 n=10+10) Noop/cols=16-24 1.57kB ± 0% 1.57kB ± 0% -0.06% (p=0.000 n=10+10) Noop/cols=256-24 3.49kB ± 0% 3.49kB ± 0% -0.03% (p=0.000 n=10+10) name old allocs/op new allocs/op delta Noop/cols=1-24 5.00 ± 0% 5.00 ± 0% ~ (all equal) Noop/cols=2-24 5.00 ± 0% 5.00 ± 0% ~ (all equal) Noop/cols=4-24 5.00 ± 0% 5.00 ± 0% ~ (all equal) Noop/cols=16-24 5.00 ± 0% 5.00 ± 0% ~ (all equal) Noop/cols=256-24 5.00 ± 0% 5.00 ± 0% ~ (all equal) ``` Release note: None --- pkg/sql/execinfra/processorsbase.go | 5 ++--- pkg/sql/flowinfra/inbound.go | 2 ++ 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/pkg/sql/execinfra/processorsbase.go b/pkg/sql/execinfra/processorsbase.go index 4cc35e0f08ab..ccdba748924e 100644 --- a/pkg/sql/execinfra/processorsbase.go +++ b/pkg/sql/execinfra/processorsbase.go @@ -225,6 +225,8 @@ func (h *ProcOutputHelper) EmitRow( return DrainRequested, nil } + // TODO(yuzefovich): consider removing this logging since the verbosity + // check is not exactly free. if log.V(3) { log.InfofDepth(ctx, 1, "pushing row %s", outRow.String(h.OutputTypes)) } @@ -714,9 +716,6 @@ func (pb *ProcessorBase) ProcessRowHelper(row rowenc.EncDatumRow) rowenc.EncDatu if !ok { pb.MoveToDraining(nil /* err */) } - if outRow != nil && log.V(3) && pb.Ctx != nil { - log.InfofDepth(pb.Ctx, 1, "pushing row %s", outRow.String(pb.OutputHelper.OutputTypes)) - } return outRow } diff --git a/pkg/sql/flowinfra/inbound.go b/pkg/sql/flowinfra/inbound.go index 2b82dd2d807c..dbc891efa847 100644 --- a/pkg/sql/flowinfra/inbound.go +++ b/pkg/sql/flowinfra/inbound.go @@ -226,6 +226,8 @@ func processProducerMessage( return processMessageResult{err: nil, consumerClosed: false} } + // TODO(yuzefovich): consider removing this logging since the verbosity + // check is not exactly free. if log.V(3) && row != nil { log.Infof(ctx, "inbound stream pushing row %s", row.String(sd.types)) }