Profiling GHC Programs

Profiling a lazy language is not quite profiling a strict one: the work attributed to a function may have been caused by a thunk something else built, and the number you most often need is allocation rather than time. This is the toolchain, in the order you should actually reach for it.

GHC's cost-centre profiler comes out of work by Sansom and Peyton Jones in the early 1990s on how to attribute cost in a non-strict language at all. Their answer was the cost centre: a lexical marker in the source that the runtime charges time and allocation to, so the numbers refer to places in your program rather than to whatever the evaluator happened to be doing. That model is still the basis of -p today. The later additions are the eventlog and ThreadScope for concurrency, and, from GHC 9.2, info-table profiling, which maps heap objects back to source locations without a profiling build at all.

Before building anything special, ask the runtime what it did. This costs nothing and frequently ends the investigation.

ghc-options: -rtsopts

$ cabal run myprog -- +RTS -s

   9,241,776,184 bytes allocated in the heap
     412,336,912 bytes copied during GC
      78,443,008 bytes maximum residency (14 sample(s))
 
  Gen  0      8823 colls,  0 par    1.204s   1.210s
  Gen  1        14 colls,  0 par    0.831s   0.833s
 
  INIT    time    0.001s
  MUT     time    2.140s
  GC      time    2.043s
  Total   time    4.184s
 
  %GC     time      48.8%
  Productivity  51.2% of total user

Three numbers decide what to do next. Productivity below roughly 80% means the garbage collector is your problem, not your code. Maximum residency that climbs with input size when it should not is a space leak. Total bytes allocated is the best single proxy for time in a GHC program, and the one to watch across changes.

$ cabal run myprog -- +RTS -s -A64m

Cost-centre profiling needs the whole dependency tree rebuilt with profiling libraries. The first build is slow; they are cached afterwards.

$ cabal build --enable-profiling

-fprof-auto            every binding, including local ones
-fprof-auto-top        top-level bindings only
-fprof-auto-exported   exported bindings only
-fprof-late            after optimization; least distortion

ghc-options: -rtsopts
 
if flag(profiling)
  ghc-options: -fprof-late

parseAll :: [ByteString] -> [Record]
parseAll xs = {-# SCC "parseAll" #-} map parse xs

The caveat that matters: -fprof-auto places cost centres where they can block inlining, so the profiled binary may have a different performance shape from the one you ship. When a profile disagrees with -s, trust -s and re-profile with -fprof-late or a handful of manual SCC annotations.

$ cabal run --enable-profiling myprog -- +RTS -p

COST CENTRE   MODULE     %time %alloc
 
parse         Parser      41.2   38.7
normalize     Record      22.8   31.1
lookupKey     Index       18.4    2.2
main          Main         6.1    9.0

                                   individual     inherited
COST CENTRE      entries        %time %alloc  %time %alloc
 
MAIN                   0          0.0    0.0  100.0  100.0
 main                  1          6.1    9.0  100.0  100.0
  parseAll             1          0.2    0.1   64.0   69.8
   parse         1048576         41.2   38.7   63.8   69.7
    normalize     1048576         22.6   31.0   22.6   31.0

$ grep -n "entries" myprog.prof | head

$ cabal install ghc-prof-flamegraph
$ ghc-prof-flamegraph myprog.prof
writes myprog.svg

$ cabal run --enable-profiling myprog -- +RTS -pj

A time profile says where cycles went. A heap profile says what is on the heap and why it is still there, which is what you need for a leak. Start with -hT, because it needs no profiling build.

$ cabal run myprog -- +RTS -hT -i0.1

-hT   by closure type            no -prof needed
-hc   by cost centre stack       needs -prof
-hd   by closure description     needs -prof
-hy   by type                    needs -prof
-hr   by retainer                needs -prof; who is holding it
-hb   by biography               lag / drag / void / use

$ hp2ps -c -e8in myprog.hp
$ ps2pdf myprog.ps

$ cabal install eventlog2html
$ cabal run myprog -- +RTS -hT -l-agu
$ eventlog2html myprog.eventlog
writes myprog.eventlog.html

$ cabal run myprog -- +RTS -hc -hcparse,normalize

A band that grows linearly and never falls is a leak. A large THUNK or _thunk band under -hT means unevaluated work is accumulating, which is the common case and usually fixed by a strict fold, a bang pattern, or StrictData on the offending record. -hr is what you run when you know what is leaking but not who is keeping it alive.

From GHC 9.2, the compiler can emit a map from info tables to source locations. That makes it possible to attribute heap objects to the line that allocated them without a profiling build, which is the single biggest practical improvement to this workflow in years, and it is the way to profile something you cannot easily rebuild the world for.

ghc-options: -finfo-table-map -fdistinct-constructor-tables

$ cabal run myprog -- +RTS -hi -l-agu
$ eventlog2html myprog.eventlog

Record.hs:42:17  normalize        31.4 MiB
Parser.hs:88:9   parse.go         18.2 MiB

The cost is binary size, since the map is embedded. It is worth keeping enabled in a staging build so a production-shaped binary can be profiled on demand.

ghc-options: -threaded -rtsopts -eventlog

$ cabal run myprog -- +RTS -N4 -l

$ cabal install threadscope
$ threadscope myprog.eventlog

$ cabal run myprog -- +RTS -N4 -s
SPARKS: 1048576 (12043 converted, 0 overflowed, 0 dud,
         982141 GC'd, 54392 fizzled)

$ cabal run --enable-profiling myprog -- +RTS -xc

$ cabal install ghc-debug-brick
$ ghc-debug-brick

The loop, in order: +RTS -s first, and stop there if productivity is fine and residency is flat. If time is the problem, -fprof-late and -p, reading entries as carefully as %time. If memory is the problem, -hT to see what, -hi to see where, and -hr to see who is holding it.