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.

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

github.com/cockroachdb/pebble/internal/metamorphic: TestMeta failed #3906

Closed
cockroach-teamcity opened this issue Aug 30, 2024 · 12 comments · Fixed by #3959
Closed

github.com/cockroachdb/pebble/internal/metamorphic: TestMeta failed #3906

cockroach-teamcity opened this issue Aug 30, 2024 · 12 comments · Fixed by #3959

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented Aug 30, 2024

github.com/cockroachdb/pebble/internal/metamorphic.TestMeta failed with artifacts on refs/heads/master @ 5294f89b6da3:

        // 09:46:55.553 INFO: [JOB 6937] compacting: sstable created 025863
        // 09:46:55.556 INFO: [JOB 6937] compacted(default) L4 [025025] (1017B) Score=10.22 + L5 [] (0B) Score=73.33 -> L5 [025862 025863] (1.9KB), in 0.0s (0.0s total), output rate 1.7MB/s
        // 09:46:56.714 INFO: [JOB 6939] compacting(default) L2 [025857] (964B) Score=22.58 + L3 [] (0B) Score=9.96; OverlappingRatio: Single 0.00, Multi 0.00
        // 09:46:56.714 INFO: [JOB 6939] compacting: sstable created 025864
        // 09:46:56.714 INFO: [JOB 6939] compacting: sstable created 025865
        // 09:46:56.714 INFO: [JOB 6939] compacting: sstable created 025866
        // 09:46:56.717 INFO: [JOB 6939] compacted(default) L2 [025857] (964B) Score=22.58 + L3 [] (0B) Score=9.96 -> L3 [025864 025865 025866] (2.4KB), in 0.0s (0.0s total), output rate 5.9MB/s
        // 09:46:57.903 INFO: [JOB 6941] compacting(default) L0 [010975 011433 011855 012166 012446 012733 013085 013443 013651 014001 014908 015330 015623 016424 016888 017621 017998 018321 018823 019133 019591 020436 022245 023177 023777 024304 024799 025194 025554] (23KB) Score=12.54 + L2 [] (0B) Score=8.55; OverlappingRatio: Single 0.00, Multi 0.00
        // 09:46:57.904 INFO: [JOB 6939] sstable deleted 025857
        // 09:46:57.907 INFO: [JOB 6941] compacting: sstable created 025867
        // 09:46:57.922 INFO: [JOB 6941] compacted(default) L0 [010975 011433 011855 012166 012446 012733 013085 013443 013651 014001 014908 015330 015623 016424 016888 017621 017998 018321 018823 019133 019591 020436 022245 023177 023777 024304 024799 025194 025554] (23KB) Score=12.54 + L2 [] (0B) Score=8.55 -> L2 [025867] (947B), in 0.0s (0.0s total), output rate 232KB/s
        // 09:46:59.100 INFO: [JOB 6943] compacting(move) L3 [025832] (2.1KB) Score=14.33 + L4 [] (0B) Score=9.85; OverlappingRatio: Single 0.00, Multi 0.00
        // 09:46:59.103 INFO: [JOB 6943] compacted(move) L3 [025832] (2.1KB) Score=14.33 + L4 [] (0B) Score=9.85 -> L4 [025832] (2.1KB), in 0.0s (0.0s total), output rate 293MB/s
        // 09:47:00.259 INFO: [JOB 6944] compacting(move) L4 [025832] (2.1KB) Score=10.33 + L5 [] (0B) Score=74.16; OverlappingRatio: Single 0.00, Multi 0.00
        // 09:47:00.259 INFO: [JOB 6941] sstable deleted 025554
        // 09:47:00.261 INFO: [JOB 6944] compacted(move) L4 [025832] (2.1KB) Score=10.33 + L5 [] (0B) Score=74.16 -> L5 [025832] (2.1KB), in 0.0s (0.0s total), output rate 338MB/s
        // 09:47:01.430 INFO: [JOB 6945] compacting(move) L2 [025867] (947B) Score=13.25 + L3 [] (0B) Score=12.57; OverlappingRatio: Single 0.00, Multi 0.00
        // 09:47:01.432 INFO: [JOB 6945] compacted(move) L2 [025867] (947B) Score=13.25 + L3 [] (0B) Score=12.57 -> L3 [025867] (947B), in 0.0s (0.0s total), output rate 217MB/s
        // 09:47:02.596 INFO: [JOB 6946] compacting(default) L0 [010989 011455 011874 012179 012459 012746 013098 013456 013664 014014 014433 014922 015344 015638 016438 016903 017636 018336 018839 019148 019608 020451 022260 023192 023793 024320 024815 025205 025367 025564 025565] (25KB) Score=12.48 + L2 [] (0B) Score=9.38; OverlappingRatio: Single 0.00, Multi 0.00
        // 09:47:02.598 INFO: [JOB 6946] compacting: sstable created 025868
        // 09:47:02.598 INFO: [JOB 6946] compacting: sstable created 025869
        // 09:47:02.613 INFO: [JOB 6946] compacted(default) L0 [010989 011455 011874 012179 012459 012746 013098 013456 013664 014014 014433 014922 015344 015638 016438 016903 017636 018336 018839 019148 019608 020451 022260 023192 023793 024320 024815 025205 025367 025564 025565] (25KB) Score=12.48 + L2 [] (0B) Score=9.38 -> L2 [025868 025869] (2.0KB), in 0.0s (0.0s total), output rate 721KB/s
        // 09:47:03.756 INFO: [JOB 6948] compacting(move) L2 [025868] (1.0KB) Score=15.13 + L3 [] (0B) Score=13.37; OverlappingRatio: Single 0.00, Multi 0.00
        // 09:47:03.758 INFO: [JOB 6948] compacted(move) L2 [025868] (1.0KB) Score=15.13 + L3 [] (0B) Score=13.37 -> L3 [025868] (1.0KB), in 0.0s (0.0s total), output rate 195MB/s
        // 09:47:04.916 INFO: [JOB 6949] compacting(move) L3 [025867] (947B) Score=14.24 + L4 [] (0B) Score=9.70; OverlappingRatio: Single 0.00, Multi 0.00
        // 09:47:04.917 INFO: [JOB 6946] sstable deleted 025564
        // 09:47:04.918 INFO: [JOB 6949] compacted(move) L3 [025867] (947B) Score=14.24 + L4 [] (0B) Score=9.70 -> L4 [025867] (947B), in 0.0s (0.0s total), output rate 218MB/s
        // 09:47:06.062 INFO: [JOB 6951] compacting(default) L3 [025868] (1.0KB) Score=14.66 + L4 [] (0B) Score=9.92; OverlappingRatio: Single 0.00, Multi 0.00
        // 09:47:06.063 INFO: [JOB 6946] sstable deleted 025565
        // 09:47:06.063 INFO: [JOB 6951] compacting: sstable created 025870
        // 09:47:06.063 INFO: [JOB 6951] compacting: sstable created 025871
        // 09:47:06.065 INFO: [JOB 6951] compacted(default) L3 [025868] (1.0KB) Score=14.66 + L4 [] (0B) Score=9.92 -> L4 [025870 025871] (1.9KB), in 0.0s (0.0s total), output rate 1.5MB/s
        // 09:47:07.212 INFO: [JOB 6953] compacting(default) L4 [025867] (947B) Score=10.38 + L5 [] (0B) Score=75.04; OverlappingRatio: Single 0.00, Multi 0.00
        // 09:47:07.213 INFO: [JOB 6953] compacting: sstable created 025872
        // 09:47:07.214 INFO: [JOB 6951] sstable deleted 025868
        // 09:47:07.216 INFO: [JOB 6953] compacted(default) L4 [025867] (947B) Score=10.38 + L5 [] (0B) Score=75.04 -> L5 [025872] (947B), in 0.0s (0.0s total), output rate 897KB/s
        // 09:47:08.373 INFO: [JOB 6954] compacting(default) L4 [025871] (1.0KB) Score=10.09 + L5 [025852] (971B) Score=75.46; OverlappingRatio: Single 0.92, Multi 0.00
        // 09:47:08.374 INFO: [JOB 6953] sstable deleted 025867
        // 09:47:08.374 INFO: [JOB 6954] compacting: sstable created 025873
        // 09:47:08.377 INFO: [JOB 6954] compacted(default) L4 [025871] (1.0KB) Score=10.09 + L5 [025852] (971B) Score=75.46 -> L5 [025873] (1.1KB), in 0.0s (0.0s total), output rate 945KB/s
        // 09:47:09.535 INFO: [JOB 6957] compacting(move) L2 [025869] (965B) Score=13.18 + L3 [] (0B) Score=12.27; OverlappingRatio: Single 0.00, Multi 0.00
        // 09:47:09.537 INFO: [JOB 6957] compacted(move) L2 [025869] (965B) Score=13.18 + L3 [] (0B) Score=12.27 -> L3 [025869] (965B), in 0.0s (0.0s total), output rate 159MB/s
        // 09:47:10.688 INFO: [JOB 6958] compacting(default) L0 [010979 011438 011865 012170 012450 012737 013089 013447 013655 014005 014912 015334 015627 016428 016892 017625 018002 018325 018828 019137 019596 020440 022249 023181 023781 024308 024803 025198 025557] (23KB) Score=12.42 + L2 [] (0B) Score=9.37; OverlappingRatio: Single 0.00, Multi 0.00
        // 09:47:10.689 INFO: [JOB 6954] sstable deleted 025852
        // 09:47:10.690 INFO: [JOB 6954] sstable deleted 025871
        // 09:47:10.692 INFO: [JOB 6958] compacting: sstable created 025874
        // 09:47:10.708 INFO: [JOB 6958] compacted(default) L0 [010979 011438 011865 012170 012450 012737 013089 013447 013655 014005 014912 015334 015627 016428 016892 017625 018002 018325 018828 019137 019596 020440 022249 023181 023781 024308 024803 025198 025557] (23KB) Score=12.42 + L2 [] (0B) Score=9.37 -> L2 [025874] (965B), in 0.0s (0.0s total), output rate 226KB/s
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240830-093017.097931573400/random-017 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-017 (1014.70s)
Help

To reproduce, try:

go test -tags 'invariants' -exec 'stress -p 1' -timeout 0 -test.v -run 'TestMeta$' ./internal/metamorphic -seed 1725010217097767096 -ops "uniform:5000-10000"

This test on roachdash | Improve this report!

Jira issue: PEBBLE-254

@cockroach-teamcity
Copy link
Member Author

github.com/cockroachdb/pebble/internal/metamorphic.TestMeta failed with artifacts on refs/heads/master @ 2801a3eab3d8:

        // 07:30:05.833 INFO: [JOB 319] flushing: sstable created 001533
        // 07:30:05.833 INFO: [JOB 319] flushing: sstable created 001534
        // 07:30:05.833 INFO: [JOB 319] flushing: sstable created 001535
        // 07:30:05.834 INFO: [JOB 319] flushing: sstable created 001536
        // 07:30:05.834 INFO: [JOB 319] flushing: sstable created 001537
        // 07:30:05.834 INFO: [JOB 319] flushing: sstable created 001538
        // 07:30:05.834 INFO: [JOB 319] flushing: sstable created 001539
        // 07:30:05.835 INFO: [JOB 319] flushing: sstable created 001540
        // 07:30:05.835 INFO: [JOB 319] flushing: sstable created 001541
        // 07:30:05.835 INFO: [JOB 319] flushing: sstable created 001542
        // 07:30:05.835 INFO: [JOB 319] flushing: sstable created 001543
        // 07:30:05.836 INFO: [JOB 319] flushing: sstable created 001544
        // 07:30:05.836 INFO: [JOB 319] flushing: sstable created 001545
        // 07:30:05.836 INFO: [JOB 319] flushing: sstable created 001546
        // 07:30:05.836 INFO: [JOB 319] flushing: sstable created 001547
        // 07:30:05.837 INFO: [JOB 319] flushing: sstable created 001548
        // 07:30:05.837 INFO: [JOB 319] flushing: sstable created 001549
        // 07:30:05.837 INFO: [JOB 319] flushing: sstable created 001550
        // 07:30:05.837 INFO: [JOB 319] flushing: sstable created 001551
        // 07:30:05.837 INFO: [JOB 319] flushing: sstable created 001552
        // 07:30:05.838 INFO: [JOB 319] flushing: sstable created 001553
        // 07:30:05.838 INFO: [JOB 319] flushing: sstable created 001554
        // 07:30:05.838 INFO: [JOB 319] flushing: sstable created 001555
        // 07:30:05.838 INFO: [JOB 319] flushing: sstable created 001556
        // 07:30:05.839 INFO: [JOB 319] flushing: sstable created 001557
        // 07:30:05.839 INFO: [JOB 319] flushing: sstable created 001558
        // 07:30:05.849 INFO: [JOB 319] flushed 1 memtable (158B) to L0 [001449 001450 001451 001452 001453 001454 001455 001456 001457 001458 001459 001460 001461 001462 001463 001464 001465 001466 001467 001468 001469 001470 001471 001472 001473 001474 001475 001476 001477 001478 001479 001480 001481 001482 001483 001484 001485 001486 001487 001488 001489 001490 001491 001492 001493 001494 001495 001496 001497 001498 001499 001500 001501 001502 001503 001504 001505 001506 001507 001508 001509 001510 001511 001512 001513 001514 001515 001516 001517 001518 001519 001520 001521 001522 001523 001524 001525 001526 001527 001528 001529 001530 001531 001532 001533 001534 001535 001536 001537 001538 001539 001540 001541 001542 001543 001544 001545 001546 001547 001548 001549 001550 001551 001552 001553 001554 001555 001556 001557 001558] (86KB), in 0.0s (0.1s total), output rate 1.9MB/s
        // 07:30:05.852 INFO: [JOB 319] WAL deleted 001311
        // 07:30:05.858 INFO: [JOB 317] ingested L0:001446 (720B), L0:001447 (720B)
        db1.IngestExternalFiles(external0, "ihsk" /* start */, "iptowihdrf" /* end */, "" /* syntheticSuffix */, "" /* syntheticPrefix */, external0, "tsybjoukgg" /* start */, "tsyzwq" /* end */, "" /* syntheticSuffix */, "ts" /* syntheticPrefix */) // <nil> #6025
        db1.Set("qnbftxcdxy@2", "bkwnffh") // <nil> #6028
        db1.Get("loqfkl@3") // [""] pebble: not found #6031
        db1.RangeKeySet("wyrydlrtxiq", "xusxwm", "@14", "kkytluzhwwotpzb") // <nil> #6032
        // 07:30:05.858 INFO: [JOB 324] flushing 1 memtable (143B) to L0
        // 07:30:05.858 INFO: [JOB 324] flushing: sstable created 001562
        // 07:30:05.858 INFO: [JOB 323] WAL created 001561
        // 07:30:05.859 INFO: [JOB 324] flushing: sstable created 001563
        // 07:30:05.859 INFO: [JOB 324] flushing: sstable created 001564
        // 07:30:05.859 INFO: [JOB 324] flushing: sstable created 001565
        // 07:30:05.859 INFO: [JOB 324] flushing: sstable created 001566
        // 07:30:05.859 INFO: [JOB 324] flushing: sstable created 001567
        // 07:30:05.860 INFO: [JOB 324] flushing: sstable created 001568
        // 07:30:05.860 INFO: [JOB 324] flushing: sstable created 001569
        // 07:30:05.874 INFO: [JOB 324] flushed 1 memtable (143B) to L0 [001562 001563 001564 001565 001566 001567 001568 001569] (6.3KB), in 0.0s (0.0s total), output rate 2.4MB/s
        // 07:30:05.884 INFO: [JOB 324] WAL deleted 001448
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240831-073002.3563514516876/random-027 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-027 (2.26s)
=== RUN   TestMeta/execution
    --- FAIL: TestMeta/execution (0.00s)
Help

To reproduce, try:

go test -tags 'invariants' -exec 'stress -p 1' -timeout 0 -test.v -run 'TestMeta$' ./internal/metamorphic -seed 1725089402356366123 -ops "uniform:5000-10000"

This test on roachdash | Improve this report!

@nicktrav nicktrav moved this from Incoming to Tests (failures, skipped, flakes) in [Deprecated] Storage Sep 3, 2024
@cockroach-teamcity
Copy link
Member Author

github.com/cockroachdb/pebble/internal/metamorphic.TestMeta failed with artifacts on refs/heads/master @ 376d455bf0f7:

        iter24.Next("fdofyzya@17") // [invalid] cannot use limit with prefix iteration #3083
        iter24.Prev("") // [false] cannot use limit with prefix iteration #3084
        iter24.SeekLT("mkarwdagzdhy", "") // [true,"lscvn",<no point>,["lscvn","mrljlhpcrwb")=>{"@9"="utmvkygz"}*] <nil> #3086
        db1.Set("nekehh@51", "evkmhbocijqqceyex") // <nil> #3087
        db1.Set("dncfxcci@46", "ddgaick") // <nil> #3088
        db1.Set("gfag@6", "mdffohcmobx") // <nil> #3089
        db1.SingleDelete("zfsszzb@4", false /* maybeReplaceDelete */) // <nil> #3090
        // 05:56:14.739 INFO: [JOB 435] ingested L0:000388 (810B)
        db1.IngestExternalFiles(external1, "ybedeaaz" /* start */, "ybedeaazf" /* end */, "@53" /* syntheticSuffix */, "yb" /* syntheticPrefix */) // <nil> #3091
        db1.Merge("nrysbzm", "hpmbtptfzpenxq") // <nil> #3092
        // 05:56:14.739 INFO: [JOB 436] ingested L0:000389 (810B), L0:000390 (810B)
        db1.IngestExternalFiles(external1, "ekledeaaz" /* start */, "ekledeaazbsn" /* end */, "" /* syntheticSuffix */, "ekl" /* syntheticPrefix */, external1, "ledeaaz" /* start */, "ledeaazbsn" /* end */, "@54" /* syntheticSuffix */, "l" /* syntheticPrefix */) // <nil> #3094
        // 05:56:14.740 INFO: [JOB 437] ingested L0:000391 (810B), L0:000392 (1.1KB)
        db1.IngestExternalFiles(external1, "edeaazbsn" /* start */, "edeaazw" /* end */, "@55" /* syntheticSuffix */, "" /* syntheticPrefix */, external0, "wnnsqzhwrb" /* start */, "wnnsxzgexc" /* end */, "" /* syntheticSuffix */, "wnn" /* syntheticPrefix */) // <nil> #3095
        db1.DeleteRange("owmzkrgn", "uixmxn") // <nil> #3096
        db1.Set("gmrjxgra@54", "lrrbwwhol") // <nil> #3101
        iter24.SeekLT("nojkud@28", "") // [true,"lscvn",<no point>,["lscvn","mrljlhpcrwb")=>{"@9"="utmvkygz"}] <nil> #3108
        iter27.SeekLT("yqkzhymjju@3", "pqnyubfgzq@12") // [valid,"srrbjeybeflka",<no point>,["srrbjeybeflka","srrbkfzgyithufja")=>{"@9"="utmvkygz"}*] <nil> #3061
        iter27.SeekGE("ndtpz@10", "") // [true,"ojeybeflka",<no point>,["ojeybeflka","omgikyvi")=>{"@9"="utmvkygz"}*] <nil> #3066
        iter27.First() // [true,"acmydksqbko",<no point>,["acmydksqbko","bbwqqee")=>{"@10"="zme"}*] <nil> #3093
        iter27.SetBounds("dgsqju@1", "mrljlhpcrwb@3") // <nil> #3097
        iter27.SeekGE("dgsqju@1", "") // [true,"dxkitkw",<no point>,["dxkitkw","dxmrljlhpcrwb")=>{"@9"="utmvkygz"}*] <nil> #3098
        iter27.Prev("") // [false] <nil> #3099
        iter27.Next("") // [true,"dxkitkw",<no point>,["dxkitkw","dxmrljlhpcrwb")=>{"@9"="utmvkygz"}*] <nil> #3100
        iter27.SetBounds("dgsqju@1", "dgsqju@1") // <nil> #3103
        iter27.Next("") // [false] <nil> #3105
        iter27.SeekLT("xwed@50", "") // [false] <nil> #3107
        iter27.Next("") // [false] <nil> #3114
        iter27.First() // [false] <nil> #3134
        iter27.SeekPrefixGE("qbtmcfos@3") // [false] pebble: SeekPrefixGE supplied with key outside of upper bound #3145
        iter27.SeekGE("qezmpmhwzmkq@1", "") // [false] <nil> #3151
        iter27.Prev("") // [false] <nil> #3160
        iter27.SeekPrefixGE("dkxdrylrr@2") // [false] pebble: SeekPrefixGE supplied with key outside of upper bound #3171
        iter27.Prev("") // [false] pebble: SeekPrefixGE supplied with key outside of upper bound #3177
        iter27.First() // [false] <nil> #3178
        iter27.Prev("") // [false] <nil> #3179
        iter27.Prev("") // [false] <nil> #3190
        iter27.Next("") // [false] <nil> #3191
        iter27.Next("") // [false] <nil> #3197
        iter27.SeekLT("frzmesycz@16", "") // [false] <nil> #3202
        iter27.SetBounds("bfakuzn@42", "bovs@4") // <nil> #3215
        iter27.SeekGE("bfakuzn@42", "") // [false] <nil> #3216
        iter27.Prev("") // [false] <nil> #3217
        iter27.Prev("") // [false] <nil> #3218
        iter27.Last() // [false] <nil> #3219
        iter27.Next("") // [false] <nil> #3225
        iter27.SetBounds("hfzqbpgsz@3", "o@9") // <nil> #3235
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240909-055610.9344188922145/random-026 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-026 (0.52s)
Help

To reproduce, try:

go test -tags 'invariants' -exec 'stress -p 1' -timeout 0 -test.v -run 'TestMeta$' ./internal/metamorphic -seed 1725861370934242848 -ops "uniform:5000-10000"

This test on roachdash | Improve this report!

@jbowens
Copy link
Collaborator

jbowens commented Sep 12, 2024

@RaduBerinde have you gotten a chance to triage this? I can start to take a look if not

@RaduBerinde
Copy link
Member

I haven't, sorry

@RaduBerinde
Copy link
Member

panic: split called on bare prefix
[05:56:30 ](https://teamcity.cockroachdb.com/buildConfiguration/Cockroach_Nightlies_Pebble_Metamorphic/16801660?buildTab=log&focusLine=4415&logView=flowAware&linesState=4415)  
[05:56:30 ](https://teamcity.cockroachdb.com/buildConfiguration/Cockroach_Nightlies_Pebble_Metamorphic/16801660?buildTab=log&focusLine=4416&logView=flowAware&linesState=4416)          goroutine 86 [running]:
[05:56:30 ](https://teamcity.cockroachdb.com/buildConfiguration/Cockroach_Nightlies_Pebble_Metamorphic/16801660?buildTab=log&focusLine=4417&logView=flowAware&linesState=4417)          github.com/cockroachdb/pebble/internal/testkeys.split(...)
[05:56:30 ](https://teamcity.cockroachdb.com/buildConfiguration/Cockroach_Nightlies_Pebble_Metamorphic/16801660?buildTab=log&focusLine=4418&logView=flowAware&linesState=4418)            github.com/cockroachdb/pebble/internal/testkeys/external/com_github_cockroachdb_pebble/internal/testkeys/testkeys.go:128
[05:56:30 ](https://teamcity.cockroachdb.com/buildConfiguration/Cockroach_Nightlies_Pebble_Metamorphic/16801660?buildTab=log&focusLine=4419&logView=flowAware&linesState=4419)          github.com/cockroachdb/pebble/internal/testkeys.compare({0xc0000f7249?, 0x7f89d0006b23?, 0x6?}, {0x7f89cc007a53?, 0x7f89d0006b31?, 0x8?})
[05:56:30 ](https://teamcity.cockroachdb.com/buildConfiguration/Cockroach_Nightlies_Pebble_Metamorphic/16801660?buildTab=log&focusLine=4420&logView=flowAware&linesState=4420)            github.com/cockroachdb/pebble/internal/testkeys/external/com_github_cockroachdb_pebble/internal/testkeys/testkeys.go:112 +0x27f
[05:56:30 ](https://teamcity.cockroachdb.com/buildConfiguration/Cockroach_Nightlies_Pebble_Metamorphic/16801660?buildTab=log&focusLine=4421&logView=flowAware&linesState=4421)          github.com/cockroachdb/pebble/sstable/rowblk.(*Iter).SeekLT(0xc00036f210, {0xc0000f7248, 0x3, 0x8}, 0x8?)

Looks like fallout from making the comparer more strict.

@RaduBerinde
Copy link
Member

The initial failure was different: panic: operation took longer than 1m0s: db1.RangeKeySet("eocgkdsm", "ozrghlab", "@126", "zglexcx")

@cockroach-teamcity
Copy link
Member Author

github.com/cockroachdb/pebble/internal/metamorphic.TestMeta failed with artifacts on refs/heads/master @ 0665a3e18dd5:

        iter52.SetBounds("", "fszdiobswka@7") // <nil> #6345
        iter52.SeekLT("fszdiobswka@7", "") // [true,"fjtuqfuubbp",<no point>,["fjtuqfuubbp","fszdiobswka@7")=>{"@15"="dsmrdsrbww","@8"="gvzrpkwpbkulfu","@6"="gxpychbr"}*] <nil> #6346
        iter52.Next("") // [false] <nil> #6347
        iter52.Prev("") // [true,"fjtuqfuubbp",<no point>,["fjtuqfuubbp","fszdiobswka@7")=>{"@15"="dsmrdsrbww","@8"="gvzrpkwpbkulfu","@6"="gxpychbr"}*] <nil> #6348
        iter52.Prev("") // [false] <nil> #6349
        // 07:32:11.085 INFO: [JOB 320] compacting: sstable created 001355
        iter52.Next("") // [true,"fjtuqfuubbp",<no point>,["fjtuqfuubbp","fszdiobswka@7")=>{"@15"="dsmrdsrbww","@8"="gvzrpkwpbkulfu","@6"="gxpychbr"}*] <nil> #6354
        iter52.Next("feoeo") // [invalid] <nil> #6355
        iter52.Next("") // [false] <nil> #6365
        iter52.SeekPrefixGE("aldz@17") // [false] <nil> #6368
        iter52.SeekPrefixGE("attjnap@17") // [false] <nil> #6384
        iter52.Last() // [true,"fjtuqfuubbp",<no point>,["fjtuqfuubbp","fszdiobswka@7")=>{"@15"="dsmrdsrbww","@8"="gvzrpkwpbkulfu","@6"="gxpychbr"}*] <nil> #6393
        iter52.Next("") // [false] <nil> #6398
        iter52.SeekGE("mlddlokrqy@2", "") // [false] <nil> #6401
        iter52.First() // [true,"fjtuqfuubbp",<no point>,["fjtuqfuubbp","fszdiobswka@7")=>{"@15"="dsmrdsrbww","@8"="gvzrpkwpbkulfu","@6"="gxpychbr"}*] <nil> #6413
        iter52.First() // [true,"fjtuqfuubbp",<no point>,["fjtuqfuubbp","fszdiobswka@7")=>{"@15"="dsmrdsrbww","@8"="gvzrpkwpbkulfu","@6"="gxpychbr"}] <nil> #6416
        // 07:32:11.090 INFO: [JOB 317] ingested L0:001269 (1019B), L0:001270 (1019B), L0:001268 (1019B)
        db1.IngestExternalFiles(external0, "xndijyx" /* start */, "xrwhbnninsp" /* end */, "" /* syntheticSuffix */, "x" /* syntheticPrefix */, external0, "mdhqppkogw" /* start */, "mdqnojacngg" /* end */, "" /* syntheticSuffix */, "md" /* syntheticPrefix */, external0, "tzqxihyvtyrz" /* start */, "tzqyymslrvbq" /* end */, "" /* syntheticSuffix */, "tzq" /* syntheticPrefix */) // <nil> #6079
        iter52.First() // [true,"fjtuqfuubbp",<no point>,["fjtuqfuubbp","fszdiobswka@7")=>{"@15"="dsmrdsrbww","@8"="gvzrpkwpbkulfu","@6"="gxpychbr"}] <nil> #6417
        iter52.Next("") // [false] <nil> #6421
        iter52.First() // [true,"fjtuqfuubbp",<no point>,["fjtuqfuubbp","fszdiobswka@7")=>{"@15"="dsmrdsrbww","@8"="gvzrpkwpbkulfu","@6"="gxpychbr"}*] <nil> #6423
        iter52.Next("") // [false] <nil> #6425
        iter52.Next("") // [false] <nil> #6429
        iter52.SeekPrefixGE("afwrtnur@14") // [false] <nil> #6439
        iter52.SeekPrefixGE("clykxxdrimegjj@5") // [false] <nil> #6441
        iter52.Last() // [true,"fjtuqfuubbp",<no point>,["fjtuqfuubbp","fszdiobswka@7")=>{"@15"="dsmrdsrbww","@8"="gvzrpkwpbkulfu","@6"="gxpychbr"}*] <nil> #6443
        iter52.Prev("") // [false] <nil> #6444
        iter52.SeekPrefixGE("attjnap@17") // [false] <nil> #6445
        iter52.SetBounds("gjymcby@1", "kwpgomm@11") // <nil> #6449
        // 07:32:11.100 INFO: [JOB 322] ingested L0:001356 (1019B)
        db1.IngestExternalFiles(external0, "vpwqsfnl" /* start */, "xxydlksrxlj" /* end */, "" /* syntheticSuffix */, "" /* syntheticPrefix */) // <nil> #6084
        db1.Delete("exvqznezxoyz@1") // <nil> #6094
        // 07:32:11.103 INFO: [JOB 320] MANIFEST created 001357
        // 07:32:11.103 INFO: [JOB 320] compacted(default) L0 [000924 000925 001065 001026 001039 001040 001042 001043 001044 001046 001047 001048 001049 001050 001051 001052 001053 001054 001055 001056 001057 001058 001059 001060 001061 001062 001063 001064 001066 001067 001068 001069 001070 001071 001093 001173 001174 001175 001145 001146 001147 001148 001149 001150 001151 001152 001153 001154 001155 001156 001157 001158 001159 001160 001161 001162 001163 001164 001165 001166 001167 001168 001169 001172 001171 001170 001094 001095 001214 001209 001210 001211 001212 001213 001208 001198 001215 001216 001217 001218 001219 001220 001221 001222 001223 001224 001225 001226 001227 001228 001229 001230 001231 001232 001233 001234 001235 001236 001237 001238 001239 001240 001241 001242 001243 001244 001245 001246 001247 001248 001249 001251 001252 001253 001201 001260 001336] (95KB) Score=8.95 + L5 [001261] (8.7KB) Score=0.25 -> L5 [001355] (9.1KB), in 0.0s (0.0s total), output rate 426KB/s
        db1.Delete("iabcrh@11") // <nil> #6095
        db1.Set("fuktr@18", "ldgojeucmliernymcbxg") // <nil> #6099
        db1.Get("ythzwmfyzw@10") // [""] pebble: not found #6100
        // 07:32:11.104 INFO: [JOB 320] sstable deleted 001336
        // 07:32:11.104 INFO: [JOB 320] MANIFEST deleted 001197
        db1.Get("qljymowakq@14") // ["rbuonaujlftsrf"] <nil> #6102
        // 07:32:11.106 INFO: [JOB 325] ingested L0:001358 (1019B), L0:001359 (1019B)
        db1.IngestExternalFiles(external0, "lwjjhowubfq" /* start */, "nkcpmihgo" /* end */, "" /* syntheticSuffix */, "" /* syntheticPrefix */, external0, "nkcpmihgo" /* start */, "noayvcefy" /* end */, "" /* syntheticSuffix */, "" /* syntheticPrefix */) // <nil> #6107
        db1.Delete("oiaxwm@18") // <nil> #6108
        db1.Get("arsybqytj@1") // [""] pebble: not found #6110
        db1.Delete("tsdvpddihp@4") // <nil> #6111
        db1.SingleDelete("vofuwlze@7", false /* maybeReplaceDelete */) // <nil> #6112
        db1.Merge("bhidbtdsbalg", "gpix") // <nil> #6113
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240913-073203.511499565158/random-010 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-010 (1.81s)
Help

To reproduce, try:

go test -tags 'invariants' -exec 'stress -p 1' -timeout 0 -test.v -run 'TestMeta$' ./internal/metamorphic -seed 1726212723511935732 -ops "uniform:5000-10000"

This test on roachdash | Improve this report!

@jbowens jbowens added the P-1 Issues/test failures with a fix SLA of 1 month label Sep 18, 2024
jbowens added a commit to jbowens/pebble that referenced this issue Sep 19, 2024
It's okay to call Split on a bare prefix but not a bare suffix.

Informs cockroachdb#3906.
jbowens added a commit that referenced this issue Sep 19, 2024
It's okay to call Split on a bare prefix but not a bare suffix.

Informs #3906.
@jbowens
Copy link
Collaborator

jbowens commented Sep 19, 2024

The comparer assertion failure looks like this is a consequence of the synthetic prefix. We strip the synthetic prefix from the search key, leaving just the suffix and then attempt to compare the block's KVs to the seek key that is now just a bare suffix.

I'm also noticing that this documented requirement:

Note that the table is assumed to contain "prefix-less" keys that become full keys when prepended with the synthetic prefix.

doesn't seem to be holding in the metamorphic tests, as we're applying the synthetic prefix to a table with prefixed-keys. Looking at this again, this doesn't seem like it could possibly ever hold? Ah I'm misreading "prefix-less". We don't mean a Comparer.Split.Prefix, but a looser user-key-encoding sense. In our case, this is expected to be the /Tenant/Table/Index prefix. Got it. (Put up #3951 to clarify)

@jbowens
Copy link
Collaborator

jbowens commented Sep 19, 2024

This is a bit tangential, but I don't think the columnar block format currently allows a sstable of prefix-less keys. The PrefixBytes encoding uses an empty slice to indicate a duplicate key, assuming that an empty slice is not valid.

Edit: nevermind, we can take advantage of the fact that prefixes are required to be lexicographically ordered, so if there's an empty slice it necessarily must be either the first key in the block or a duplicate of the first key in the block: #3950

@RaduBerinde
Copy link
Member

RaduBerinde commented Sep 19, 2024

I think "prefix-less" in that comment is not phrased properly. Keys should not have empty prefixes, even when we have a synthetic prerix to prepend. We prpbably need to fix the meta test.

@cockroach-teamcity
Copy link
Member Author

github.com/cockroachdb/pebble/internal/metamorphic.TestMeta failed with artifacts on refs/heads/master @ aba5868b355a:

        // 07:42:54.410 INFO: [JOB 1705] ingested L0:004861 (808B), L0:004862 (957B)
        db1.IngestExternalFiles(external0, "pvnaekwzwcm" /* start */, "pvnrdfuzvri" /* end */, "" /* syntheticSuffix */, "pv" /* syntheticPrefix */, external1, "ttyb" /* start */, "unonocawjvl" /* end */, "@44" /* syntheticSuffix */, "" /* syntheticPrefix */) // <nil> #5067
        iter45.SeekGE("hmlalm@5", "") // [false] <nil> #5068
        db1.Set("ahluvey@40", "") // <nil> #5070
        iter45.Last() // [true,"bequxm",<no point>,["bequxm","bquczrcjnun")=>{"@8"="ycqvpjyq"}*] <nil> #5072
        // 07:42:54.411 INFO: [JOB 1706] ingested L0:004863 (957B)
        db1.IngestExternalFiles(external1, "mtndc" /* start */, "rwkknypia" /* end */, "" /* syntheticSuffix */, "" /* syntheticPrefix */) // <nil> #5076
        db1.Merge("dieuwnecllaz@20", "hawlfewjpjcvnu") // <nil> #5077
        db1.Merge("jbweh@39", "gglxmqmbnshmsdc") // <nil> #5078
        db1.Merge("dztfqxwhk@7", "") // <nil> #5080
        iter48 = snap35.NewIter("kldxrorz@9", "kldxrorz@9", 2 /* key types */, 0, 0, false /* use L6 filters */, "@33" /* masking suffix */) // <nil> #5082
        iter48.SeekPrefixGE("gqjayphhay@21") // [false] pebble: SeekPrefixGE supplied with key outside of lower bound #5084
        iter48.SeekPrefixGE("fuaalf@10") // [false] pebble: SeekPrefixGE supplied with key outside of lower bound #5085
        iter48.SeekPrefixGE("wyqmmdkbsirg@34") // [false] pebble: SeekPrefixGE supplied with key outside of upper bound #5088
        iter48.SeekPrefixGE("iypiajb@2") // [false] pebble: SeekPrefixGE supplied with key outside of lower bound #5096
        iter48.SeekPrefixGE("zdcrjem@34") // [false] pebble: SeekPrefixGE supplied with key outside of upper bound #5098
        iter48.Next("") // [false] pebble: SeekPrefixGE supplied with key outside of upper bound #5108
        iter48.SeekPrefixGE("gcdz@4") // [false] pebble: SeekPrefixGE supplied with key outside of lower bound #5109
        iter48.Last() // [false] <nil> #5115
        iter48.Prev("") // [false] <nil> #5136
        iter48.Last() // [false] <nil> #5162
        iter48.Last() // [false] <nil> #5180
        iter48.Next("iypiajb@2") // [invalid] <nil> #5190
        iter48.SeekPrefixGE("isobwhjfq@1") // [false] pebble: SeekPrefixGE supplied with key outside of lower bound #5197
        snap33.Close() // <nil> #5083
        snap35.Get("lfyxllv@23") // [""] pebble: not found #5086
        iter47.SeekGE("xnzid@1", "") // [false] <nil> #5097
        db1.Merge("tozgeyfqtogs@38", "fhmtwh") // <nil> #5089
        db1.Set("cewxsos@33", "kdufkimugcwoaau") // <nil> #5095
        // 07:42:54.412 INFO: [JOB 1709] flushing 1 memtable (662B) to L0
        // 07:42:54.412 INFO: [JOB 1709] flushing: sstable created 004866
        // 07:42:54.412 INFO: [JOB 1709] flushing: sstable created 004867
        // 07:42:54.412 INFO: [JOB 1709] flushing: sstable created 004868
        // 07:42:54.412 INFO: [JOB 1709] flushing: sstable created 004869
        // 07:42:54.412 INFO: [JOB 1709] flushing: sstable created 004870
        // 07:42:54.412 INFO: [JOB 1709] flushing: sstable created 004871
        // 07:42:54.412 INFO: [JOB 1709] flushing: sstable created 004872
        // 07:42:54.412 INFO: [JOB 1709] flushing: sstable created 004873
        // 07:42:54.412 INFO: [JOB 1709] flushing: sstable created 004874
        // 07:42:54.412 INFO: [JOB 1709] flushing: sstable created 004875
        // 07:42:54.412 INFO: [JOB 1709] flushing: sstable created 004876
        // 07:42:54.412 INFO: [JOB 1709] flushing: sstable created 004877
        // 07:42:54.412 INFO: [JOB 1709] flushing: sstable created 004878
        // 07:42:54.413 INFO: [JOB 1709] flushing: sstable created 004879
        // 07:42:54.413 INFO: [JOB 1709] flushing: sstable created 004880
        // 07:42:54.413 INFO: [JOB 1709] flushing: sstable created 004881
        // 07:42:54.413 INFO: [JOB 1709] flushing: sstable created 004882
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240920-074244.2493527988966/random-002 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-002 (2.82s)
Help

To reproduce, try:

go test -tags 'invariants' -exec 'stress -p 1' -timeout 0 -test.v -run 'TestMeta$' ./internal/metamorphic -seed 1726818164249947891 -ops "uniform:5000-10000"

This test on roachdash | Improve this report!

@jbowens
Copy link
Collaborator

jbowens commented Sep 24, 2024

The comparer assertion failure looks like this is a consequence of the synthetic prefix. We strip the synthetic prefix from the search key, leaving just the suffix and then attempt to compare the block's KVs to the seek key that is now just a bare suffix.

@RaduBerinde If the user provides a seek key that's the beginning of an index's keyspace, we can end up calling Compare with just a suffix. I'm not sure we can restrict Compare to never being called with a bare suffix.

RaduBerinde added a commit to RaduBerinde/pebble that referenced this issue Sep 24, 2024
When synthetic prefix is used, we can trim the synthetic prefix from a
given seek key and compare it with the "bare" key in a table. After
trimming the key prefix can become "empty" (with just the terminator
left). This change extends the comparer test suite to check that we
can remove leading bytes from prefixes and adjusts the testkeys and
crdb comparers.

Fixes cockroachdb#3906
@github-project-automation github-project-automation bot moved this from Tests (failures, skipped, flakes) to Done in [Deprecated] Storage Sep 25, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
No open projects
Archived in project
Development

Successfully merging a pull request may close this issue.

3 participants