Skip to content

Commit cda25d0

Browse files
craig[bot]nvb
andcommitted
Merge #114773
114773: storage: avoid expensive logging in MVCCAcquireLock r=nvanbenschoten a=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.17% of CPU time in a run of TPC-C with Read Committed isolation: <img width="1780" alt="Screenshot 2023-11-20 at 2 49 52 PM" src="https://github.com/cockroachdb/cockroach/assets/5438456/a89d0808-7994-4662-bc4c-bffea8e24349"> 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 Co-authored-by: Nathan VanBenschoten <[email protected]>
2 parents 2859e5f + 41bbd88 commit cda25d0

File tree

1 file changed

+5
-3
lines changed

1 file changed

+5
-3
lines changed

pkg/storage/mvcc.go

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -5916,9 +5916,11 @@ func MVCCAcquireLock(
59165916
// number, our newer sequence number could then be rolled back and
59175917
// we would forget that the lock held at the older sequence number
59185918
// had been and still should be held.
5919-
log.VEventf(ctx, 3, "skipping lock acquisition for txn %s on key %s "+
5920-
"with strength %s; found existing lock with strength %s and sequence %d",
5921-
txn, key.String(), str.String(), iterStr.String(), foundLock.Txn.Sequence)
5919+
if log.ExpensiveLogEnabled(ctx, 3) {
5920+
log.VEventf(ctx, 3, "skipping lock acquisition for txn %s on key %s "+
5921+
"with strength %s; found existing lock with strength %s and sequence %d",
5922+
txn, key, str, iterStr, foundLock.Txn.Sequence)
5923+
}
59225924
return nil
59235925
}
59245926

0 commit comments

Comments
 (0)