Skip to content

Conversation

@nvb
Copy link
Contributor

@nvb nvb commented Nov 20, 2023

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

@nvb nvb added the backport-23.2.x PAST MAINTENANCE SUPPORT: 23.2 patch releases via ER request only label Nov 20, 2023
@nvb nvb requested a review from a team as a code owner November 20, 2023 23:47
@cockroach-teamcity
Copy link
Member

This change is Reviewable

Copy link
Collaborator

@arulajmani arulajmani left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

:lgtm:

Reviewed 3 of 3 files at r1, 1 of 1 files at r2, all commit messages.
Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained (waiting on @sumeerbhola)

Copy link
Collaborator

@sumeerbhola sumeerbhola left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

:lgtm:

Reviewable status: :shipit: complete! 2 of 0 LGTMs obtained (waiting on @nvanbenschoten)

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
@nvb nvb force-pushed the nvanbenschoten/replLockAcquireLog2 branch from b8223c3 to 41bbd88 Compare November 23, 2023 07:45
@blathers-crl
Copy link

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.

@nvb
Copy link
Contributor Author

nvb commented Nov 23, 2023

TFTRs!

bors r+

@craig
Copy link
Contributor

craig bot commented Nov 23, 2023

Build succeeded:

@craig craig bot merged commit cda25d0 into cockroachdb:master Nov 23, 2023
@nvb nvb deleted the nvanbenschoten/replLockAcquireLog2 branch December 13, 2023 04:31
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

backport-23.2.x PAST MAINTENANCE SUPPORT: 23.2 patch releases via ER request only

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants