Unexpected IPE information being generated
Summary
It seems unexpected info table provenance map entries (IPEs) are being created, causing IPE enabled GHCs to fail some tests. My IPE data compression MR introduces a CI job which tests IPE enabled GHCs for issues with the IPE label. I first observed the failures in a CI job for that branch, and then I discovered the failures could be reproduced on master
.
Steps to reproduce
Build a GHC on master
with the +ipe
flavour transformer (the tests do not fail without it) and run the RTS test suite:
hadrian/build -j --flavour=devel2+ipe test --test-root-dirs="testsuite/tests/rts"
Results in unexpected failures (ignore the unexpected passes, I believe they are specific to my machine):
Beginning test run at Wed Mar 8 07:41:26 2023
...
=====> 20 of 196 [0, 0, 0]
=====> 30 of 196 [0, 0, 0]
=====> 40 of 196 [0, 0, 0]
=====> 50 of 196 [0, 0, 0]
*** unexpected pass for T7040_ghci(ghci)
=====> 70 of 196 [1, 0, 0]
=====> 80 of 196 [1, 0, 0]
=====> 80 of 196 [1, 0, 0]
*** fragile test T12903(normal) resulted in pass
=====> 90 of 196 [1, 0, 0]
Actual stdout output differs from expected:
--- "/tmp/ghctest-nfn6zupr/test spaces/testsuite/tests/rts/InitEventLogging.run/InitEventLogging.stdout.normalised" 2023-03-08 07:41:35.694521152 -0700
+++ "/tmp/ghctest-nfn6zupr/test spaces/testsuite/tests/rts/InitEventLogging.run/InitEventLogging.run.stdout.normalised" 2023-03-08 07:41:35.694521152 -0700
@@ -3,4 +3,8 @@
write
write
write
+write
+write
+write
+write
stop
*** unexpected failure for InitEventLogging(normal)
*** unexpected pass for T13676(ghci)
Actual stdout output differs from expected:
--- "/tmp/ghctest-nfn6zupr/test spaces/testsuite/tests/rts/decodeMyStack.run/decodeMyStack.stdout.normalised" 2023-03-08 07:41:38.174589552 -0700
+++ "/tmp/ghctest-nfn6zupr/test spaces/testsuite/tests/rts/decodeMyStack.run/decodeMyStack.run.stdout.normalised" 2023-03-08 07:41:38.174589552 -0700
@@ -1,12 +1,41 @@
+StackEntry {functionName = "", moduleName = "Cmm$rts/StgStartup.cmm", srcLoc = ":", closureType = 36}
+StackEntry {functionName = "", moduleName = "Cmm$rts/Exception.cmm", srcLoc = ":", closureType = 34}
+StackEntry {functionName = "", moduleName = "Cmm$_build/stage1/rts/build/cmm/AutoApply.cmm", srcLoc = ":", closureType = 30}
+StackEntry {functionName = "", moduleName = "Cmm$rts/Updates.cmm", srcLoc = ":", closureType = 33}
+StackEntry {functionName = "", moduleName = "GHC.Base", srcLoc = ":", closureType = 53}
+StackEntry {functionName = "", moduleName = "Cmm$rts/Updates.cmm", srcLoc = ":", closureType = 33}
StackEntry {functionName = "main.(...)", moduleName = "Main", srcLoc = "decodeMyStack.hs:22:27-41", closureType = 53}
StackEntry {functionName = "getDeepStack.getDeepStackCase", moduleName = "Main", srcLoc = "decodeMyStack.hs:18:26-28", closureType = 53}
+StackEntry {functionName = "", moduleName = "Data.Tuple", srcLoc = ":", closureType = 53}
+StackEntry {functionName = "", moduleName = "Cmm$rts/Updates.cmm", srcLoc = ":", closureType = 33}
StackEntry {functionName = "getDeepStack.getDeepStackCase", moduleName = "Main", srcLoc = "decodeMyStack.hs:18:26-28", closureType = 53}
+StackEntry {functionName = "", moduleName = "Data.Tuple", srcLoc = ":", closureType = 53}
+StackEntry {functionName = "", moduleName = "Cmm$rts/Updates.cmm", srcLoc = ":", closureType = 33}
StackEntry {functionName = "getDeepStack.getDeepStackCase", moduleName = "Main", srcLoc = "decodeMyStack.hs:18:26-28", closureType = 53}
+StackEntry {functionName = "", moduleName = "Data.Tuple", srcLoc = ":", closureType = 53}
+StackEntry {functionName = "", moduleName = "Cmm$rts/Updates.cmm", srcLoc = ":", closureType = 33}
StackEntry {functionName = "getDeepStack.getDeepStackCase", moduleName = "Main", srcLoc = "decodeMyStack.hs:18:26-28", closureType = 53}
+StackEntry {functionName = "", moduleName = "Data.Tuple", srcLoc = ":", closureType = 53}
+StackEntry {functionName = "", moduleName = "Cmm$rts/Updates.cmm", srcLoc = ":", closureType = 33}
StackEntry {functionName = "getDeepStack.getDeepStackCase", moduleName = "Main", srcLoc = "decodeMyStack.hs:18:26-28", closureType = 53}
+StackEntry {functionName = "", moduleName = "Data.Tuple", srcLoc = ":", closureType = 53}
+StackEntry {functionName = "", moduleName = "Cmm$rts/Updates.cmm", srcLoc = ":", closureType = 33}
StackEntry {functionName = "getDeepStack.getDeepStackCase", moduleName = "Main", srcLoc = "decodeMyStack.hs:18:26-28", closureType = 53}
+StackEntry {functionName = "", moduleName = "Data.Tuple", srcLoc = ":", closureType = 53}
+StackEntry {functionName = "", moduleName = "Cmm$rts/Updates.cmm", srcLoc = ":", closureType = 33}
StackEntry {functionName = "getDeepStack.getDeepStackCase", moduleName = "Main", srcLoc = "decodeMyStack.hs:18:26-28", closureType = 53}
+StackEntry {functionName = "", moduleName = "Data.Tuple", srcLoc = ":", closureType = 53}
+StackEntry {functionName = "", moduleName = "Cmm$rts/Updates.cmm", srcLoc = ":", closureType = 33}
StackEntry {functionName = "getDeepStack.getDeepStackCase", moduleName = "Main", srcLoc = "decodeMyStack.hs:18:26-28", closureType = 53}
+StackEntry {functionName = "", moduleName = "Data.Tuple", srcLoc = ":", closureType = 53}
+StackEntry {functionName = "", moduleName = "Cmm$rts/Updates.cmm", srcLoc = ":", closureType = 33}
StackEntry {functionName = "getDeepStack.getDeepStackCase", moduleName = "Main", srcLoc = "decodeMyStack.hs:18:26-28", closureType = 53}
+StackEntry {functionName = "", moduleName = "Data.Tuple", srcLoc = ":", closureType = 53}
+StackEntry {functionName = "", moduleName = "Cmm$rts/Updates.cmm", srcLoc = ":", closureType = 33}
StackEntry {functionName = "getDeepStack.getDeepStackCase", moduleName = "Main", srcLoc = "decodeMyStack.hs:18:26-28", closureType = 53}
+StackEntry {functionName = "", moduleName = "Data.Tuple", srcLoc = ":", closureType = 53}
+StackEntry {functionName = "", moduleName = "Cmm$rts/Updates.cmm", srcLoc = ":", closureType = 33}
StackEntry {functionName = "getDeepStack.getDeepStackCase", moduleName = "Main", srcLoc = "decodeMyStack.hs:13:7-21", closureType = 53}
+StackEntry {functionName = "noDuplicate", moduleName = "GHC.IO.Unsafe", srcLoc = "libraries/base/GHC/IO/Unsafe.hs:208:58-59", closureType = 53}
+StackEntry {functionName = "bindIO", moduleName = "GHC.Base", srcLoc = "libraries/base/GHC/Base.hs:1681:1-76", closureType = 53}
+StackEntry {functionName = "$", moduleName = "GHC.Stack.CloneStack", srcLoc = "libraries/base/GHC/Base.hs:1615:1-12", closureType = 53}
*** unexpected failure for decodeMyStack(normal)
Wrong exit code for decodeMyStack_emptyListForMissingFlag(normal)(expected 0 , actual 1 )
Stderr ( decodeMyStack_emptyListForMissingFlag ):
decodeMyStack_emptyListForMissingFlag: assertEqual: [StackEntry {functionName = "", moduleName = "Cmm$rts/StgStartup.cmm", srcLoc = ":", closureType = 36},StackEntry {functionName = "", moduleName = "Cmm$rts/Exception.cmm", srcLoc = ":", closureType = 34},StackEntry {functionName = "thenIO", moduleName = "GHC.Base", srcLoc = "libraries/base/GHC/Base.hs:1684:1-72", closureType = 53},StackEntry {functionName = "", moduleName = "Cmm$_build/stage1/rts/build/cmm/AutoApply.cmm", srcLoc = ":", closureType = 30},StackEntry {functionName = "", moduleName = "Cmm$rts/Updates.cmm", srcLoc = ":", closureType = 33},StackEntry {functionName = "", moduleName = "GHC.Classes", srcLoc = ":", closureType = 53},StackEntry {functionName = "", moduleName = "Cmm$rts/Updates.cmm", srcLoc = ":", closureType = 33},StackEntry {functionName = "noDuplicate", moduleName = "GHC.IO.Unsafe", srcLoc = "libraries/base/GHC/IO/Unsafe.hs:208:58-59", closureType = 53},StackEntry {functionName = "bindIO", moduleName = "GHC.Base", srcLoc = "libraries/base/GHC/Base.hs:1681:1-76", closureType = 53},StackEntry {functionName = "$", moduleName = "GHC.Stack.CloneStack", srcLoc = "libraries/base/GHC/Base.hs:1615:1-12", closureType = 53}] /= []
CallStack (from HasCallStack):
error, called at decodeMyStack_emptyListForMissingFlag.hs:24:10 in main:Main
*** unexpected failure for decodeMyStack_emptyListForMissingFlag(normal)
Wrong exit code for decodeMyStack_underflowFrames(normal)(expected 0 , actual 1 )
Stderr ( decodeMyStack_underflowFrames ):
decodeMyStack_underflowFrames: assertEqual: 3020 /= 1003
CallStack (from HasCallStack):
error, called at decodeMyStack_underflowFrames.hs:25:10 in main:Main
*** unexpected failure for decodeMyStack_underflowFrames(normal)
=====> 130 of 196 [2, 4, 0]
=====> 140 of 196 [2, 4, 0]
*** fragile test T7919(normal) resulted in pass
=====> 160 of 196 [2, 4, 0]
*** fragile test T5435_v_asm_b(normal) resulted in pass
*** fragile test T5435_v_asm_a(normal) resulted in pass
Actual stderr output differs from expected:
*** fragile test T5435_dyn_asm(normal) resulted in pass
*** fragile test T5435_v_gcc(normal) resulted in pass
--- "/tmp/ghctest-nfn6zupr/test spaces/testsuite/tests/rts/ipe/ipeEventLog_fromMap.run/ipeEventLog_fromMap.stderr.normalised" 2023-03-08 07:42:42.616076954 -0700
+++ "/tmp/ghctest-nfn6zupr/test spaces/testsuite/tests/rts/ipe/ipeEventLog_fromMap.run/ipeEventLog_fromMap.run.stderr.normalised" 2023-03-08 07:42:42.632077261 -0700
@@ -1,20 +1,20 @@
-IPE: table_name table_name_009, closure_desc closure_desc_009, ty_desc ty_desc_009, label label_009, module module_009, srcloc src_file_009:src_span_009
-IPE: table_name table_name_008, closure_desc closure_desc_008, ty_desc ty_desc_008, label label_008, module module_008, srcloc src_file_008:src_span_008
-IPE: table_name table_name_007, closure_desc closure_desc_007, ty_desc ty_desc_007, label label_007, module module_007, srcloc src_file_007:src_span_007
-IPE: table_name table_name_006, closure_desc closure_desc_006, ty_desc ty_desc_006, label label_006, module module_006, srcloc src_file_006:src_span_006
-IPE: table_name table_name_005, closure_desc closure_desc_005, ty_desc ty_desc_005, label label_005, module module_005, srcloc src_file_005:src_span_005
-IPE: table_name table_name_004, closure_desc closure_desc_004, ty_desc ty_desc_004, label label_004, module module_004, srcloc src_file_004:src_span_004
-IPE: table_name table_name_003, closure_desc closure_desc_003, ty_desc ty_desc_003, label label_003, module module_003, srcloc src_file_003:src_span_003
-IPE: table_name table_name_002, closure_desc closure_desc_002, ty_desc ty_desc_002, label label_002, module module_002, srcloc src_file_002:src_span_002
-IPE: table_name table_name_001, closure_desc closure_desc_001, ty_desc ty_desc_001, label label_001, module module_001, srcloc src_file_001:src_span_001
IPE: table_name table_name_000, closure_desc closure_desc_000, ty_desc ty_desc_000, label label_000, module module_000, srcloc src_file_000:src_span_000
-IPE: table_name table_name_009, closure_desc closure_desc_009, ty_desc ty_desc_009, label label_009, module module_009, srcloc src_file_009:src_span_009
-IPE: table_name table_name_008, closure_desc closure_desc_008, ty_desc ty_desc_008, label label_008, module module_008, srcloc src_file_008:src_span_008
-IPE: table_name table_name_007, closure_desc closure_desc_007, ty_desc ty_desc_007, label label_007, module module_007, srcloc src_file_007:src_span_007
-IPE: table_name table_name_006, closure_desc closure_desc_006, ty_desc ty_desc_006, label label_006, module module_006, srcloc src_file_006:src_span_006
-IPE: table_name table_name_005, closure_desc closure_desc_005, ty_desc ty_desc_005, label label_005, module module_005, srcloc src_file_005:src_span_005
-IPE: table_name table_name_004, closure_desc closure_desc_004, ty_desc ty_desc_004, label label_004, module module_004, srcloc src_file_004:src_span_004
-IPE: table_name table_name_003, closure_desc closure_desc_003, ty_desc ty_desc_003, label label_003, module module_003, srcloc src_file_003:src_span_003
-IPE: table_name table_name_002, closure_desc closure_desc_002, ty_desc ty_desc_002, label label_002, module module_002, srcloc src_file_002:src_span_002
IPE: table_name table_name_001, closure_desc closure_desc_001, ty_desc ty_desc_001, label label_001, module module_001, srcloc src_file_001:src_span_001
+IPE: table_name table_name_002, closure_desc closure_desc_002, ty_desc ty_desc_002, label label_002, module module_002, srcloc src_file_002:src_span_002
+IPE: table_name table_name_003, closure_desc closure_desc_003, ty_desc ty_desc_003, label label_003, module module_003, srcloc src_file_003:src_span_003
+IPE: table_name table_name_004, closure_desc closure_desc_004, ty_desc ty_desc_004, label label_004, module module_004, srcloc src_file_004:src_span_004
+IPE: table_name table_name_005, closure_desc closure_desc_005, ty_desc ty_desc_005, label label_005, module module_005, srcloc src_file_005:src_span_005
+IPE: table_name table_name_006, closure_desc closure_desc_006, ty_desc ty_desc_006, label label_006, module module_006, srcloc src_file_006:src_span_006
+IPE: table_name table_name_007, closure_desc closure_desc_007, ty_desc ty_desc_007, label label_007, module module_007, srcloc src_file_007:src_span_007
+IPE: table_name table_name_008, closure_desc closure_desc_008, ty_desc ty_desc_008, label label_008, module module_008, srcloc src_file_008:src_span_008
+IPE: table_name table_name_009, closure_desc closure_desc_009, ty_desc ty_desc_009, label label_009, module module_009, srcloc src_file_009:src_span_009
IPE: table_name table_name_000, closure_desc closure_desc_000, ty_desc ty_desc_000, label label_000, module module_000, srcloc src_file_000:src_span_000
+IPE: table_name table_name_001, closure_desc closure_desc_001, ty_desc ty_desc_001, label label_001, module module_001, srcloc src_file_001:src_span_001
+IPE: table_name table_name_002, closure_desc closure_desc_002, ty_desc ty_desc_002, label label_002, module module_002, srcloc src_file_002:src_span_002
+IPE: table_name table_name_003, closure_desc closure_desc_003, ty_desc ty_desc_003, label label_003, module module_003, srcloc src_file_003:src_span_003
+IPE: table_name table_name_004, closure_desc closure_desc_004, ty_desc ty_desc_004, label label_004, module module_004, srcloc src_file_004:src_span_004
+IPE: table_name table_name_005, closure_desc closure_desc_005, ty_desc ty_desc_005, label label_005, module module_005, srcloc src_file_005:src_span_005
+IPE: table_name table_name_006, closure_desc closure_desc_006, ty_desc ty_desc_006, label label_006, module module_006, srcloc src_file_006:src_span_006
+IPE: table_name table_name_007, closure_desc closure_desc_007, ty_desc ty_desc_007, label label_007, module module_007, srcloc src_file_007:src_span_007
+IPE: table_name table_name_008, closure_desc closure_desc_008, ty_desc ty_desc_008, label label_008, module module_008, srcloc src_file_008:src_span_008
+IPE: table_name table_name_009, closure_desc closure_desc_009, ty_desc ty_desc_009, label label_009, module module_009, srcloc src_file_009:src_span_009
*** fragile test T5435_dyn_gcc(normal) resulted in pass
*** unexpected failure for ipeEventLog_fromMap(threaded1)
=====> 180 of 196 [2, 5, 0]
*** unexpected pass for T20494(normal)
=====> 190 of 196 [3, 5, 0]
Performance Metrics (test environment: local):
None collected.
Unexpected results from:
TEST="InitEventLogging T13676 T20494 T7040_ghci decodeMyStack decodeMyStack_emptyListForMissingFlag decodeMyStack_underflowFrames ipeEventLog_fromMap"
SUMMARY for test run started at Wed Mar 8 07:41:26 2023
0:01:25.484536 spent to go through
196 total tests, which gave rise to
1172 test cases, of which
996 were skipped
0 had missing libraries
154 expected passes
7 expected failures
0 caused framework failures
0 caused framework warnings
3 unexpected passes
5 unexpected failures
0 unexpected stat failures
7 fragile tests
Unexpected passes:
/tmp/ghctest-nfn6zupr/test spaces/testsuite/tests/rts/T13676.run T13676 [unexpected] (ghci)
/tmp/ghctest-nfn6zupr/test spaces/testsuite/tests/rts/linker/T20494.run T20494 [unexpected] (normal)
/tmp/ghctest-nfn6zupr/test spaces/testsuite/tests/rts/T7040_ghci.run T7040_ghci [unexpected] (ghci)
Unexpected failures:
/tmp/ghctest-nfn6zupr/test spaces/testsuite/tests/rts/decodeMyStack.run decodeMyStack [bad stdout] (normal)
/tmp/ghctest-nfn6zupr/test spaces/testsuite/tests/rts/decodeMyStack_emptyListForMissingFlag.run decodeMyStack_emptyListForMissingFlag [bad exit code (1)] (normal)
/tmp/ghctest-nfn6zupr/test spaces/testsuite/tests/rts/decodeMyStack_underflowFrames.run decodeMyStack_underflowFrames [bad exit code (1)] (normal)
/tmp/ghctest-nfn6zupr/test spaces/testsuite/tests/rts/InitEventLogging.run InitEventLogging [bad stdout] (normal)
/tmp/ghctest-nfn6zupr/test spaces/testsuite/tests/rts/ipe/ipeEventLog_fromMap.run ipeEventLog_fromMap [bad stderr] (threaded1)
Expected behavior
Tests should pass.
Environment
- GHC version used: Latest
Optional:
- Operating System: Ubuntu
- System Architecture: x86_64