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
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
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  1629180 camlAtp__itlist_116   12.0 0.02 0.01 1657397 camlMlss__fun_1052 
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
-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
** 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?