Skip to content

Commit

Permalink
Merge #89461
Browse files Browse the repository at this point in the history
89461: execinfra: remove possible logging for each output row of processors r=yuzefovich a=yuzefovich

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 ea559df, 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)
```

Addresses: #87685.

Release note: None

Co-authored-by: Yahor Yuzefovich <[email protected]>
  • Loading branch information
craig[bot] and yuzefovich committed Oct 27, 2022
2 parents a5e5a01 + 0f563dd commit 1004523
Show file tree
Hide file tree
Showing 2 changed files with 4 additions and 3 deletions.
5 changes: 2 additions & 3 deletions pkg/sql/execinfra/processorsbase.go
Original file line number Diff line number Diff line change
Expand Up @@ -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))
}
Expand Down Expand Up @@ -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
}

Expand Down
2 changes: 2 additions & 0 deletions pkg/sql/flowinfra/inbound.go
Original file line number Diff line number Diff line change
Expand Up @@ -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))
}
Expand Down

0 comments on commit 1004523

Please sign in to comment.