From 41bbd886915f10a8bb0002d9596b6ac5fb9183df Mon Sep 17 00:00:00 2001 From: Nathan VanBenschoten Date: Mon, 20 Nov 2023 18:43:35 -0500 Subject: [PATCH] storage: avoid expensive logging in MVCCAcquireLock MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- pkg/storage/mvcc.go | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/pkg/storage/mvcc.go b/pkg/storage/mvcc.go index 4aef5a7ea242..2b32991b4417 100644 --- a/pkg/storage/mvcc.go +++ b/pkg/storage/mvcc.go @@ -5916,9 +5916,11 @@ func MVCCAcquireLock( // number, our newer sequence number could then be rolled back and // we would forget that the lock held at the older sequence number // had been and still should be held. - log.VEventf(ctx, 3, "skipping lock acquisition for txn %s on key %s "+ - "with strength %s; found existing lock with strength %s and sequence %d", - txn, key.String(), str.String(), iterStr.String(), foundLock.Txn.Sequence) + if log.ExpensiveLogEnabled(ctx, 3) { + log.VEventf(ctx, 3, "skipping lock acquisition for txn %s on key %s "+ + "with strength %s; found existing lock with strength %s and sequence %d", + txn, key, str, iterStr, foundLock.Txn.Sequence) + } return nil }