Skip to content

Conversation

@blathers-crl
Copy link

@blathers-crl blathers-crl bot commented Nov 23, 2023

Backport 1/1 commits from #114773 on behalf of @nvanbenschoten.

/cc @cockroachdb/release


This commit puts expensive logging in MVCCAcquireLock behind a log.ExpensiveLogEnabled condition. This logging was bad in two ways:

  1. it was boxing structs inside of interfaces, which can cause them to allocate and risks them escaping to the heap.
  2. to avoid this risk of escaping, it was prematurely calling .String() on them. This was expensive for the key value, which was being pretty-printed even when tracing was disabled.

This showed up as taking 0.17% of CPU time in a run of TPC-C with Read Committed isolation:

Screenshot 2023-11-20 at 2 49 52 PM

This also showed up in the new MVCCAcquireLock_Pebble benchmark, which this commit improves:

name                                                                                          old time/op    new time/op    delta
MVCCAcquireLock_Pebble/batch=false/heldOtherTxn=false/heldSameTxn=true/strength=Shared-10       4.01µs ± 3%    2.42µs ± 1%  -39.70%  (p=0.000 n=10+9)
MVCCAcquireLock_Pebble/batch=false/heldOtherTxn=false/heldSameTxn=true/strength=Exclusive-10    4.02µs ± 2%    2.42µs ± 1%  -39.75%  (p=0.000 n=9+9)
MVCCAcquireLock_Pebble/batch=true/heldOtherTxn=false/heldSameTxn=true/strength=Shared-10        2.92µs ± 3%    1.60µs ± 2%  -45.18%  (p=0.000 n=9+10)
MVCCAcquireLock_Pebble/batch=true/heldOtherTxn=false/heldSameTxn=true/strength=Exclusive-10     2.91µs ± 2%    1.60µs ± 1%  -45.13%  (p=0.000 n=10+9)

name                                                                                          old alloc/op   new alloc/op   delta
MVCCAcquireLock_Pebble/batch=false/heldOtherTxn=false/heldSameTxn=true/strength=Shared-10         834B ± 0%      372B ± 0%  -55.38%  (p=0.000 n=10+10)
MVCCAcquireLock_Pebble/batch=false/heldOtherTxn=false/heldSameTxn=true/strength=Exclusive-10      834B ± 0%      372B ± 0%  -55.40%  (p=0.000 n=9+10)
MVCCAcquireLock_Pebble/batch=true/heldOtherTxn=false/heldSameTxn=true/strength=Shared-10          811B ± 0%      352B ± 0%  -56.58%  (p=0.000 n=10+10)
MVCCAcquireLock_Pebble/batch=true/heldOtherTxn=false/heldSameTxn=true/strength=Exclusive-10       810B ± 0%      352B ± 0%  -56.56%  (p=0.000 n=10+10)

name                                                                                          old allocs/op  new allocs/op  delta
MVCCAcquireLock_Pebble/batch=false/heldOtherTxn=false/heldSameTxn=true/strength=Shared-10         23.0 ± 0%       8.0 ± 0%  -65.22%  (p=0.000 n=10+10)
MVCCAcquireLock_Pebble/batch=false/heldOtherTxn=false/heldSameTxn=true/strength=Exclusive-10      23.0 ± 0%       8.0 ± 0%  -65.22%  (p=0.000 n=10+10)
MVCCAcquireLock_Pebble/batch=true/heldOtherTxn=false/heldSameTxn=true/strength=Shared-10          22.0 ± 0%       7.0 ± 0%  -68.18%  (p=0.000 n=10+10)
MVCCAcquireLock_Pebble/batch=true/heldOtherTxn=false/heldSameTxn=true/strength=Exclusive-10       22.0 ± 0%       7.0 ± 0%  -68.18%  (p=0.000 n=10+10)

Epic: None
Release note: None


Release justification: avoids expensive logging in replicated lock acquisition, which is in public preview.

This commit puts expensive logging in MVCCAcquireLock behind a
log.ExpensiveLogEnabled condition. This logging was bad in two ways:
1. it was boxing structs inside of interfaces, which can cause them
   to allocate and risks them escaping to the heap.
2. to avoid this risk of escaping, it was prematurely calling
   `.String()` on them. This was expensive for the `key` value, which
   was being pretty-printed even when tracing was disabled.

This showed up as taking 0.2% of CPU time in a run of TPC-C with Read
Committed isolation.

This also showed up in the new `MVCCAcquireLock_Pebble` benchmark:

```
name                                                                                          old time/op    new time/op    delta
MVCCAcquireLock_Pebble/batch=false/heldOtherTxn=false/heldSameTxn=true/strength=Shared-10       4.01µs ± 3%    2.42µs ± 1%  -39.70%  (p=0.000 n=10+9)
MVCCAcquireLock_Pebble/batch=false/heldOtherTxn=false/heldSameTxn=true/strength=Exclusive-10    4.02µs ± 2%    2.42µs ± 1%  -39.75%  (p=0.000 n=9+9)
MVCCAcquireLock_Pebble/batch=true/heldOtherTxn=false/heldSameTxn=true/strength=Shared-10        2.92µs ± 3%    1.60µs ± 2%  -45.18%  (p=0.000 n=9+10)
MVCCAcquireLock_Pebble/batch=true/heldOtherTxn=false/heldSameTxn=true/strength=Exclusive-10     2.91µs ± 2%    1.60µs ± 1%  -45.13%  (p=0.000 n=10+9)

name                                                                                          old alloc/op   new alloc/op   delta
MVCCAcquireLock_Pebble/batch=false/heldOtherTxn=false/heldSameTxn=true/strength=Shared-10         834B ± 0%      372B ± 0%  -55.38%  (p=0.000 n=10+10)
MVCCAcquireLock_Pebble/batch=false/heldOtherTxn=false/heldSameTxn=true/strength=Exclusive-10      834B ± 0%      372B ± 0%  -55.40%  (p=0.000 n=9+10)
MVCCAcquireLock_Pebble/batch=true/heldOtherTxn=false/heldSameTxn=true/strength=Shared-10          811B ± 0%      352B ± 0%  -56.58%  (p=0.000 n=10+10)
MVCCAcquireLock_Pebble/batch=true/heldOtherTxn=false/heldSameTxn=true/strength=Exclusive-10       810B ± 0%      352B ± 0%  -56.56%  (p=0.000 n=10+10)

name                                                                                          old allocs/op  new allocs/op  delta
MVCCAcquireLock_Pebble/batch=false/heldOtherTxn=false/heldSameTxn=true/strength=Shared-10         23.0 ± 0%       8.0 ± 0%  -65.22%  (p=0.000 n=10+10)
MVCCAcquireLock_Pebble/batch=false/heldOtherTxn=false/heldSameTxn=true/strength=Exclusive-10      23.0 ± 0%       8.0 ± 0%  -65.22%  (p=0.000 n=10+10)
MVCCAcquireLock_Pebble/batch=true/heldOtherTxn=false/heldSameTxn=true/strength=Shared-10          22.0 ± 0%       7.0 ± 0%  -68.18%  (p=0.000 n=10+10)
MVCCAcquireLock_Pebble/batch=true/heldOtherTxn=false/heldSameTxn=true/strength=Exclusive-10       22.0 ± 0%       7.0 ± 0%  -68.18%  (p=0.000 n=10+10)
```

Epic: None
Release note: None
@blathers-crl blathers-crl bot requested a review from a team as a code owner November 23, 2023 08:39
@blathers-crl blathers-crl bot force-pushed the blathers/backport-release-23.2-114773 branch from 814dec5 to 4e981c4 Compare November 23, 2023 08:39
@blathers-crl blathers-crl bot requested a review from aadityasondhi November 23, 2023 08:39
@blathers-crl blathers-crl bot added blathers-backport This is a backport that Blathers created automatically. O-robot Originated from a bot. labels Nov 23, 2023
@blathers-crl blathers-crl bot force-pushed the blathers/backport-release-23.2-114773 branch from 13b8a85 to 49d1821 Compare November 23, 2023 08:39
@blathers-crl
Copy link
Author

blathers-crl bot commented Nov 23, 2023

Thanks for opening a backport.

Please check the backport criteria before merging:

  • Backports should only be created for serious
    issues
    or test-only changes.
  • Backports should not break backwards-compatibility.
  • Backports should change as little code as possible.
  • Backports should not change on-disk formats or node communication protocols.
  • Backports should not add new functionality (except as defined
    here).
  • Backports must not add, edit, or otherwise modify cluster versions; or add version gates.
  • All backports must be reviewed by the owning areas TL and one additional
    TL. For more information as to how that review should be conducted, please consult the backport
    policy
    .
If your backport adds new functionality, please ensure that the following additional criteria are satisfied:
  • There is a high priority need for the functionality that cannot wait until the next release and is difficult to address in another way.
  • The new functionality is additive-only and only runs for clusters which have specifically “opted in” to it (e.g. by a cluster setting).
  • New code is protected by a conditional check that is trivial to verify and ensures that it only runs for opt-in clusters. State changes must be further protected such that nodes running old binaries will not be negatively impacted by the new state (with a mixed version test added).
  • The PM and TL on the team that owns the changed code have signed off that the change obeys the above rules.
  • Your backport must be accompanied by a post to the appropriate Slack
    channel (#db-backports-point-releases or #db-backports-XX-X-release) for awareness and discussion.

Also, please add a brief release justification to the body of your PR to justify this
backport.

@blathers-crl blathers-crl bot added the backport Label PR's that are backports to older release branches label Nov 23, 2023
@blathers-crl
Copy link
Author

blathers-crl bot commented Nov 23, 2023

It looks like your PR touches production code but doesn't add or edit any test code. Did you consider adding tests to your PR?

🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is dev-inf.

@cockroach-teamcity
Copy link
Member

This change is Reviewable

@nvb nvb merged commit 44eeb48 into release-23.2 Nov 27, 2023
@nvb nvb deleted the blathers/backport-release-23.2-114773 branch November 27, 2023 18:48
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

backport Label PR's that are backports to older release branches blathers-backport This is a backport that Blathers created automatically. O-robot Originated from a bot.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants