Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
cockroach-teamcity opened this issue May 14, 2024 · 15 comments
Closed

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

cockroach-teamcity opened this issue May 14, 2024 · 15 comments
Assignees
@RaduBerinde
Labels
A-storage C-test-failure O-metamorphic O-robot release-blocker T-storage

Comments

@cockroach-teamcity
Copy link
Member

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

        // 06:32:29.112 INFO: [JOB 180] compacting(download,rewrite) L0 [010464] (751B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:32:29.113 INFO: [JOB 180] compacting: sstable created 011889
        // 06:32:29.127 INFO: [JOB 179] compacted(move) multilevelL1 [011887] (899B) Score=5.87 + L2 [] (0B) Score=4.04 + L3 [] (0B) Score=8.50 -> L3 [011887] (899B), in 0.0s (0.0s total), output rate 75MB/s
        // 06:32:33.250 INFO: [JOB 181] compacting(default) L0 [007188 007360 007548 007740 007969 007970 008286 008287 008379 008380 008616 008617 008838 008839 008998 008999 009141 009142 009417 009418 009539 009540 009828 009829 010171 010172 010358 010359 010512 010513 010741 010742 011062 011063 011279 011280 011680] (29KB) Score=7.76 + L1 [] (0B) Score=2.83; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:32:33.283 INFO: [JOB 181] compacting: sstable created 011890
        // 06:32:33.327 INFO: [JOB 180] compacted(download,rewrite) L0 [010464] (751B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [011889] (754B), in 4.1s (4.2s total), output rate 182B/s
        // 06:32:37.428 INFO: [JOB 182] compacting(download,rewrite) L0 [011360] (751B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:32:37.505 INFO: [JOB 181] compacted(default) L0 [007188 007360 007548 007740 007969 007970 008286 008287 008379 008380 008616 008617 008838 008839 008998 008999 009141 009142 009417 009418 009539 009540 009828 009829 010171 010172 010358 010359 010512 010513 010741 010742 011062 011063 011279 011280 011680] (29KB) Score=7.76 + L1 [] (0B) Score=2.83 -> L1 [011890] (1.4KB), in 0.0s (4.3s total), output rate 39KB/s
        // 06:32:41.907 INFO: [JOB 181] sstable deleted 011279
        // 06:32:41.907 INFO: [JOB 181] sstable deleted 011280
        // 06:32:41.907 INFO: [JOB 181] sstable deleted 011680
        // 06:32:41.982 INFO: [JOB 182] compacted(download,rewrite) L0 [011360] (751B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [] (0B), in 0.0s (4.6s total), output rate 0B/s
        // 06:32:46.098 INFO: [JOB 184] compacting(move) L1 [011890] (1.4KB) Score=7.82 + L2 [] (0B) Score=3.73; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:32:46.099 INFO: [JOB 185] compacting(download,rewrite) L0 [008474] (751B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:32:46.112 INFO: [JOB 184] compacted(move) L1 [011890] (1.4KB) Score=7.82 + L2 [] (0B) Score=3.73 -> L2 [011890] (1.4KB), in 0.0s (0.0s total), output rate 84MB/s
        // 06:32:50.332 INFO: [JOB 186] compacting(default) L0 [007189 007361 007550 007741 007971 008288 008381 008618 008840 009000 009143 009419 009541 009830 010173 010360 010514 010743 011064 011281 011681] (16KB) Score=7.67 + L1 [] (0B) Score=2.01; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:32:50.356 INFO: [JOB 186] compacting: sstable created 011891
        // 06:32:50.408 INFO: [JOB 185] compacted(download,rewrite) L0 [008474] (751B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [] (0B), in 4.2s (4.3s total), output rate 0B/s
        // 06:32:54.563 INFO: [JOB 187] compacting(download,rewrite) L0 [010030] (751B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:32:54.637 INFO: [JOB 186] compacted(default) L0 [007189 007361 007550 007741 007971 008288 008381 008618 008840 009000 009143 009419 009541 009830 010173 010360 010514 010743 011064 011281 011681] (16KB) Score=7.67 + L1 [] (0B) Score=2.01 -> L1 [011891] (1.2KB), in 0.0s (4.3s total), output rate 40KB/s
        // 06:32:58.706 INFO: [JOB 186] sstable deleted 011281
        // 06:32:58.706 INFO: [JOB 186] sstable deleted 011681
        // 06:32:58.781 INFO: [JOB 187] compacted(download,rewrite) L0 [010030] (751B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [] (0B), in 0.0s (4.2s total), output rate 0B/s
        // 06:33:02.792 INFO: [JOB 189] compacting(copy) multilevelL3 [011887] (899B) Score=8.92 + L4 [] (0B) Score=5.68 + L5 [] (0B) Score=0.34; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:33:02.792 INFO: [JOB 190] compacting(download,rewrite) L0 [010465] (751B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:33:02.795 INFO: [JOB 190] compacting: sstable created 011893
        // 06:33:02.811 INFO: [JOB 189] compacted(copy) multilevelL3 [011887] (899B) Score=8.92 + L4 [] (0B) Score=5.68 + L5 [] (0B) Score=0.34 -> L5 [011892] (899B), in 0.0s (0.0s total), output rate 248KB/s
        // 06:33:07.085 INFO: [JOB 192] compacting(copy) multilevelL3 [011855] (836B) Score=8.47 + L4 [] (0B) Score=5.59 + L5 [] (0B) Score=0.34; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:33:07.154 INFO: [JOB 190] compacted(download,rewrite) L0 [010465] (751B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [011893] (756B), in 4.3s (4.4s total), output rate 176B/s
        // 06:33:11.299 INFO: [JOB 193] compacting(download,rewrite) L0 [011017] (751B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:33:11.300 INFO: [JOB 190] sstable deleted 011887
        // 06:33:11.313 INFO: [JOB 192] compacted(copy) multilevelL3 [011855] (836B) Score=8.47 + L4 [] (0B) Score=5.59 + L5 [] (0B) Score=0.34 -> L5 [011894] (836B), in 0.0s (4.2s total), output rate 1.7MB/s
        // 06:33:15.426 INFO: [JOB 194] compacting(default) L2 [011568] (2.2KB) Score=6.03 + L3 [] (0B) Score=8.05; OverlappingRatio: Single 0.00, Multi 0.46
        // 06:33:15.430 INFO: [JOB 194] compacting: sstable created 011895
        // 06:33:15.500 INFO: [JOB 193] compacted(download,rewrite) L0 [011017] (751B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [] (0B), in 4.1s (4.2s total), output rate 0B/s
        // 06:33:19.625 INFO: [JOB 193] sstable deleted 011855
        // 06:33:19.639 INFO: [JOB 194] compacted(default) L2 [011568] (2.2KB) Score=6.03 + L3 [] (0B) Score=8.05 -> L3 [011895] (2.2KB), in 0.0s (4.2s total), output rate 254KB/s
        // 06:33:23.768 INFO: [JOB 197] compacting(move) L1 [011891] (1.2KB) Score=8.81 + L2 [] (0B) Score=2.79; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:33:23.768 INFO: [JOB 198] compacting(download,rewrite) L0 [011162] (751B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:33:23.770 INFO: [JOB 194] sstable deleted 011568
        // 06:33:23.770 INFO: [JOB 198] compacting: sstable created 011896
        // 06:33:23.783 INFO: [JOB 197] compacted(move) L1 [011891] (1.2KB) Score=8.81 + L2 [] (0B) Score=2.79 -> L2 [011891] (1.2KB), in 0.0s (0.0s total), output rate 81MB/s
        // 06:33:27.879 INFO: [JOB 199] compacting(default) L0 [007190 007362 007551 007742 007972 008289 008382 008619 008841 009001 009144 009420 009542 009831 010174 010361 010515 010744 011065 011282 011682] (17KB) Score=7.61 + L1 [] (0B) Score=2.52; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:33:27.896 INFO: [JOB 199] compacting: sstable created 011897
        // 06:33:27.953 INFO: [JOB 198] compacted(download,rewrite) L0 [011162] (751B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [011896] (753B), in 4.1s (4.2s total), output rate 183B/s
        // 06:33:32.078 INFO: [JOB 200] compacting(download,rewrite) L0 [010209] (751B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:33:32.151 INFO: [JOB 199] compacted(default) L0 [007190 007362 007551 007742 007972 008289 008382 008619 008841 009001 009144 009420 009542 009831 010174 010361 010515 010744 011065 011282 011682] (17KB) Score=7.61 + L1 [] (0B) Score=2.52 -> L1 [011897] (1.2KB), in 0.0s (4.3s total), output rate 58KB/s
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240514-061253.718509443150/random-013 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-013 (1152.21s)
Help

To reproduce, try: 

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

This test on roachdash | Improve this report!
@cockroach-teamcity
Copy link
Member Author

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

        iter3.SetBounds("kfthaabrpip@6", "kfthaabrpip@6") // <nil> #224
        iter3.SeekPrefixGE("ylkktvexhutu@4") // [false] pebble: SeekPrefixGE supplied with key outside of upper bound #229
        iter3.First() // [false] <nil> #236
        iter3.Next("wvhmgrwkgi") // [invalid] <nil> #248
        iter3.SeekLT("tpvqc@4", "") // [false] <nil> #260
        iter3.SetBounds("kfthaabrpip@2", "kfthaabrpip@2") // <nil> #268
        iter3.SeekLT("kfthaabrpip@2", "") // [false] <nil> #269
        iter3.Prev("") // [false] <nil> #270
        iter3.SetBounds("npjassd", "ssvrj") // <nil> #277
        iter3.SeekLT("ssvrj", "") // [false] <nil> #278
        iter3.Next("") // [false] <nil> #279
        iter3.Prev("") // [false] <nil> #280
        iter3.SeekGE("kijasmnffmyk@7", "") // [false] <nil> #282
        iter3.SeekPrefixGE("kfthaabrpip@6") // [false] pebble: SeekPrefixGE supplied with key outside of lower bound #283
        iter3.First() // [false] <nil> #285
        iter3.SetBounds("tpvqc@4", "tpvqc@4") // <nil> #296
        iter3.SeekGE("tpvqc@4", "") // [false] <nil> #297
        iter3.Prev("") // [false] <nil> #298
        iter3.SeekLT("kijasmnffmyk", "") // [false] <nil> #301
        iter3.Prev("") // [false] <nil> #311
        iter3.SeekPrefixGE("suhs@3") // [false] pebble: SeekPrefixGE supplied with key outside of lower bound #314
        iter3.SeekGE("ysaa", "") // [false] <nil> #321
        iter3.First() // [false] <nil> #326
        iter3.SeekLT("qzgtsutwszey", "kfthaabrpip@1") // [invalid] <nil> #328
        iter3.Prev("") // [false] <nil> #347
        iter3.SeekLT("kijasmnffmyk", "") // [false] <nil> #358
        iter3.First() // [false] <nil> #363
        iter3.Next("") // [false] <nil> #369
        iter3.SeekGE("suhs@3", "") // [false] <nil> #370
        db1.Set("kfthaabrpip@6", "gtbthmstrxphba") // <nil> #220
        snap0.Get("kfthaabrpip@1") // ["urczo"] <nil> #223
        iter0.Last() // [false] <nil> #227
        iter2.Next("") // [false] <nil> #228
        iter2.SeekPrefixGE("tpvqc@4") // [false] <nil> #231
        iter0.Prev("kijasmnffmyk") // [invalid] <nil> #232
        iter2.SetBounds("ylkktvexhutu", "ylkktvexhutu") // <nil> #235
        iter0.SeekLT("kijasmnffmyk@5", "") // [false] <nil> #237
        iter0.Last() // [false] <nil> #239
        db1.Set("kijasmnffmyk@7", "h") // <nil> #225
        db1.Set("suhs", "pgfthlymidjdamwv") // <nil> #230
        db1.RangeKeyDelete("ssvrj", "tpvqc") // <nil> #233
        db1.Set("npjassd@7", "rlmlfjzgtvtryqdkic") // <nil> #238
        snap0.Get("kfthaabrpip@1") // ["urczo"] <nil> #240
        iter0.SetOptions("npjassd", "suhs", 2 /* key types */, 0, 0, true /* use L6 filters */, "" /* masking suffix */) // <nil> #242
        iter0.SeekGE("npjassd", "") // [false] <nil> #243
        iter0.Next("") // [false] <nil> #246
        iter2.SeekPrefixGE("suhs") // [false] pebble: SeekPrefixGE supplied with key outside of lower bound #249
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240514-084542.5391129228913/random-010 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-010 (0.12s)
Help

To reproduce, try: 

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

This test on roachdash | Improve this report!

@jbowens
Copy link
Collaborator

jbowens commented May 14, 2024

From the second failure:

=== CONT  TestMeta/execution/random-010
    meta.go:241: 
        ===== SEED =====
        1715676342539380917
        ===== ERR =====
        exit status 2
        ===== OUT =====
        panic: interval is too long
        
        goroutine 16 [running]:
        github.com/cockroachdb/pebble/wal.(*dirProber).getMeanMax(0xc000324000?, 0xc000082f00?)
        	github.com/cockroachdb/pebble/wal/external/com_github_cockroachdb_pebble/wal/failover_manager.go:175 +0x1db
        github.com/cockroachdb/pebble/wal.(*failoverMonitor).monitorLoop(0xc000324000, 0xc00025fbc0)
        	github.com/cockroachdb/pebble/wal/external/com_github_cockroachdb_pebble/wal/failover_manager.go:386 +0x1fd
        github.com/cockroachdb/pebble/wal.newFailoverMonitor.func1()
        	github.com/cockroachdb/pebble/wal/external/com_github_cockroachdb_pebble/wal/failover_manager.go:258 +0x25
        github.com/cockroachdb/pebble/wal.(*stopper).runAsync.func1()
        	github.com/cockroachdb/pebble/wal/external/com_github_cockroachdb_pebble/wal/failover_manager.go:813 +0x22
        created by github.com/cockroachdb/pebble/wal.(*stopper).runAsync in goroutine 11
        	github.com/cockroachdb/pebble/wal/external/com_github_cockroachdb_pebble/wal/failover_manager.go:812 +0x79

@jbowens
Copy link
Collaborator

jbowens commented May 14, 2024 •
edited
Loading

From the first (-race) failure:

=== NAME  TestMeta/execution/random-013
    meta.go:241: 
        ===== SEED =====
        1715667173718235083
        ===== ERR =====
        exit status 2
        ===== OUT =====
        panic: operation took longer than 5m0s: db1.Download("bvfmdbpsf@65" /* start */, "yltsrqoul@169" /* end */, false /* viaBackingFileDownload */)
        
        goroutine 88525 [running]:
        github.com/cockroachdb/pebble/metamorphic.(*Test).runOp.func1()
        	github.com/cockroachdb/pebble/metamorphic/external/com_github_cockroachdb_pebble/metamorphic/test.go:412 +0x114
        created by time.goFunc
        	GOROOT/src/time/sleep.go:177 +0x45
        
        ===== OPTIONS =====

@jbowens
Copy link
Collaborator

jbowens commented May 14, 2024

@itsbilal @RaduBerinde - you were looking at long-running Download operations before, right? should we do something specific to -race builds?

jbowens added a commit to jbowens/pebble that referenced this issue May 14, 2024
@jbowens
metamorphic: fix WAL failover config generation
9b491cf 
Previously it was possible for the metamorphic test to generate an invalid WAL
failover configuration where the healthy interval was too long for the given
probe interval, resulting in a healthy interval that could never be satisfied
with the fixed 120-entry probe history.

Informs cockroachdb#3618.
@jbowens jbowens mentioned this issue May 14, 2024
Merged
jbowens added a commit that referenced this issue May 14, 2024
@jbowens
metamorphic: fix WAL failover config generation
5e941d8 
Previously it was possible for the metamorphic test to generate an invalid WAL
failover configuration where the healthy interval was too long for the given
probe interval, resulting in a healthy interval that could never be satisfied
with the fixed 120-entry probe history.

Informs #3618.
@sumeerbhola sumeerbhola mentioned this issue May 14, 2024
Closed
@cockroach-teamcity
Copy link
Member Author

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

        // 04:55:26.284 INFO: [JOB 562] flushing: sstable created 009600
        // 04:55:26.286 INFO: [JOB 605] compacted(default) L0 [005347 005524 005807 006007 006368 006478 006676 007007 007355 007640 008547 008859 009153] (11KB) Score=224.32 + L2 [] (0B) Score=0.00 -> L2 [009575] (957B), in 3.4s (3.4s total), output rate 279B/s
        // 04:55:28.011 INFO: [JOB 609] compacting(default) L0 [005346 005523 005806 006006 006367 006477 006675 007006 007354 007639 008546 008858 009152] (11KB) Score=223.05 + L2 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:55:28.011 INFO: [JOB 605] sstable deleted 008547
        // 04:55:28.011 INFO: [JOB 610] compacting(move) multilevelL2 [009575] (957B) Score=15.47 + L3 [] (0B) Score=0.97 + L4 [] (0B) Score=0.96; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:55:28.012 INFO: [JOB 610] compacted(move) multilevelL2 [009575] (957B) Score=15.47 + L3 [] (0B) Score=0.97 + L4 [] (0B) Score=0.96 -> L4 [009575] (957B), in 0.0s (0.0s total), output rate 170MB/s
        // 04:55:29.801 INFO: [JOB 609] compacting: sstable created 009602
        // 04:55:29.802 INFO: [JOB 562] flushing: sstable created 009601
        // 04:55:29.802 INFO: [JOB 611] compacting(move) multilevelL4 [009575] (957B) Score=7.74 + L5 [] (0B) Score=0.16 + L6 [] (0B) Score=0.04; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:55:29.802 INFO: [JOB 605] sstable deleted 008752
        // 04:55:29.803 INFO: [JOB 562] flushing: sstable created 009603
        // 04:55:29.803 INFO: [JOB 605] sstable deleted 008787
        // 04:55:29.804 INFO: [JOB 611] compacted(move) multilevelL4 [009575] (957B) Score=7.74 + L5 [] (0B) Score=0.16 + L6 [] (0B) Score=0.04 -> L6 [009575] (957B), in 0.0s (0.0s total), output rate 240MB/s
        // 04:55:31.644 INFO: [JOB 605] sstable deleted 008789
        // 04:55:31.644 INFO: [JOB 605] sstable deleted 008859
        // 04:55:31.646 INFO: [JOB 605] sstable deleted 008968
        // 04:55:31.647 INFO: [JOB 562] flushing: sstable created 009604
        // 04:55:31.647 INFO: [JOB 562] flushing: sstable created 009605
        // 04:55:31.647 INFO: [JOB 562] flushing: sstable created 009606
        // 04:55:31.647 INFO: [JOB 562] flushing: sstable created 009607
        // 04:55:31.647 INFO: [JOB 562] flushing: sstable created 009608
        // 04:55:31.648 INFO: [JOB 562] flushing: sstable created 009609
        // 04:55:31.648 INFO: [JOB 562] flushing: sstable created 009610
        // 04:55:31.648 INFO: [JOB 562] flushing: sstable created 009611
        // 04:55:31.648 INFO: [JOB 562] flushing: sstable created 009612
        // 04:55:31.648 INFO: [JOB 562] flushing: sstable created 009613
        // 04:55:31.648 INFO: [JOB 562] flushing: sstable created 009614
        // 04:55:31.648 INFO: [JOB 562] flushing: sstable created 009615
        // 04:55:31.648 INFO: [JOB 562] flushing: sstable created 009616
        // 04:55:31.648 INFO: [JOB 562] flushing: sstable created 009617
        // 04:55:31.648 INFO: [JOB 562] flushing: sstable created 009618
        // 04:55:31.648 INFO: [JOB 562] flushing: sstable created 009619
        // 04:55:31.649 INFO: [JOB 562] flushing: sstable created 009620
        // 04:55:31.649 INFO: [JOB 562] flushing: sstable created 009621
        // 04:55:31.649 INFO: [JOB 562] flushing: sstable created 009622
        // 04:55:31.649 INFO: [JOB 562] flushing: sstable created 009623
        // 04:55:31.649 INFO: [JOB 562] flushing: sstable created 009624
        // 04:55:31.649 INFO: [JOB 562] flushing: sstable created 009625
        // 04:55:31.649 INFO: [JOB 562] flushing: sstable created 009626
        // 04:55:31.649 INFO: [JOB 562] flushing: sstable created 009627
        // 04:55:31.649 INFO: [JOB 562] flushing: sstable created 009628
        // 04:55:31.649 INFO: [JOB 562] flushing: sstable created 009629
        // 04:55:31.649 INFO: [JOB 562] flushing: sstable created 009630
        // 04:55:31.649 INFO: [JOB 562] flushing: sstable created 009631
        // 04:55:31.649 INFO: [JOB 562] flushing: sstable created 009632
        // 04:55:31.650 INFO: [JOB 609] compacted(default) L0 [005346 005523 005806 006006 006367 006477 006675 007006 007354 007639 008546 008858 009152] (11KB) Score=223.05 + L2 [] (0B) Score=0.00 -> L2 [009602] (954B), in 1.8s (3.6s total), output rate 532B/s
        // 04:55:31.657 INFO: [JOB 605] sstable deleted 009153
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240516-044726.4263225727557/random-007 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-007 (479.67s)
Help

To reproduce, try: 

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

This test on roachdash | Improve this report!

@jbowens
Copy link
Collaborator

jbowens commented May 16, 2024

Latest failure is a non-race build with a slow IngestExternalFiles:

=== NAME  TestMeta/execution/random-007
    meta.go:241: 
        ===== SEED =====
        1715834846426028703
        ===== ERR =====
        exit status 2
        ===== OUT =====
        panic: operation took longer than 1m0s: db1.IngestExternalFiles(external0, "qfkyeeem" /* start */, "qfkyeeemtf" /* end */, "" /* syntheticSuffix */, "qfk" /* syntheticPrefix */, external0, "yedwmwypmg" /* start */, "yeeemad" /* end */, "" /* syntheticSuffix */, "" /* syntheticPrefix */, external0, "lznbyeae" /* start */, "lznbyeeemvg" /* end */, "" /* syntheticSuffix */, "lznb" /* syntheticPrefix */)
        
        goroutine 21483 [running]:
        github.com/cockroachdb/pebble/metamorphic.(*Test).runOp.func1()
        	github.com/cockroachdb/pebble/metamorphic/external/com_github_cockroachdb_pebble/metamorphic/test.go:412 +0xb4
        created by time.goFunc
        	GOROOT/src/time/sleep.go:177 +0x2d
        
        ===== OPTIONS =====

@cockroach-teamcity
Copy link
Member Author

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

        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015101
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015102
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015104
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015596
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015597
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015598
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015599
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015600
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015601
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015602
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015603
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015604
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015605
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015966
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015967
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015968
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015969
        // 09:23:01.947 INFO: [JOB 3764] sstable deleted 015970
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 015971
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 015972
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 015973
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 015974
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 015975
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 016521
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 016522
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 016523
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 016524
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 016525
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 016526
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 016527
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 016528
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 016529
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 016530
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 017085
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 017086
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 017087
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 017088
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 017089
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 017092
        // 09:23:01.948 INFO: [JOB 3764] sstable deleted 017094
        // 09:23:01.962 INFO: [JOB 3767] compacted(download,rewrite) L0 [013096] (857B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [017466] (859B), in 0.0s (3.3s total), output rate 3.1MB/s
        // 09:23:05.219 INFO: [JOB 3770] compacting(download,rewrite) L0 [013540] (857B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 09:23:05.219 INFO: [JOB 3770] compacting: sstable created 017467
        // 09:23:05.221 INFO: [JOB 3769] compacted(move) L3 [017465] (2.2KB) Score=7.15 + L4 [] (0B) Score=5.35 -> L4 [017465] (2.2KB), in 0.0s (3.3s total), output rate 482MB/s
        // 09:23:08.510 INFO: [JOB 3771] compacting(default) L4 [017465] (2.2KB) Score=6.36 + L5 [011757] (1.6KB) Score=112.93; OverlappingRatio: Single 0.73, Multi 0.00
        // 09:23:08.510 INFO: [JOB 3771] compacting: sstable created 017468
        // 09:23:08.527 INFO: [JOB 3770] compacted(download,rewrite) L0 [013540] (857B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [017467] (859B), in 3.3s (3.3s total), output rate 261B/s
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240519-090710.6771861007759/random-006 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-006 (945.28s)
Help

To reproduce, try: 

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

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

        // 05:45:08.572 INFO: [JOB 401] compacting: sstable created 011778
        // 05:45:08.587 INFO: [JOB 400] compacted(default) multilevelL3 [011775] (1.0KB) Score=38.51 + L4 [] (0B) Score=35.58 + L5 [] (0B) Score=102.67 -> L5 [011777] (1.0KB), in 0.0s (2.4s total), output rate 592KB/s
        // 05:45:10.957 INFO: [JOB 403] compacting(default) L0 [004843 005135 005457 005565 005717 005909 006240 006697 006959 007328 007573 008070 008545 008805 009067 009283 009512 009677 009935 010212 010463 010741 010944 011021 011203 011621] (21KB) Score=88400.00 + L3 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 05:45:10.965 INFO: [JOB 403] compacting: sstable created 011779
        // 05:45:11.045 INFO: [JOB 401] compacted(download,rewrite) L0 [010086] (788B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [011778] (789B), in 2.4s (2.5s total), output rate 330B/s
        // 05:45:13.279 INFO: [JOB 401] sstable deleted 011775
        // 05:45:13.365 INFO: [JOB 403] compacted(default) L0 [004843 005135 005457 005565 005717 005909 006240 006697 006959 007328 007573 008070 008545 008805 009067 009283 009512 009677 009935 010212 010463 010741 010944 011021 011203 011621] (21KB) Score=88400.00 + L3 [] (0B) Score=0.00 -> L3 [011779] (1.2KB), in 0.0s (2.4s total), output rate 90KB/s
        // 05:45:15.597 INFO: [JOB 405] compacting(download,rewrite) L0 [007036] (788B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 05:45:15.598 INFO: [JOB 406] compacting(default) L5 [009902] (1.1KB) Score=108.29 + L6 [009908] (1.3KB) Score=0.01; OverlappingRatio: Single 1.18, Multi 0.00
        // 05:45:15.599 INFO: [JOB 406] compacting: sstable created 011780
        // 05:45:15.616 INFO: [JOB 406] compacted(default) L5 [009902] (1.1KB) Score=108.29 + L6 [009908] (1.3KB) Score=0.01 -> L6 [011780] (1.3KB), in 0.0s (0.0s total), output rate 372KB/s
        // 05:45:17.948 INFO: [JOB 407] compacting(move) L3 [011779] (1.2KB) Score=46.61 + L4 [] (0B) Score=35.50; OverlappingRatio: Single 0.00, Multi 0.00
        // 05:45:18.032 INFO: [JOB 405] compacted(download,rewrite) L0 [007036] (788B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [] (0B), in 0.0s (2.4s total), output rate 0B/s
        // 05:45:20.331 INFO: [JOB 408] compacting(download,rewrite) L0 [009131] (788B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 05:45:20.346 INFO: [JOB 407] compacted(move) L3 [011779] (1.2KB) Score=46.61 + L4 [] (0B) Score=35.50 -> L4 [011779] (1.2KB), in 0.0s (2.4s total), output rate 76MB/s
        // 05:45:22.835 INFO: [JOB 409] compacting(default) L0 [001975 002453 002884 003066 003257 003790 004220 004694 004732 005257 006044 006580 006622 006782 007236 008222 008331 008713 009000 009459 009980 010633 010665 011298] (20KB) Score=87725.00 + L3 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 05:45:22.842 INFO: [JOB 409] compacting: sstable created 011781
        // 05:45:22.918 INFO: [JOB 408] compacted(download,rewrite) L0 [009131] (788B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [] (0B), in 0.0s (2.6s total), output rate 0B/s
        // 05:45:25.222 INFO: [JOB 410] compacting(download,rewrite) L0 [006058] (788B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 05:45:25.324 INFO: [JOB 409] MANIFEST created 011782
        // 05:45:25.337 INFO: [JOB 409] compacted(default) L0 [001975 002453 002884 003066 003257 003790 004220 004694 004732 005257 006044 006580 006622 006782 007236 008222 008331 008713 009000 009459 009980 010633 010665 011298] (20KB) Score=87725.00 + L3 [] (0B) Score=0.00 -> L3 [011781] (1.1KB), in 0.0s (2.5s total), output rate 94KB/s
        // 05:45:27.705 INFO: [JOB 409] MANIFEST deleted 009028
        // 05:45:27.706 INFO: [JOB 411] compacting(default) L5 [011728] (784B) Score=103.03 + L6 [010591] (867B) Score=0.01; OverlappingRatio: Single 1.11, Multi 0.00
        // 05:45:27.707 INFO: [JOB 411] compacting: sstable created 011783
        // 05:45:27.791 INFO: [JOB 410] compacted(download,rewrite) L0 [006058] (788B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [] (0B), in 0.0s (2.6s total), output rate 0B/s
        // 05:45:30.067 INFO: [JOB 413] compacting(download,rewrite) L0 [007399] (788B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 05:45:30.068 INFO: [JOB 413] compacting: sstable created 011784
        // 05:45:30.083 INFO: [JOB 411] compacted(default) L5 [011728] (784B) Score=103.03 + L6 [010591] (867B) Score=0.01 -> L6 [011783] (867B), in 0.0s (2.4s total), output rate 563KB/s
        // 05:45:32.396 INFO: [JOB 414] compacting(default) L4 [011779] (1.2KB) Score=46.01 + L5 [] (0B) Score=0.99; OverlappingRatio: Single 0.00, Multi 1.01
        // 05:45:32.398 INFO: [JOB 414] compacting: sstable created 011785
        // 05:45:32.483 INFO: [JOB 413] compacted(download,rewrite) L0 [007399] (788B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [011784] (792B), in 2.3s (2.4s total), output rate 340B/s
        // 05:45:34.705 INFO: [JOB 415] compacting(download,rewrite) L0 [011353] (788B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 05:45:34.705 INFO: [JOB 413] sstable deleted 011728
        // 05:45:34.706 INFO: [JOB 415] compacting: sstable created 011786
        // 05:45:34.720 INFO: [JOB 414] compacted(default) L4 [011779] (1.2KB) Score=46.01 + L5 [] (0B) Score=0.99 -> L5 [011785] (1.2KB), in 0.0s (2.3s total), output rate 622KB/s
        // 05:45:37.030 INFO: [JOB 416] compacting(default) L5 [011785] (1.2KB) Score=105.49 + L6 [011750] (1.3KB) Score=0.01; OverlappingRatio: Single 1.01, Multi 0.00
        // 05:45:37.031 INFO: [JOB 416] compacting: sstable created 011787
        // 05:45:37.115 INFO: [JOB 415] compacted(download,rewrite) L0 [011353] (788B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [011786] (792B), in 2.3s (2.4s total), output rate 340B/s
        // 05:45:39.648 INFO: [JOB 418] compacting(download,rewrite) L0 [010598] (788B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 05:45:39.648 INFO: [JOB 415] sstable deleted 011779
        // 05:45:39.663 INFO: [JOB 416] compacted(default) L5 [011785] (1.2KB) Score=105.49 + L6 [011750] (1.3KB) Score=0.01 -> L6 [011787] (1.3KB), in 0.0s (2.6s total), output rate 874KB/s
        // 05:45:41.973 INFO: [JOB 419] compacting(default) multilevelL3 [011781] (1.1KB) Score=39.64 + L4 [] (0B) Score=36.72 + L5 [] (0B) Score=0.99; OverlappingRatio: Single 0.00, Multi 0.00
        // 05:45:41.975 INFO: [JOB 419] compacting: sstable created 011788
        // 05:45:42.061 INFO: [JOB 418] compacted(download,rewrite) L0 [010598] (788B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [] (0B), in 2.3s (2.4s total), output rate 0B/s
        // 05:45:44.336 INFO: [JOB 418] sstable deleted 011750
        // 05:45:44.336 INFO: [JOB 418] sstable deleted 011785
        // 05:45:44.350 INFO: [JOB 419] compacted(default) multilevelL3 [011781] (1.1KB) Score=39.64 + L4 [] (0B) Score=36.72 + L5 [] (0B) Score=0.99 -> L5 [011788] (1.1KB), in 0.0s (2.4s total), output rate 567KB/s
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240520-052145.2522402681326/random-027 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-027 (1442.28s)
Help

To reproduce, try: 

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

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

        // 08:52:09.720 INFO: [JOB 2289] compacting(move) L5 [015275] (1.2KB) Score=37.31 + L6 [] (0B) Score=0.03; OverlappingRatio: Single 0.00, Multi 0.00
        // 08:52:09.720 INFO: [JOB 2278] flushing: sstable created 015417
        // 08:52:09.721 INFO: [JOB 2289] compacted(move) L5 [015275] (1.2KB) Score=37.31 + L6 [] (0B) Score=0.03 -> L6 [015275] (1.2KB), in 0.0s (0.0s total), output rate 224MB/s
        // 08:52:13.012 INFO: [JOB 2290] compacting(move) multilevelL3 [015300] (1.1KB) Score=15.96 + L4 [] (0B) Score=13.27 + L5 [] (0B) Score=35.72; OverlappingRatio: Single 0.00, Multi 0.00
        // 08:52:13.012 INFO: [JOB 2278] flushing: sstable created 015418
        // 08:52:13.013 INFO: [JOB 2290] compacted(move) multilevelL3 [015300] (1.1KB) Score=15.96 + L4 [] (0B) Score=13.27 + L5 [] (0B) Score=35.72 -> L5 [015300] (1.1KB), in 0.0s (0.0s total), output rate 290MB/s
        // 08:52:16.646 INFO: [JOB 2278] flushing: sstable created 015419
        // 08:52:16.646 INFO: [JOB 2291] compacting(default) L0 [010924 011309 011808 012201 012714 012973 013353 013775 013677 013968 013969 013970 014194 014195 014196 014478 014479 014480 014648 014649 014650] (16KB) Score=305.96 + L3 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 08:52:16.646 INFO: [JOB 2278] flushing: sstable created 015420
        // 08:52:16.646 INFO: [JOB 2278] flushing: sstable created 015421
        // 08:52:16.647 INFO: [JOB 2278] flushing: sstable created 015422
        // 08:52:16.647 INFO: [JOB 2278] flushing: sstable created 015423
        // 08:52:16.647 INFO: [JOB 2278] flushing: sstable created 015424
        // 08:52:16.647 INFO: [JOB 2278] flushing: sstable created 015425
        // 08:52:16.647 INFO: [JOB 2278] flushing: sstable created 015426
        // 08:52:16.647 INFO: [JOB 2278] flushing: sstable created 015427
        // 08:52:16.647 INFO: [JOB 2278] flushing: sstable created 015428
        // 08:52:16.647 INFO: [JOB 2278] flushing: sstable created 015429
        // 08:52:16.647 INFO: [JOB 2278] flushing: sstable created 015430
        // 08:52:16.647 INFO: [JOB 2278] flushing: sstable created 015431
        // 08:52:16.647 INFO: [JOB 2278] flushing: sstable created 015432
        // 08:52:16.647 INFO: [JOB 2278] flushing: sstable created 015433
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015434
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015435
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015436
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015437
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015438
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015439
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015440
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015441
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015442
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015443
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015444
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015445
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015446
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015447
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015448
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015449
        // 08:52:16.648 INFO: [JOB 2278] flushing: sstable created 015450
        // 08:52:16.660 INFO: [JOB 2291] compacting: sstable created 015452
        // 08:52:16.667 INFO: [JOB 2278] flushing: sstable created 015451
        // 08:52:16.667 INFO: [JOB 2278] flushing: sstable created 015453
        // 08:52:16.667 INFO: [JOB 2278] flushing: sstable created 015454
        // 08:52:16.668 INFO: [JOB 2291] compacted(default) L0 [010924 011309 011808 012201 012714 012973 013353 013775 013677 013968 013969 013970 014194 014195 014196 014478 014479 014480 014648 014649 014650] (16KB) Score=305.96 + L3 [] (0B) Score=0.00 -> L3 [015452] (1.3KB), in 0.0s (0.0s total), output rate 92KB/s
        // 08:52:20.186 INFO: [JOB 2293] compacting(move) L5 [015300] (1.1KB) Score=36.64 + L6 [] (0B) Score=0.03; OverlappingRatio: Single 0.00, Multi 0.00
        // 08:52:20.186 INFO: [JOB 2278] flushing: sstable created 015455
        // 08:52:20.187 INFO: [JOB 2293] compacted(move) L5 [015300] (1.1KB) Score=36.64 + L6 [] (0B) Score=0.03 -> L6 [015300] (1.1KB), in 0.0s (0.0s total), output rate 238MB/s
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240520-084242.6853796487266/random-012 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-012 (571.47s)
Help

To reproduce, try: 

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

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

        // 04:22:47.070 INFO: [JOB 2120] compacting: sstable created 011949
        // 04:22:47.070 INFO: [JOB 2120] compacting: sstable created 011950
        // 04:22:47.070 INFO: [JOB 2120] compacting: sstable created 011951
        // 04:22:47.084 INFO: [JOB 2120] compacted(default) L0 [006593 006594 006596 006597 006598 006599 006600 006601 006606 006617 006619 006627 006921 006934 006936 006944 006908 006909 006911 006912 006913 006914 006915 006916 007234 007247 007249 007258 007489 007495 007510 007512 007521 007481 007482 007484 007485 007486 007487 007488 007784 007785 007788 007789 007790 007791 007792 007793 007799 007814 007816 007825 008040 008041 008043 008044 008045 008046 008047 008048 008054 008069 008071 008080 008313 008305 008306 008308 008309 008310 008311 008312 008319 008334 008337 008346 008355 008646 008610 008616 008617 008565 008566 008568 008569 008570 008571 008572 008600 008607 008576 008582 008597 008587 008756 008759 008766 008767 008768 008769 008770 008778 008797 008798 008808 008943 008944 008945 008946 008947 008948 008954 008956 008964 008967 008972 008973 008976 008980 008981 008982 008983 008984 008992 009009 009010 009011 009012 009013 009014 009015 009016 009017 009020 009022 009024 009026 009030 009041 009047 009048 009049 008939 008940 009142 009196 009249 009266 009195 009174 009183 009188 009199 009203 009204 009205 009206 009207 009208 009209 009216 009230 009231 009232 009233 009234 009235 009236 009237 009238 009244 009245 009246 009247 009250 009251 009252 009259 009264 009265 009163 009418 009319 009320 009323 009324 009325 009326 009327 009328 009334 009337 009340 009341 009351 009354 009355 009356 009357 009358 009359 009360 009365 009366 009367 009368 009369 009370 009371 009372 009373 009374 009375 009384 009401 009402 009403 009404 009405 009406 009407 009408 009409 009412 009413 009414 009415 009417 009514 009515 009518 009519 009520 009521 009522 009523 009529 009530 009531 009533 009534 009561 009548 009563 009585 009564 009565 009566 009567 009568 009569 009570 009571 009574 009575 009576 009577 009583 009584 009586 009551 009707 009708 009712 009713 009714 009715 009716 009717 009722 009723 009724 009725 009727 009728 009729 009730 009731 009732 009734 009735 009741 009744 009745 009746 009747 009748 009749 009750 009751 009752 009753 009754 009755 009756 009757 009758 009759 009760 009762 009764 009765 009768 009771 009773 009781 009782 009785 009786 009787 009788 009789 009790 009791 009793 009794 009799 009800 009801 009802 009803 009804 009805 009806 009807 009808 009809 009813 009814 009815 009816 009822 009823 009824 009825 009591 010083 010086 010087 010088 010089 010090 010091 010092 010093 010094 010095 010096 010097 010098 010099 010100 010101 010102 010103 010104 010105 010106 010107 010108 010110 010111 010112 010113 010114 010115 010116 010117 010118 010125 010126 010129 010130 010131 010132 010133 010134 010135 010136 010137 010140 010142 010143 010144 010145 010146 010148 010149 010150 010151 010152 010154 010157 010158 010160 010161 010167 010168 010169 010170 010046 010047 010054 010055 010056 010057 010058 010059 010064 010065 010066 010067 010069 010070 010071 010072 010073 010074 010075 010076 010079 010080 010300 010301 010304 010307 010308 010309 010310 010311 010312 010317 010318 010319 010320 010322 010323 010324 010325 010326 010327 010328 010011 010460 010461 010462 010463 010464 010465 010466 010467 010468 010469 010470 010471 010472 010474 010475 010477 010478 010479 010480 010482 010483 010484 010485 010486 010487 010488 010489 010490 010492 010493 010494 010495 010498 010499 010500 010501 010502 010503 010504 010505 010506 010507 010508 010509 010510 010511 010512 010513 010514 010515 010516 010517 010518 010519 010520 010522 010523 010524 010525 010526 010528 010530 010533 010534 010541 010542 010544 010545 010546 010547 010548 010549 010550 010551 010552 010555 010556 010557 010558 010559 010560 010561 010562 010563 010564 010565 010566 010567 010569 010570 010571 010572 010573 010574 010575 010580 010581 010582 010583 010587 010588 010665 010666 010667 010668 010669 010670 010671 010673 010674 010675 010676 010677 010678 010679 010680 010681 010683 010684 010685 010686 010687 010688 010689 010691 010692 010660 010864 010865 010866 010868 010869 010870 010871 010872 010873 010874 010875 010876 010878 010879 010880 010881 010882 010884 010886 010887 010888 010889 010890 010891 010892 010893 010895 010896 010897 010899 010900 010901 010902 010903 010906 010907 010908 010909 010910 010911 010912 010913 010914 010915 010916 010917 010918 010919 010920 010921 010922 010923 010924 010926 010928 010930 010932 010935 010936 010937 010939 010940 010941 010942 010943 010944 010951 010952 010955 010956 010957 010958 010959 010960 010961 010962 010963 010966 010967 010968 010969 010970 010971 010972 010973 010974 010975 010976 010977 010978 010979 010980 010981 010982 010983 010984 010985 010986 010987 010990 010992 010993 010994 010995 010996 010997 010998 010999 011000 011001 011002 011003 011004 011005 011006 011013 011014 010867 011087 011126 011100 011101 011103 011104 011105 011106 011107 011108 011109 011110 011111 011118 011119 011122 011123 011124 011125 011127 011128 011129 011130 011132 011133 011134 011135 011136 011137 011138 011139 011140 011141 011142 011143 011144 011145 011146 011147 011148 011149 011150 011151 011152 011153 011154 011155 011156 011157 011158 011159 011160 011161 011162 011163 011164 011165 011166 011167 011168 011169 011176 011177 011315 011316 011317 011318 011319 011320 011321 011322 011323 011324 011325 011326 011327 011330 011331 011332 011333 011334 011335 011336 011337 011339 011340 011341 011342 011343 011344 011345 011346 011347 011349 011350 011351 011352 011353 011357 011359 011360 011361 011362 011363 011364 011365 011366 011367 011368 011369 011370 011371 011372 011373 011374 011376 011377 011378 011379 011380 011381 011383 011384 011385 011386 011387 011388 011389 011390 011391 011393 011394 011399 011400 011401 011404 011405 011406 011407 011408 011409 011410 011411 011412 011413 011414 011415 011416 011417 011419 011420 011421 011423 011424 011425 011375 011484 011485 011482 011492 011493 011494 011495 011496 011497 011498 011499 011500 011501 011502 011504 011505 011506 011507 011508 011509 011510 011511 011512 011513 011514 011516 011517 011503 011657 011658 011659 011611 011735 011736 011737 011738 011739 011740 011741 011742 011743 011744 011745 011746 011747 011748 011749 011750 011751 011752 011753 011754 011755 011756 011757 011758 011759 011760 011761 011762 011763 011764 011765 011766 011767 011768 011769 011770 011771 011772 011773 011774 011775 011776 011779 011781 011782 011784 011785 011786 011787 011788 011789 011790 011791 011792 011793 011794 011795 011796 011798 011799 011800 011801 011802 011803 011804 011805 011806 011807 011808 011809 011810 011811 011812 011813 011814 011815 011816 011817 011818 011819 011821 011822 011823 011824 011825 011826 011683 011684 011685 011686 011687 011688 011689 011690 011691 011692 011693 011694 011695 011696 011697 011698 011699 011700 011701 011702 011703 011704 011705 011706 011707 011708 011709 011710 011711 011712 011713 011714 011715 011716 011717 011718 011720 011721 011722 011723 011724 011725 011726 011727 011728 011729 011730 011731 011732 011733 011734 011820] (826KB) Score=0.00 + L3 [011936] (780B) Score=0.00 -> L3 [011937 011938 011939 011940 011941 011942 011943 011944 011945 011946 011947 011948 011949 011950 011951] (21KB), in 2.2s (2.2s total), output rate 9.6KB/s
        // 04:22:48.170 INFO: [JOB 2123] compacting(default) L3 [011948] (802B) Score=4.23 + L4 [] (0B) Score=2.35; OverlappingRatio: Single 0.00, Multi 1.30
        // 04:22:48.170 INFO: [JOB 2124] compacting(default) L3 [011939] (2.9KB) Score=3.94 + L4 [010332] (1.0KB) Score=2.41; OverlappingRatio: Single 0.36, Multi 0.00
        // 04:22:48.170 INFO: [JOB 2125] compacting(default) L3 [011937] (2.9KB) Score=5.45 + L4 [] (0B) Score=2.14; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:22:48.170 INFO: [JOB 2120] sstable deleted 011936
        // 04:22:48.170 INFO: [JOB 2123] compacting: sstable created 011952
        // 04:22:48.170 INFO: [JOB 2124] compacting: sstable created 011953
        // 04:22:48.171 INFO: [JOB 2123] compacted(default) L3 [011948] (802B) Score=4.23 + L4 [] (0B) Score=2.35 -> L4 [011952] (802B), in 0.0s (0.0s total), output rate 1.2MB/s
        // 04:22:49.412 INFO: [JOB 2126] compacting(default) L3 [011946] (2.1KB) Score=2.98 + L4 [011429] (1.0KB) Score=2.62; OverlappingRatio: Single 0.49, Multi 0.00
        // 04:22:49.412 INFO: [JOB 2125] compacting: sstable created 011955
        // 04:22:49.412 INFO: [JOB 2124] compacting: sstable created 011954
        // 04:22:49.412 INFO: [JOB 2125] compacting: sstable created 011956
        // 04:22:49.412 INFO: [JOB 2124] compacting: sstable created 011957
        // 04:22:49.412 INFO: [JOB 2125] compacting: sstable created 011958
        // 04:22:49.412 INFO: [JOB 2124] compacting: sstable created 011959
        // 04:22:49.412 INFO: [JOB 2125] compacting: sstable created 011960
        // 04:22:49.412 INFO: [JOB 2124] compacting: sstable created 011961
        // 04:22:49.412 INFO: [JOB 2125] compacting: sstable created 011962
        // 04:22:49.412 INFO: [JOB 2124] compacting: sstable created 011963
        // 04:22:49.412 INFO: [JOB 2125] compacting: sstable created 011964
        // 04:22:49.412 INFO: [JOB 2124] compacting: sstable created 011965
        // 04:22:49.412 INFO: [JOB 2125] compacting: sstable created 011966
        // 04:22:49.412 INFO: [JOB 2124] compacting: sstable created 011967
        // 04:22:49.413 INFO: [JOB 2125] compacting: sstable created 011968
        // 04:22:49.413 INFO: [JOB 2124] compacting: sstable created 011969
        // 04:22:49.413 INFO: [JOB 2125] compacting: sstable created 011970
        // 04:22:49.413 INFO: [JOB 2124] compacting: sstable created 011971
        // 04:22:49.413 INFO: [JOB 2124] compacting: sstable created 011972
        // 04:22:49.413 INFO: [JOB 2124] compacting: sstable created 011973
        // 04:22:49.413 INFO: [JOB 2124] compacting: sstable created 011974
        // 04:22:49.413 INFO: [JOB 2124] compacting: sstable created 011975
        // 04:22:49.413 INFO: [JOB 2124] compacting: sstable created 011976
        // 04:22:49.413 INFO: [JOB 2124] compacting: sstable created 011977
        // 04:22:49.414 INFO: [JOB 2125] compacted(default) L3 [011937] (2.9KB) Score=5.45 + L4 [] (0B) Score=2.14 -> L4 [011955 011956 011958 011960 011962 011964 011966 011968 011970] (9.5KB), in 1.2s (1.2s total), output rate 7.6KB/s
        // 04:22:50.361 INFO: [JOB 2129] compacting(delete-only) L4 [010532] (1.2KB) Score=0.00 + L5 [010988 008737 009797 009848 008742 009289 009364 009549 008745 009382 009488 009435 009420 009388 008882 010045 010155 010141 010202 008995 008996 009192 009243 010835 010938 010925 010933 009090 010769 011667] (35KB) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:22:50.361 INFO: [JOB 2126] compacting: sstable created 011978
        // 04:22:50.362 INFO: [JOB 2129] compacted(delete-only) L4 [010532] (1.2KB) Score=0.00 + L5 [010988 008737 009797 009848 008742 009289 009364 009549 008745 009382 009488 009435 009420 009388 008882 010045 010155 010141 010202 008995 008996 009192 009243 010835 010938 010925 010933 009090 010769 011667] (35KB) Score=0.00 -> L6 [] (0B), in 0.0s (0.0s total), output rate 0B/s
        // 04:22:51.416 INFO: [JOB 2130] compacting(move) multilevelL4 [011960] (961B) Score=5.04 + L5 [] (0B) Score=0.35 + L6 [] (0B) Score=0.01; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:22:51.416 INFO: [JOB 2126] compacting: sstable created 011979
        // 04:22:51.416 INFO: [JOB 2129] sstable deleted 011948
        // 04:22:51.416 INFO: [JOB 2124] compacted(default) L3 [011939] (2.9KB) Score=3.94 + L4 [010332] (1.0KB) Score=2.41 -> L4 [011953 011954 011957 011959 011961 011963 011965 011967 011969 011971 011972 011973 011974 011975 011976 011977] (16KB), in 2.2s (3.2s total), output rate 7.2KB/s
        // 04:22:52.551 INFO: [JOB 2132] compacting(move) multilevelL4 [011962] (1.2KB) Score=7.29 + L5 [] (0B) Score=0.34 + L6 [] (0B) Score=0.01; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:22:52.551 INFO: [JOB 2126] compacting: sstable created 011980
        // 04:22:52.552 INFO: [JOB 2132] compacted(move) multilevelL4 [011962] (1.2KB) Score=7.29 + L5 [] (0B) Score=0.34 + L6 [] (0B) Score=0.01 -> L6 [011962] (1.2KB), in 0.0s (0.0s total), output rate 213MB/s
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240521-041554.9773150088574/random-029 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-029 (418.48s)
Help

To reproduce, try: 

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

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

        // 04:18:42.472 INFO: [JOB 3537] sstable deleted 020911
        // 04:18:42.472 INFO: [JOB 3537] sstable deleted 021257
        // 04:18:42.472 INFO: [JOB 3537] sstable deleted 021596
        // 04:18:42.472 INFO: [JOB 3537] sstable deleted 021763
        // 04:18:42.472 INFO: [JOB 3537] sstable deleted 022102
        // 04:18:42.472 INFO: [JOB 3537] sstable deleted 022361
        // 04:18:42.472 INFO: [JOB 3537] sstable deleted 022496
        // 04:18:42.473 INFO: [JOB 3541] compacting: sstable created 022808
        // 04:18:42.479 INFO: [JOB 3539] compacted(download,rewrite) L0 [019719] (691B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [022807] (612B), in 0.0s (1.7s total), output rate 2.0MB/s
        // 04:18:44.203 INFO: [JOB 3542] compacting(download,rewrite) L0 [020072] (691B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:18:44.210 INFO: [JOB 3538] compacted(download,rewrite) L0 [022451] (691B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [] (0B), in 0.0s (5.5s total), output rate 0B/s
        // 04:18:46.140 INFO: [JOB 3543] compacting(download,rewrite) L0 [019716] (691B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:18:46.141 INFO: [JOB 3543] compacting: sstable created 022809
        // 04:18:46.148 INFO: [JOB 3541] compacted(default) L0 [017739 018029 018409 018663 018933 019259 019526 019820 020364 020671 020838 021175 021517 021683 022041 022750] (11KB) Score=78125.00 + L5 [] (0B) Score=0.01 -> L5 [022808] (1.1KB), in 1.7s (3.7s total), output rate 638B/s
        // 04:18:48.008 INFO: [JOB 3545] compacting(default) L0 [018490 018714 018990 019344 019601 019913 020204 020760 020797 020929 021277 021616 021783 022122 022381 022516] (11KB) Score=77700.00 + L5 [] (0B) Score=0.01; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:18:48.008 INFO: [JOB 3541] sstable deleted 020364
        // 04:18:48.008 INFO: [JOB 3541] sstable deleted 020671
        // 04:18:48.008 INFO: [JOB 3541] sstable deleted 020838
        // 04:18:48.008 INFO: [JOB 3541] sstable deleted 021175
        // 04:18:48.008 INFO: [JOB 3541] sstable deleted 021517
        // 04:18:48.008 INFO: [JOB 3541] sstable deleted 021683
        // 04:18:48.008 INFO: [JOB 3541] sstable deleted 022041
        // 04:18:48.008 INFO: [JOB 3541] sstable deleted 022750
        // 04:18:48.012 INFO: [JOB 3545] compacting: sstable created 022810
        // 04:18:48.015 INFO: [JOB 3543] compacted(download,rewrite) L0 [019716] (691B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [022809] (610B), in 0.0s (1.9s total), output rate 2.9MB/s
        // 04:18:49.783 INFO: [JOB 3546] compacting(download,rewrite) L0 [020251] (691B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:18:49.783 INFO: [JOB 3546] compacting: sstable created 022811
        // 04:18:49.791 INFO: [JOB 3542] compacted(download,rewrite) L0 [020072] (691B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [] (0B), in 0.0s (5.6s total), output rate 0B/s
        // 04:18:51.720 INFO: [JOB 3547] compacting(download,rewrite) L0 [020480] (691B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:18:51.727 INFO: [JOB 3545] compacted(default) L0 [018490 018714 018990 019344 019601 019913 020204 020760 020797 020929 021277 021616 021783 022122 022381 022516] (11KB) Score=77700.00 + L5 [] (0B) Score=0.01 -> L5 [022810] (825B), in 0.0s (3.7s total), output rate 182KB/s
        // 04:18:53.628 INFO: [JOB 3549] compacting(default) L0 [017768 018059 018440 018695 019291 019858 020144 020405 020708 020872 021214 021215 021552 021553 021718 021719 022076 022077 022078 022453 022785 022786 022787 022788] (17KB) Score=77275.00 + L5 [] (0B) Score=0.01; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:18:53.628 INFO: [JOB 3545] sstable deleted 020204
        // 04:18:53.628 INFO: [JOB 3545] sstable deleted 020760
        // 04:18:53.628 INFO: [JOB 3545] sstable deleted 020797
        // 04:18:53.628 INFO: [JOB 3545] sstable deleted 020929
        // 04:18:53.628 INFO: [JOB 3545] sstable deleted 021277
        // 04:18:53.628 INFO: [JOB 3545] sstable deleted 021616
        // 04:18:53.628 INFO: [JOB 3545] sstable deleted 021783
        // 04:18:53.628 INFO: [JOB 3545] sstable deleted 022122
        // 04:18:53.628 INFO: [JOB 3545] sstable deleted 022381
        // 04:18:53.628 INFO: [JOB 3545] sstable deleted 022516
        // 04:18:53.629 INFO: [JOB 3549] compacting: sstable created 022812
        // 04:18:53.636 INFO: [JOB 3547] compacted(download,rewrite) L0 [020480] (691B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [] (0B), in 0.0s (1.9s total), output rate 0B/s
        // 04:18:55.363 INFO: [JOB 3550] compacting(download,rewrite) L0 [022093] (691B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:18:55.370 INFO: [JOB 3546] compacted(download,rewrite) L0 [020251] (691B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [022811] (639B), in 0.0s (5.6s total), output rate 2.3MB/s
        // 04:18:57.217 INFO: [JOB 3552] compacting(download,rewrite) L0 [019769] (691B) Score=0.00 + L0 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 04:18:57.224 INFO: [JOB 3550] compacted(download,rewrite) L0 [022093] (691B) Score=0.00 + L0 [] (0B) Score=0.00 -> L0 [] (0B), in 0.0s (1.9s total), output rate 0B/s
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240522-041244.5811896638550/random-015 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-015 (367.87s)
Help

To reproduce, try: 

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

This test on roachdash | Improve this report!

@RaduBerinde
Copy link
Member

RaduBerinde commented May 23, 2024 •
edited
Loading

Looking at the latest failure above, random-015 has block_size=4 and target_file_size=12 which leads to 20k+ tables created. I will try to repro with those ops locally to see if it's just expected slowness or something else.

RaduBerinde added a commit to RaduBerinde/pebble that referenced this issue May 23, 2024
@RaduBerinde
metamorphic: bump timeout for Compact/Download/NewSnapshot
ece2f64 
Bump up the timeout for these ops, which can be very slow if both the
block size and target file size are small and we end up with a ton of
tiny tables.

Informs cockroachdb#3618
@RaduBerinde RaduBerinde mentioned this issue May 23, 2024
Merged
RaduBerinde added a commit that referenced this issue May 23, 2024
@RaduBerinde
metamorphic: bump timeout for Compact/Download/NewSnapshot
8b278ee 
Bump up the timeout for these ops, which can be very slow if both the
block size and target file size are small and we end up with a ton of
tiny tables.

Informs #3618
@cockroach-teamcity
Copy link
Member Author

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

        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010938
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010944
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010947
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010948
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010949
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010950
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010951
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010952
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010953
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010954
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010955
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010956
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010957
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010958
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010959
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010960
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010961
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010962
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010963
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010964
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010965
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010976
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010977
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010987
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010988
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010991
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 010994
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011037
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011038
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011042
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011047
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011049
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011051
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011052
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011054
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011055
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011056
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011057
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011058
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011059
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011061
        // 05:56:23.992 INFO: [JOB 3908] sstable deleted 011062
        // 05:56:23.993 INFO: [JOB 3973] compacted(default) L0 [014565 014946 015579 015773 015985 016022 016023 016283 016285 016507 016508 016667 016668 016897 016898 017189 017190 017572 017573 017981 017982 018310 018311 018420 018421 018422 018805 018807] (22KB) Score=284.18 + L2 [] (0B) Score=0.00 -> L2 [018899] (1.4KB), in 2.3s (2.4s total), output rate 613B/s
        // 05:56:23.997 INFO: [JOB 3908] sstable deleted 011071
        // 05:56:26.743 INFO: [JOB 3975] compacted(default) multilevelL3 [018897] (1.2KB) Score=23.87 + L4 [] (0B) Score=2.86 + L5 [] (0B) Score=0.74 -> L5 [018900] (1.2KB), in 0.0s (2.8s total), output rate 2.5MB/s
        // 05:56:28.882 INFO: [JOB 3978] compacting(move) L2 [018899] (1.4KB) Score=144000.00 + L3 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 05:56:28.883 INFO: [JOB 3978] compacted(move) L2 [018899] (1.4KB) Score=144000.00 + L3 [] (0B) Score=0.00 -> L3 [018899] (1.4KB), in 0.0s (2.1s total), output rate 296MB/s
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240526-053800.052696869194/random-026 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-026 (1096.43s)
Help

To reproduce, try: 

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

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

        // 06:30:44.483 INFO: [JOB 3551] flushing: sstable created 014090
        // 06:30:44.483 INFO: [JOB 3551] flushing: sstable created 014091
        // 06:30:44.484 INFO: [JOB 3551] flushing: sstable created 014092
        // 06:30:44.484 INFO: [JOB 3551] flushing: sstable created 014093
        // 06:30:44.484 INFO: [JOB 3554] compacting: sstable created 014094
        // 06:30:44.484 INFO: [JOB 3551] flushing: sstable created 014095
        // 06:30:44.484 INFO: [JOB 3551] flushing: sstable created 014096
        // 06:30:44.484 INFO: [JOB 3551] flushing: sstable created 014097
        // 06:30:44.484 INFO: [JOB 3551] flushing: sstable created 014098
        // 06:30:44.484 INFO: [JOB 3551] flushing: sstable created 014099
        // 06:30:44.484 INFO: [JOB 3551] flushing: sstable created 014100
        // 06:30:44.484 INFO: [JOB 3551] flushing: sstable created 014101
        // 06:30:44.484 INFO: [JOB 3551] flushing: sstable created 014102
        // 06:30:44.485 INFO: [JOB 3551] flushing: sstable created 014103
        // 06:30:44.485 INFO: [JOB 3551] flushing: sstable created 014104
        // 06:30:44.485 INFO: [JOB 3551] flushing: sstable created 014105
        // 06:30:44.485 INFO: [JOB 3551] flushing: sstable created 014106
        // 06:30:44.485 INFO: [JOB 3551] flushing: sstable created 014107
        // 06:30:44.485 INFO: [JOB 3551] flushing: sstable created 014108
        // 06:30:44.485 INFO: [JOB 3551] flushing: sstable created 014109
        // 06:30:44.485 INFO: [JOB 3551] flushing: sstable created 014110
        // 06:30:44.485 INFO: [JOB 3551] flushing: sstable created 014111
        // 06:30:44.488 INFO: [JOB 3551] flushing: sstable created 014112
        // 06:30:44.489 INFO: [JOB 3554] compacted(default) L0 [011634 011836 011910 012147 012308 012622 012899 013168 013443 013548 013549 013825 013826 013953] (12KB) Score=6.38 + L1 [] (0B) Score=9.38 -> L1 [014094] (1.2KB), in 0.0s (0.0s total), output rate 594KB/s
        // 06:30:46.555 INFO: [JOB 3556] compacting(default) L0 [011632 011833 011907 012144 012305 012619 012896 013165 013442 013547 013824 013951] (11KB) Score=5.95 + L1 [] (0B) Score=9.72; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:30:46.556 INFO: [JOB 3554] sstable deleted 013825
        // 06:30:46.556 INFO: [JOB 3554] sstable deleted 013826
        // 06:30:46.556 INFO: [JOB 3554] sstable deleted 013953
        // 06:30:46.556 INFO: [JOB 3551] flushing: sstable created 014113
        // 06:30:46.556 INFO: [JOB 3551] flushing: sstable created 014114
        // 06:30:46.556 INFO: [JOB 3551] flushing: sstable created 014115
        // 06:30:46.556 INFO: [JOB 3551] flushing: sstable created 014116
        // 06:30:46.556 INFO: [JOB 3551] flushing: sstable created 014117
        // 06:30:46.556 INFO: [JOB 3551] flushing: sstable created 014118
        // 06:30:46.556 INFO: [JOB 3551] flushing: sstable created 014119
        // 06:30:46.556 INFO: [JOB 3551] flushing: sstable created 014120
        // 06:30:46.557 INFO: [JOB 3551] flushing: sstable created 014121
        // 06:30:46.557 INFO: [JOB 3551] flushing: sstable created 014122
        // 06:30:46.557 INFO: [JOB 3551] flushing: sstable created 014123
        // 06:30:46.557 INFO: [JOB 3551] flushing: sstable created 014124
        // 06:30:46.557 INFO: [JOB 3551] flushing: sstable created 014125
        // 06:30:46.557 INFO: [JOB 3551] flushing: sstable created 014126
        // 06:30:46.557 INFO: [JOB 3551] flushing: sstable created 014127
        // 06:30:46.557 INFO: [JOB 3551] flushing: sstable created 014128
        // 06:30:46.557 INFO: [JOB 3551] flushing: sstable created 014129
        // 06:30:46.557 INFO: [JOB 3551] flushing: sstable created 014130
        // 06:30:46.557 INFO: [JOB 3551] flushing: sstable created 014131
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240528-062556.7801432971592/random-028 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-028 (284.74s)
Help

To reproduce, try: 

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

This test on roachdash | Improve this report!

@RaduBerinde
Copy link
Member

We haven't seen failures since the timeouts were bumped.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@RaduBerinde RaduBerinde

Labels
A-storage C-test-failure O-metamorphic O-robot release-blocker T-storage
Projects
Storage
Archived in project
Milestone
No milestone
Development

No branches or pull requests
3 participants
@jbowens @RaduBerinde @cockroach-teamcity