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 #3733

Closed
cockroach-teamcity opened this issue Jul 4, 2024 · 3 comments
Closed

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

cockroach-teamcity opened this issue Jul 4, 2024 · 3 comments
Assignees
@jbowens
Labels
A-storage branch-master C-test-failure metamorphic-failure O-robot T-storage

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented Jul 4, 2024 •
edited by cockroach-jira-scripts
Loading

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

        // 06:38:08.688 INFO: [JOB 5660] sstable deleted 019695
        // 06:38:08.688 INFO: [JOB 5660] sstable deleted 019704
        // 06:38:08.688 INFO: [JOB 5664] sstable deleted 018685
        // 06:38:08.688 INFO: [JOB 5664] sstable deleted 019705
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 011020
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 011082
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 011749
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 011962
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 012129
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 012326
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 012899
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 013197
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 014057
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 014971
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 015853
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 016128
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 016322
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 016761
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 017173
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 017777
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 017930
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 018255
        // 06:38:08.688 INFO: [JOB 5667] sstable deleted 018773
        // 06:38:08.689 INFO: [JOB 5667] sstable deleted 018990
        // 06:38:08.689 INFO: [JOB 5667] sstable deleted 019200
        // 06:38:08.689 INFO: [JOB 5667] sstable deleted 019621
        // 06:38:08.689 INFO: [JOB 5667] sstable deleted 019810
        // 06:38:11.658 INFO: [JOB 5646] flushed 1 memtable (316B) to L0 [019707 019708 019709 019710 019711 019712 019713 019714 019715 019716 019717 019718 019719 019720 019721 019722 019723 019724 019725 019726 019727 019728 019729 019730 019731 019732 019733 019734 019735 019736 019737 019738 019739 019740 019741 019742 019743 019744 019745 019746 019747 019748 019749 019750 019751 019752 019753 019754 019755 019756 019757 019758 019759 019760 019761 019762 019763 019764 019765 019766 019767 019768 019769 019770 019771 019772 019773 019774 019775 019776 019777 019778 019779 019780 019781 019782 019783 019784 019785 019786 019787 019788 019789 019790 019791 019792 019793 019794 019795 019796 019797 019798 019799 019800 019801 019802 019803 019804 019805 019806 019807 019808 019809 019811 019812 019813 019814 019815 019816 019818 019819 019820 019821 019822 019823 019824 019825 019826 019827 019828 019829 019830 019831 019832 019833 019834 019835 019836 019838 019839 019841 019842 019844 019845 019846 019847 019848 019849 019850 019851 019852 019853 019854 019855 019856 019857 019858 019859 019860 019861 019862 019863 019864 019865 019866 019867 019868 019869 019870 019871 019872 019873 019874 019875 019876 019877 019878 019879 019880 019881 019882 019883 019884 019885 019886 019887 019888 019889 019890 019891 019892 019893 019894 019895 019896 019897 019898 019899 019900 019901 019902 019903 019904 019905 019906 019907 019908 019909 019910 019911 019912 019913 019914 019915 019916 019917 019918 019919 019920 019921 019922 019923 019924 019925 019926 019927 019928 019929 019930 019931 019932 019933 019934 019935 019936 019937 019938 019939 019940 019941 019942 019943 019945 019946 019948 019949 019950 019951 019952 019953 019954 019955 019956 019957 019958 019959 019960 019961 019962 019963 019964 019965 019966 019967 019968 019969 019970 019971 019972 019973 019974 019975 019976 019977 019978 019979 019980 019982 019983 019985 019986 019987 019988 019989 019990 019991 019992 019993 019994 019995 019996 019997 019998 019999 020000 020001 020002 020003 020004 020005 020006 020007 020008 020009 020010 020011 020012 020013 020014 020015 020016 020017 020018 020019 020020 020021 020022 020023 020024 020025 020026 020027 020028 020029 020030 020031 020032 020033 020034 020035 020036 020037 020038 020039 020040 020041 020042 020043 020044 020045 020046 020047 020048 020049 020050 020051 020052 020053 020054 020055 020056] (316KB), in 40.9s (43.9s total), output rate 7.7KB/s
        // 06:38:11.659 INFO: [JOB 5675] flushing 1 memtable (0B) to L0
        // 06:38:11.659 INFO: [JOB 5646] sstable deleted 010219
        // 06:38:11.662 INFO: [JOB 5673] compacted(default) L2 [019840] (1.1KB) Score=2.43 + L3 [] (0B) Score=2.33 -> L3 [020058] (1.1KB), in 0.0s (3.0s total), output rate 415KB/s
        // 06:38:14.921 INFO: [JOB 5676] compacting(delete-only) L5 [006692] (2.2KB) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:38:14.922 INFO: [JOB 5646] sstable deleted 015991
        // 06:38:14.922 INFO: [JOB 5673] sstable deleted 019840
        // 06:38:14.924 INFO: [JOB 5676] compacted(delete-only) L5 [006692] (2.2KB) Score=0.00 -> L6 [] (0B), in 0.0s (0.0s total), output rate 0B/s
        // 06:38:17.912 INFO: [JOB 5678] compacting(move) L1 [019947] (1.2KB) Score=2.97 + L2 [] (0B) Score=1.71; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:38:17.912 INFO: [JOB 5676] sstable deleted 006692
        // 06:38:17.914 INFO: [JOB 5671] compacted(default) L4 [019658 019478 018807] (4.4KB) Score=2.79 + L5 [018641] (1.8KB) Score=0.41 -> L5 [020057] (1.7KB), in 3.1s (12.3s total), output rate 566B/s
        // 06:38:21.053 INFO: [JOB 5671] sstable deleted 018641
        // 06:38:21.053 INFO: [JOB 5680] compacting(default) L0 [011072 011744 011957 012124 012321 012895 013191 014052 014965 015845 016122 016316 017167 017770 017923 018073 018248 018766 018983 019193 019614 019697 020051] (19KB) Score=507.91 + L1 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:38:21.053 INFO: [JOB 5671] sstable deleted 018807
        // 06:38:21.053 INFO: [JOB 5671] sstable deleted 019478
        // 06:38:21.053 INFO: [JOB 5671] sstable deleted 019658
        // 06:38:24.085 INFO: [JOB 5675] flush error: pebble: empty table
        // 06:38:24.085 INFO: [JOB 5680] compacting: sstable created 020059
        // 06:38:24.087 INFO: [JOB 5678] compacted(move) L1 [019947] (1.2KB) Score=2.97 + L2 [] (0B) Score=1.71 -> L2 [019947] (1.2KB), in 0.0s (6.2s total), output rate 238MB/s
        // 06:38:27.010 INFO: [JOB 5680] compacted(default) L0 [011072 011744 011957 012124 012321 012895 013191 014052 014965 015845 016122 016316 017167 017770 017923 018073 018248 018766 018983 019193 019614 019697 020051] (19KB) Score=507.91 + L1 [] (0B) Score=0.00 -> L1 [020059] (1.1KB), in 5.9s (6.0s total), output rate 197B/s
        
        To reduce:  go test ./internal/metamorphic -tags invariants -run 'TestMeta$' --run-dir /artifacts/meta/240704-060933.5791114646816/random-017 --try-to-reduce -v
        --- FAIL: TestMeta/execution/random-017 (1726.39s)
Help

To reproduce, try: 

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

Same failure on other branches

This test on roachdash | Improve this report!

Jira issue: PEBBLE-37
@jbowens
Copy link
Collaborator

jbowens commented Jul 9, 2024 

=== NAME  TestMeta/execution/random-017
    meta.go:241: 
        ===== SEED =====
        1720073373579003102
        ===== ERR =====
        exit status 2
        ===== OUT =====
        panic: operation took longer than 1m0s: db1.Close()
        
        goroutine 44615 [running]:
        github.com/cockroachdb/pebble/metamorphic.(*Test).runOp.func1()
        	github.com/cockroachdb/pebble/metamorphic/external/com_github_cockroachdb_pebble/metamorphic/test.go:419 +0xac
        created by time.goFunc
        	GOROOT/src/time/sleep.go:177 +0x2d

@jbowens
Copy link
Collaborator

jbowens commented Jul 9, 2024 

        // 06:38:11.658 INFO: [JOB 5646] flushed 1 memtable (316B) to L0 [019707 019708 019709 019710 019711 019712 019713 019714 019715 019716 019717 019718 019719 019720 019721 019722 019723 019724 019725 019726 019727 019728 019729 019730 019731 019732 019733 019734 019735 019736 019737 019738 019739 019740 019741 019742 019743 019744 019745 019746 019747 019748 019749 019750 019751 019752 019753 019754 019755 019756 019757 019758 019759 019760 019761 019762 019763 019764 019765 019766 019767 019768 019769 019770 019771 019772 019773 019774 019775 019776 019777 019778 019779 019780 019781 019782 019783 019784 019785 019786 019787 019788 019789 019790 019791 019792 019793 019794 019795 019796 019797 019798 019799 019800 019801 019802 019803 019804 019805 019806 019807 019808 019809 019811 019812 019813 019814 019815 019816 019818 019819 019820 019821 019822 019823 019824 019825 019826 019827 019828 019829 019830 019831 019832 019833 019834 019835 019836 019838 019839 019841 019842 019844 019845 019846 019847 019848 019849 019850 019851 019852 019853 019854 019855 019856 019857 019858 019859 019860 019861 019862 019863 019864 019865 019866 019867 019868 019869 019870 019871 019872 019873 019874 019875 019876 019877 019878 019879 019880 019881 019882 019883 019884 019885 019886 019887 019888 019889 019890 019891 019892 019893 019894 019895 019896 019897 019898 019899 019900 019901 019902 019903 019904 019905 019906 019907 019908 019909 019910 019911 019912 019913 019914 019915 019916 019917 019918 019919 019920 019921 019922 019923 019924 019925 019926 019927 019928 019929 019930 019931 019932 019933 019934 019935 019936 019937 019938 019939 019940 019941 019942 019943 019945 019946 019948 019949 019950 019951 019952 019953 019954 019955 019956 019957 019958 019959 019960 019961 019962 019963 019964 019965 019966 019967 019968 019969 019970 019971 019972 019973 019974 019975 019976 019977 019978 019979 019980 019982 019983 019985 019986 019987 019988 019989 019990 019991 019992 019993 019994 019995 019996 019997 019998 019999 020000 020001 020002 020003 020004 020005 020006 020007 020008 020009 020010 020011 020012 020013 020014 020015 020016 020017 020018 020019 020020 020021 020022 020023 020024 020025 020026 020027 020028 020029 020030 020031 020032 020033 020034 020035 020036 020037 020038 020039 020040 020041 020042 020043 020044 020045 020046 020047 020048 020049 020050 020051 020052 020053 020054 020055 020056] (316KB), in 40.9s (43.9s total), output rate 7.7KB/s
        // 06:38:11.659 INFO: [JOB 5675] flushing 1 memtable (0B) to L0
        // 06:38:11.659 INFO: [JOB 5646] sstable deleted 010219
        // 06:38:11.662 INFO: [JOB 5673] compacted(default) L2 [019840] (1.1KB) Score=2.43 + L3 [] (0B) Score=2.33 -> L3 [020058] (1.1KB), in 0.0s (3.0s total), output rate 415KB/s
        // 06:38:14.921 INFO: [JOB 5676] compacting(delete-only) L5 [006692] (2.2KB) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:38:14.922 INFO: [JOB 5646] sstable deleted 015991
        // 06:38:14.922 INFO: [JOB 5673] sstable deleted 019840
        // 06:38:14.924 INFO: [JOB 5676] compacted(delete-only) L5 [006692] (2.2KB) Score=0.00 -> L6 [] (0B), in 0.0s (0.0s total), output rate 0B/s
        // 06:38:17.912 INFO: [JOB 5678] compacting(move) L1 [019947] (1.2KB) Score=2.97 + L2 [] (0B) Score=1.71; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:38:17.912 INFO: [JOB 5676] sstable deleted 006692
        // 06:38:17.914 INFO: [JOB 5671] compacted(default) L4 [019658 019478 018807] (4.4KB) Score=2.79 + L5 [018641] (1.8KB) Score=0.41 -> L5 [020057] (1.7KB), in 3.1s (12.3s total), output rate 566B/s
        // 06:38:21.053 INFO: [JOB 5671] sstable deleted 018641
        // 06:38:21.053 INFO: [JOB 5680] compacting(default) L0 [011072 011744 011957 012124 012321 012895 013191 014052 014965 015845 016122 016316 017167 017770 017923 018073 018248 018766 018983 019193 019614 019697 020051] (19KB) Score=507.91 + L1 [] (0B) Score=0.00; OverlappingRatio: Single 0.00, Multi 0.00
        // 06:38:21.053 INFO: [JOB 5671] sstable deleted 018807
        // 06:38:21.053 INFO: [JOB 5671] sstable deleted 019478
        // 06:38:21.053 INFO: [JOB 5671] sstable deleted 019658
        // 06:38:24.085 INFO: [JOB 5675] flush error: pebble: empty table
        // 06:38:24.085 INFO: [JOB 5680] compacting: sstable created 020059
        // 06:38:24.087 INFO: [JOB 5678] compacted(move) L1 [019947] (1.2KB) Score=2.97 + L2 [] (0B) Score=1.71 -> L2 [019947] (1.2KB), in 0.0s (6.2s total), output rate 238MB/s
        // 06:38:27.010 INFO: [JOB 5680] compacted(default) L0 [011072 011744 011957 012124 012321 012895 013191 014052 014965 015845 016122 016316 017167 017770 017923 018073 018248 018766 018983 019193 019614 019697 020051] (19KB) Score=507.91 + L1 [] (0B) Score=0.00 -> L1 [020059] (1.1KB), in 5.9s (6.0s total), output rate 197B/s

jbowens added a commit to jbowens/pebble that referenced this issue Jul 10, 2024
@jbowens
metamorphic: limit aggregate injected I/O latency
4381080 
Limit the amount of I/O latency injected into any individual run of the
metamorphic test to improve worst-case test runtimes.

Informs cockroachdb#3681.
Informs cockroachdb#3733.
@jbowens jbowens mentioned this issue Jul 10, 2024
Merged
jbowens added a commit to jbowens/pebble that referenced this issue Jul 10, 2024
@jbowens
metamorphic: limit aggregate injected I/O latency
1635b06 
Limit the amount of I/O latency injected into any individual run of the
metamorphic test to improve worst-case test runtimes.

Informs cockroachdb#3681.
Informs cockroachdb#3733.
jbowens added a commit that referenced this issue Jul 10, 2024
@jbowens
metamorphic: limit aggregate injected I/O latency
3b1077d 
Limit the amount of I/O latency injected into any individual run of the
metamorphic test to improve worst-case test runtimes.

Informs #3681.
Informs #3733.
@jbowens
Copy link
Collaborator

jbowens commented Jul 11, 2024

Closing in hope that #3742 resolves it.

@jbowens jbowens closed this as completed Jul 11, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jbowens jbowens

Labels
A-storage branch-master C-test-failure metamorphic-failure O-robot T-storage
Projects
Storage
Status: Done
Milestone
No milestone
Development

No branches or pull requests
2 participants
@jbowens @cockroach-teamcity