Profiling Template Haskell splices

Ben Gamari - 2020-05-25

This weekend a user came into #ghc asking how to profile their Template Haskell splices using GHC’s cost-center profiler. While this is not so hard in the simple case where you have no dependencies, doing so with a real package took a surprisingly long time and was non-obvious to even GHC developers. Consequently, I felt this might be helpful to write down the prescription.

In short, the method we arrived at takes advantage of GHC’s external interpreter coupled with cabal-install’s support for producing package environment files. To demonstrate the approach, we will profile the Template Haskell-based lens derivation logic of the optics-th package, using the T799 module as our source of splices.

We first start by setting up a working directory of the project:

$ cabal unpack optics-th
$ cd optics-th-0.3

Now we will build the package with cabal v2-build, taking care to instruct cabal to enable profiling and create a GHC environment file (which will be necessary shortly):

$ cabal v2-build lib:optics-th \
    --enable-profiling --write-ghc-environment-files=always

Finally, we can invoke ghc on the module containing our splices, instructing GHC to evaluate splices using the external interpreter with profiling enabled:

$ ghc -prof -fexternal-interpreter -opti+RTS -opti-p tests/Optics/TH/Tests/T799.hs 

Now we have our profile:

$ cat ghc-iserv-prof.prof 
	Sun May 24 17:20 2020 Time and Allocation Profiling Report  (Final)

	   ghc-iserv-prof +RTS -p -RTS 12 13

	total time  =        0.25 secs   (253 ticks @ 1000 us, 1 processor)
	total alloc =   4,607,184 bytes  (excludes profiling overheads)

COST CENTRE         MODULE                       SRC                                                     %time %alloc

MAIN                MAIN                         <built-in>                                               96.8   82.0
reifyDatatype       Language.Haskell.TH.Datatype src/Language/Haskell/TH/Datatype.hs:353:1-70              1.2    1.9
makeFieldOptics     Optics.TH.Internal.Product   src/Optics/TH/Internal/Product.hs:63:1-101                0.8    7.6
resolveTypeSynonyms Language.Haskell.TH.Datatype src/Language/Haskell/TH/Datatype.hs:(1257,1)-(1303,28)    0.4    5.7

...

Of course, we can also pass any of the usual heap profiling flags to the interpreter by adding additional -opti flags. For instance,

$ ghc -prof -fexternal-interpreter -opti+RTS -opti-p -opti-hy tests/Optics/TH/Tests/T799.hs 

would produce a heap profile by type, in addition to the usual .prof file.

How does it work?

The challenge in profiling Template Haskell is that we must arrange that splices run under a profiling-enabled runtime system. In GHC’s default internal interpreter mode of operation, splices (and, e.g., GHCi evaluations) are evaluated in the same process as the compiler. However, the ghc executable provided in GHC binary distributions is not built with profiling enabled.

For this reason we must instruct GHC to rather run splices in another process via the -fexternal-interpreter flag. This process is provided by the ghc-iserv executable; your GHC binary distribution ships with several variants of this executable, including one with profiling enabled. The easiest way to enable use of profiling and the external interpreter do this is by invoking GHC manually (all of my attempts at achieving this via cabal-install came up short).

However, if we invoke GHC manually we must somehow tell it where to find the dependencies that cabal-install built. For this we tell cabal-install to save this information as a GHC package environment with the --write-ghc-environment-files flag. GHC will look for this file (which is named, e.g., .ghc.environment.x86_64-linux-8.10.1) when invoked.

Finally, invoking ghc with -prof not only tells the compiler to produce profiled code, but also forces the compiler to build dependencies with profiling support. This includes both runtime dependencies, as well as the dependencies which provide splice expressions.