Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

kvsever: hacky raft proposal tracer #131863

Draft
wants to merge 1 commit into
base: master
Choose a base branch
from
Draft

kvsever: hacky raft proposal tracer #131863

wants to merge 1 commit into from
+239 −1

Conversation

pav-kv
Copy link
Collaborator

@pav-kv pav-kv commented Oct 3, 2024

Epic: none
Release note: none

@pav-kv
kvsever: hacky raft proposal tracer
50a5ef8 
Epic: none
Release note: none
@cockroach-teamcity
Copy link
Member

This change is Reviewable

@pav-kv
Copy link
Collaborator Author

pav-kv commented Oct 3, 2024

Example "trace" in the log:

I241003 23:07:28.056918 508 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 279  [raft] registered proposal ‹5f5844c970dda9df› at log mark (t6,i50) for tracing
I241003 23:07:28.056937 508 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 280  [raft] message covering mark (t6,i50): ‹1->2 MsgApp Term:6 Log:6/49 Commit:49 Entries:[6/50 EntryNormal]›
I241003 23:07:28.056949 508 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 281  [raft] message covering mark (t6,i50): ‹1->3 MsgApp Term:6 Log:6/49 Commit:49 Entries:[6/50 EntryNormal]›
I241003 23:07:28.056956 508 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 282  [raft] message covering mark (t6,i50): ‹1->AppendThread MsgStorageAppend Term:0 Log:6/50 Entries:[6/50 EntryNormal] Responses:[›
I241003 23:07:28.056970 508 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 283  [raft] message past mark (t6,i50): ‹1->1 MsgAppResp Term:6 Log:0/50 Commit:49›
I241003 23:07:28.056976 508 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 284  [raft] message past mark (t6,i50): ‹AppendThread->1 MsgStorageAppendResp Term:0 Log:6/50›
I241003 23:07:28.057069 2781 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 285  [raft] registered log mark (t6,i50) for tracing
I241003 23:07:28.057070 1930 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 286  [raft] registered log mark (t6,i50) for tracing
I241003 23:07:28.057079 2781 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 287  [raft] message covering mark (t6,i50): ‹1->3 MsgApp Term:6 Log:6/49 Commit:49 Entries:[6/50 EntryNormal]›
I241003 23:07:28.057081 1930 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 288  [raft] message covering mark (t6,i50): ‹1->2 MsgApp Term:6 Log:6/49 Commit:49 Entries:[6/50 EntryNormal]›
I241003 23:07:28.057091 1930 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 289  [raft] message covering mark (t6,i50): ‹2->AppendThread MsgStorageAppend Term:0 Log:6/50 Entries:[6/50 EntryNormal] Responses:[›
I241003 23:07:28.057089 2781 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 290  [raft] message covering mark (t6,i50): ‹3->AppendThread MsgStorageAppend Term:0 Log:6/50 Entries:[6/50 EntryNormal] Responses:[›
I241003 23:07:28.057105 1930 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 291  [raft] message past mark (t6,i50): ‹2->1 MsgAppResp Term:6 Log:0/50 Commit:49›
I241003 23:07:28.057113 1930 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 292  [raft] message past mark (t6,i50): ‹AppendThread->2 MsgStorageAppendResp Term:0 Log:6/50›
I241003 23:07:28.057110 2875 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 293  [raft] message past mark (t6,i50): ‹3->1 MsgAppResp Term:6 Log:0/50 Commit:49›
I241003 23:07:28.057130 2782 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 294  [raft] message past mark (t6,i50): ‹AppendThread->3 MsgStorageAppendResp Term:0 Log:6/50›
I241003 23:07:28.057170 510 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 295  [raft] message past mark (t6,i50): ‹2->1 MsgAppResp Term:6 Log:0/50 Commit:49›
I241003 23:07:28.057190 510 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 296  [raft] message covering mark (t6,i50): ‹1->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[6/50 EntryNormal] Responses:[›
I241003 23:07:28.057205 510 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 297  [raft] message past mark (t6,i50): ‹ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[6/50 EntryNormal]›
I241003 23:07:28.057210 510 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 298  [raft] unregistered log mark (t6,i50) from tracing
I241003 23:07:28.057215 510 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 299  [raft] registered log mark (t6,i50) for tracing
I241003 23:07:28.057219 510 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 300  [raft] message past mark (t6,i50): ‹3->1 MsgAppResp Term:6 Log:0/50 Commit:49›
I241003 23:07:28.057245 1931 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 301  [raft] message past mark (t6,i50): ‹2->1 MsgAppResp Term:6 Log:0/50 Commit:50›
I241003 23:07:28.057256 1931 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 302  [raft] message covering mark (t6,i50): ‹2->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[6/50 EntryNormal] Responses:[›
I241003 23:07:28.057258 2783 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 303  [raft] message past mark (t6,i50): ‹3->1 MsgAppResp Term:6 Log:0/50 Commit:50›
I241003 23:07:28.057261 512 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 304  [raft] message past mark (t6,i50): ‹1->1 MsgAppResp Term:6 Log:0/51 Commit:50›
I241003 23:07:28.057266 2783 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 305  [raft] message covering mark (t6,i50): ‹3->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[6/50 EntryNormal] Responses:[›
I241003 23:07:28.057268 512 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 306  [raft] message past mark (t6,i50): ‹AppendThread->1 MsgStorageAppendResp Term:0 Log:6/51›
I241003 23:07:28.057268 1931 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 307  [raft] message past mark (t6,i50): ‹ApplyThread->2 MsgStorageApplyResp Term:0 Log:0/0 Entries:[6/50 EntryNormal]›
I241003 23:07:28.057273 1931 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 308  [raft] unregistered log mark (t6,i50) from tracing
I241003 23:07:28.057277 2783 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 309  [raft] message past mark (t6,i50): ‹ApplyThread->3 MsgStorageApplyResp Term:0 Log:0/0 Entries:[6/50 EntryNormal]›
I241003 23:07:28.057281 2783 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 310  [raft] unregistered log mark (t6,i50) from tracing
I241003 23:07:28.057315 511 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 311  [raft] message past mark (t6,i50): ‹2->1 MsgAppResp Term:6 Log:0/50 Commit:50›
I241003 23:07:28.057381 497 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 312  [raft] message past mark (t6,i50): ‹3->1 MsgAppResp Term:6 Log:0/50 Commit:50›
I241003 23:07:28.057456 498 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 313  [raft] message past mark (t6,i50): ‹3->1 MsgAppResp Term:6 Log:0/51 Commit:50›
I241003 23:07:28.057480 498 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 314  [raft] message past mark (t6,i50): ‹ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[6/51 EntryNormal]›
I241003 23:07:28.057485 498 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 315  [raft] unregistered log mark (t6,i50) from tracing

By node:

n1 (proposer/leaseholder/leader):

I241003 23:07:28.056918 508 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 279  [raft] registered proposal ‹5f5844c970dda9df› at log mark (t6,i50) for tracing
I241003 23:07:28.056937 508 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 280  [raft] message covering mark (t6,i50): ‹1->2 MsgApp Term:6 Log:6/49 Commit:49 Entries:[6/50 EntryNormal]›
I241003 23:07:28.056949 508 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 281  [raft] message covering mark (t6,i50): ‹1->3 MsgApp Term:6 Log:6/49 Commit:49 Entries:[6/50 EntryNormal]›
I241003 23:07:28.056956 508 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 282  [raft] message covering mark (t6,i50): ‹1->AppendThread MsgStorageAppend Term:0 Log:6/50 Entries:[6/50 EntryNormal] Responses:[›
I241003 23:07:28.056970 508 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 283  [raft] message past mark (t6,i50): ‹1->1 MsgAppResp Term:6 Log:0/50 Commit:49›
I241003 23:07:28.056976 508 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 284  [raft] message past mark (t6,i50): ‹AppendThread->1 MsgStorageAppendResp Term:0 Log:6/50›
I241003 23:07:28.057170 510 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 295  [raft] message past mark (t6,i50): ‹2->1 MsgAppResp Term:6 Log:0/50 Commit:49›
I241003 23:07:28.057190 510 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 296  [raft] message covering mark (t6,i50): ‹1->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[6/50 EntryNormal] Responses:[›
I241003 23:07:28.057205 510 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 297  [raft] message past mark (t6,i50): ‹ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[6/50 EntryNormal]›
I241003 23:07:28.057210 510 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 298  [raft] unregistered log mark (t6,i50) from tracing
I241003 23:07:28.057215 510 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 299  [raft] registered log mark (t6,i50) for tracing
I241003 23:07:28.057219 510 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 300  [raft] message past mark (t6,i50): ‹3->1 MsgAppResp Term:6 Log:0/50 Commit:49›
I241003 23:07:28.057261 512 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 304  [raft] message past mark (t6,i50): ‹1->1 MsgAppResp Term:6 Log:0/51 Commit:50›
I241003 23:07:28.057268 512 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 306  [raft] message past mark (t6,i50): ‹AppendThread->1 MsgStorageAppendResp Term:0 Log:6/51›
I241003 23:07:28.057315 511 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 311  [raft] message past mark (t6,i50): ‹2->1 MsgAppResp Term:6 Log:0/50 Commit:50›
I241003 23:07:28.057381 497 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 312  [raft] message past mark (t6,i50): ‹3->1 MsgAppResp Term:6 Log:0/50 Commit:50›
I241003 23:07:28.057456 498 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 313  [raft] message past mark (t6,i50): ‹3->1 MsgAppResp Term:6 Log:0/51 Commit:50›
I241003 23:07:28.057480 498 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 314  [raft] message past mark (t6,i50): ‹ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[6/51 EntryNormal]›
I241003 23:07:28.057485 498 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/Max-Max}›] 315  [raft] unregistered log mark (t6,i50) from tracing

n2 (follower):

I241003 23:07:28.057070 1930 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 286  [raft] registered log mark (t6,i50) for tracing
I241003 23:07:28.057081 1930 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 288  [raft] message covering mark (t6,i50): ‹1->2 MsgApp Term:6 Log:6/49 Commit:49 Entries:[6/50 EntryNormal]›
I241003 23:07:28.057091 1930 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 289  [raft] message covering mark (t6,i50): ‹2->AppendThread MsgStorageAppend Term:0 Log:6/50 Entries:[6/50 EntryNormal] Responses:[›
I241003 23:07:28.057105 1930 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 291  [raft] message past mark (t6,i50): ‹2->1 MsgAppResp Term:6 Log:0/50 Commit:49›
I241003 23:07:28.057113 1930 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 292  [raft] message past mark (t6,i50): ‹AppendThread->2 MsgStorageAppendResp Term:0 Log:6/50›
I241003 23:07:28.057245 1931 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 301  [raft] message past mark (t6,i50): ‹2->1 MsgAppResp Term:6 Log:0/50 Commit:50›
I241003 23:07:28.057256 1931 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 302  [raft] message covering mark (t6,i50): ‹2->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[6/50 EntryNormal] Responses:[›
I241003 23:07:28.057268 1931 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 307  [raft] message past mark (t6,i50): ‹ApplyThread->2 MsgStorageApplyResp Term:0 Log:0/0 Entries:[6/50 EntryNormal]›
I241003 23:07:28.057273 1931 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n2,s2,r70/2:‹/{Table/Max-Max}›] 308  [raft] unregistered log mark (t6,i50) from tracing

n3 (follower):

I241003 23:07:28.057069 2781 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 285  [raft] registered log mark (t6,i50) for tracing
I241003 23:07:28.057079 2781 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 287  [raft] message covering mark (t6,i50): ‹1->3 MsgApp Term:6 Log:6/49 Commit:49 Entries:[6/50 EntryNormal]›
I241003 23:07:28.057089 2781 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 290  [raft] message covering mark (t6,i50): ‹3->AppendThread MsgStorageAppend Term:0 Log:6/50 Entries:[6/50 EntryNormal] Responses:[›
I241003 23:07:28.057110 2875 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 293  [raft] message past mark (t6,i50): ‹3->1 MsgAppResp Term:6 Log:0/50 Commit:49›
I241003 23:07:28.057130 2782 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 294  [raft] message past mark (t6,i50): ‹AppendThread->3 MsgStorageAppendResp Term:0 Log:6/50›
I241003 23:07:28.057258 2783 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 303  [raft] message past mark (t6,i50): ‹3->1 MsgAppResp Term:6 Log:0/50 Commit:50›
I241003 23:07:28.057266 2783 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 305  [raft] message covering mark (t6,i50): ‹3->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[6/50 EntryNormal] Responses:[›
I241003 23:07:28.057277 2783 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 309  [raft] message past mark (t6,i50): ‹ApplyThread->3 MsgStorageApplyResp Term:0 Log:0/0 Entries:[6/50 EntryNormal]›
I241003 23:07:28.057281 2783 kv/kvserver/raft.go:57 ⋮ [T1,Vsystem,n3,s3,r70/3:‹/{Table/Max-Max}›] 310  [raft] unregistered log mark (t6,i50) from tracing

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@pav-kv @cockroach-teamcity