Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

storage: MVCCGet showing significant MVCCIterator.Stats() CPU time #86083

Closed
erikgrinaker opened this issue Aug 13, 2022 · 3 comments · Fixed by #86084
Closed

storage: MVCCGet showing significant MVCCIterator.Stats() CPU time #86083

erikgrinaker opened this issue Aug 13, 2022 · 3 comments · Fixed by #86084
Assignees
@erikgrinaker
Labels
A-storage Relating to our storage engine (Pebble) on-disk storage. C-performance Perf of queries or internals. Solution not expected to change functional behavior. T-storage Storage Team

Comments

@erikgrinaker
Copy link
Contributor

erikgrinaker commented Aug 13, 2022 •
edited by cockroach-jira-scripts
Loading

MVCCIterator.Stats() has been seen to use ~4% of CPU during MVCCGet benchmarks:

Screenshot 2022-08-13 at 17 15 06

This is used to attach iterator stats to a running trace, but the stats collection is called unconditionally (regardless of whether an actual trace is in progress):

cockroach/pkg/storage/mvcc.go

Lines 999 to 1000 in 9fb8d36

// If we have a trace, emit the scan stats that we produced.
recordIteratorStats(ctx, mvccScanner.stats())

Jira issue: CRDB-18562
@erikgrinaker erikgrinaker added C-performance Perf of queries or internals. Solution not expected to change functional behavior. T-storage Storage Team labels Aug 13, 2022
@erikgrinaker erikgrinaker self-assigned this Aug 13, 2022
@blathers-crl blathers-crl bot added the A-storage Relating to our storage engine (Pebble) on-disk storage. label Aug 13, 2022
@erikgrinaker erikgrinaker mentioned this issue Aug 13, 2022
Merged
@erikgrinaker
Copy link
Contributor Author

erikgrinaker commented Aug 13, 2022 •
edited
Loading

@jbowens I'm removing the unconditional stats collection in #86084, but it's a bit suspicious that the stats collection here is so expensive in the first place.

@jbowens
Copy link
Collaborator

jbowens commented Aug 13, 2022

Good call removing it.

cc @sumeerbhola — rather than descending the internal iterator stack summing stats across iterators, maybe we should thread a single stats pointer that all the internal iterators may incrementally add to, but only if stats are explicitly enabled on the iterator?

@craig craig bot closed this as completed in dff8a8b Aug 13, 2022
@sumeerbhola
Copy link
Collaborator

cc @sumeerbhola — rather than descending the internal iterator stack summing stats across iterators, maybe we should thread a single stats pointer that all the internal iterators may incrementally add to

that sounds very reasonable

@jbowens jbowens mentioned this issue Aug 19, 2022
Merged
jbowens added a commit to jbowens/pebble that referenced this issue Aug 19, 2022
@jbowens
*: propagate pointer to InternalIteratorStats
8a90664 
Replace the base.InternalIteratorWithStats interface with logic to propagate a
pointer to a shared *InternalIteratorStats down the iterator tree during
iterator construction. This reduces the cost of collecting stats, which no
longer needs to descend the iterator tree summing stats as it goes.

Informs cockroachdb/cockroach#86083.
Informs cockroachdb/cockroach#82559.

```
name                                                                     old time/op    new time/op    delta
MVCCScan_Pebble/rows=1/versions=1/valueSize=64/numRangeKeys=0-24           6.80µs ± 1%    6.58µs ± 1%  -3.16%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=1/versions=1/valueSize=64/numRangeKeys=1-24           14.1µs ± 1%    13.4µs ± 2%  -4.65%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=1/versions=1/valueSize=64/numRangeKeys=100-24          154µs ± 2%     155µs ± 1%    ~     (p=1.000 n=5+5)
MVCCScan_Pebble/rows=1/versions=2/valueSize=64/numRangeKeys=0-24           7.16µs ± 2%    7.05µs ± 1%    ~     (p=0.095 n=5+5)
MVCCScan_Pebble/rows=1/versions=2/valueSize=64/numRangeKeys=1-24           15.0µs ± 1%    14.4µs ± 2%  -3.90%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=1/versions=2/valueSize=64/numRangeKeys=100-24          155µs ± 1%     156µs ± 2%    ~     (p=0.690 n=5+5)
MVCCScan_Pebble/rows=1/versions=10/valueSize=64/numRangeKeys=0-24          9.15µs ± 2%    8.72µs ± 3%  -4.71%  (p=0.032 n=5+5)
MVCCScan_Pebble/rows=1/versions=10/valueSize=64/numRangeKeys=1-24          18.2µs ± 2%    17.7µs ± 1%  -3.01%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=1/versions=10/valueSize=64/numRangeKeys=100-24         147µs ± 4%     144µs ± 4%    ~     (p=0.151 n=5+5)
MVCCScan_Pebble/rows=1/versions=100/valueSize=64/numRangeKeys=0-24         18.1µs ± 2%    17.6µs ± 2%  -2.52%  (p=0.032 n=5+5)
MVCCScan_Pebble/rows=1/versions=100/valueSize=64/numRangeKeys=1-24         27.5µs ± 1%    26.9µs ± 1%  -2.18%  (p=0.032 n=5+5)
MVCCScan_Pebble/rows=1/versions=100/valueSize=64/numRangeKeys=100-24        112µs ± 4%     111µs ± 1%    ~     (p=0.151 n=5+5)
MVCCScan_Pebble/rows=10/versions=1/valueSize=64/numRangeKeys=0-24          12.1µs ± 2%    11.7µs ± 4%    ~     (p=0.056 n=5+5)
MVCCScan_Pebble/rows=10/versions=1/valueSize=64/numRangeKeys=1-24          21.5µs ± 1%    20.8µs ± 3%  -3.26%  (p=0.016 n=5+5)
MVCCScan_Pebble/rows=10/versions=1/valueSize=64/numRangeKeys=100-24         105µs ± 3%     105µs ± 1%    ~     (p=0.310 n=5+5)
MVCCScan_Pebble/rows=10/versions=2/valueSize=64/numRangeKeys=0-24          13.8µs ± 2%    13.4µs ± 1%  -3.07%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=10/versions=2/valueSize=64/numRangeKeys=1-24          24.3µs ± 2%    23.5µs ± 2%  -2.98%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=10/versions=2/valueSize=64/numRangeKeys=100-24         109µs ± 2%     108µs ± 2%    ~     (p=0.690 n=5+5)
MVCCScan_Pebble/rows=10/versions=10/valueSize=64/numRangeKeys=0-24         25.0µs ± 1%    24.4µs ± 2%  -2.37%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=10/versions=10/valueSize=64/numRangeKeys=1-24         42.6µs ± 2%    41.0µs ± 1%  -3.83%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=10/versions=10/valueSize=64/numRangeKeys=100-24        129µs ± 3%     127µs ± 1%    ~     (p=0.095 n=5+5)
MVCCScan_Pebble/rows=10/versions=100/valueSize=64/numRangeKeys=0-24        63.2µs ± 1%    61.6µs ± 1%  -2.48%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=10/versions=100/valueSize=64/numRangeKeys=1-24        83.4µs ± 1%    81.1µs ± 1%  -2.71%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=10/versions=100/valueSize=64/numRangeKeys=100-24       178µs ± 2%     175µs ± 2%    ~     (p=0.056 n=5+5)
MVCCScan_Pebble/rows=100/versions=1/valueSize=64/numRangeKeys=0-24         47.4µs ± 2%    47.5µs ± 3%    ~     (p=1.000 n=5+5)
MVCCScan_Pebble/rows=100/versions=1/valueSize=64/numRangeKeys=1-24         74.2µs ± 1%    72.1µs ± 2%  -2.74%  (p=0.032 n=5+5)
MVCCScan_Pebble/rows=100/versions=1/valueSize=64/numRangeKeys=100-24        173µs ± 1%     174µs ± 2%    ~     (p=0.690 n=5+5)
MVCCScan_Pebble/rows=100/versions=2/valueSize=64/numRangeKeys=0-24         60.8µs ± 2%    60.5µs ± 3%    ~     (p=0.421 n=5+5)
MVCCScan_Pebble/rows=100/versions=2/valueSize=64/numRangeKeys=1-24         95.8µs ± 1%    93.4µs ± 1%  -2.55%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=100/versions=2/valueSize=64/numRangeKeys=100-24        197µs ± 2%     195µs ± 3%    ~     (p=0.421 n=5+5)
MVCCScan_Pebble/rows=100/versions=10/valueSize=64/numRangeKeys=0-24         148µs ± 1%     146µs ± 2%    ~     (p=0.310 n=5+5)
MVCCScan_Pebble/rows=100/versions=10/valueSize=64/numRangeKeys=1-24         247µs ± 1%     240µs ± 1%  -2.89%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=100/versions=10/valueSize=64/numRangeKeys=100-24       390µs ± 2%     385µs ± 1%    ~     (p=0.421 n=5+5)
MVCCScan_Pebble/rows=100/versions=100/valueSize=64/numRangeKeys=0-24        441µs ± 2%     443µs ± 2%    ~     (p=0.690 n=5+5)
MVCCScan_Pebble/rows=100/versions=100/valueSize=64/numRangeKeys=1-24        558µs ± 1%     540µs ± 2%  -3.22%  (p=0.016 n=4+5)
MVCCScan_Pebble/rows=100/versions=100/valueSize=64/numRangeKeys=100-24      790µs ± 2%     771µs ± 1%  -2.36%  (p=0.016 n=5+5)
MVCCScan_Pebble/rows=1000/versions=1/valueSize=64/numRangeKeys=0-24         350µs ± 1%     352µs ± 1%    ~     (p=0.548 n=5+5)
MVCCScan_Pebble/rows=1000/versions=1/valueSize=64/numRangeKeys=1-24         539µs ± 1%     531µs ± 1%  -1.42%  (p=0.016 n=5+5)
MVCCScan_Pebble/rows=1000/versions=1/valueSize=64/numRangeKeys=100-24       759µs ± 1%     752µs ± 2%    ~     (p=0.222 n=5+5)
MVCCScan_Pebble/rows=1000/versions=2/valueSize=64/numRangeKeys=0-24         472µs ± 0%     474µs ± 1%    ~     (p=0.556 n=4+5)
MVCCScan_Pebble/rows=1000/versions=2/valueSize=64/numRangeKeys=1-24         755µs ± 1%     752µs ± 1%    ~     (p=0.548 n=5+5)
MVCCScan_Pebble/rows=1000/versions=2/valueSize=64/numRangeKeys=100-24      1.02ms ± 3%    0.97ms ± 1%  -4.30%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=1000/versions=10/valueSize=64/numRangeKeys=0-24       1.29ms ± 1%    1.27ms ± 2%    ~     (p=0.056 n=5+5)
MVCCScan_Pebble/rows=1000/versions=10/valueSize=64/numRangeKeys=1-24       2.19ms ± 1%    2.11ms ± 1%  -3.80%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=1000/versions=10/valueSize=64/numRangeKeys=100-24     2.82ms ± 2%    2.75ms ± 3%    ~     (p=0.056 n=5+5)
MVCCScan_Pebble/rows=1000/versions=100/valueSize=64/numRangeKeys=0-24      4.11ms ± 1%    4.03ms ± 1%  -1.86%  (p=0.032 n=5+5)
MVCCScan_Pebble/rows=1000/versions=100/valueSize=64/numRangeKeys=1-24      5.17ms ± 2%    4.96ms ± 2%  -4.07%  (p=0.008 n=5+5)
MVCCScan_Pebble/rows=1000/versions=100/valueSize=64/numRangeKeys=100-24    6.69ms ± 2%    6.51ms ± 2%    ~     (p=0.056 n=5+5)
```
jbowens added a commit to jbowens/pebble that referenced this issue Aug 23, 2022
@jbowens
*: propagate pointer to InternalIteratorStats
14d80cd 
Replace the base.InternalIteratorWithStats interface with logic to propagate a
pointer to a shared *InternalIteratorStats down the iterator tree during
iterator construction. This reduces the cost of collecting stats, which no
longer needs to descend the iterator tree summing stats as it goes.

Informs cockroachdb/cockroach#86083.
Informs cockroachdb/cockroach#82559.
jbowens added a commit to cockroachdb/pebble that referenced this issue Aug 23, 2022
@jbowens
*: propagate pointer to InternalIteratorStats
4cc0974 
Replace the base.InternalIteratorWithStats interface with logic to propagate a
pointer to a shared *InternalIteratorStats down the iterator tree during
iterator construction. This reduces the cost of collecting stats, which no
longer needs to descend the iterator tree summing stats as it goes.

Informs cockroachdb/cockroach#86083.
Informs cockroachdb/cockroach#82559.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@erikgrinaker erikgrinaker

Labels
A-storage Relating to our storage engine (Pebble) on-disk storage. C-performance Perf of queries or internals. Solution not expected to change functional behavior. T-storage Storage Team
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

storage: omit MVCCIterator.Stats() call during MVCCScan/MVCCGet erikgrinaker/cockroach
3 participants
@erikgrinaker @jbowens @sumeerbhola