diff --git a/pkg/storage/mvcc_history_test.go b/pkg/storage/mvcc_history_test.go index 7c13fb62d13e..a7b681dd7b51 100644 --- a/pkg/storage/mvcc_history_test.go +++ b/pkg/storage/mvcc_history_test.go @@ -13,6 +13,8 @@ package storage import ( "context" "fmt" + "regexp" + "sort" "strconv" "strings" "testing" @@ -43,6 +45,8 @@ import ( // // The input files use the following DSL: // +// run [ok|trace|stats|error] +// // txn_begin t= [ts=[,]] [globalUncertaintyLimit=[,]] // txn_remove t= // txn_restart t= @@ -97,6 +101,9 @@ func TestMVCCHistories(t *testing.T) { // Everything reads/writes under the same prefix. span := roachpb.Span{Key: keys.LocalMax, EndKey: roachpb.KeyMax} + // Timestamp for MVCC stats calculations, in nanoseconds. + const statsTS = 100e9 + datadriven.Walk(t, testutils.TestDataPath(t, "mvcc_histories"), func(t *testing.T, path string) { // We start from a clean slate in every test file. engine, err := Open(ctx, InMemory(), CacheSize(1<<20 /* 1 MiB */)) @@ -167,18 +174,14 @@ func TestMVCCHistories(t *testing.T) { // It stops upon the first error encountered, if any. // // Options: - // "trace" means detail each operation in the output. - // "error" means expect an error to occur. The specific error type/ - // message to expect is spelled out in the expected output. + // - trace: emit intermediate results after each operation. + // - stats: emit MVCC statistics for each operation and at the end. + // - error: expect an error to occur. The specific error type/ message + // to expect is spelled out in the expected output. // - trace := false - if e.hasArg("trace") { - trace = true - } - expectError := false - if e.hasArg("error") { - expectError = true - } + trace := e.hasArg("trace") + stats := e.hasArg("stats") + expectError := e.hasArg("error") // buf will accumulate the actual output, which the // datadriven driver will use to compare to the expected @@ -292,7 +295,7 @@ func TestMVCCHistories(t *testing.T) { txnChange = txnChange || cmd.typ == typTxnUpdate dataChange = dataChange || cmd.typ == typDataUpdate - if trace { + if trace || (stats && cmd.typ == typDataUpdate) { // If tracing is also requested by the datadriven input, // we'll trace the statement in the actual results too. buf.Printf(">> %s", d.Cmd) @@ -302,7 +305,13 @@ func TestMVCCHistories(t *testing.T) { _ = buf.WriteByte('\n') } + var msInitial enginepb.MVCCStats + if stats { + msInitial = computeStats(e.t, e.engine, span.Key, span.EndKey, statsTS) + } + // Run the command. + e.ms = &enginepb.MVCCStats{} foundErr = cmd.fn(e) if trace { @@ -312,6 +321,21 @@ func TestMVCCHistories(t *testing.T) { reportResults(cmd.typ == typTxnUpdate, cmd.typ == typDataUpdate) } + if stats && cmd.typ == typDataUpdate { + // If stats are enabled, emit evaluated stats returned by the + // command, and compare them with the real computed stats diff. + msEval := *e.ms + msEval.AgeTo(statsTS) + buf.Printf("stats: %s\n", formatStats(msEval, true)) + + msDiff := computeStats(e.t, e.engine, span.Key, span.EndKey, statsTS) + msDiff.Subtract(msInitial) + if msEval != msDiff { + e.t.Errorf("MVCC stats mismatch for %q at %s\nReturned: %s\nExpected: %s", + d.Cmd, d.Pos, formatStats(msEval, true), formatStats(msDiff, true)) + } + } + if foundErr != nil { // An error occurred. Stop the script prematurely. break @@ -327,6 +351,12 @@ func TestMVCCHistories(t *testing.T) { reportResults(txnChange, dataChange) } + // Calculate and output final stats if requested and the data changed. + if stats && dataChange { + ms := computeStats(t, e.engine, span.Key, span.EndKey, statsTS) + buf.Printf("stats: %s\n", formatStats(ms, false)) + } + signalError := e.t.Errorf if txnChange || dataChange { // We can't recover from an error and continue @@ -560,7 +590,7 @@ func (e *evalCtx) resolveIntent( intent := roachpb.MakeLockUpdate(txn, roachpb.Span{Key: key}) intent.Status = resolveStatus intent.ClockWhilePending = roachpb.ObservedTimestamp{Timestamp: clockWhilePending} - _, err := MVCCResolveWriteIntent(e.ctx, rw, nil, intent) + _, err := MVCCResolveWriteIntent(e.ctx, rw, e.ms, intent) return err } @@ -613,7 +643,7 @@ func cmdCPut(e *evalCtx) error { resolve, resolveStatus := e.getResolve() return e.withWriter("cput", func(rw ReadWriter) error { - if err := MVCCConditionalPut(e.ctx, rw, nil, key, ts, localTs, val, expVal, behavior, txn); err != nil { + if err := MVCCConditionalPut(e.ctx, rw, e.ms, key, ts, localTs, val, expVal, behavior, txn); err != nil { return err } if resolve { @@ -630,7 +660,7 @@ func cmdDelete(e *evalCtx) error { localTs := hlc.ClockTimestamp(e.getTsWithName("localTs")) resolve, resolveStatus := e.getResolve() return e.withWriter("del", func(rw ReadWriter) error { - if err := MVCCDelete(e.ctx, rw, nil, key, ts, localTs, txn); err != nil { + if err := MVCCDelete(e.ctx, rw, e.ms, key, ts, localTs, txn); err != nil { return err } if resolve { @@ -654,7 +684,7 @@ func cmdDeleteRange(e *evalCtx) error { resolve, resolveStatus := e.getResolve() return e.withWriter("del_range", func(rw ReadWriter) error { deleted, resumeSpan, num, err := MVCCDeleteRange( - e.ctx, rw, nil, key, endKey, int64(max), ts, localTs, txn, returnKeys) + e.ctx, rw, e.ms, key, endKey, int64(max), ts, localTs, txn, returnKeys) if err != nil { return err } @@ -729,7 +759,7 @@ func cmdIncrement(e *evalCtx) error { resolve, resolveStatus := e.getResolve() return e.withWriter("increment", func(rw ReadWriter) error { - curVal, err := MVCCIncrement(e.ctx, rw, nil, key, ts, localTs, txn, inc) + curVal, err := MVCCIncrement(e.ctx, rw, e.ms, key, ts, localTs, txn, inc) if err != nil { return err } @@ -746,7 +776,7 @@ func cmdMerge(e *evalCtx) error { val := e.getVal() ts := e.getTs(nil) return e.withWriter("merge", func(rw ReadWriter) error { - return MVCCMerge(e.ctx, rw, nil, key, ts, val) + return MVCCMerge(e.ctx, rw, e.ms, key, ts, val) }) } @@ -761,7 +791,7 @@ func cmdPut(e *evalCtx) error { resolve, resolveStatus := e.getResolve() return e.withWriter("put", func(rw ReadWriter) error { - if err := MVCCPut(e.ctx, rw, nil, key, ts, localTs, val, txn); err != nil { + if err := MVCCPut(e.ctx, rw, e.ms, key, ts, localTs, val, txn); err != nil { return err } if resolve { @@ -840,6 +870,54 @@ func cmdScan(e *evalCtx) error { return err } +// formatStats formats MVCC stats. +func formatStats(ms enginepb.MVCCStats, delta bool) string { + // Split stats into field pairs. Subindex 1 is key, 2 is value. + fields := regexp.MustCompile(`(\w+):(-?\d+)`).FindAllStringSubmatch(ms.String(), -1) + + // Sort some fields in preferred order, keeping the rest as-is at the end. + // + // TODO(erikgrinaker): Consider just reordering the MVCCStats struct fields + // instead, which determines the order of MVCCStats.String(). + order := []string{"key_count", "key_bytes", "val_count", "val_bytes", + "live_count", "live_bytes", "gc_bytes_age", + "intent_count", "intent_bytes", "separated_intent_count", "intent_age"} + sort.SliceStable(fields, func(i, j int) bool { + for _, name := range order { + if fields[i][1] == name { + return true + } else if fields[j][1] == name { + return false + } + } + return false + }) + + // Format and output fields. + var s string + for _, field := range fields { + key, value := field[1], field[2] + + // Always skip zero-valued fields and LastUpdateNanos. + if value == "0" || key == "last_update_nanos" { + continue + } + + if len(s) > 0 { + s += " " + } + s += key + "=" + if delta && value[0] != '-' { + s += "+" // prefix unsigned deltas with + + } + s += value + } + if len(s) == 0 && delta { + return "no change" + } + return s +} + // evalCtx stored the current state of the environment of a running // script. type evalCtx struct { @@ -854,6 +932,7 @@ type evalCtx struct { td *datadriven.TestData txns map[string]*roachpb.Transaction txnCounter uint128.Uint128 + ms *enginepb.MVCCStats } func newEvalCtx(ctx context.Context, engine Engine) *evalCtx { diff --git a/pkg/storage/testdata/mvcc_histories/conditional_put b/pkg/storage/testdata/mvcc_histories/conditional_put index 981f4522e6c9..a7888b6c353c 100644 --- a/pkg/storage/testdata/mvcc_histories/conditional_put +++ b/pkg/storage/testdata/mvcc_histories/conditional_put @@ -16,11 +16,14 @@ error: (*roachpb.ConditionFailedError:) unexpected value: # Do a conditional put with expectation that the value is completely missing; will succeed. -run ok +run stats ok cput k=k v=v ts=123,2 ---- +>> cput k=k v=v ts=123,2 +stats: key_count=+1 key_bytes=+14 val_count=+1 val_bytes=+6 live_count=+1 live_bytes=+20 >> at end: data: "k"/123.000000000,2 -> /BYTES/v +stats: key_count=1 key_bytes=14 val_count=1 val_bytes=6 live_count=1 live_bytes=20 # Another conditional put expecting value missing will fail, now that value1 is written. @@ -42,12 +45,15 @@ error: (*roachpb.ConditionFailedError:) unexpected value: raw_bytes:"\000\000\00 # Move to an empty value. Will succeed. -run ok +run stats ok cput k=k v= cond=v ts=123,5 ---- +>> cput k=k v= cond=v ts=123,5 +stats: key_bytes=+12 val_count=+1 val_bytes=+5 live_bytes=-1 gc_bytes_age=-414 >> at end: data: "k"/123.000000000,5 -> /BYTES/ data: "k"/123.000000000,2 -> /BYTES/v +stats: key_count=1 key_bytes=26 val_count=2 val_bytes=11 live_count=1 live_bytes=19 gc_bytes_age=-414 # Move key2 (which does not exist) to from value1 to value2. # Expect it to fail since it does not exist with value1. @@ -63,13 +69,16 @@ error: (*roachpb.ConditionFailedError:) unexpected value: # Move key2 (which does not yet exist) to from value1 to value2, but # allowing for it not existing. -run ok +run stats ok cput k=k2 v=v2 cond=v ts=123,7 allow_missing ---- +>> cput k=k2 v=v2 cond=v ts=123,7 allow_missing +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+7 live_count=+1 live_bytes=+22 >> at end: data: "k"/123.000000000,5 -> /BYTES/ data: "k"/123.000000000,2 -> /BYTES/v data: "k2"/123.000000000,7 -> /BYTES/v2 +stats: key_count=2 key_bytes=41 val_count=3 val_bytes=18 live_count=2 live_bytes=41 gc_bytes_age=-414 # Try to move key2 (which has value2) from value1 to empty. Expect error. @@ -84,26 +93,32 @@ error: (*roachpb.ConditionFailedError:) unexpected value: raw_bytes:"\000\000\00 # Try to move key2 (which has value2) from value2 to empty. Expect success. -run ok +run stats ok cput k=k2 v= cond=v2 allow_missing ts=123,9 ---- +>> cput k=k2 v= cond=v2 allow_missing ts=123,9 +stats: key_bytes=+12 val_count=+1 val_bytes=+5 live_bytes=-2 gc_bytes_age=-437 >> at end: data: "k"/123.000000000,5 -> /BYTES/ data: "k"/123.000000000,2 -> /BYTES/v data: "k2"/123.000000000,9 -> /BYTES/ data: "k2"/123.000000000,7 -> /BYTES/v2 +stats: key_count=2 key_bytes=53 val_count=4 val_bytes=23 live_count=2 live_bytes=39 gc_bytes_age=-851 # Now move to value2 from expected empty value. -run ok +run stats ok cput k=k v=v2 cond= ts=123,10 ---- +>> cput k=k v=v2 cond= ts=123,10 +stats: key_bytes=+12 val_count=+1 val_bytes=+7 live_bytes=+2 gc_bytes_age=-391 >> at end: data: "k"/123.000000000,10 -> /BYTES/v2 data: "k"/123.000000000,5 -> /BYTES/ data: "k"/123.000000000,2 -> /BYTES/v data: "k2"/123.000000000,9 -> /BYTES/ data: "k2"/123.000000000,7 -> /BYTES/v2 +stats: key_count=2 key_bytes=65 val_count=5 val_bytes=30 live_count=2 live_bytes=41 gc_bytes_age=-1242 # Verify we get value2 as expected. diff --git a/pkg/storage/testdata/mvcc_histories/conditional_put_with_txn_enable_separated b/pkg/storage/testdata/mvcc_histories/conditional_put_with_txn_enable_separated index 7ad2343a69dd..14358d67cac4 100644 --- a/pkg/storage/testdata/mvcc_histories/conditional_put_with_txn_enable_separated +++ b/pkg/storage/testdata/mvcc_histories/conditional_put_with_txn_enable_separated @@ -6,52 +6,64 @@ txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=123.000000000,0 min= # Write value1. -run ok +run stats ok with t=A txn_step cput k=k v=v ---- +>> cput k=k v=v t=A +stats: key_count=+1 key_bytes=+14 val_count=+1 val_bytes=+58 live_count=+1 live_bytes=+72 intent_count=+1 intent_bytes=+18 separated_intent_count=+1 intent_age=-23 >> at end: txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=123.000000000,0 min=0,0 seq=1} lock=true stat=PENDING rts=123.000000000,0 wto=false gul=0,0 meta: "k"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=123.000000000,0 min=0,0 seq=1} ts=123.000000000,0 del=false klen=12 vlen=6 mergeTs= txnDidNotUpdateMeta=true data: "k"/123.000000000,0 -> /BYTES/v +stats: key_count=1 key_bytes=14 val_count=1 val_bytes=58 live_count=1 live_bytes=72 intent_count=1 intent_bytes=18 separated_intent_count=1 intent_age=-23 # Now, overwrite value1 with value2 from same txn; should see value1 # as pre-existing value. -run ok +run stats ok with t=A txn_step cput k=k v=v2 cond=v ---- +>> cput k=k v=v2 cond=v t=A +stats: val_bytes=+11 live_bytes=+11 intent_bytes=+1 >> at end: txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=123.000000000,0 min=0,0 seq=2} lock=true stat=PENDING rts=123.000000000,0 wto=false gul=0,0 meta: "k"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=123.000000000,0 min=0,0 seq=2} ts=123.000000000,0 del=false klen=12 vlen=7 ih={{1 /BYTES/v}} mergeTs= txnDidNotUpdateMeta=false data: "k"/123.000000000,0 -> /BYTES/v2 +stats: key_count=1 key_bytes=14 val_count=1 val_bytes=69 live_count=1 live_bytes=83 intent_count=1 intent_bytes=19 separated_intent_count=1 intent_age=-23 # Writing value3 from a new epoch should see nil again. -run ok +run stats ok with t=A txn_restart txn_step cput k=k v=v3 ---- +>> cput k=k v=v3 t=A +stats: val_bytes=-10 live_bytes=-10 >> at end: txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=1 ts=123.000000000,0 min=0,0 seq=1} lock=true stat=PENDING rts=123.000000000,0 wto=false gul=0,0 meta: "k"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=1 ts=123.000000000,0 min=0,0 seq=1} ts=123.000000000,0 del=false klen=12 vlen=7 mergeTs= txnDidNotUpdateMeta=false data: "k"/123.000000000,0 -> /BYTES/v3 +stats: key_count=1 key_bytes=14 val_count=1 val_bytes=59 live_count=1 live_bytes=73 intent_count=1 intent_bytes=19 separated_intent_count=1 intent_age=-23 # Commit value3 at a later timestamp. -run ok +run stats ok with t=A txn_advance ts=124 resolve_intent k=k txn_remove ---- +>> resolve_intent k=k t=A +stats: val_bytes=-38 live_bytes=-38 intent_count=-1 intent_bytes=-19 separated_intent_count=-1 intent_age=+23 >> at end: data: "k"/124.000000000,0 -> vheader{ localTs=123.000000000,0 } /BYTES/v3 +stats: key_count=1 key_bytes=14 val_count=1 val_bytes=21 live_count=1 live_bytes=35 # Write value4 with an old timestamp without txn...should get a write # too old error. @@ -77,7 +89,7 @@ clear_range k=k end=-k # First txn attempt -run ok +run stats ok # Before txn start: put k=c v=value ts=1 with t=A @@ -85,15 +97,20 @@ with t=A txn_step cput k=c v=cput cond=value ---- +>> put k=c v=value ts=1 +stats: key_count=+1 key_bytes=+14 val_count=+1 val_bytes=+10 live_count=+1 live_bytes=+24 +>> cput k=c v=cput cond=value t=A +stats: key_bytes=+12 val_count=+1 val_bytes=+59 live_bytes=+49 gc_bytes_age=+2156 intent_count=+1 intent_bytes=+21 separated_intent_count=+1 intent_age=+98 >> at end: txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,0 min=0,0 seq=1} lock=true stat=PENDING rts=2.000000000,0 wto=false gul=0,0 meta: "c"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,0 min=0,0 seq=1} ts=2.000000000,0 del=false klen=12 vlen=9 mergeTs= txnDidNotUpdateMeta=true data: "c"/2.000000000,0 -> /BYTES/cput data: "c"/1.000000000,0 -> /BYTES/value +stats: key_count=1 key_bytes=26 val_count=2 val_bytes=69 live_count=1 live_bytes=73 gc_bytes_age=2156 intent_count=1 intent_bytes=21 separated_intent_count=1 intent_age=98 # Restart and retry cput. It should succeed. -run trace ok +run trace stats ok with t=A txn_restart ts=3 txn_step @@ -108,3 +125,5 @@ called PutIntent("c", _, 00000000-0000-0000-0000-000000000002) meta: "c"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=1 ts=3.000000000,0 min=0,0 seq=1} ts=3.000000000,0 del=false klen=12 vlen=9 mergeTs= txnDidNotUpdateMeta=false data: "c"/3.000000000,0 -> /BYTES/cput data: "c"/1.000000000,0 -> /BYTES/value +stats: gc_bytes_age=-22 intent_age=-1 +stats: key_count=1 key_bytes=26 val_count=2 val_bytes=69 live_count=1 live_bytes=73 gc_bytes_age=2134 intent_count=1 intent_bytes=21 separated_intent_count=1 intent_age=97 diff --git a/pkg/storage/testdata/mvcc_histories/delete_range b/pkg/storage/testdata/mvcc_histories/delete_range index 1fa89908c08c..4073e71af5ad 100644 --- a/pkg/storage/testdata/mvcc_histories/delete_range +++ b/pkg/storage/testdata/mvcc_histories/delete_range @@ -25,10 +25,12 @@ data: "d/123"/44.000000000,0 -> /BYTES/abc # A simple non-txn that deletes a range of keys. ## The delete tombstone is placed alongside each of the previous values, at the newer timestamp. -run ok +run stats ok del_range k=a end=b ts=45 ---- +>> del_range k=a end=b ts=45 del_range: "a"-"b" -> deleted 2 key(s) +stats: key_bytes=+24 val_count=+2 live_count=-2 live_bytes=-48 gc_bytes_age=+3960 >> at end: data: "a"/45.000000000,0 -> / data: "a"/44.000000000,0 -> /BYTES/abc @@ -40,13 +42,14 @@ data: "c"/44.000000000,0 -> /BYTES/abc data: "c/123"/44.000000000,0 -> /BYTES/abc data: "d"/44.000000000,0 -> /BYTES/abc data: "d/123"/44.000000000,0 -> /BYTES/abc +stats: key_count=8 key_bytes=152 val_count=10 val_bytes=64 live_count=6 live_bytes=144 gc_bytes_age=3960 # A simple txn that deletes a range of keys. ## The delete tombstone is placed alongside each of the previous values, at the newer timestamp. ## The deleted keys are returned. -run ok +run stat with t=A txn_begin ts=46 del_range k=b end=c returnKeys @@ -76,13 +79,15 @@ data: "d/123"/44.000000000,0 -> /BYTES/abc ## Only up to two keys are deleted. ## The deleted keys are returned. -run ok +run stats ok del_range k=c end=z ts=47 max=2 returnKeys ---- +>> del_range k=c end=z ts=47 max=2 returnKeys del_range: "c"-"z" -> deleted 2 key(s) del_range: returned "c" del_range: returned "c/123" del_range: resume span ["d","z") +stats: key_bytes=+24 val_count=+2 live_count=-2 live_bytes=-48 gc_bytes_age=+3816 >> at end: data: "a"/45.000000000,0 -> / data: "a"/44.000000000,0 -> /BYTES/abc @@ -100,6 +105,7 @@ data: "c/123"/47.000000000,0 -> / data: "c/123"/44.000000000,0 -> /BYTES/abc data: "d"/44.000000000,0 -> /BYTES/abc data: "d/123"/44.000000000,0 -> /BYTES/abc +stats: key_count=8 key_bytes=200 val_count=14 val_bytes=164 live_count=2 live_bytes=48 gc_bytes_age=17064 intent_count=2 intent_bytes=24 separated_intent_count=2 intent_age=108 # A txn that performs a delete range at a lower timestamp returns a WriteTooOld error. @@ -138,15 +144,17 @@ txn_remove t=A # A txn that performs a delete range at a higher timestamp does not place duplicate tombstones. -run ok +run stats ok with t=A txn_begin ts=48 del_range k=c end=z returnKeys txn_remove ---- +>> del_range k=c end=z returnKeys t=A del_range: "c"-"z" -> deleted 2 key(s) del_range: returned "d" del_range: returned "d/123" +stats: key_bytes=+24 val_count=+2 val_bytes=+100 live_count=-2 live_bytes=-48 gc_bytes_age=+8944 intent_count=+2 intent_bytes=+24 separated_intent_count=+2 intent_age=+104 >> at end: data: "a"/45.000000000,0 -> / data: "a"/44.000000000,0 -> /BYTES/abc @@ -168,3 +176,4 @@ data: "d"/44.000000000,0 -> /BYTES/abc meta: "d/123"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=48.000000000,0 min=0,0 seq=0} ts=48.000000000,0 del=true klen=12 vlen=0 mergeTs= txnDidNotUpdateMeta=true data: "d/123"/48.000000000,0 -> / data: "d/123"/44.000000000,0 -> /BYTES/abc +stats: key_count=8 key_bytes=224 val_count=16 val_bytes=264 gc_bytes_age=26008 intent_count=4 intent_bytes=48 separated_intent_count=4 intent_age=212 diff --git a/pkg/storage/testdata/mvcc_histories/deletes b/pkg/storage/testdata/mvcc_histories/deletes index a2422ae3bce3..c7498f3e8304 100644 --- a/pkg/storage/testdata/mvcc_histories/deletes +++ b/pkg/storage/testdata/mvcc_histories/deletes @@ -1,14 +1,17 @@ ## A simple txn that deletes. ## The delete tombstone is placed alongside the previous value, at the newer timestamp. -run ok +run stats ok with t=A txn_begin ts=44 del k=a resolve txn_remove ---- +>> del k=a resolve t=A +stats: key_count=+1 key_bytes=+14 val_count=+1 gc_bytes_age=+784 >> at end: data: "a"/44.000000000,0 -> / +stats: key_count=1 key_bytes=14 val_count=1 gc_bytes_age=784 # Show the value disappears from gets. diff --git a/pkg/storage/testdata/mvcc_histories/idempotent_transactions b/pkg/storage/testdata/mvcc_histories/idempotent_transactions index 02f7d3b6b819..3541b3b356cc 100644 --- a/pkg/storage/testdata/mvcc_histories/idempotent_transactions +++ b/pkg/storage/testdata/mvcc_histories/idempotent_transactions @@ -1,4 +1,4 @@ -run ok +run stats ok with t=a k=a txn_begin ts=11 # Lay down an intent. @@ -6,10 +6,15 @@ with t=a k=a # Lay down an intent again with no problem because we're idempotent. put v=first ---- +>> put v=first t=a k=a +stats: key_count=+1 key_bytes=+14 val_count=+1 val_bytes=+61 live_count=+1 live_bytes=+75 intent_count=+1 intent_bytes=+22 separated_intent_count=+1 intent_age=+89 +>> put v=first t=a k=a +stats: no change >> at end: txn: "a" meta={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=0} lock=true stat=PENDING rts=11.000000000,0 wto=false gul=0,0 meta: "a"/0,0 -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=0} ts=11.000000000,0 del=false klen=12 vlen=10 mergeTs= txnDidNotUpdateMeta=true data: "a"/11.000000000,0 -> /BYTES/first +stats: key_count=1 key_bytes=14 val_count=1 val_bytes=61 live_count=1 live_bytes=75 intent_count=1 intent_bytes=22 separated_intent_count=1 intent_age=89 # Lay down an intent without increasing the sequence but with a different value. # Expect an error. @@ -22,7 +27,7 @@ meta: "a"/0,0 -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 data: "a"/11.000000000,0 -> /BYTES/first error: (*assert.withAssertionFailure:) transaction 00000000-0000-0000-0000-000000000001 with sequence 0 has a different value [0 0 0 0 3 115 101 99 111 110 100] after recomputing from what was written: [0 0 0 0 3 102 105 114 115 116] -run ok +run stats ok with t=a k=a # Lay down a second intent. txn_step @@ -34,11 +39,16 @@ with t=a k=a txn_step check_intent ---- +>> put v=second t=a k=a +stats: val_bytes=+17 live_bytes=+17 intent_bytes=+1 +>> put v=first t=a k=a +stats: no change meta: "a" -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=1} ts=11.000000000,0 del=false klen=12 vlen=11 ih={{0 /BYTES/first}} mergeTs= txnDidNotUpdateMeta=false >> at end: txn: "a" meta={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=1} lock=true stat=PENDING rts=11.000000000,0 wto=false gul=0,0 meta: "a"/0,0 -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=1} ts=11.000000000,0 del=false klen=12 vlen=11 ih={{0 /BYTES/first}} mergeTs= txnDidNotUpdateMeta=false data: "a"/11.000000000,0 -> /BYTES/second +stats: key_count=1 key_bytes=14 val_count=1 val_bytes=78 live_count=1 live_bytes=92 intent_count=1 intent_bytes=23 separated_intent_count=1 intent_age=89 run error with t=a k=a @@ -52,7 +62,7 @@ meta: "a"/0,0 -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 data: "a"/11.000000000,0 -> /BYTES/second error: (*issuelink.withIssueLink:) transaction 00000000-0000-0000-0000-000000000001 with sequence 1 missing an intent with lower sequence -1 -run ok +run stats ok with t=a k=i # On a separate nonexistent key, start an increment. txn_step n=3 @@ -62,18 +72,27 @@ with t=a k=i increment increment ---- +>> increment t=a k=i inc: current value = 1 +stats: key_count=+1 key_bytes=+14 val_count=+1 val_bytes=+59 live_count=+1 live_bytes=+73 intent_count=+1 intent_bytes=+18 separated_intent_count=+1 intent_age=+89 +>> increment t=a k=i inc: current value = 1 +stats: no change +>> increment t=a k=i inc: current value = 1 +stats: no change +>> increment t=a k=i inc: current value = 1 +stats: no change >> at end: txn: "a" meta={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=2} lock=true stat=PENDING rts=11.000000000,0 wto=false gul=0,0 meta: "a"/0,0 -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=1} ts=11.000000000,0 del=false klen=12 vlen=11 ih={{0 /BYTES/first}} mergeTs= txnDidNotUpdateMeta=false data: "a"/11.000000000,0 -> /BYTES/second meta: "i"/0,0 -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=2} ts=11.000000000,0 del=false klen=12 vlen=6 mergeTs= txnDidNotUpdateMeta=true data: "i"/11.000000000,0 -> /INT/1 +stats: key_count=2 key_bytes=28 val_count=2 val_bytes=137 live_count=2 live_bytes=165 intent_count=2 intent_bytes=41 separated_intent_count=2 intent_age=178 -run ok +run stats ok with t=a k=i # Increment previously nonexistent key again. txn_step @@ -87,32 +106,48 @@ with t=a k=i increment increment ---- +>> increment t=a k=i inc: current value = 2 +stats: val_bytes=+10 live_bytes=+10 +>> increment t=a k=i inc: current value = 2 +stats: no change +>> increment t=a k=i inc: current value = 2 +stats: no change +>> increment t=a k=i inc: current value = 1 +stats: no change +>> increment t=a k=i inc: current value = 1 +stats: no change +>> increment t=a k=i inc: current value = 1 +stats: no change >> at end: txn: "a" meta={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=2} lock=true stat=PENDING rts=11.000000000,0 wto=false gul=0,0 meta: "a"/0,0 -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=1} ts=11.000000000,0 del=false klen=12 vlen=11 ih={{0 /BYTES/first}} mergeTs= txnDidNotUpdateMeta=false data: "a"/11.000000000,0 -> /BYTES/second meta: "i"/0,0 -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=3} ts=11.000000000,0 del=false klen=12 vlen=6 ih={{2 /INT/1}} mergeTs= txnDidNotUpdateMeta=false data: "i"/11.000000000,0 -> /INT/2 +stats: key_count=2 key_bytes=28 val_count=2 val_bytes=147 live_count=2 live_bytes=175 intent_count=2 intent_bytes=41 separated_intent_count=2 intent_age=178 # Write a key outside of the transaction. -run ok +run stats ok increment k=i2 ts=10 ---- +>> increment k=i2 ts=10 inc: current value = 1 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+6 live_count=+1 live_bytes=+21 >> at end: meta: "a"/0,0 -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=1} ts=11.000000000,0 del=false klen=12 vlen=11 ih={{0 /BYTES/first}} mergeTs= txnDidNotUpdateMeta=false data: "a"/11.000000000,0 -> /BYTES/second meta: "i"/0,0 -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=3} ts=11.000000000,0 del=false klen=12 vlen=6 ih={{2 /INT/1}} mergeTs= txnDidNotUpdateMeta=false data: "i"/11.000000000,0 -> /INT/2 data: "i2"/10.000000000,0 -> /INT/1 +stats: key_count=3 key_bytes=43 val_count=3 val_bytes=153 live_count=3 live_bytes=196 intent_count=2 intent_bytes=41 separated_intent_count=2 intent_age=178 -run ok +run stats ok with t=a k=i2 # On a separate existent key, start an increment. txn_step n=2 @@ -122,10 +157,18 @@ with t=a k=i2 increment increment ---- +>> increment t=a k=i2 inc: current value = 2 +stats: key_bytes=+12 val_count=+1 val_bytes=+59 live_bytes=+53 gc_bytes_age=+1602 intent_count=+1 intent_bytes=+18 separated_intent_count=+1 intent_age=+89 +>> increment t=a k=i2 inc: current value = 2 +stats: no change +>> increment t=a k=i2 inc: current value = 2 +stats: no change +>> increment t=a k=i2 inc: current value = 2 +stats: no change >> at end: txn: "a" meta={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=4} lock=true stat=PENDING rts=11.000000000,0 wto=false gul=0,0 meta: "a"/0,0 -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=1} ts=11.000000000,0 del=false klen=12 vlen=11 ih={{0 /BYTES/first}} mergeTs= txnDidNotUpdateMeta=false @@ -135,8 +178,9 @@ data: "i"/11.000000000,0 -> /INT/2 meta: "i2"/0,0 -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=4} ts=11.000000000,0 del=false klen=12 vlen=6 mergeTs= txnDidNotUpdateMeta=true data: "i2"/11.000000000,0 -> /INT/2 data: "i2"/10.000000000,0 -> /INT/1 +stats: key_count=3 key_bytes=55 val_count=4 val_bytes=212 live_count=3 live_bytes=249 gc_bytes_age=1602 intent_count=3 intent_bytes=59 separated_intent_count=3 intent_age=267 -run ok +run stats ok with t=a k=i2 # Increment previously existent key again. txn_step @@ -150,12 +194,24 @@ with t=a k=i2 increment increment ---- +>> increment t=a k=i2 inc: current value = 3 +stats: val_bytes=+10 live_bytes=+10 +>> increment t=a k=i2 inc: current value = 3 +stats: no change +>> increment t=a k=i2 inc: current value = 3 +stats: no change +>> increment t=a k=i2 inc: current value = 2 +stats: no change +>> increment t=a k=i2 inc: current value = 2 +stats: no change +>> increment t=a k=i2 inc: current value = 2 +stats: no change >> at end: txn: "a" meta={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=4} lock=true stat=PENDING rts=11.000000000,0 wto=false gul=0,0 meta: "a"/0,0 -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=1} ts=11.000000000,0 del=false klen=12 vlen=11 ih={{0 /BYTES/first}} mergeTs= txnDidNotUpdateMeta=false @@ -165,3 +221,4 @@ data: "i"/11.000000000,0 -> /INT/2 meta: "i2"/0,0 -> txn={id=00000000 key="a" pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=5} ts=11.000000000,0 del=false klen=12 vlen=6 ih={{4 /INT/2}} mergeTs= txnDidNotUpdateMeta=false data: "i2"/11.000000000,0 -> /INT/3 data: "i2"/10.000000000,0 -> /INT/1 +stats: key_count=3 key_bytes=55 val_count=4 val_bytes=222 live_count=3 live_bytes=259 gc_bytes_age=1602 intent_count=3 intent_bytes=59 separated_intent_count=3 intent_age=267 diff --git a/pkg/storage/testdata/mvcc_histories/ignored_seq_nums_commit b/pkg/storage/testdata/mvcc_histories/ignored_seq_nums_commit index adb413ba46fc..6ae3be9b518f 100644 --- a/pkg/storage/testdata/mvcc_histories/ignored_seq_nums_commit +++ b/pkg/storage/testdata/mvcc_histories/ignored_seq_nums_commit @@ -1,7 +1,7 @@ # Perform some writes at various sequence numbers. -run ok +run stats ok with t=A txn_begin ts=11 txn_step seq=10 @@ -22,11 +22,32 @@ with t=A resolve_intent k=k/20 resolve_intent k=k/30 ---- +>> put k=k v=a t=A +stats: key_count=+1 key_bytes=+14 val_count=+1 val_bytes=+56 live_count=+1 live_bytes=+70 intent_count=+1 intent_bytes=+18 separated_intent_count=+1 intent_age=+89 +>> put k=k/10 v=10 t=A +stats: key_count=+1 key_bytes=+17 val_count=+1 val_bytes=+57 live_count=+1 live_bytes=+74 intent_count=+1 intent_bytes=+19 separated_intent_count=+1 intent_age=+89 +>> put k=k v=b t=A +stats: val_bytes=+10 live_bytes=+10 +>> put k=k/20 v=20 t=A +stats: key_count=+1 key_bytes=+17 val_count=+1 val_bytes=+57 live_count=+1 live_bytes=+74 intent_count=+1 intent_bytes=+19 separated_intent_count=+1 intent_age=+89 +>> put k=k v=c t=A +stats: val_bytes=+12 live_bytes=+12 +>> put k=k/30 v=30 t=A +stats: key_count=+1 key_bytes=+17 val_count=+1 val_bytes=+57 live_count=+1 live_bytes=+74 intent_count=+1 intent_bytes=+19 separated_intent_count=+1 intent_age=+89 +>> resolve_intent k=k t=A +stats: val_bytes=-72 live_bytes=-72 intent_count=-1 intent_bytes=-18 separated_intent_count=-1 intent_age=-89 +>> resolve_intent k=k/10 t=A +stats: val_bytes=-50 live_bytes=-50 intent_count=-1 intent_bytes=-19 separated_intent_count=-1 intent_age=-89 +>> resolve_intent k=k/20 t=A +stats: val_bytes=-50 live_bytes=-50 intent_count=-1 intent_bytes=-19 separated_intent_count=-1 intent_age=-89 +>> resolve_intent k=k/30 t=A +stats: key_count=-1 key_bytes=-17 val_count=-1 val_bytes=-57 live_count=-1 live_bytes=-74 intent_count=-1 intent_bytes=-19 separated_intent_count=-1 intent_age=-89 >> at end: txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=40} lock=true stat=PENDING rts=11.000000000,0 wto=false gul=0,0 isn=1 data: "k"/11.000000000,0 -> /BYTES/b data: "k/10"/11.000000000,0 -> /BYTES/10 data: "k/20"/11.000000000,0 -> /BYTES/20 +stats: key_count=3 key_bytes=48 val_count=3 val_bytes=20 live_count=3 live_bytes=68 run ok scan k=k end=-k @@ -42,7 +63,7 @@ txn_remove t=A >> at end: -run ok +run stats ok with t=A txn_begin ts=11 txn_step seq=10 @@ -63,11 +84,32 @@ with t=A resolve_intent k=k/20 resolve_intent k=k/30 ---- +>> put k=k v=a t=A +stats: key_count=+1 key_bytes=+14 val_count=+1 val_bytes=+56 live_count=+1 live_bytes=+70 intent_count=+1 intent_bytes=+18 separated_intent_count=+1 intent_age=+89 +>> put k=k/10 v=10 t=A +stats: key_count=+1 key_bytes=+17 val_count=+1 val_bytes=+57 live_count=+1 live_bytes=+74 intent_count=+1 intent_bytes=+19 separated_intent_count=+1 intent_age=+89 +>> put k=k v=b t=A +stats: val_bytes=+10 live_bytes=+10 +>> put k=k/20 v=20 t=A +stats: key_count=+1 key_bytes=+17 val_count=+1 val_bytes=+57 live_count=+1 live_bytes=+74 intent_count=+1 intent_bytes=+19 separated_intent_count=+1 intent_age=+89 +>> put k=k v=c t=A +stats: val_bytes=+12 live_bytes=+12 +>> put k=k/30 v=30 t=A +stats: key_count=+1 key_bytes=+17 val_count=+1 val_bytes=+57 live_count=+1 live_bytes=+74 intent_count=+1 intent_bytes=+19 separated_intent_count=+1 intent_age=+89 +>> resolve_intent k=k t=A +stats: val_bytes=-72 live_bytes=-72 intent_count=-1 intent_bytes=-18 separated_intent_count=-1 intent_age=-89 +>> resolve_intent k=k/10 t=A +stats: val_bytes=-50 live_bytes=-50 intent_count=-1 intent_bytes=-19 separated_intent_count=-1 intent_age=-89 +>> resolve_intent k=k/20 t=A +stats: key_count=-1 key_bytes=-17 val_count=-1 val_bytes=-57 live_count=-1 live_bytes=-74 intent_count=-1 intent_bytes=-19 separated_intent_count=-1 intent_age=-89 +>> resolve_intent k=k/30 t=A +stats: val_bytes=-50 live_bytes=-50 intent_count=-1 intent_bytes=-19 separated_intent_count=-1 intent_age=-89 >> at end: txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=11.000000000,0 min=0,0 seq=40} lock=true stat=PENDING rts=11.000000000,0 wto=false gul=0,0 isn=1 data: "k"/11.000000000,0 -> /BYTES/c data: "k/10"/11.000000000,0 -> /BYTES/10 data: "k/30"/11.000000000,0 -> /BYTES/30 +stats: key_count=3 key_bytes=48 val_count=3 val_bytes=20 live_count=3 live_bytes=68 run ok scan k=k end=-k diff --git a/pkg/storage/testdata/mvcc_histories/increment b/pkg/storage/testdata/mvcc_histories/increment index 1d0f40b75832..e28fde3d7d84 100644 --- a/pkg/storage/testdata/mvcc_histories/increment +++ b/pkg/storage/testdata/mvcc_histories/increment @@ -3,18 +3,23 @@ # Non-transactional increments. -run ok +run stats ok with k=k increment ts=0,1 inc=0 get ts=0,1 increment ts=0,2 inc=2 ---- +>> increment ts=0,1 inc=0 k=k inc: current value = 0 +stats: key_count=+1 key_bytes=+14 val_count=+1 val_bytes=+6 live_count=+1 live_bytes=+20 get: "k" -> /INT/0 @0,1 +>> increment ts=0,2 inc=2 k=k inc: current value = 2 +stats: key_bytes=+12 val_count=+1 val_bytes=+6 gc_bytes_age=+1800 >> at end: data: "k"/0,2 -> /INT/2 data: "k"/0,1 -> /INT/0 +stats: key_count=1 key_bytes=26 val_count=2 val_bytes=12 live_count=1 live_bytes=20 gc_bytes_age=1800 run ok clear_range k=k end=-k @@ -23,7 +28,7 @@ clear_range k=k end=-k # Transactional increments. -run ok +run stats ok with k=k t=a ts=0,1 txn_begin txn_step @@ -31,12 +36,17 @@ with k=k t=a ts=0,1 txn_step increment ---- +>> increment k=k t=a ts=0,1 inc: current value = 1 +stats: key_count=+1 key_bytes=+14 val_count=+1 val_bytes=+51 live_count=+1 live_bytes=+65 intent_count=+1 intent_bytes=+18 separated_intent_count=+1 intent_age=+100 +>> increment k=k t=a ts=0,1 inc: current value = 2 +stats: val_bytes=+10 live_bytes=+10 >> at end: txn: "a" meta={id=00000000 key="k" pri=0.00000000 epo=0 ts=0,1 min=0,0 seq=2} lock=true stat=PENDING rts=0,1 wto=false gul=0,0 meta: "k"/0,0 -> txn={id=00000000 key="k" pri=0.00000000 epo=0 ts=0,1 min=0,0 seq=2} ts=0,1 del=false klen=12 vlen=6 ih={{1 /INT/1}} mergeTs= txnDidNotUpdateMeta=false data: "k"/0,1 -> /INT/2 +stats: key_count=1 key_bytes=14 val_count=1 val_bytes=61 live_count=1 live_bytes=75 intent_count=1 intent_bytes=18 separated_intent_count=1 intent_age=100 # Increments at older timestamp generate WriteTooOld. diff --git a/pkg/storage/testdata/mvcc_histories/intent_history_enable_separated b/pkg/storage/testdata/mvcc_histories/intent_history_enable_separated index b4fd8d9aa650..1e744cbad50d 100644 --- a/pkg/storage/testdata/mvcc_histories/intent_history_enable_separated +++ b/pkg/storage/testdata/mvcc_histories/intent_history_enable_separated @@ -1,17 +1,20 @@ ## Write the base (default) value. -run ok +run stats ok with t=A txn_begin ts=1 put k=a v=default resolve txn_remove ---- +>> put k=a v=default resolve t=A +stats: key_count=+1 key_bytes=+14 val_count=+1 val_bytes=+12 live_count=+1 live_bytes=+26 >> at end: data: "a"/1.000000000,0 -> /BYTES/default +stats: key_count=1 key_bytes=14 val_count=1 val_bytes=12 live_count=1 live_bytes=26 ## See how the intent history evolves throughout the test. -run trace ok +run trace stats ok with t=A txn_begin ts=2 with k=a @@ -31,6 +34,7 @@ called PutIntent("a", _, 00000000-0000-0000-0000-000000000002) meta: "a"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,0 min=0,0 seq=0} ts=2.000000000,0 del=false klen=12 vlen=10 mergeTs= txnDidNotUpdateMeta=true data: "a"/2.000000000,0 -> /BYTES/first data: "a"/1.000000000,0 -> /BYTES/default +stats: key_bytes=+12 val_count=+1 val_bytes=+58 live_bytes=+46 gc_bytes_age=+2352 intent_count=+1 intent_bytes=+22 separated_intent_count=+1 intent_age=+98 >> txn_step k=a t=A txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,0 min=0,0 seq=1} lock=true stat=PENDING rts=2.000000000,0 wto=false gul=0,0 >> put v=second k=a t=A @@ -38,6 +42,7 @@ called PutIntent("a", _, 00000000-0000-0000-0000-000000000002) meta: "a"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,0 min=0,0 seq=1} ts=2.000000000,0 del=false klen=12 vlen=11 ih={{0 /BYTES/first}} mergeTs= txnDidNotUpdateMeta=false data: "a"/2.000000000,0 -> /BYTES/second data: "a"/1.000000000,0 -> /BYTES/default +stats: val_bytes=+17 live_bytes=+17 intent_bytes=+1 >> txn_step n=2 k=a t=A txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,0 min=0,0 seq=3} lock=true stat=PENDING rts=2.000000000,0 wto=false gul=0,0 >> del k=a t=A @@ -45,6 +50,7 @@ called PutIntent("a", _, 00000000-0000-0000-0000-000000000002) meta: "a"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,0 min=0,0 seq=3} ts=2.000000000,0 del=true klen=12 vlen=0 ih={{0 /BYTES/first}{1 /BYTES/second}} mergeTs= txnDidNotUpdateMeta=false data: "a"/2.000000000,0 -> / data: "a"/1.000000000,0 -> /BYTES/default +stats: val_bytes=+6 live_count=-1 live_bytes=-89 gc_bytes_age=+9310 intent_bytes=-11 >> txn_step n=6 k=a t=A txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,0 min=0,0 seq=9} lock=true stat=PENDING rts=2.000000000,0 wto=false gul=0,0 >> put v=first k=a t=A @@ -52,7 +58,10 @@ called PutIntent("a", _, 00000000-0000-0000-0000-000000000002) meta: "a"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,0 min=0,0 seq=9} ts=2.000000000,0 del=false klen=12 vlen=10 ih={{0 /BYTES/first}{1 /BYTES/second}{3 /}} mergeTs= txnDidNotUpdateMeta=false data: "a"/2.000000000,0 -> /BYTES/first data: "a"/1.000000000,0 -> /BYTES/default +stats: val_bytes=+16 live_count=+1 live_bytes=+111 gc_bytes_age=-9310 intent_bytes=+10 >> resolve_intent k=a t=A called ClearIntent("a", TDNUM(false), 00000000-0000-0000-0000-000000000002) data: "a"/2.000000000,0 -> /BYTES/first data: "a"/1.000000000,0 -> /BYTES/default +stats: val_bytes=-87 live_bytes=-87 intent_count=-1 intent_bytes=-22 separated_intent_count=-1 intent_age=-98 +stats: key_count=1 key_bytes=26 val_count=2 val_bytes=22 live_count=1 live_bytes=24 gc_bytes_age=2352 diff --git a/pkg/storage/testdata/mvcc_histories/intent_with_write_tracing_enable_separated b/pkg/storage/testdata/mvcc_histories/intent_with_write_tracing_enable_separated index 3d19aa0d32a9..de2d2afcab3d 100644 --- a/pkg/storage/testdata/mvcc_histories/intent_with_write_tracing_enable_separated +++ b/pkg/storage/testdata/mvcc_histories/intent_with_write_tracing_enable_separated @@ -1,4 +1,4 @@ -run trace ok +run trace stats ok with t=A txn_begin ts=2 put k=k1 v=v1 @@ -9,8 +9,10 @@ txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,0 min=0, called PutIntent("k1", _, 00000000-0000-0000-0000-000000000001) meta: "k1"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,0 min=0,0 seq=0} ts=2.000000000,0 del=false klen=12 vlen=7 mergeTs= txnDidNotUpdateMeta=true data: "k1"/2.000000000,0 -> /BYTES/v1 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+55 live_count=+1 live_bytes=+70 intent_count=+1 intent_bytes=+19 separated_intent_count=+1 intent_age=+98 +stats: key_count=1 key_bytes=15 val_count=1 val_bytes=55 live_count=1 live_bytes=70 intent_count=1 intent_bytes=19 separated_intent_count=1 intent_age=98 -run trace ok +run trace stats ok with t=A txn_advance ts=3 txn_step @@ -25,14 +27,17 @@ txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=3.000000000,0 min=0, called PutIntent("k1", _, 00000000-0000-0000-0000-000000000001) meta: "k1"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=3.000000000,0 min=0,0 seq=1} ts=3.000000000,0 del=false klen=12 vlen=7 ih={{0 /BYTES/v1}} mergeTs= txnDidNotUpdateMeta=false data: "k1"/3.000000000,0 -> /BYTES/v1 +stats: val_bytes=+13 live_bytes=+13 intent_age=-1 >> put k=k2 v=v2 t=A called PutIntent("k2", _, 00000000-0000-0000-0000-000000000001) meta: "k1"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=3.000000000,0 min=0,0 seq=1} ts=3.000000000,0 del=false klen=12 vlen=7 ih={{0 /BYTES/v1}} mergeTs= txnDidNotUpdateMeta=false data: "k1"/3.000000000,0 -> /BYTES/v1 meta: "k2"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=3.000000000,0 min=0,0 seq=1} ts=3.000000000,0 del=false klen=12 vlen=7 mergeTs= txnDidNotUpdateMeta=true data: "k2"/3.000000000,0 -> /BYTES/v2 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+57 live_count=+1 live_bytes=+72 intent_count=+1 intent_bytes=+19 separated_intent_count=+1 intent_age=+97 +stats: key_count=2 key_bytes=30 val_count=2 val_bytes=125 live_count=2 live_bytes=155 intent_count=2 intent_bytes=38 separated_intent_count=2 intent_age=194 -run trace ok +run trace stats ok put k=k3 v=v3 ts=1 ---- >> put k=k3 v=v3 ts=1 @@ -41,8 +46,10 @@ data: "k1"/3.000000000,0 -> /BYTES/v1 meta: "k2"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=3.000000000,0 min=0,0 seq=1} ts=3.000000000,0 del=false klen=12 vlen=7 mergeTs= txnDidNotUpdateMeta=true data: "k2"/3.000000000,0 -> /BYTES/v2 data: "k3"/1.000000000,0 -> /BYTES/v3 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+7 live_count=+1 live_bytes=+22 +stats: key_count=3 key_bytes=45 val_count=3 val_bytes=132 live_count=3 live_bytes=177 intent_count=2 intent_bytes=38 separated_intent_count=2 intent_age=194 -run trace ok +run trace stats ok with t=A put k=k3 v=v33 ---- @@ -55,11 +62,13 @@ data: "k2"/3.000000000,0 -> /BYTES/v2 meta: "k3"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=3.000000000,0 min=0,0 seq=1} ts=3.000000000,0 del=false klen=12 vlen=8 mergeTs= txnDidNotUpdateMeta=true data: "k3"/3.000000000,0 -> /BYTES/v33 data: "k3"/1.000000000,0 -> /BYTES/v3 +stats: key_bytes=+12 val_count=+1 val_bytes=+58 live_bytes=+51 gc_bytes_age=+1843 intent_count=+1 intent_bytes=+20 separated_intent_count=+1 intent_age=+97 +stats: key_count=3 key_bytes=57 val_count=4 val_bytes=190 live_count=3 live_bytes=228 gc_bytes_age=1843 intent_count=3 intent_bytes=58 separated_intent_count=3 intent_age=291 # transactionDidNotUpdateMeta (TDNUM) is false below for k2 and k3 since # disallowSeparatedIntents=true causes mvcc.go to always set it to false to maintain # consistency in a mixed version cluster. -run trace ok +run trace stats ok with t=A resolve_intent k=k1 resolve_intent k=k2 status=ABORTED @@ -74,14 +83,18 @@ data: "k2"/3.000000000,0 -> /BYTES/v2 meta: "k3"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=3.000000000,0 min=0,0 seq=1} ts=3.000000000,0 del=false klen=12 vlen=8 mergeTs= txnDidNotUpdateMeta=true data: "k3"/3.000000000,0 -> /BYTES/v33 data: "k3"/1.000000000,0 -> /BYTES/v3 +stats: val_bytes=-61 live_bytes=-61 intent_count=-1 intent_bytes=-19 separated_intent_count=-1 intent_age=-97 >> resolve_intent k=k2 status=ABORTED t=A called ClearIntent("k2", TDNUM(false), 00000000-0000-0000-0000-000000000001) data: "k1"/3.000000000,0 -> /BYTES/v1 meta: "k3"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=3.000000000,0 min=0,0 seq=1} ts=3.000000000,0 del=false klen=12 vlen=8 mergeTs= txnDidNotUpdateMeta=true data: "k3"/3.000000000,0 -> /BYTES/v33 data: "k3"/1.000000000,0 -> /BYTES/v3 +stats: key_count=-1 key_bytes=-15 val_count=-1 val_bytes=-57 live_count=-1 live_bytes=-72 intent_count=-1 intent_bytes=-19 separated_intent_count=-1 intent_age=-97 >> resolve_intent k=k3 status=ABORTED t=A called ClearIntent("k3", TDNUM(false), 00000000-0000-0000-0000-000000000001) data: "k1"/3.000000000,0 -> /BYTES/v1 data: "k3"/1.000000000,0 -> /BYTES/v3 +stats: key_bytes=-12 val_count=-1 val_bytes=-58 live_bytes=-51 gc_bytes_age=-1843 intent_count=-1 intent_bytes=-20 separated_intent_count=-1 intent_age=-97 >> txn_remove t=A +stats: key_count=2 key_bytes=30 val_count=2 val_bytes=14 live_count=2 live_bytes=44 diff --git a/pkg/storage/testdata/mvcc_histories/local_timestamp b/pkg/storage/testdata/mvcc_histories/local_timestamp index 79e71ec3ca9d..bbfbda3cf1fa 100644 --- a/pkg/storage/testdata/mvcc_histories/local_timestamp +++ b/pkg/storage/testdata/mvcc_histories/local_timestamp @@ -1,22 +1,35 @@ # Exercise each write operation with a local timestamp. -run ok +run stats ok with ts=20 put localTs=10 k=k1 v=v put localTs=20 k=k2 v=v put localTs=30 k=k3 v=v ---- +>> put localTs=10 k=k1 v=v ts=20 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+19 live_count=+1 live_bytes=+34 +>> put localTs=20 k=k2 v=v ts=20 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+6 live_count=+1 live_bytes=+21 +>> put localTs=30 k=k3 v=v ts=20 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+6 live_count=+1 live_bytes=+21 >> at end: data: "k1"/20.000000000,0 -> vheader{ localTs=10.000000000,0 } /BYTES/v data: "k2"/20.000000000,0 -> /BYTES/v data: "k3"/20.000000000,0 -> /BYTES/v +stats: key_count=3 key_bytes=45 val_count=3 val_bytes=31 live_count=3 live_bytes=76 -run ok +run stats ok with ts=30 cput localTs=40 k=k1 v=v cond=v cput localTs=30 k=k2 v=v cond=v cput localTs=20 k=k3 v=v cond=v ---- +>> cput localTs=40 k=k1 v=v cond=v ts=30 +stats: key_bytes=+12 val_count=+1 val_bytes=+6 live_bytes=-13 gc_bytes_age=+2170 +>> cput localTs=30 k=k2 v=v cond=v ts=30 +stats: key_bytes=+12 val_count=+1 val_bytes=+6 gc_bytes_age=+1260 +>> cput localTs=20 k=k3 v=v cond=v ts=30 +stats: key_bytes=+12 val_count=+1 val_bytes=+19 live_bytes=+13 gc_bytes_age=+1260 >> at end: data: "k1"/30.000000000,0 -> /BYTES/v data: "k1"/20.000000000,0 -> vheader{ localTs=10.000000000,0 } /BYTES/v @@ -24,13 +37,20 @@ data: "k2"/30.000000000,0 -> /BYTES/v data: "k2"/20.000000000,0 -> /BYTES/v data: "k3"/30.000000000,0 -> vheader{ localTs=20.000000000,0 } /BYTES/v data: "k3"/20.000000000,0 -> /BYTES/v +stats: key_count=3 key_bytes=81 val_count=6 val_bytes=62 live_count=3 live_bytes=76 gc_bytes_age=4690 -run ok +run stats ok with ts=40 del localTs=30 k=k1 del localTs=40 k=k2 del localTs=50 k=k3 ---- +>> del localTs=30 k=k1 ts=40 +stats: key_bytes=+12 val_count=+1 val_bytes=+13 live_count=-1 live_bytes=-21 gc_bytes_age=+2760 +>> del localTs=40 k=k2 ts=40 +stats: key_bytes=+12 val_count=+1 live_count=-1 live_bytes=-21 gc_bytes_age=+1980 +>> del localTs=50 k=k3 ts=40 +stats: key_bytes=+12 val_count=+1 live_count=-1 live_bytes=-34 gc_bytes_age=+2760 >> at end: data: "k1"/40.000000000,0 -> vheader{ localTs=30.000000000,0 } / data: "k1"/30.000000000,0 -> /BYTES/v @@ -41,16 +61,23 @@ data: "k2"/20.000000000,0 -> /BYTES/v data: "k3"/40.000000000,0 -> / data: "k3"/30.000000000,0 -> vheader{ localTs=20.000000000,0 } /BYTES/v data: "k3"/20.000000000,0 -> /BYTES/v +stats: key_count=3 key_bytes=117 val_count=9 val_bytes=75 gc_bytes_age=12190 -run ok +run stats ok with ts=50 increment localTs=60 k=k1 increment localTs=50 k=k2 increment localTs=40 k=k3 ---- +>> increment localTs=60 k=k1 ts=50 inc: current value = 1 +stats: key_bytes=+12 val_count=+1 val_bytes=+6 live_count=+1 live_bytes=+21 gc_bytes_age=-180 +>> increment localTs=50 k=k2 ts=50 inc: current value = 1 +stats: key_bytes=+12 val_count=+1 val_bytes=+6 live_count=+1 live_bytes=+21 gc_bytes_age=-180 +>> increment localTs=40 k=k3 ts=50 inc: current value = 1 +stats: key_bytes=+12 val_count=+1 val_bytes=+20 live_count=+1 live_bytes=+35 gc_bytes_age=-180 >> at end: data: "k1"/50.000000000,0 -> /INT/1 data: "k1"/40.000000000,0 -> vheader{ localTs=30.000000000,0 } / @@ -64,16 +91,23 @@ data: "k3"/50.000000000,0 -> vheader{ localTs=40.000000000,0 } /INT/1 data: "k3"/40.000000000,0 -> / data: "k3"/30.000000000,0 -> vheader{ localTs=20.000000000,0 } /BYTES/v data: "k3"/20.000000000,0 -> /BYTES/v +stats: key_count=3 key_bytes=153 val_count=12 val_bytes=107 live_count=3 live_bytes=77 gc_bytes_age=11650 -run ok +run stats ok with ts=60 del_range localTs=50 k=k1 end=k2 del_range localTs=60 k=k2 end=k3 del_range localTs=70 k=k3 end=k4 ---- +>> del_range localTs=50 k=k1 end=k2 ts=60 del_range: "k1"-"k2" -> deleted 1 key(s) +stats: key_bytes=+12 val_count=+1 val_bytes=+14 live_count=-1 live_bytes=-21 gc_bytes_age=+1880 +>> del_range localTs=60 k=k2 end=k3 ts=60 del_range: "k2"-"k3" -> deleted 1 key(s) +stats: key_bytes=+12 val_count=+1 live_count=-1 live_bytes=-21 gc_bytes_age=+1320 +>> del_range localTs=70 k=k3 end=k4 ts=60 del_range: "k3"-"k4" -> deleted 1 key(s) +stats: key_bytes=+12 val_count=+1 live_count=-1 live_bytes=-35 gc_bytes_age=+1880 >> at end: data: "k1"/60.000000000,0 -> vheader{ localTs=50.000000000,0 } / data: "k1"/50.000000000,0 -> /INT/1 @@ -90,6 +124,7 @@ data: "k3"/50.000000000,0 -> vheader{ localTs=40.000000000,0 } /INT/1 data: "k3"/40.000000000,0 -> / data: "k3"/30.000000000,0 -> vheader{ localTs=20.000000000,0 } /BYTES/v data: "k3"/20.000000000,0 -> /BYTES/v +stats: key_count=3 key_bytes=189 val_count=15 val_bytes=121 gc_bytes_age=16730 run ok with ts=19 @@ -200,7 +235,7 @@ clear_range k=k1 end=k4 # Exercise intent resolution with and without prior observation timestamps. -run ok +run stats ok with t=A ts=20 localTs=10 txn_begin put k=k1 v=v @@ -216,6 +251,30 @@ with t=A ts=20 localTs=10 put k=k11 v=v put k=k12 v=v ---- +>> put k=k1 v=v t=A ts=20 localTs=10 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+67 live_count=+1 live_bytes=+82 intent_count=+1 intent_bytes=+31 separated_intent_count=+1 intent_age=+80 +>> put k=k2 v=v t=A ts=20 localTs=10 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+67 live_count=+1 live_bytes=+82 intent_count=+1 intent_bytes=+31 separated_intent_count=+1 intent_age=+80 +>> put k=k3 v=v t=A ts=20 localTs=10 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+67 live_count=+1 live_bytes=+82 intent_count=+1 intent_bytes=+31 separated_intent_count=+1 intent_age=+80 +>> put k=k4 v=v t=A ts=20 localTs=10 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+67 live_count=+1 live_bytes=+82 intent_count=+1 intent_bytes=+31 separated_intent_count=+1 intent_age=+80 +>> put k=k5 v=v t=A ts=20 localTs=10 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+67 live_count=+1 live_bytes=+82 intent_count=+1 intent_bytes=+31 separated_intent_count=+1 intent_age=+80 +>> put k=k6 v=v t=A ts=20 localTs=10 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+67 live_count=+1 live_bytes=+82 intent_count=+1 intent_bytes=+31 separated_intent_count=+1 intent_age=+80 +>> put k=k7 v=v t=A ts=20 localTs=10 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+67 live_count=+1 live_bytes=+82 intent_count=+1 intent_bytes=+31 separated_intent_count=+1 intent_age=+80 +>> put k=k8 v=v t=A ts=20 localTs=10 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+67 live_count=+1 live_bytes=+82 intent_count=+1 intent_bytes=+31 separated_intent_count=+1 intent_age=+80 +>> put k=k9 v=v t=A ts=20 localTs=10 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+67 live_count=+1 live_bytes=+82 intent_count=+1 intent_bytes=+31 separated_intent_count=+1 intent_age=+80 +>> put k=k10 v=v t=A ts=20 localTs=10 +stats: key_count=+1 key_bytes=+16 val_count=+1 val_bytes=+67 live_count=+1 live_bytes=+83 intent_count=+1 intent_bytes=+31 separated_intent_count=+1 intent_age=+80 +>> put k=k11 v=v t=A ts=20 localTs=10 +stats: key_count=+1 key_bytes=+16 val_count=+1 val_bytes=+67 live_count=+1 live_bytes=+83 intent_count=+1 intent_bytes=+31 separated_intent_count=+1 intent_age=+80 +>> put k=k12 v=v t=A ts=20 localTs=10 +stats: key_count=+1 key_bytes=+16 val_count=+1 val_bytes=+67 live_count=+1 live_bytes=+83 intent_count=+1 intent_bytes=+31 separated_intent_count=+1 intent_age=+80 >> at end: txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=20.000000000,0 min=0,0 seq=0} lock=true stat=PENDING rts=20.000000000,0 wto=false gul=0,0 meta: "k1"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=20.000000000,0 min=0,0 seq=0} ts=20.000000000,0 del=false klen=12 vlen=19 mergeTs= txnDidNotUpdateMeta=true @@ -242,6 +301,7 @@ meta: "k8"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=20.000000000 data: "k8"/20.000000000,0 -> vheader{ localTs=10.000000000,0 } /BYTES/v meta: "k9"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=20.000000000,0 min=0,0 seq=0} ts=20.000000000,0 del=false klen=12 vlen=19 mergeTs= txnDidNotUpdateMeta=true data: "k9"/20.000000000,0 -> vheader{ localTs=10.000000000,0 } /BYTES/v +stats: key_count=12 key_bytes=183 val_count=12 val_bytes=804 live_count=12 live_bytes=987 intent_count=12 intent_bytes=372 separated_intent_count=12 intent_age=960 run ok with t=A @@ -251,7 +311,7 @@ with t=A >> at end: txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=30.000000000,0 min=0,0 seq=1} lock=true stat=PENDING rts=20.000000000,0 wto=false gul=0,0 -run ok +run stats ok with t=A localTs=20 put k=k1 v=v2 put k=k2 v=v2 @@ -266,6 +326,30 @@ with t=A localTs=20 put k=k11 v=v2 put k=k12 v=v2 ---- +>> put k=k1 v=v2 t=A localTs=20 +stats: val_bytes=+26 live_bytes=+26 intent_bytes=+1 intent_age=-10 +>> put k=k2 v=v2 t=A localTs=20 +stats: val_bytes=+26 live_bytes=+26 intent_bytes=+1 intent_age=-10 +>> put k=k3 v=v2 t=A localTs=20 +stats: val_bytes=+26 live_bytes=+26 intent_bytes=+1 intent_age=-10 +>> put k=k4 v=v2 t=A localTs=20 +stats: val_bytes=+26 live_bytes=+26 intent_bytes=+1 intent_age=-10 +>> put k=k5 v=v2 t=A localTs=20 +stats: val_bytes=+26 live_bytes=+26 intent_bytes=+1 intent_age=-10 +>> put k=k6 v=v2 t=A localTs=20 +stats: val_bytes=+26 live_bytes=+26 intent_bytes=+1 intent_age=-10 +>> put k=k7 v=v2 t=A localTs=20 +stats: val_bytes=+26 live_bytes=+26 intent_bytes=+1 intent_age=-10 +>> put k=k8 v=v2 t=A localTs=20 +stats: val_bytes=+26 live_bytes=+26 intent_bytes=+1 intent_age=-10 +>> put k=k9 v=v2 t=A localTs=20 +stats: val_bytes=+26 live_bytes=+26 intent_bytes=+1 intent_age=-10 +>> put k=k10 v=v2 t=A localTs=20 +stats: val_bytes=+26 live_bytes=+26 intent_bytes=+1 intent_age=-10 +>> put k=k11 v=v2 t=A localTs=20 +stats: val_bytes=+26 live_bytes=+26 intent_bytes=+1 intent_age=-10 +>> put k=k12 v=v2 t=A localTs=20 +stats: val_bytes=+26 live_bytes=+26 intent_bytes=+1 intent_age=-10 >> at end: meta: "k1"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=30.000000000,0 min=0,0 seq=1} ts=30.000000000,0 del=false klen=12 vlen=20 ih={{0 vheader{ localTs=10.000000000,0 } /BYTES/v}} mergeTs= txnDidNotUpdateMeta=false data: "k1"/30.000000000,0 -> vheader{ localTs=20.000000000,0 } /BYTES/v2 @@ -291,8 +375,9 @@ meta: "k8"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=30.000000000 data: "k8"/30.000000000,0 -> vheader{ localTs=20.000000000,0 } /BYTES/v2 meta: "k9"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=30.000000000,0 min=0,0 seq=1} ts=30.000000000,0 del=false klen=12 vlen=20 ih={{0 vheader{ localTs=10.000000000,0 } /BYTES/v}} mergeTs= txnDidNotUpdateMeta=false data: "k9"/30.000000000,0 -> vheader{ localTs=20.000000000,0 } /BYTES/v2 +stats: key_count=12 key_bytes=183 val_count=12 val_bytes=1116 live_count=12 live_bytes=1299 intent_count=12 intent_bytes=384 separated_intent_count=12 intent_age=840 -run ok +run stats ok with t=A txn_advance ts=40 resolve_intent k=k1 status=ABORTED @@ -308,6 +393,30 @@ with t=A resolve_intent k=k11 status=COMMITTED clockWhilePending=30 resolve_intent k=k12 status=COMMITTED clockWhilePending=40 ---- +>> resolve_intent k=k1 status=ABORTED t=A +stats: key_count=-1 key_bytes=-15 val_count=-1 val_bytes=-93 live_count=-1 live_bytes=-108 intent_count=-1 intent_bytes=-32 separated_intent_count=-1 intent_age=-70 +>> resolve_intent k=k2 status=ABORTED clockWhilePending=20 t=A +stats: key_count=-1 key_bytes=-15 val_count=-1 val_bytes=-93 live_count=-1 live_bytes=-108 intent_count=-1 intent_bytes=-32 separated_intent_count=-1 intent_age=-70 +>> resolve_intent k=k3 status=ABORTED clockWhilePending=30 t=A +stats: key_count=-1 key_bytes=-15 val_count=-1 val_bytes=-93 live_count=-1 live_bytes=-108 intent_count=-1 intent_bytes=-32 separated_intent_count=-1 intent_age=-70 +>> resolve_intent k=k4 status=ABORTED clockWhilePending=40 t=A +stats: key_count=-1 key_bytes=-15 val_count=-1 val_bytes=-93 live_count=-1 live_bytes=-108 intent_count=-1 intent_bytes=-32 separated_intent_count=-1 intent_age=-70 +>> resolve_intent k=k5 status=PENDING t=A +stats: val_bytes=+2 live_bytes=+2 intent_age=-10 +>> resolve_intent k=k6 status=PENDING clockWhilePending=20 t=A +stats: val_bytes=+2 live_bytes=+2 intent_age=-10 +>> resolve_intent k=k7 status=PENDING clockWhilePending=30 t=A +stats: val_bytes=+2 live_bytes=+2 intent_age=-10 +>> resolve_intent k=k8 status=PENDING clockWhilePending=40 t=A +stats: val_bytes=-11 live_bytes=-11 intent_bytes=-13 intent_age=-10 +>> resolve_intent k=k9 status=COMMITTED t=A +stats: val_bytes=-73 live_bytes=-73 intent_count=-1 intent_bytes=-32 separated_intent_count=-1 intent_age=-70 +>> resolve_intent k=k10 status=COMMITTED clockWhilePending=20 t=A +stats: val_bytes=-73 live_bytes=-73 intent_count=-1 intent_bytes=-32 separated_intent_count=-1 intent_age=-70 +>> resolve_intent k=k11 status=COMMITTED clockWhilePending=30 t=A +stats: val_bytes=-73 live_bytes=-73 intent_count=-1 intent_bytes=-32 separated_intent_count=-1 intent_age=-70 +>> resolve_intent k=k12 status=COMMITTED clockWhilePending=40 t=A +stats: val_bytes=-86 live_bytes=-86 intent_count=-1 intent_bytes=-32 separated_intent_count=-1 intent_age=-70 >> at end: txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=40.000000000,0 min=0,0 seq=1} lock=true stat=PENDING rts=20.000000000,0 wto=false gul=0,0 data: "k10"/40.000000000,0 -> vheader{ localTs=20.000000000,0 } /BYTES/v2 @@ -322,3 +431,4 @@ data: "k7"/40.000000000,0 -> vheader{ localTs=30.000000000,0 } /BYTES/v2 meta: "k8"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=40.000000000,0 min=0,0 seq=1} ts=40.000000000,0 del=false klen=12 vlen=7 ih={{0 vheader{ localTs=10.000000000,0 } /BYTES/v}} mergeTs= txnDidNotUpdateMeta=false data: "k8"/40.000000000,0 -> /BYTES/v2 data: "k9"/40.000000000,0 -> vheader{ localTs=20.000000000,0 } /BYTES/v2 +stats: key_count=8 key_bytes=123 val_count=8 val_bytes=434 live_count=8 live_bytes=557 intent_count=4 intent_bytes=115 separated_intent_count=4 intent_age=240 diff --git a/pkg/storage/testdata/mvcc_histories/put_after_rollback b/pkg/storage/testdata/mvcc_histories/put_after_rollback index cb4d47edce45..89e8f2cf8d40 100644 --- a/pkg/storage/testdata/mvcc_histories/put_after_rollback +++ b/pkg/storage/testdata/mvcc_histories/put_after_rollback @@ -1,4 +1,4 @@ -run ok +run stats ok with t=A k=k2 txn_begin ts=1 txn_step seq=10 @@ -10,14 +10,19 @@ with t=A k=k2 txn_ignore_seqs seqs=(5-25) get ---- +>> put v=a t=A k=k2 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+60 live_count=+1 live_bytes=+75 intent_count=+1 intent_bytes=+18 separated_intent_count=+1 intent_age=+99 +>> put v=b t=A k=k2 +stats: val_bytes=-2 live_bytes=-2 get: "k2" -> /BYTES/b @1.000000000,0 get: "k2" -> >> at end: txn: "A" meta={id=00000000 key="k2" pri=0.00000000 epo=0 ts=1.000000000,0 min=0,0 seq=20} lock=true stat=PENDING rts=1.000000000,0 wto=false gul=0,0 isn=1 meta: "k2"/0,0 -> txn={id=00000000 key="k2" pri=0.00000000 epo=0 ts=1.000000000,0 min=0,0 seq=20} ts=1.000000000,0 del=false klen=12 vlen=6 mergeTs= txnDidNotUpdateMeta=false data: "k2"/1.000000000,0 -> /BYTES/b +stats: key_count=1 key_bytes=15 val_count=1 val_bytes=58 live_count=1 live_bytes=73 intent_count=1 intent_bytes=18 separated_intent_count=1 intent_age=99 -run ok +run stats ok with t=A k=k3 txn_step seq=30 put v=a @@ -25,14 +30,19 @@ with t=A k=k3 txn_step seq=40 del ---- +>> put v=a t=A k=k3 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+60 live_count=+1 live_bytes=+75 intent_count=+1 intent_bytes=+18 separated_intent_count=+1 intent_age=+99 +>> del t=A k=k3 +stats: val_bytes=-8 live_count=-1 live_bytes=-75 gc_bytes_age=+6633 intent_bytes=-6 >> at end: txn: "A" meta={id=00000000 key="k2" pri=0.00000000 epo=0 ts=1.000000000,0 min=0,0 seq=40} lock=true stat=PENDING rts=1.000000000,0 wto=false gul=0,0 isn=1 meta: "k2"/0,0 -> txn={id=00000000 key="k2" pri=0.00000000 epo=0 ts=1.000000000,0 min=0,0 seq=20} ts=1.000000000,0 del=false klen=12 vlen=6 mergeTs= txnDidNotUpdateMeta=false data: "k2"/1.000000000,0 -> /BYTES/b meta: "k3"/0,0 -> txn={id=00000000 key="k2" pri=0.00000000 epo=0 ts=1.000000000,0 min=0,0 seq=40} ts=1.000000000,0 del=true klen=12 vlen=0 mergeTs= txnDidNotUpdateMeta=false data: "k3"/1.000000000,0 -> / +stats: key_count=2 key_bytes=30 val_count=2 val_bytes=110 live_count=1 live_bytes=73 gc_bytes_age=6633 intent_count=2 intent_bytes=30 separated_intent_count=2 intent_age=198 -run ok +run stats ok with t=A k=k4 txn_step seq=50 put v=a @@ -42,6 +52,12 @@ with t=A k=k4 txn_step seq=60 cput v=c ---- +>> put v=a t=A k=k4 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+60 live_count=+1 live_bytes=+75 intent_count=+1 intent_bytes=+18 separated_intent_count=+1 intent_age=+99 +>> cput v=b cond=a t=A k=k4 +stats: val_bytes=+10 live_bytes=+10 +>> cput v=c t=A k=k4 +stats: val_bytes=-12 live_bytes=-12 >> at end: txn: "A" meta={id=00000000 key="k2" pri=0.00000000 epo=0 ts=1.000000000,0 min=0,0 seq=60} lock=true stat=PENDING rts=1.000000000,0 wto=false gul=0,0 isn=1 meta: "k2"/0,0 -> txn={id=00000000 key="k2" pri=0.00000000 epo=0 ts=1.000000000,0 min=0,0 seq=20} ts=1.000000000,0 del=false klen=12 vlen=6 mergeTs= txnDidNotUpdateMeta=false @@ -50,8 +66,9 @@ meta: "k3"/0,0 -> txn={id=00000000 key="k2" pri=0.00000000 epo=0 ts=1.000000000, data: "k3"/1.000000000,0 -> / meta: "k4"/0,0 -> txn={id=00000000 key="k2" pri=0.00000000 epo=0 ts=1.000000000,0 min=0,0 seq=60} ts=1.000000000,0 del=false klen=12 vlen=6 mergeTs= txnDidNotUpdateMeta=false data: "k4"/1.000000000,0 -> /BYTES/c +stats: key_count=3 key_bytes=45 val_count=3 val_bytes=168 live_count=2 live_bytes=146 gc_bytes_age=6633 intent_count=3 intent_bytes=48 separated_intent_count=3 intent_age=297 -run ok +run stats ok put k=k5 v=foo ts=3 with t=B k=k5 txn_begin ts=5 @@ -69,8 +86,20 @@ with t=B k=k5 check_intent resolve_intent status=COMMITTED ---- +>> put k=k5 v=foo ts=3 +stats: key_count=+1 key_bytes=+15 val_count=+1 val_bytes=+8 live_count=+1 live_bytes=+23 +>> put v=a t=B k=k5 +stats: key_bytes=+12 val_count=+1 val_bytes=+60 live_bytes=+52 gc_bytes_age=+1900 intent_count=+1 intent_bytes=+18 separated_intent_count=+1 intent_age=+95 +>> put v=b t=B k=k5 +stats: val_bytes=+10 live_bytes=+10 +>> put v=c t=B k=k5 +stats: no change meta: "k5" -> txn={id=00000000 key="k5" pri=0.00000000 epo=0 ts=5.000000000,0 min=0,0 seq=30} ts=5.000000000,0 del=false klen=12 vlen=6 ih={{10 /BYTES/a}} mergeTs= txnDidNotUpdateMeta=false +>> put v=d t=B k=k5 +stats: no change meta: "k5" -> txn={id=00000000 key="k5" pri=0.00000000 epo=0 ts=5.000000000,0 min=0,0 seq=40} ts=5.000000000,0 del=false klen=12 vlen=6 ih={{10 /BYTES/a}} mergeTs= txnDidNotUpdateMeta=false +>> resolve_intent status=COMMITTED t=B k=k5 +stats: val_bytes=-64 live_bytes=-64 intent_count=-1 intent_bytes=-18 separated_intent_count=-1 intent_age=-95 >> at end: txn: "B" meta={id=00000000 key="k5" pri=0.00000000 epo=0 ts=5.000000000,0 min=0,0 seq=40} lock=true stat=PENDING rts=5.000000000,0 wto=false gul=0,0 isn=1 meta: "k2"/0,0 -> txn={id=00000000 key="k2" pri=0.00000000 epo=0 ts=1.000000000,0 min=0,0 seq=20} ts=1.000000000,0 del=false klen=12 vlen=6 mergeTs= txnDidNotUpdateMeta=false @@ -81,3 +110,4 @@ meta: "k4"/0,0 -> txn={id=00000000 key="k2" pri=0.00000000 epo=0 ts=1.000000000, data: "k4"/1.000000000,0 -> /BYTES/c data: "k5"/5.000000000,0 -> /BYTES/d data: "k5"/3.000000000,0 -> /BYTES/foo +stats: key_count=4 key_bytes=72 val_count=5 val_bytes=182 live_count=3 live_bytes=167 gc_bytes_age=8533 intent_count=3 intent_bytes=48 separated_intent_count=3 intent_age=297 diff --git a/pkg/storage/testdata/mvcc_histories/put_out_of_order b/pkg/storage/testdata/mvcc_histories/put_out_of_order index 7c5b535f5620..4158fc78fa24 100644 --- a/pkg/storage/testdata/mvcc_histories/put_out_of_order +++ b/pkg/storage/testdata/mvcc_histories/put_out_of_order @@ -3,28 +3,34 @@ # resulting intent remains equal to the higher timestamp - it does not # regress. -run ok +run stats ok with t=A txn_begin ts=1 txn_advance ts=2,1 put ts=1 k=k v=v ---- +>> put ts=1 k=k v=v t=A +stats: key_count=+1 key_bytes=+14 val_count=+1 val_bytes=+56 live_count=+1 live_bytes=+70 intent_count=+1 intent_bytes=+18 separated_intent_count=+1 intent_age=+98 >> at end: txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,1 min=0,0 seq=0} lock=true stat=PENDING rts=1.000000000,0 wto=false gul=0,0 meta: "k"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,1 min=0,0 seq=0} ts=2.000000000,1 del=false klen=12 vlen=6 mergeTs= txnDidNotUpdateMeta=true data: "k"/2.000000000,1 -> /BYTES/v +stats: key_count=1 key_bytes=14 val_count=1 val_bytes=56 live_count=1 live_bytes=70 intent_count=1 intent_bytes=18 separated_intent_count=1 intent_age=98 # Put operation with earlier wall time. Will NOT be ignored. -run ok +run stats ok with t=A txn_step txn_advance ts=1 put ts=1 k=k v=v2 ---- +>> put ts=1 k=k v=v2 t=A +stats: val_bytes=+13 live_bytes=+13 intent_bytes=+1 >> at end: txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=1.000000000,0 min=0,0 seq=1} lock=true stat=PENDING rts=1.000000000,0 wto=false gul=0,0 meta: "k"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,1 min=0,0 seq=1} ts=2.000000000,1 del=false klen=12 vlen=7 ih={{0 /BYTES/v}} mergeTs= txnDidNotUpdateMeta=false data: "k"/2.000000000,1 -> /BYTES/v2 +stats: key_count=1 key_bytes=14 val_count=1 val_bytes=69 live_count=1 live_bytes=83 intent_count=1 intent_bytes=19 separated_intent_count=1 intent_age=98 # We're expecting v2 here. @@ -36,15 +42,18 @@ get: "k" -> /BYTES/v2 @2.000000000,1 # Another put operation with earlier logical time. Will NOT be ignored. -run ok +run stats ok with t=A txn_step put ts=1 k=k v=v2 ---- +>> put ts=1 k=k v=v2 t=A +stats: val_bytes=+13 live_bytes=+13 >> at end: txn: "A" meta={id=00000000 key=/Min pri=0.00000000 epo=0 ts=1.000000000,0 min=0,0 seq=2} lock=true stat=PENDING rts=1.000000000,0 wto=false gul=0,0 meta: "k"/0,0 -> txn={id=00000000 key=/Min pri=0.00000000 epo=0 ts=2.000000000,1 min=0,0 seq=2} ts=2.000000000,1 del=false klen=12 vlen=7 ih={{0 /BYTES/v}{1 /BYTES/v2}} mergeTs= txnDidNotUpdateMeta=false data: "k"/2.000000000,1 -> /BYTES/v2 +stats: key_count=1 key_bytes=14 val_count=1 val_bytes=82 live_count=1 live_bytes=96 intent_count=1 intent_bytes=19 separated_intent_count=1 intent_age=98 # We're expecting v2 here. diff --git a/pkg/storage/testdata/mvcc_histories/put_with_txn b/pkg/storage/testdata/mvcc_histories/put_with_txn index cbd42dd090f0..d6c250f9d131 100644 --- a/pkg/storage/testdata/mvcc_histories/put_with_txn +++ b/pkg/storage/testdata/mvcc_histories/put_with_txn @@ -1,4 +1,4 @@ -run ok +run stats ok with t=A k=k txn_begin ts=0,1 put v=v @@ -6,6 +6,8 @@ with t=A k=k get ts=0,2 get ts=1 ---- +>> put v=v t=A k=k +stats: key_count=+1 key_bytes=+14 val_count=+1 val_bytes=+49 live_count=+1 live_bytes=+63 intent_count=+1 intent_bytes=+18 separated_intent_count=+1 intent_age=+100 get: "k" -> /BYTES/v @0,1 get: "k" -> /BYTES/v @0,1 get: "k" -> /BYTES/v @0,1 @@ -13,3 +15,4 @@ get: "k" -> /BYTES/v @0,1 txn: "A" meta={id=00000000 key="k" pri=0.00000000 epo=0 ts=0,1 min=0,0 seq=0} lock=true stat=PENDING rts=0,1 wto=false gul=0,0 meta: "k"/0,0 -> txn={id=00000000 key="k" pri=0.00000000 epo=0 ts=0,1 min=0,0 seq=0} ts=0,1 del=false klen=12 vlen=6 mergeTs= txnDidNotUpdateMeta=true data: "k"/0,1 -> /BYTES/v +stats: key_count=1 key_bytes=14 val_count=1 val_bytes=49 live_count=1 live_bytes=63 intent_count=1 intent_bytes=18 separated_intent_count=1 intent_age=100 diff --git a/pkg/storage/testdata/mvcc_histories/put_without_txn b/pkg/storage/testdata/mvcc_histories/put_without_txn index 2986d4cab214..a0f6d8c081ea 100644 --- a/pkg/storage/testdata/mvcc_histories/put_without_txn +++ b/pkg/storage/testdata/mvcc_histories/put_without_txn @@ -1,12 +1,15 @@ -run ok +run stats ok with k=k put v=v ts=0,1 get ts=0,1 get ts=0,2 get ts=1 ---- +>> put v=v ts=0,1 k=k +stats: key_count=+1 key_bytes=+14 val_count=+1 val_bytes=+6 live_count=+1 live_bytes=+20 get: "k" -> /BYTES/v @0,1 get: "k" -> /BYTES/v @0,1 get: "k" -> /BYTES/v @0,1 >> at end: data: "k"/0,1 -> /BYTES/v +stats: key_count=1 key_bytes=14 val_count=1 val_bytes=6 live_count=1 live_bytes=20 diff --git a/pkg/storage/testdata/mvcc_histories/update_existing_key b/pkg/storage/testdata/mvcc_histories/update_existing_key index 762c596274e5..1f44ed3317b6 100644 --- a/pkg/storage/testdata/mvcc_histories/update_existing_key +++ b/pkg/storage/testdata/mvcc_histories/update_existing_key @@ -1,13 +1,18 @@ -run ok +run stats ok with k=k put ts=0,1 v=v get ts=1 put ts=2 v=v2 ---- +>> put ts=0,1 v=v k=k +stats: key_count=+1 key_bytes=+14 val_count=+1 val_bytes=+6 live_count=+1 live_bytes=+20 get: "k" -> /BYTES/v @0,1 +>> put ts=2 v=v2 k=k +stats: key_bytes=+12 val_count=+1 val_bytes=+7 live_bytes=+1 gc_bytes_age=+1764 >> at end: data: "k"/2.000000000,0 -> /BYTES/v2 data: "k"/0,1 -> /BYTES/v +stats: key_count=1 key_bytes=26 val_count=2 val_bytes=13 live_count=1 live_bytes=21 gc_bytes_age=1764 # Read the latest version. run ok