Skip to content

Commit

Permalink
kv: add txn push reason(s) to trace events
Browse files Browse the repository at this point in the history 
This commit adds the reason(s) for pushing a lock holder while in a lock
wait-queue to trace events.
  • Loading branch information
@nvanbenschoten
nvanbenschoten committed Jul 5, 2022
1 parent 83ac099 commit f6a7a2c
Show file tree
Hide file tree
Showing 17 changed files with 99 additions and 0 deletions.
6 changes: 6 additions & 0 deletions pkg/kv/kvserver/concurrency/lock_table_waiter.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -230,6 +230,7 @@ func (w *lockTableWaiterImpl) WaitOn(
// If the request doesn't want to perform a delayed push for any
// reason, continue waiting without a timer.
if !(livenessPush || deadlockPush || timeoutPush || priorityPush) {
log.Eventf(ctx, "not pushing")
continue
}

Expand Down Expand Up @@ -260,6 +261,11 @@ func (w *lockTableWaiterImpl) WaitOn(
delay = 0
}

log.Eventf(ctx, "pushing after %s for: "+
"liveness detection = %t, deadlock detection = %t, "+
"timeout enforcement = %t, priority enforcement = %t",
delay, livenessPush, deadlockPush, timeoutPush, priorityPush)

if delay > 0 {
if timer == nil {
timer = timeutil.NewTimer()
Expand Down
4 changes: 4 additions & 0 deletions pkg/kv/kvserver/concurrency/testdata/concurrency_manager/basic
View file
Original file line number Diff line number Diff line change
Expand Up @@ -117,6 +117,7 @@ sequence req=req3
[2] sequence req3: scanning lock table for conflicting locks
[2] sequence req3: waiting in lock wait-queues
[2] sequence req3: lock wait-queue event: wait for (distinguished) txn 00000002 holding lock @ key "k" (queuedWriters: 0, queuedReaders: 1)
[2] sequence req3: pushing after 0s for: liveness detection = true, deadlock detection = true, timeout enforcement = false, priority enforcement = false
[2] sequence req3: pushing timestamp of txn 00000002 above 14.000000000,1
[2] sequence req3: blocked on select in concurrency_test.(*cluster).PushTransaction

Expand Down Expand Up @@ -204,6 +205,7 @@ sequence req=req5
[2] sequence req5: scanning lock table for conflicting locks
[2] sequence req5: waiting in lock wait-queues
[2] sequence req5: lock wait-queue event: wait for (distinguished) txn 00000002 holding lock @ key "k" (queuedWriters: 0, queuedReaders: 1)
[2] sequence req5: pushing after 0s for: liveness detection = true, deadlock detection = false, timeout enforcement = false, priority enforcement = false
[2] sequence req5: pushing timestamp of txn 00000002 above 14.000000000,1
[2] sequence req5: blocked on select in concurrency_test.(*cluster).PushTransaction

Expand All @@ -218,6 +220,7 @@ sequence req=req6
[3] sequence req6: scanning lock table for conflicting locks
[3] sequence req6: waiting in lock wait-queues
[3] sequence req6: lock wait-queue event: wait for txn 00000002 holding lock @ key "k" (queuedWriters: 0, queuedReaders: 2)
[3] sequence req6: not pushing
[3] sequence req6: blocked on select in concurrency.(*lockTableWaiterImpl).WaitOn

debug-advance-clock ts=123
Expand Down Expand Up @@ -261,6 +264,7 @@ finish req=req6
[4] sequence req7: scanning lock table for conflicting locks
[4] sequence req7: waiting in lock wait-queues
[4] sequence req7: lock wait-queue event: wait for (distinguished) txn 00000002 holding lock @ key "k" (queuedWriters: 1, queuedReaders: 0)
[4] sequence req7: pushing after 0s for: liveness detection = true, deadlock detection = false, timeout enforcement = false, priority enforcement = false
[4] sequence req7: pushing txn 00000002 to abort
[4] sequence req7: blocked on select in concurrency_test.(*cluster).PushTransaction

Expand Down
7 changes: 7 additions & 0 deletions pkg/kv/kvserver/concurrency/testdata/concurrency_manager/clear_abandoned_intents
View file
Original file line number Diff line number Diff line change
Expand Up @@ -65,6 +65,7 @@ sequence req=req1
[3] sequence req1: scanning lock table for conflicting locks
[3] sequence req1: waiting in lock wait-queues
[3] sequence req1: lock wait-queue event: wait for (distinguished) txn 00000002 holding lock @ key "a" (queuedWriters: 0, queuedReaders: 1)
[3] sequence req1: pushing after 0s for: liveness detection = true, deadlock detection = true, timeout enforcement = false, priority enforcement = false
[3] sequence req1: pushing timestamp of txn 00000002 above 10.000000000,1
[3] sequence req1: blocked on select in concurrency_test.(*cluster).PushTransaction

Expand Down Expand Up @@ -178,6 +179,7 @@ sequence req=req1
[3] sequence req1: scanning lock table for conflicting locks
[3] sequence req1: waiting in lock wait-queues
[3] sequence req1: lock wait-queue event: wait for (distinguished) txn 00000002 holding lock @ key "a" (queuedWriters: 1, queuedReaders: 0)
[3] sequence req1: pushing after 0s for: liveness detection = true, deadlock detection = true, timeout enforcement = false, priority enforcement = false
[3] sequence req1: pushing txn 00000002 to abort
[3] sequence req1: blocked on select in concurrency_test.(*cluster).PushTransaction

Expand Down Expand Up @@ -354,6 +356,7 @@ sequence req=req1
[4] sequence req1: scanning lock table for conflicting locks
[4] sequence req1: waiting in lock wait-queues
[4] sequence req1: lock wait-queue event: wait for (distinguished) txn 00000002 holding lock @ key "a" (queuedWriters: 0, queuedReaders: 1)
[4] sequence req1: pushing after 0s for: liveness detection = true, deadlock detection = true, timeout enforcement = false, priority enforcement = false
[4] sequence req1: pushing timestamp of txn 00000002 above 10.000000000,1
[4] sequence req1: blocked on select in concurrency_test.(*cluster).PushTransaction

Expand Down Expand Up @@ -471,6 +474,7 @@ sequence req=req1
[3] sequence req1: scanning lock table for conflicting locks
[3] sequence req1: waiting in lock wait-queues
[3] sequence req1: lock wait-queue event: wait for (distinguished) txn 00000003 holding lock @ key "c" (queuedWriters: 1, queuedReaders: 0)
[3] sequence req1: pushing after 0s for: liveness detection = true, deadlock detection = true, timeout enforcement = false, priority enforcement = false
[3] sequence req1: pushing txn 00000003 to abort
[3] sequence req1: blocked on select in concurrency_test.(*cluster).PushTransaction

Expand Down Expand Up @@ -564,6 +568,7 @@ sequence req=req2
[6] sequence req2: scanning lock table for conflicting locks
[6] sequence req2: waiting in lock wait-queues
[6] sequence req2: lock wait-queue event: wait for (distinguished) txn 00000003 holding lock @ key "a" (queuedWriters: 0, queuedReaders: 1)
[6] sequence req2: pushing after 0s for: liveness detection = true, deadlock detection = true, timeout enforcement = false, priority enforcement = false
[6] sequence req2: pushing timestamp of txn 00000003 above 11.000000000,1
[6] sequence req2: blocked on select in concurrency_test.(*cluster).PushTransaction

Expand Down Expand Up @@ -603,11 +608,13 @@ on-txn-updated txn=txn3 status=aborted
[3] sequence req1: resolving intent "c" for txn 00000003 with ABORTED status
[3] sequence req1: lock wait-queue event: wait for (distinguished) txn 00000005 holding lock @ key "e" (queuedWriters: 1, queuedReaders: 0)
[3] sequence req1: conflicted with 00000003-0000-0000-0000-000000000000 on "c" for 123.000s
[3] sequence req1: pushing after 0s for: liveness detection = true, deadlock detection = true, timeout enforcement = false, priority enforcement = false
[3] sequence req1: pushing txn 00000005 to abort
[3] sequence req1: blocked on select in concurrency_test.(*cluster).PushTransaction
[6] sequence req2: resolving intent "a" for txn 00000003 with ABORTED status
[6] sequence req2: lock wait-queue event: wait for (distinguished) txn 00000004 holding lock @ key "b" (queuedWriters: 0, queuedReaders: 1)
[6] sequence req2: conflicted with 00000003-0000-0000-0000-000000000000 on "a" for 123.000s
[6] sequence req2: pushing after 0s for: liveness detection = true, deadlock detection = true, timeout enforcement = false, priority enforcement = false
[6] sequence req2: pushing timestamp of txn 00000004 above 11.000000000,1
[6] sequence req2: blocked on select in concurrency_test.(*cluster).PushTransaction

Expand Down
1 change: 1 addition & 0 deletions ...urrency/testdata/concurrency_manager/clear_abandoned_intents_without_adding_to_lock_table
View file
Original file line number Diff line number Diff line change
Expand Up @@ -44,6 +44,7 @@ sequence req=req1
[3] sequence req1: scanning lock table for conflicting locks
[3] sequence req1: waiting in lock wait-queues
[3] sequence req1: lock wait-queue event: wait for (distinguished) txn 00000002 holding lock @ key "a" (queuedWriters: 0, queuedReaders: 1)
[3] sequence req1: pushing after 0s for: liveness detection = true, deadlock detection = true, timeout enforcement = false, priority enforcement = false
[3] sequence req1: pushing timestamp of txn 00000002 above 10.000000000,1
[3] sequence req1: blocked on select in concurrency_test.(*cluster).PushTransaction

Expand Down
Loading

0 comments on commit f6a7a2c

Please sign in to comment.