What does .(...) mean in a .prof report mean?

Question

I'm looking for optimization oportunities in my Haskell program by compiling with -prof, but I don't know how to interpret the cost centres that contain ellipses. What are filter.(...) and jankRoulette.select.(...)?

COST CENTRE                MODULE                     %time %alloc

filter.(...)               Forest                      46.5   22.3
set-union                  Forest                      22.5    4.1
cache-lookup               Forest                      16.0    0.1
removeMany                 MultiMapSet                  3.7    1.9
insertMany                 MultiMapSet                  3.3    1.8
jankRoulette.select.(...)  Forest                       1.4   15.2

I generated that with: $ ghc --make -rtsopts -prof -auto-all main.hs && ./main +RTS -p && cat main.prof

The function filter has a few definitions in a where clause, like this:

filter a b = blahblah where
    foo = bar
    bar = baz
    baz = bing

But those all show up as filter.foo, filter.bar, etc.

I thought they might be nested let expressions, but jankRoulette.select doesn't have any. And I've added SCC directives in front of most of them without any of those cost centres rising to the top.

Since most of the time is spent in filter.(...), I'd like to know what that is. :)

Answer 1

TL; DR: GHC generates this when you do a pattern match in a let binding, like let (x,y) = c. The cost of evaluating c is tracked by the ... cost centre (since there is no unique name to it)`.

---

So how did I find this out? A grep for (...) in the GHC source code finds the following (from compiler/deSugar/Coverage.hs):

-- TODO: Revisit this
addTickLHsBind (L pos (pat@(PatBind { pat_lhs = lhs, pat_rhs = rhs }))) = do
  let name = "(...)"
  (fvs, rhs') <- getFreeVars $ addPathEntry name $ addTickGRHSs False False rhs

   {- ... more code following, but not relevant to this purpose
   -}

That code tells us that it has to do something with pattern bindings. So we can make a small test program to check the behavior:

x :: Int
(x:_) = reverse [1..1000000000]

main :: IO ()
main = print x

Then, we can run this program with profiling enabled. An indeed, GHC generates the following output:

COST CENTRE MODULE                  no.     entries  %time %alloc   %time 

%alloc
MAIN        MAIN                     42           0    0.0    0.0   100.0  100.0
 CAF        Main                     83           0    0.0    0.0   100.0  100.0
  (...)     Main                     86           1  100.0  100.0   100.0  100.0
  x         Main                     85           1    0.0    0.0     0.0    0.0
  main      Main                     84           1    0.0    0.0     0.0    0.0

So it turns out the assumption made from the code was correct. All of the time of the program is spent evaluating the reverse [1..1000000000] expression, and it's assigned to the (...) cost centre.