ProcrastiBlog

Profiling OCaml code is kind of a hassle. The simplest thing is to use ocamlopt with the -p option, then apply gprof as usual. The problem here is that the debugging symbols produced by the OCaml compiler are of limited usefulness. For example, fun expressions show up with names like camlModule__fun_2397 (where 2397 has nothing to do with anything) and, I think, continuation-passing transformations in the back-end can lead to confusing call graph relationships where functions that shouldn't be compute-intensive at all end up looking like hot spots.

Now, you may think this is all due to the conversion to C calling conventions and the corresponding loss of high-level information at execution time and therefore the solution would be to profile bytecode. So you might try to compile with ocamlcp, the profiling bytecode compiler. Along the way, you'll figure out that ocamlcp doesn't allow the -pp option... No problem—if your project is sufficiently small or your Makefiles are sufficiently modular—you can just run the preprocessor separately and pass the preprocessed files in to ocamlcp (just add pr_o.cmo to your camlp4 command, to dump the pretty-printed version of your code instead of the AST object).*

Then you'll discover** that what ocamlprof gives you is not a data dump like the output of gprof, but a source file annotated with execution counts for each expression. And you'll realize that this is in some ways useless—you really need time information to do effective profiling. For example, the polymorphic equality function (that's, um, = for you non-functional programming types) is going to have a massive execution count in just about any program you write; that doesn't mean you need to rip it out and hot-rod it.***

Now, here's where I made an interesting discovery: the byte- and native-code compilers seemingly dismantle the source code in similar or identical ways. You can take the execution count for an anonymous fun expression from the gprof output and match it up with the execution count on the source expression from ocamlprof.

Here's an example. gprof tells me the following:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ms/call  ms/call  name    
 28.57      0.08     0.08  1064344     0.00     0.00  compare_val
 17.86      0.13     0.05    82370     0.00     0.00  camlAtp__itlist_116
 10.71      0.16     0.03  2284937     0.00     0.00  caml_apply2
  7.14      0.18     0.02  1657397     0.00     0.00  camlMlss__fun_1052

The far left column tells you what percentage of the execution time was spent in the function named on the far right. The column in the middle tells you how many time the function was called. The first three rows name built-in and generic functions—it's not surprising that the program spends a lot of time comparing things, iterating over lists, and invoking functions. The fourth row names camlMlss__fun_1052, an anonymous function, which accounts for 7.14% of running time. Where is this function?

gprof outputs the following call graph information:

-----------------------------------------------
                               28217             camlMlss__fun_1046  [167]
                             1629180             camlAtp__itlist_116  [11]
[16]    12.0    0.02    0.01 1657397         camlMlss__fun_1052  [16]

In other words, camlMlss__fun_1052 is called from some other anonymous function and from a generic list iterator. That's not very helpful.

But if we go over to the output of ocamlprof, we find this:

let saturation_rule2 f terms theta =
  (* 546 *) itlist
    (fun fm r ->
       (* 28217 *) try
         let g = f fm in
         itlist
           (fun fm r ->
              (* 1657397 *) try g fm @ r with
                Match_failure _ -> r)
           theta r
       with
         Match_failure _ -> r)
    theta []

The numbers in comments are invocation counts. The innermost fun expression is called 1,657,397 times. Does that number look familiar? Notice also that the next enclosing fun expression is called 28,217 times, which is exactly the number of calls attributed to the anonymous parent of camlMlss__fun_1052 in the gprof call graph data. We have found our hot (er, warm-ish) spot!

I'm not sure how reliably this works in general. The cited results were obtained by running ocamlcp with the -g and -p f arguments. It might be fun, if one could find some spare time, to write a utility that used the ocamlcp output to annotate the gprof data with (probable) line numbers.

* Note that the pre-processed file must have a .ml extension or the OCaml compiler will refuse to have anything to do with it. Note also that foo-pp.ml is not an option, because the filename must be a valid module identifer when the first letter is capitalized (i.e., your canonical [A-Za-z][A-Za-z0-9_]* identifier).****

** We assume throughout that you are a foolish person like me: that you only read the documentation for such things far enough to get them running and are consequently constantly surprised by what programs actually do, since you assume that they ought to do what they seem to be intended to do.

*** Although you may run into trouble if you use polymorphic equality on big, complicated (or, gasp, cyclic) data structures.

**** Note to self: is there a reason the OCaml convention is to use lowercase file names when the module system implicitly capitalizes it and for use as a module identifier and a capitalized file name is also accepted by the compiler? I.e., why don't we match the case of file names and implicit module declarations? Oh me, oh my, why, why, why?