Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Implement -find-nonatomic-writes filter #9

Merged
merged 7 commits into from
Apr 1, 2019

Conversation

qrilka
Copy link
Collaborator

@qrilka qrilka commented Mar 28, 2019

stack run -- hatrace --find-nonatomic-writes stack test on hatrace itself ended up with

test failure and many nonatomically written files
hatrace-0.1.0.0: Test suite hatrace-test failed
Completed 2 action(s).
Test suite failure for package hatrace-0.1.0.0
    hatrace-test:  exited with: ExitFailure 1
Logs printed to console

The following files were written nonatomically by the program:
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace.dyn_hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace.dyn_o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace.hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace.o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/Main.dyn_hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/Main.dyn_o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/Main.hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/Main.o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/SyscallTables.dyn_hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/SyscallTables.dyn_o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/SyscallTables.hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/SyscallTables.o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/SyscallTables/Generated.dyn_hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/SyscallTables/Generated.dyn_o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/SyscallTables/Generated.hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/SyscallTables/Generated.o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/SyscallTables/Util.dyn_hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/SyscallTables/Util.dyn_o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/SyscallTables/Util.hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/System/Hatrace/SyscallTables/Util.o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/hatrace-test/hatrace-test-tmp/HatraceSpec.hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/hatrace-test/hatrace-test-tmp/HatraceSpec.o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/hatrace-test/hatrace-test-tmp/Main.hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/hatrace-test/hatrace-test-tmp/Main.o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/hatrace-test/hatrace-test-tmp/test/HatraceSpec.dump-hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/hatrace-test/hatrace-test-tmp/test/Spec.dump-hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/hatrace/hatrace-tmp/Main.hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/hatrace/hatrace-tmp/Main.o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/hatrace/hatrace-tmp/app/Main.dump-hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/objs-29366/ar29366-2.rsp"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/src/System/Hatrace.dump-hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/src/System/Hatrace/Main.dump-hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/src/System/Hatrace/SyscallTables.dump-hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/src/System/Hatrace/SyscallTables/Generated.dump-hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/build/src/System/Hatrace/SyscallTables/Util.dump-hi"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/stack-build-caches/exe-hatrace"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/stack-build-caches/lib"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/stack-build-caches/test-hatrace-test"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/stack-cabal-mod"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/stack-config-cache"
 - "/home/qrilka/ws/h/hatrace/.stack-work/dist/x86_64-linux-tinfo6/Cabal-2.4.0.1/stack-test-success"
 - "/home/qrilka/ws/h/hatrace/.stack-work/install/x86_64-linux-tinfo6/lts-13.6/8.6.3/flag-cache/hatrace-0.1.0.0-4Xc0nbwTGqM4mpFStsQs5y"
 - "/home/qrilka/ws/h/hatrace/.stack-work/install/x86_64-linux-tinfo6/lts-13.6/8.6.3/lib/x86_64-linux-ghc-8.6.3/hatrace-0.1.0.0-4Xc0nbwTGqM4mpFStsQs5y/st4CzNEy/Generated.o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/install/x86_64-linux-tinfo6/lts-13.6/8.6.3/lib/x86_64-linux-ghc-8.6.3/hatrace-0.1.0.0-4Xc0nbwTGqM4mpFStsQs5y/st4CzNEy/Hatrace.o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/install/x86_64-linux-tinfo6/lts-13.6/8.6.3/lib/x86_64-linux-ghc-8.6.3/hatrace-0.1.0.0-4Xc0nbwTGqM4mpFStsQs5y/st4CzNEy/Main.o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/install/x86_64-linux-tinfo6/lts-13.6/8.6.3/lib/x86_64-linux-ghc-8.6.3/hatrace-0.1.0.0-4Xc0nbwTGqM4mpFStsQs5y/st4CzNEy/SyscallTables.o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/install/x86_64-linux-tinfo6/lts-13.6/8.6.3/lib/x86_64-linux-ghc-8.6.3/hatrace-0.1.0.0-4Xc0nbwTGqM4mpFStsQs5y/st4CzNEy/Util.o"
 - "/home/qrilka/ws/h/hatrace/.stack-work/install/x86_64-linux-tinfo6/lts-13.6/8.6.3/lib/x86_64-linux-ghc-8.6.3/hatrace-0.1.0.0-4Xc0nbwTGqM4mpFStsQs5y/st4CzNEy/fork-exec-ptrace.o"
 - "/home/qrilka/ws/h/hatrace/example-programs-build/Main.hi"
 - "/home/qrilka/ws/h/hatrace/example-programs-build/Main.o"
 - "/tmp/29304-0.c"
 - "/tmp/29304-1.o"
 - "/tmp/29304-4.c"
 - "/tmp/cc2jQlJ7"
 - "/tmp/cc48PIsb"
 - "/tmp/cc4gt17L.s"
 - "/tmp/cc6TeU9f"
 - "/tmp/ccCJcdSa"
 - "/tmp/ccCSqQzu.o"
 - "/tmp/ccHyCbfl"
 - "/tmp/ccI1l0ew"
 - "/tmp/ccOXjJYb"
 - "/tmp/ccUsWEzQ.s"
 - "/tmp/ccY0JCSc.s"
 - "/tmp/ccp9JTmj"
 - "/tmp/cctzY1tC"
 - "/tmp/ccuEA9Fg"
 - "/tmp/ccz5kOyU.s"
 - "/tmp/ghc29346_0/ghc_1.s"
 - "/tmp/ghc29346_0/ghc_2.rsp"
 - "/tmp/ghc29372_0/ghc_1.hscpp"
 - "/tmp/ghc29372_0/ghc_11.s"
 - "/tmp/ghc29372_0/ghc_14.rsp"
 - "/tmp/ghc29372_0/ghc_16.s"
 - "/tmp/ghc29372_0/ghc_18.s"
 - "/tmp/ghc29372_0/ghc_2.h"
 - "/tmp/ghc29372_0/ghc_21.s"
 - "/tmp/ghc29372_0/ghc_23.s"
 - "/tmp/ghc29372_0/ghc_26.s"
 - "/tmp/ghc29372_0/ghc_28.s"
 - "/tmp/ghc29372_0/ghc_4.s"
 - "/tmp/ghc29372_0/ghc_6.s"
 - "/tmp/ghc29372_0/ghc_9.s"
 - "/tmp/ghc29521_0/ghc_1.rsp"
 - "/tmp/ghc29540_0/ghc_2.s"
 - "/tmp/ghc29555_0/ghc_1.c"
 - "/tmp/ghc29555_0/ghc_2.o"
 - "/tmp/ghc29555_0/ghc_3.rsp"
 - "/tmp/ghc29555_0/ghc_4.s"
 - "/tmp/ghc29555_0/ghc_5.o"
 - "/tmp/ghc29555_0/ghc_6.rsp"
 - "/tmp/ghc29555_0/ghc_7.rsp"
 - "/tmp/ghc29587_0/ghc_1.hspp"
 - "/tmp/ghc29587_0/ghc_3.s"
 - "/tmp/ghc29587_0/ghc_6.s"
 - "/tmp/ghc29612_0/ghc_1.hspp"
 - "/tmp/ghc29612_0/ghc_2.c"
 - "/tmp/ghc29612_0/ghc_3.o"
 - "/tmp/ghc29612_0/ghc_4.rsp"
 - "/tmp/ghc29612_0/ghc_5.s"
 - "/tmp/ghc29612_0/ghc_6.o"
 - "/tmp/ghc29612_0/ghc_7.rsp"
 - "/tmp/ghc29612_0/ghc_8.rsp"
 - "/tmp/ghc29876_0/ghc_10.rsp"
 - "/tmp/ghc29876_0/ghc_2.s"
 - "/tmp/ghc29876_0/ghc_4.c"
 - "/tmp/ghc29876_0/ghc_5.o"
 - "/tmp/ghc29876_0/ghc_6.rsp"
 - "/tmp/ghc29876_0/ghc_7.s"
 - "/tmp/ghc29876_0/ghc_8.o"
 - "/tmp/ghc29876_0/ghc_9.rsp"
The following files could not be properly analyzed:
 - "/tmp/ccCmHopn.ld": expected FileOpen, but FileWrite was seen
 - "/tmp/ccEVe04g.ld": expected FileOpen, but FileWrite was seen
 - "/tmp/ccJVK5fG.ld": expected FileOpen, but FileWrite was seen
 - "/tmp/ccRb8LBd.ld": expected FileOpen, but FileWrite was seen
 - "/tmp/ccut9yzR.ld": expected FileOpen, but FileWrite was seen

This change is Reviewable

@nh2
Copy link
Owner

nh2 commented Mar 28, 2019

This works well for me:

normal ghc

.stack-work/dist/x86_64-linux/Cabal-2.4.0.1/build/hatrace/hatrace --find-nonatomic-writes -- /raid/stack/programs/x86_64-linux/ghc-8.6.3/bin/ghc --make -outputdir example-programs-build/ example-programs/Hello.hs -o example-programs-build/haskell-hello -fforce-recomp
[1 of 1] Compiling Main             ( example-programs/Hello.hs, example-programs-build/Main.o )
Linking example-programs-build/haskell-hello ...
The following files were written nonatomically by the program:
 - "/home/niklas/src/haskell/hatrace/example-programs-build/Main.o"
 - "/tmp/ccDD6Lbq.s"
 - "/tmp/ccdYu5KA"
 - "/tmp/ccrHJwv6"
 - "/tmp/ghc19492_0/ghc_10.rsp"
 - "/tmp/ghc19492_0/ghc_2.s"
 - "/tmp/ghc19492_0/ghc_4.c"
 - "/tmp/ghc19492_0/ghc_5.o"
 - "/tmp/ghc19492_0/ghc_6.rsp"
 - "/tmp/ghc19492_0/ghc_7.s"
 - "/tmp/ghc19492_0/ghc_8.o"
 - "/tmp/ghc19492_0/ghc_9.rsp"
The following files could not be properly analyzed:
 - "/tmp/cc77KPXI.ld": expected FileOpen, but FileWrite was seen
.stack-work/dist/x86_64-linux/Cabal-2.4.0.1/build/hatrace/hatrace

15.78s user 2.16s system 103% cpu 17.293 total

fixed ghc

.stack-work/dist/x86_64-linux/Cabal-2.4.0.1/build/hatrace/hatrace --find-nonatomic-writes -- env GHC_PACKAGE_PATH=/raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/package.conf.d /raid/src/ghc/ghc-atomic-writes/_build/stage1/bin/ghc --make -outputdir example-programs-build/ example-programs/Hello.hs -o example-programs-build/haskell-hello -fforce-recomp
[1 of 1] Compiling Main             ( example-programs/Hello.hs, example-programs-build/Main.o )
Linking example-programs-build/haskell-hello ...
The following files were written nonatomically by the program:
 - "/tmp/cc74ywXq.s"
 - "/tmp/ccColn3F"
 - "/tmp/ccUk7fZl"
 - "/tmp/ghc18846_0/ghc_10.rsp"
 - "/tmp/ghc18846_0/ghc_2.s"
 - "/tmp/ghc18846_0/ghc_4.c"
 - "/tmp/ghc18846_0/ghc_5.o"
 - "/tmp/ghc18846_0/ghc_6.rsp"
 - "/tmp/ghc18846_0/ghc_7.s"
 - "/tmp/ghc18846_0/ghc_8.o"
 - "/tmp/ghc18846_0/ghc_9.rsp"
The following files could not be properly analyzed:
 - "/tmp/ccjrMhQw.ld": expected FileOpen, but FileWrite was seen

1.90s user 0.49s system 115% cpu 2.072 total

Note the difference in the fixed one: It has no - "/home/niklas/src/haskell/hatrace/example-programs-build/Main.o".

@nh2
Copy link
Owner

nh2 commented Mar 28, 2019

Tangential, but very interesting, is that tracing the new GHC is almost 10x faster (2 seconds vs 17 seconds).

Using strace -c on hatrace, we found that there's a big difference in ptrace calls made:

-90.73    4.769502           1   3552745        28 ptrace
+54.17    0.560906           1    417026        28 ptrace

Because we use ptrace's PTRACE_PEEKDATA with peekBytes, this suggests that for the new GHC hatrace has to peek out much less syscall details for some reason.

By printing counts of bytes peeked, we investigated which syscalls are responsible for the difference. It turns out it's read on the libHSghc-prim-*.a file.

On older GHCs, access patterns look like this:

% strace -s 10 -P /raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a -fy /raid/stack/programs/x86_64-linux/ghc-8.6.3/bin/ghc -fforce-recomp "--make" "-outputdir" "example-programs-build/" "example-programs/Hello.hs" "-o" "example-programs-build/haskell-hello"
...
[pid 28362] open("/raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a", O_RDONLY|O_CLOEXEC) = 17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>
[pid 28362] fstat(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, {st_mode=S_IFREG|0644, st_size=13081744, ...}) = 0
[pid 28362] mmap(NULL, 13081744, PROT_READ, MAP_PRIVATE, 17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 0) = 0x7f8fb1119000
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1256324, SEEK_SET) = 1256324
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\177ELF\2\1\1\0\0\0"..., 16) = 16
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1256324, SEEK_SET) = 1256324
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\177ELF\2\1\1\0\0\0"..., 64) = 64
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1264324, SEEK_SET) = 1264324
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\33\0\0\0\1\0\0\0\6\0"..., 3712) = 3712
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1263108, SEEK_SET) = 1263108
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\0.symtab\0."..., 1149) = 1149
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1264324, SEEK_SET) = 1264324
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\33\0\0\0\1\0\0\0\6\0"..., 3712) = 3712
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1263108, SEEK_SET) = 1263108
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\0.symtab\0."..., 1149) = 1149
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1268096, SEEK_SET) = 1268096
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\177ELF\2\1\1\0\0\0"..., 16) = 16
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1268096, SEEK_SET) = 1268096
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\177ELF\2\1\1\0\0\0"..., 64) = 64
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 4892936, SEEK_SET) = 4892936
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\33\0\0\0\1\0\0\0\6\0"..., 1249792) = 1249792
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 3748408, SEEK_SET) = 3748408
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\0.symtab\0."..., 1144457) = 1144457
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 4892936, SEEK_SET) = 4892936
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\33\0\0\0\1\0\0\0\6\0"..., 1249792) = 1249792
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 3748408, SEEK_SET) = 3748408
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\0.symtab\0."..., 1144457) = 1144457
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 6484916, SEEK_SET) = 6484916
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\177ELF\2\1\1\0\0\0"..., 16) = 16
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 6484916, SEEK_SET) = 6484916
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\177ELF\2\1\1\0\0\0"..., 64) = 64
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 7400548, SEEK_SET) = 7400548
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\33\0\0\0\1\0\0\0\6\0"..., 600640) = 600640
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 7207004, SEEK_SET) = 7207004
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\0.symtab\0."..., 193478) = 193478
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 7400548, SEEK_SET) = 7400548
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\33\0\0\0\1\0\0\0\6\0"..., 600640) = 600640
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 7207004, SEEK_SET) = 7207004
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\0.symtab\0."..., 193478) = 193478
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 8001248, SEEK_SET) = 8001248
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\177ELF\2\1\1\0\0\0"..., 16) = 16
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 8001248, SEEK_SET) = 8001248
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\177ELF\2\1\1\0\0\0"..., 64) = 64
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 10843040, SEEK_SET) = 10843040
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\33\0\0\0\1\0\0\0\6\0"..., 2204224) = 2204224
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 10330176, SEEK_SET) = 10330176
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\0.symtab\0."..., 512800) = 512800
[pid 28362] lseek(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 10843040, SEEK_SET) = 10843040
[pid 28362] read(17</raid/stack/programs/x86_64-linux/ghc-8.6.3/lib/ghc-8.6.3/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\33\0\0\0\1\0\0\0\6\0"..., 2204224) = 2204224

and for the new one:

% strace -s 10 -fy env GHC_PACKAGE_PATH=/raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/package.conf.d /raid/src/ghc/ghc-atomic-writes/_build/stage1/bin/ghc --make -outputdir example-programs-build/ example-programs/Hello.hs -o example-programs-build/haskell-hello -fforce-recomp 2>&1 | grep libHSghc-prim
[pid 26355] open("/raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/../lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a", O_RDONLY|O_CLOEXEC) = 17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>
[pid 26355] fstat(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, {st_mode=S_IFREG|0644, st_size=6041694, ...}) = 0
[pid 26355] mmap(NULL, 6041694, PROT_READ, MAP_PRIVATE, 17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 0) = 0x7f6f249dc000
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1011970, SEEK_SET) = 1011970
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\177ELF\2\1\1\0\0\0"..., 16) = 16
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1011970, SEEK_SET) = 1011970
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\177ELF\2\1\1\0\0\0"..., 64) = 64
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1017370, SEEK_SET) = 1017370
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\33\0\0\0\1\0\0\0\6\0"..., 640) = 640
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1017218, SEEK_SET) = 1017218
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\0.symtab\0."..., 84) = 84
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1017370, SEEK_SET) = 1017370
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\33\0\0\0\1\0\0\0\6\0"..., 640) = 640
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1017218, SEEK_SET) = 1017218
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\0.symtab\0."..., 84) = 84
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1029322, SEEK_SET) = 1029322
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\177ELF\2\1\1\0\0\0"..., 16) = 16
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1029322, SEEK_SET) = 1029322
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\177ELF\2\1\1\0\0\0"..., 64) = 64
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1031706, SEEK_SET) = 1031706
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, " \0\0\0\1\0\0\0\6\0"..., 768) = 768
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1031538, SEEK_SET) = 1031538
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\0.symtab\0."..., 97) = 97
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1031706, SEEK_SET) = 1031706
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, " \0\0\0\1\0\0\0\6\0"..., 768) = 768
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1031538, SEEK_SET) = 1031538
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\0.symtab\0."..., 97) = 97
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1032534, SEEK_SET) = 1032534
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\177ELF\2\1\1\0\0\0"..., 16) = 16
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1032534, SEEK_SET) = 1032534
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\177ELF\2\1\1\0\0\0"..., 64) = 64
[pid 26355] lseek(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, 1033310, SEEK_SET) = 1033310
[pid 26355] read(17</raid/src/ghc/ghc-atomic-writes/_build/stage1/lib/x86_64-linux-ghc-8.7.20190217/ghc-prim-0.5.3/libHSghc-prim-0.5.3.a>, "\33\0\0\0\1\0\0\0\6\0"..., 640) = 640

Note how the old GHC reads from libHSghc-prim-0.5.3.a big chunks of up to 2204224 many bytes, while the new one reads e.g. 640 bytes.

This suggests that the new one is somehow much smarter at getting the relevant data out.

We also checked which exact program it is that does the reading; that's ld.gold in both cases. That sort-of suggests that it's the contents of the .a file that facilitate less reading of the data.

What could create this difference?

One thing I know is that my new-GHC build may be a quickest build from a GHC tree. Perhaps there's also split-sections in effect in one of them, or something similar?

It seems worth investigating this to know what change/difference makes for this big difference in IO and thus compiler build performance.

CC @bgamari

Edit: I filed GHC issue https://gitlab.haskell.org/ghc/ghc/issues/16515 for this.

Copy link
Owner

@nh2 nh2 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed 4 of 4 files at r1.
Reviewable status: all files reviewed, 9 unresolved discussions (waiting on @qrilka)


src/System/Hatrace.hs, line 980 at r1 (raw file):

  | FileWrite
  | FileClose
  | FileRename ByteString

Haddock if it's the old or new name


src/System/Hatrace.hs, line 988 at r1 (raw file):

-- * only calls to `write` are currently used as a marker for writes and syscalls
--   `pwrite`, `writev`, `pwritev` are not taken into account
fileWritesConduit :: (MonadIO m) => ConduitT (CPid, TraceEvent) (FilePath, FileWriteEvent) m ()

Add nice explanation


src/System/Hatrace.hs, line 1019 at r1 (raw file):

              yieldFdEvent pid fd FileClose
            DetailedSyscallEnter_rename SyscallEnterDetails_rename { oldpathBS, newpathBS } -> do
              path <- liftIO $ resolveToPidCwd pid (T.unpack $ T.decodeUtf8 oldpathBS)

decodeUtf8 is partial and doens't have HasCallStack yet; add wrapper


src/System/Hatrace.hs, line 1032 at r1 (raw file):

      yield (path, event)
    o_WRONLY = 0o00000001
    o_RDWR   = 0o00000002

Link some source


src/System/Hatrace.hs, line 1067 at r1 (raw file):

    checkWrites' (FileWrite:es) = checkWrites' es
    checkWrites' (FileClose:es) = checkRename es
    checkWrites' (e: _) = unexpected "FileClose or FileWrite" e

case for better readability? Nicer tnames to reflect semantics?


src/System/Hatrace.hs, line 1068 at r1 (raw file):

    checkWrites' (FileClose:es) = checkRename es
    checkWrites' (e: _) = unexpected "FileClose or FileWrite" e
    checkRename (FileRename path:es) =

Explain this; perhaps :for readability


src/System/Hatrace.hs, line 1088 at r1 (raw file):

  extract <$> (fileWritesConduit .| foldlC collectWrite mempty)
  where
    collectWrite m (fp, e) = Map.alter (Just . maybe [e] (e:)) fp m

I recommend some types on the helper functions


src/System/Hatrace.hs, line 1093 at r1 (raw file):

            partitionEithers . map (analyzeWrites' . second reverse) $ Map.toList m
      in Map.fromList noRenames <> Map.fromList (map (second AtomicWrite) renames)
    analyzeWrites' (src, es) = case analyzeWrites es of

Explain a bit


src/System/Hatrace.hs, line 1094 at r1 (raw file):

      in Map.fromList noRenames <> Map.fromList (map (second AtomicWrite) renames)
    analyzeWrites' (src, es) = case analyzeWrites es of
      AtomicWrite target -> Right (target, src)

Terminology rename() further up, then here AtomicWrite, and then renames again -- warrants comment

Copy link
Owner

@nh2 nh2 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewable status: all files reviewed, 7 unresolved discussions (waiting on @qrilka)


src/System/Hatrace.hs, line 980 at r1 (raw file):

Previously, nh2 (Niklas Hambüchen) wrote…

Haddock if it's the old or new name

Done


src/System/Hatrace.hs, line 1019 at r1 (raw file):

Previously, nh2 (Niklas Hambüchen) wrote…

decodeUtf8 is partial and doens't have HasCallStack yet; add wrapper

Done

@nh2
Copy link
Owner

nh2 commented Mar 28, 2019

Here's the output of the new tool on stack build on call-haskell-from-anything commit 550c25cbe67ba378c7bebf4df3a970ef5bfe7702:

Click to expand outputs
% /home/niklas/src/haskell/hatrace/.stack-work/dist/x86_64-linux/Cabal-2.4.0.1/build/hatrace/hatrace --find-nonatomic-writes stack build
Building all executables for `call-haskell-from-anything' once. After a successful build of all of them, only specified executables will be rebuilt.
call-haskell-from-anything-1.1.0.0: configure (lib + exe)
[1 of 2] Compiling Main             ( /home/niklas/src/haskell/call-haskell-from-anything/Setup.hs, /home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/setup/Main.o )
[2 of 2] Compiling StackSetupShim   ( /raid/stack/setup-exe-src/setup-shim-mPHDZzAJ.hs, /home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/setup/StackSetupShim.o )
Linking /home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/setup/setup ...
Configuring call-haskell-from-anything-1.1.0.0...
Determining GHC version: 8.0.2
call-haskell-from-anything-1.1.0.0: build (lib + exe)
Preprocessing library call-haskell-from-anything-1.1.0.0...
[1 of 4] Compiling FFI.Anything.TypeUncurry.DataKinds ( src/FFI/Anything/TypeUncurry/DataKinds.hs, .stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry/DataKinds.o )
[2 of 4] Compiling FFI.Anything.TypeUncurry ( src/FFI/Anything/TypeUncurry.hs, .stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry.o )
[3 of 4] Compiling FFI.Anything.TypeUncurry.Msgpack ( src/FFI/Anything/TypeUncurry/Msgpack.hs, .stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry/Msgpack.o )
[4 of 4] Compiling FFI.Anything.TH  ( src/FFI/Anything/TH.hs, .stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TH.o )
Preprocessing executable 'call-haskell-from-anything.so' for
call-haskell-from-anything-1.1.0.0...
[1 of 1] Compiling Test1            ( test/Test1.hs, .stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/call-haskell-from-anything.so/call-haskell-from-anything.so-tmp/Test1.o )
Linking a.out ...
Linking .stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/call-haskell-from-anything.so/call-haskell-from-anything.so ...
call-haskell-from-anything-1.1.0.0: copy/register
Installing library in
/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/install/x86_64-linux/lts-8.22/8.0.2/lib/x86_64-linux-ghc-8.0.2/call-haskell-from-anything-1.1.0.0-6Xcajdv7jFLAvwMt571tKe
Installing executable(s) in
/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/install/x86_64-linux/lts-8.22/8.0.2/bin
Registering call-haskell-from-anything-1.1.0.0...
The following files were written nonatomically by the program:
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TH.dyn_hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TH.dyn_o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TH.hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TH.o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry.dyn_hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry.dyn_o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry.hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry.o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry/DataKinds.dyn_hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry/DataKinds.dyn_o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry/DataKinds.hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry/DataKinds.o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry/Msgpack.dyn_hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry/Msgpack.dyn_o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry/Msgpack.hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/FFI/Anything/TypeUncurry/Msgpack.o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/call-haskell-from-anything.so/call-haskell-from-anything.so"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/call-haskell-from-anything.so/call-haskell-from-anything.so-tmp/Test1.hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/call-haskell-from-anything.so/call-haskell-from-anything.so-tmp/Test1.o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/call-haskell-from-anything.so/call-haskell-from-anything.so-tmp/Test1_stub.h"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/call-haskell-from-anything.so/call-haskell-from-anything.so-tmp/test/Test1.dump-hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/libHScall-haskell-from-anything-1.1.0.0-6Xcajdv7jFLAvwMt571tKe-ghc8.0.2.so"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/src/FFI/Anything/TH.dump-hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/src/FFI/Anything/TypeUncurry.dump-hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/src/FFI/Anything/TypeUncurry/DataKinds.dump-hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/build/src/FFI/Anything/TypeUncurry/Msgpack.dump-hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/package.conf.inplace/package.cache"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/setup/Main.hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/setup/Main.o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/setup/StackSetupShim.hi"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/setup/StackSetupShim.o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/setup/setup"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/stack-build-caches/exe-call-haskell-from-anything.so"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/stack-build-caches/lib"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/stack-cabal-mod"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/dist/x86_64-linux/Cabal-1.24.2.0/stack-config-cache"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/install/x86_64-linux/lts-8.22/8.0.2/flag-cache/call-haskell-from-anything-1.1.0.0-6Xcajdv7jFLAvwMt571tKe"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/install/x86_64-linux/lts-8.22/8.0.2/lib/x86_64-linux-ghc-8.0.2/call-haskell-from-anything-1.1.0.0-6Xcajdv7jFLAvwMt571tKe/st4joiWL/DataKinds.o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/install/x86_64-linux/lts-8.22/8.0.2/lib/x86_64-linux-ghc-8.0.2/call-haskell-from-anything-1.1.0.0-6Xcajdv7jFLAvwMt571tKe/st4joiWL/Msgpack.o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/install/x86_64-linux/lts-8.22/8.0.2/lib/x86_64-linux-ghc-8.0.2/call-haskell-from-anything-1.1.0.0-6Xcajdv7jFLAvwMt571tKe/st4joiWL/TH.o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/install/x86_64-linux/lts-8.22/8.0.2/lib/x86_64-linux-ghc-8.0.2/call-haskell-from-anything-1.1.0.0-6Xcajdv7jFLAvwMt571tKe/st4joiWL/TypeUncurry.o"
 - "/home/niklas/src/haskell/call-haskell-from-anything/.stack-work/install/x86_64-linux/lts-8.22/8.0.2/pkgdb/package.cache"
 - "/home/niklas/src/haskell/call-haskell-from-anything/a.out"
 - "/home/niklas/src/haskell/call-haskell-from-anything/call-haskell-from-anything.buildinfo"
 - "/tmp/10252023621350490027"
 - "/tmp/16816927771714636915.o"
 - "/tmp/1804289383846930886.c"
 - "/tmp/1957747793424238335.o"
 - "/tmp/5965166491189641421.c"
 - "/tmp/ccAylIpP"
 - "/tmp/ccCY96jk"
 - "/tmp/ccHj3dnb.s"
 - "/tmp/ccd93KBV"
 - "/tmp/ccf1quqZ"
 - "/tmp/ccgaI90t"
 - "/tmp/ccjmVnuI.s"
 - "/tmp/cclhll5P"
 - "/tmp/ccmcZMOJ"
 - "/tmp/ccnhhLEM.o"
 - "/tmp/ccqsX9eQ"
 - "/tmp/ccuWx69Q"
 - "/tmp/ccybQLYF"
 - "/tmp/ghc5688_0/ghc_10.s"
 - "/tmp/ghc5688_0/ghc_11.o"
 - "/tmp/ghc5688_0/ghc_12.rsp"
 - "/tmp/ghc5688_0/ghc_13.rsp"
 - "/tmp/ghc5688_0/ghc_2.s"
 - "/tmp/ghc5688_0/ghc_5.s"
 - "/tmp/ghc5688_0/ghc_7.c"
 - "/tmp/ghc5688_0/ghc_8.o"
 - "/tmp/ghc5688_0/ghc_9.rsp"
 - "/tmp/ghc7921_0/ghc_1.s"
 - "/tmp/ghc7921_0/ghc_2.rsp"
 - "/tmp/ghc7954_0/ghc_12.s"
 - "/tmp/ghc7954_0/ghc_14.s"
 - "/tmp/ghc7954_0/ghc_17.s"
 - "/tmp/ghc7954_0/ghc_19.s"
 - "/tmp/ghc7954_0/ghc_2.s"
 - "/tmp/ghc7954_0/ghc_4.s"
 - "/tmp/ghc7954_0/ghc_7.s"
 - "/tmp/ghc7954_0/ghc_9.s"
 - "/tmp/ghc8022_0/ghc_1.rsp"
 - "/tmp/ghc8039_0/ghc_10.rsp"
 - "/tmp/ghc8039_0/ghc_2.s"
 - "/tmp/ghc8039_0/ghc_3.c"
 - "/tmp/ghc8039_0/ghc_4.s"
 - "/tmp/ghc8039_0/ghc_5.rsp"
 - "/tmp/ghc8039_0/ghc_6.o"
 - "/tmp/ghc8039_0/ghc_7.o"
 - "/tmp/ghc8039_0/ghc_8.ldscript"
 - "/tmp/ghc8039_0/ghc_9.rsp"
 - "/tmp/ghc8074_0/ghc_1.rsp"
The following files could not be properly analyzed:
 - "/tmp/cc4MsHQn.ld": expected FileOpen, but FileWrite was seen
 - "/tmp/ccDr4NXd.ld": expected FileOpen, but FileWrite was seen
 - "/tmp/ccbIHlct.ld": expected FileOpen, but FileWrite was seen
 - "/tmp/ccc4oMnp.ld": expected FileOpen, but FileWrite was seen
 --find-nonatomic-writes stack build  206.65s user 54.10s system 107% cpu 4:01.95 total

To be analysed in and after commercialhaskell/stack#4559 (comment).

Using this filtering on other syscalls requires tracking file
open modes which complicate the code
@qrilka qrilka force-pushed the nonatomic-writes-filter branch from 88f7ca1 to d76f533 Compare March 28, 2019 15:33
Copy link
Collaborator Author

@qrilka qrilka left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewable status: 0 of 5 files reviewed, 6 unresolved discussions (waiting on @nh2)


src/System/Hatrace.hs, line 988 at r1 (raw file):

Previously, nh2 (Niklas Hambüchen) wrote…

Add nice explanation

Done.


src/System/Hatrace.hs, line 1032 at r1 (raw file):

Previously, nh2 (Niklas Hambüchen) wrote…

Link some source

removed in the end


src/System/Hatrace.hs, line 1068 at r1 (raw file):

Previously, nh2 (Niklas Hambüchen) wrote…

Explain this; perhaps :for readability

Done.


src/System/Hatrace.hs, line 1088 at r1 (raw file):

Previously, nh2 (Niklas Hambüchen) wrote…

I recommend some types on the helper functions

Done.


src/System/Hatrace.hs, line 1093 at r1 (raw file):

Previously, nh2 (Niklas Hambüchen) wrote…

Explain a bit

Done.


src/System/Hatrace.hs, line 1094 at r1 (raw file):

Previously, nh2 (Niklas Hambüchen) wrote…

Terminology rename() further up, then here AtomicWrite, and then renames again -- warrants comment

Done.

Copy link
Collaborator Author

@qrilka qrilka left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewable status: 0 of 5 files reviewed, 6 unresolved discussions (waiting on @nh2)


src/System/Hatrace.hs, line 1032 at r1 (raw file):

Previously, qrilka (Kirill Zaborsky) wrote…

removed in the end

Done.

Copy link
Owner

@nh2 nh2 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

:lgtm:

Reviewed 1 of 5 files at r2, 3 of 4 files at r3, 1 of 1 files at r5.
Reviewable status: all files reviewed, 2 unresolved discussions (waiting on @qrilka)


src/System/Hatrace.hs, line 1007 at r5 (raw file):

  deriving (Eq, Ord, Show)

-- | Uses raw trace events to produces more focused events aimed at analysing file writes.

typo produce


src/System/Hatrace.hs, line 1095 at r5 (raw file):

        unexpected : _ -> unexpectedEvent "FileClose or FileWrite" unexpected
    -- when it happens that a path gets more than 1 sequence open-write-close
    -- for it we need to check whethere there was a `rename` after the 1st one

typo whether

@qrilka qrilka force-pushed the nonatomic-writes-filter branch from d76f533 to 73c4f0d Compare March 29, 2019 19:24
Copy link
Owner

@nh2 nh2 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed 1 of 1 files at r6.
Reviewable status: :shipit: complete! all files reviewed, all discussions resolved

@nh2 nh2 merged commit 7bca32d into nh2:master Apr 1, 2019
@qrilka qrilka deleted the nonatomic-writes-filter branch April 1, 2019 14:08
@nh2
Copy link
Owner

nh2 commented Apr 1, 2019

I filed GHC issue https://gitlab.haskell.org/ghc/ghc/issues/16515 for the investigation of GHC linker performance.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants