Skip to content

Commit

Permalink
log every raft command during application
Browse files Browse the repository at this point in the history 
Perplexingly, when I run `./cockroach start-single-node --logtostderr --insecure` and against it

`bin/workload kv --max-rate=10 --read-percent=0`, I see that ~30% of the proposals
are... empty entries?! This seems unexpected to me, these should not be
emitted by raft in steady state as far as I can tell? I verified that
the term is not going up, and that the pattern persists for minutes.

```
I210330 10:30:39.144043 234 kv/kvserver/replica_application_state_machine.go:446 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2863  applying command with forced error: ‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry
I210330 10:30:39.144165 234 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2864  idx=1260 mlai=0 forcedErr=‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry: ‹<nil>›
I210330 10:30:39.240853 241 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2865  idx=1261 mlai=834 forcedErr=<nil>: ‹Put: 1617100239.237121482,0 /Table/53/1/2850286295254940972/0 (0xbd89fd278e4048b8d5bd2c8800167118198ded85ca09):›
I210330 10:30:39.340764 243 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2866  idx=1262 mlai=835 forcedErr=<nil>: ‹Put: 1617100239.337076872,0 /Table/53/1/-6356694038928198937/0 (0xbd8980a7c87c7367d772e788001671181993e2b88809):›
I210330 10:30:39.343700 243 kv/kvserver/replica_application_state_machine.go:446 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2867  applying command with forced error: ‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry
I210330 10:30:39.343806 243 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2868  idx=1263 mlai=0 forcedErr=‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry: ‹<nil>›
I210330 10:30:39.440865 245 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2869  idx=1264 mlai=836 forcedErr=<nil>: ‹Put: 1617100239.437089067,0 /Table/53/1/-7437556609187321794/0 (0xbd898098c87dab7887e83e88001671181999d8c92b09):›
I210330 10:30:39.540660 246 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2870  idx=1265 mlai=837 forcedErr=<nil>: ‹Put: 1617100239.537074620,0 /Table/53/1/6351514490197923581/0 (0xbd89fd58251cc6edfe56fd8800167118199fce71bc09):›
I210330 10:30:39.543499 246 kv/kvserver/replica_application_state_machine.go:446 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2871  applying command with forced error: ‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry
I210330 10:30:39.543594 246 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2872  idx=1266 mlai=0 forcedErr=‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry: ‹<nil>›
I210330 10:30:39.640657 247 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2873  idx=1267 mlai=838 forcedErr=<nil>: ‹Put: 1617100239.637102583,0 /Table/53/1/7437542101176764196/0 (0xbd89fd673775229ea74724880016711819a5c4bff709):›
I210330 10:30:39.740974 248 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2874  idx=1268 mlai=839 forcedErr=<nil>: ‹Put: 1617100239.737099626,0 /Table/53/1/6928540211947731053/0 (0xbd89fd60271e9d2127786d880016711819abba956a09):›
I210330 10:30:39.743917 248 kv/kvserver/replica_application_state_machine.go:446 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2875  applying command with forced error: ‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry
I210330 10:30:39.744028 248 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2876  idx=1269 mlai=0 forcedErr=‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry: ‹<nil>›
I210330 10:30:39.840652 250 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2877  idx=1270 mlai=840 forcedErr=<nil>: ‹Put: 1617100239.837097210,0 /Table/53/1/-185871630413023141/0 (0xbd8980fd6ba6bca768b85b880016711819b1b06cfa09):›
I210330 10:30:39.940911 252 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2878  idx=1271 mlai=841 forcedErr=<nil>: ‹Put: 1617100239.937072913,0 /Table/53/1/8801482429265706073/0 (0xbd89fd7a2525a31d397c59880016711819b7a5ef1109):›
I210330 10:30:39.943859 252 kv/kvserver/replica_application_state_machine.go:446 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2879  applying command with forced error: ‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry
I210330 10:30:39.943977 252 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2880  idx=1272 mlai=0 forcedErr=‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry: ‹<nil>›
I210330 10:30:40.040607 261 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2881  idx=1273 mlai=842 forcedErr=<nil>: ‹Put: 1617100240.037083544,0 /Table/53/1/136968409589023503/0 (0xbd89fd01e69c0af701030f880016711819bd9bf99809):›
I210330 10:30:40.140983 262 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2882  idx=1274 mlai=843 forcedErr=<nil>: ‹Put: 1617100240.137103713,0 /Table/53/1/-6530552929161390779/0 (0xbd8980a55ed0b61672d545880016711819c392296109):›
I210330 10:30:40.143834 262 kv/kvserver/replica_application_state_machine.go:446 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2883  applying command with forced error: ‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry
I210330 10:30:40.143944 262 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2884  idx=1275 mlai=0 forcedErr=‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry: ‹<nil>›
I210330 10:30:40.240619 253 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2885  idx=1276 mlai=844 forcedErr=<nil>: ‹Put: 1617100240.237056860,0 /Table/53/1/-5536958579423093401/0 (0xbd8980b328c582116f5d67880016711819c987535c09):›
I210330 10:30:40.341190 260 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2886  idx=1277 mlai=845 forcedErr=<nil>: ‹Put: 1617100240.337302231,0 /Table/53/1/-1684406313953726943/0 (0xbd8980e89fc961bf5cee21880016711819cf80f2d709):›
I210330 10:30:40.344021 260 kv/kvserver/replica_application_state_machine.go:446 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2887  applying command with forced error: ‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry
I210330 10:30:40.344117 260 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2888  idx=1278 mlai=0 forcedErr=‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry: ‹<nil>›
I210330 10:30:40.440918 263 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2889  idx=1279 mlai=846 forcedErr=<nil>: ‹Put: 1617100240.437037366,0 /Table/53/1/-2038798571150465276/0 (0xbd8980e3b4bb806600a704880016711819d572c93609):›
I210330 10:30:40.540687 255 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2890  idx=1280 mlai=847 forcedErr=<nil>: ‹Put: 1617100240.537087989,0 /Table/53/1/2068322336664695263/0 (0xbd89fd1cb42834ede7b1df880016711819db696ff509):›
I210330 10:30:40.543574 255 kv/kvserver/replica_application_state_machine.go:446 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2891  applying command with forced error: ‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry
I210330 10:30:40.543689 255 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2892  idx=1281 mlai=0 forcedErr=‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry: ‹<nil>›
I210330 10:30:40.642543 275 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2893  idx=1282 mlai=848 forcedErr=<nil>: ‹Put: 1617100240.637041509,0 /Table/53/1/-2575353514682209952/0 (0xbd8980dc42819f8a502960880016711819e15e9b6509):›
I210330 10:30:40.740678 256 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2894  idx=1283 mlai=849 forcedErr=<nil>: ‹Put: 1617100240.737047364,0 /Table/53/1/2429899135975807835/0 (0xbd89fd21b8bc63d7dddb5b880016711819e754934409):›
I210330 10:30:40.743399 256 kv/kvserver/replica_application_state_machine.go:446 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2895  applying command with forced error: ‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry
I210330 10:30:40.743491 256 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2896  idx=1284 mlai=0 forcedErr=‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry: ‹<nil>›
I210330 10:30:40.840984 258 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2897  idx=1285 mlai=850 forcedErr=<nil>: ‹Put: 1617100240.837095095,0 /Table/53/1/5460400427895041357/0 (0xbd89fd4bc73d423c132d4d880016711819ed4b2eb709):›
I210330 10:30:40.944030 268 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2898  idx=1286 mlai=851 forcedErr=<nil>: ‹Put: 1617100240.937078927,0 /Table/53/1/6057308348334647400/0 (0xbd89fd540fe1d98d7ea868880016711819f340d08f09):›
I210330 10:30:40.946959 268 kv/kvserver/replica_application_state_machine.go:446 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2899  applying command with forced error: ‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry
I210330 10:30:40.947064 268 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r37/1:‹/{Table/53-Max}›] 2900  idx=1287 mlai=0 forcedErr=‹kv/kvserver/replica_application_state_machine.go›:157: no-op on empty Raft entry: ‹<nil>›
I210330 10:30:41.007033 267 kv/kvserver/replica_application_cmd.go:172 ⋮ [n1,s1,r35/1:‹/Table/{39-40}›] 2901  idx=150 mlai=103 forcedErr=<nil>: ‹Put: 0,0 /Table/39/1/"\xe9\x1a\x89E1\x89K\xa9\xb4s B\xa1\xd9 \x95"/0 (0xaf8912e91a8945318

```

Release note (<category, see below>): <what> <show> <why>
  • Loading branch information
@tbg
tbg committed Mar 30, 2021
1 parent 6f56df5 commit 42628ed
Show file tree
Hide file tree
Showing 3 changed files with 24 additions and 17 deletions.
29 changes: 13 additions & 16 deletions pkg/kv/kvserver/debug_print.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -130,31 +130,28 @@ func decodeWriteBatch(writeBatch *kvserverpb.WriteBatch) (string, error) {
if err != nil {
return sb.String(), err
}
sb.WriteString(fmt.Sprintf("Delete: %s\n", SprintKey(mvccKey)))
sb.WriteString(fmt.Sprintf("Delete: %s ", SprintKey(mvccKey)))
case storage.BatchTypeValue:
mvccKey, err := r.MVCCKey()
if err != nil {
return sb.String(), err
}
sb.WriteString(fmt.Sprintf("Put: %s\n", SprintKeyValue(storage.MVCCKeyValue{
Key: mvccKey,
Value: r.Value(),
}, true /* printKey */)))
sb.WriteString(fmt.Sprintf("Put: %s ", SprintKey(mvccKey)))
case storage.BatchTypeMerge:
mvccKey, err := r.MVCCKey()
if err != nil {
return sb.String(), err
}
sb.WriteString(fmt.Sprintf("Merge: %s\n", SprintKeyValue(storage.MVCCKeyValue{
Key: mvccKey,
Value: r.Value(),
}, true /* printKey */)))
//mvccKey, err := r.MVCCKey()
//if err != nil {
// return sb.String(), err
//}
//sb.WriteString(fmt.Sprintf("Merge: %s\n", SprintKeyValue(storage.MVCCKeyValue{
// Key: mvccKey,
// Value: r.Value(),
//}, true /* printKey */)))
case storage.BatchTypeSingleDeletion:
mvccKey, err := r.MVCCKey()
if err != nil {
return sb.String(), err
}
sb.WriteString(fmt.Sprintf("Single Delete: %s\n", SprintKey(mvccKey)))
sb.WriteString(fmt.Sprintf("Single Delete: %s ", SprintKey(mvccKey)))
case storage.BatchTypeRangeDeletion:
mvccStartKey, err := r.MVCCKey()
if err != nil {
Expand All @@ -165,10 +162,10 @@ func decodeWriteBatch(writeBatch *kvserverpb.WriteBatch) (string, error) {
return sb.String(), err
}
sb.WriteString(fmt.Sprintf(
"Delete Range: [%s, %s)\n", SprintKey(mvccStartKey), SprintKey(mvccEndKey),
"Delete Range: [%s, %s) ", SprintKey(mvccStartKey), SprintKey(mvccEndKey),
))
default:
sb.WriteString(fmt.Sprintf("unsupported batch type: %d\n", r.BatchType()))
sb.WriteString(fmt.Sprintf("unsupported batch type: %d", r.BatchType()))
}
}
return sb.String(), r.Error()
Expand Down
10 changes: 10 additions & 0 deletions pkg/kv/kvserver/replica_application_cmd.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@ package kvserver

import (
"context"
"fmt"

"github.com/cockroachdb/cockroach/pkg/kv/kvserver/batcheval/result"
"github.com/cockroachdb/cockroach/pkg/kv/kvserver/kvserverbase"
Expand Down Expand Up @@ -164,6 +165,15 @@ func (c *replicatedCmd) AckSuccess(_ context.Context) error {

// AckOutcomeAndFinish implements the apply.AppliedCommand interface.
func (c *replicatedCmd) AckOutcomeAndFinish(ctx context.Context) error {
s, err := decodeWriteBatch(c.decodedRaftEntry.raftCmd.WriteBatch)
if err != nil {
s = fmt.Sprint(err)
}
log.Infof(ctx, "idx=%d mlai=%d forcedErr=%v: %v",
c.ent.Index,
c.decodedRaftEntry.raftCmd.MaxLeaseIndex,
c.forcedErr,
s)
if c.IsLocal() {
c.proposal.finishApplication(ctx, c.response)
}
Expand Down
2 changes: 1 addition & 1 deletion pkg/kv/kvserver/replica_application_state_machine.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -443,7 +443,7 @@ func (b *replicaAppBatch) Stage(cmdI apply.Command) (apply.CheckedCommand, error
// This check is deterministic on all replicas, so if one replica decides to
// reject a command, all will.
if !b.r.shouldApplyCommand(ctx, cmd, &b.state) {
log.VEventf(ctx, 1, "applying command with forced error: %s", cmd.forcedErr)
log.Infof(ctx, "applying command with forced error: %s", cmd.forcedErr)

// Apply an empty command.
cmd.raftCmd.ReplicatedEvalResult = kvserverpb.ReplicatedEvalResult{}
Expand Down

0 comments on commit 42628ed

Please sign in to comment.