Skip to content

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.

To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information