Document limitations of the GHC profiler
The user's guide promises profiling for all programs in https://downloads.haskell.org/~ghc/latest/docs/html/users_guide/profiling.html
However, there seems to be some folklore advising that incorrect results might be obtained if profiling programs which do IO or safe foreign calls. In my experiments these look like:
-- test.hs
main = g
g = getContents >>= print . length
and
-- test2.hs
{-# LANGUAGE CApiFFI #-}
foreign import capi safe "stdio.h getchar" getchar :: IO Int
main = g
g = getchar >>= print
Building these programs with
ghc -threaded -O0 -hide-all-packages -package base -prof -fprof-auto test.hs
ghc -threaded -O0 -hide-all-packages -package base -prof -fprof-auto test2.hs
and running them with
./test +RTS -p
./test2 +RTS -p
produces .prof
files that don't account any time to g
, no matter how long one waits to provide input or terminate the programs (I tried in the range from 2 to 20 seconds).
Mon Jun 20 22:08 2022 Time and Allocation Profiling Report (Final)
tests +RTS -p -RTS
total time = 0.00 secs (0 ticks @ 1000 us, 1 processor)
total alloc = 96,944 bytes (excludes profiling overheads)
COST CENTRE MODULE SRC %time %alloc
MAIN MAIN <built-in> 0.0 25.9
CAF GHC.Event.Thread <entire-module> 0.0 1.3
CAF GHC.IO.Handle.FD <entire-module> 0.0 53.7
CAF GHC.IO.Encoding <entire-module> 0.0 2.7
g Main tests.hs:2:1-34 0.0 14.7
individual inherited
COST CENTRE MODULE SRC no. entries %time %alloc %time %alloc
MAIN MAIN <built-in> 120 0 0.0 25.9 0.0 100.0
CAF Main <entire-module> 239 0 0.0 0.0 0.0 0.2
g Main tests.hs:2:1-34 241 1 0.0 0.2 0.0 0.2
main Main tests.hs:1:1-8 240 1 0.0 0.0 0.0 0.0
CAF GHC.Conc.Signal <entire-module> 231 0 0.0 0.7 0.0 0.7
CAF GHC.IO.Encoding <entire-module> 220 0 0.0 2.7 0.0 2.7
CAF GHC.IO.Encoding.Iconv <entire-module> 218 0 0.0 0.2 0.0 0.2
CAF GHC.IO.Exception <entire-module> 212 0 0.0 0.7 0.0 0.7
CAF GHC.IO.Handle.FD <entire-module> 210 0 0.0 53.7 0.0 53.7
CAF GHC.IO.Handle.Internals <entire-module> 209 0 0.0 0.0 0.0 0.0
CAF GHC.Event.Thread <entire-module> 173 0 0.0 1.3 0.0 1.3
CAF GHC.IO.Handle.Text <entire-module> 148 0 0.0 0.1 0.0 0.1
CAF GHC.Event.Poll <entire-module> 138 0 0.0 0.0 0.0 0.0
g Main tests.hs:2:1-34 242 0 0.0 14.5 0.0 14.5
I tried these with ghc-8.10.7
and ghc-9.2.2
.
Proposed improvements or changes
The documentation should discuss these programs and explain why the profiler can't deal with them. Otherwise, users are misguided into optimizing the wrong parts of their programs.
If people here know of any resources discussing this pitfall, it could be helpful in the meantime.