The last time Hackerfall tried to access this page, it returned a not found error. A cached version of the page is below, or click here to continue anyway

In this blog post, we explain how ocp-memprof helped us identify a piece of code in Alt-Ergo that needed to be improved. Simply put, a function that merges two maps was performing a lot of unnecessary allocations, negatively impacting the garbage collector's activity. A simple patch allowed us to prevent these allocations, and thus speed up Alt-Ergo's execution.

The Story

Il all started with a challenging example coming from an industrial user of Alt-Ergo, our SMT solver. It was proven by Alt-Ergo in approximately 70 seconds. This seemed abnormnally long and needed to be investigated. Unfortunately, all our tests with different options (number of triggers, case-split analysis, ...) and different plugins (satML plugin, profiling plugin, fm-simplex plugin) of Alt-Ergo failed to improve the resolution time. We then profiled an execution using ocp-memprof to understand the memory behavior of this example.

Profiling an Execution with ocp-memprof

As usual, profiling an OCaml application with ocp-memprof is very simple (see the user manual for more details). We just compiled Alt-Ergo in the OPAM switch for ocp-memprof (version 4.01.0+ocp1) and executed the following command:

$ ocp-memprof --exec ./ae-4.01.0+ocp1-public-without-patch pb-many-GCs.why

The execution above triggers 612 garbage collections in about 114 seconds. The analysis of the generated dumps produces the evolution graph below. We notice on the graph that:

We are not able to precisely identify the allocation origins of the maps in this graph (maps are generic structures that are intensively used in Alt-Ergo). To investigate further, we wanted to know if some global value was abnormally retaining a lot of memory, or if some (non recursive-terminal) iterator was causing some trouble when applied on huge data structures. For that, we extended the analysis with the --per-root option to focus on the memory graph of the last dump. This is done by executing the following command, where 4242 is the PID of the process launched by ocp-memprof --exec in the previous command:

$ ocp-memprof --load 4242 --per-root 611

The per-root graph (above, on the right) gives more interesting information. When expanding the stack node and sorting the sixth column in decreasing order, we notice that:

Uf.Make(Uf.??Make.X).LX.t ->
Explanation.t ->
Explanation.t Map.Make(Uf.Make(Uf.??Make.X).LX).t ->
Explanation.t Map.Make(Uf.Make(Uf.??Make.X).LX).t

This information allows us to see the precise origin of the allocation: the map of module LX used in uf.ml. Lucky us, there is only one fold function of LX's maps in the Uf module with the same type.

Optimizing the Code

Thanks to the information provided by the --per-root option, we identified the code responsible for this behavior:

(*** function extracted from module uf.ml ***)

01 | module MapL = Map.Make(LX)
02 |
03 | let update_neqs r1 r2 dep env =
04 |   let merge_disjoint_maps l1 ex1 mapl =
05 |     try
06 |       let ex2 = MapL.find l1 mapl in
07 |       let ex = Ex.union (Ex.union ex1 ex2) dep in
08 |       raise (Inconsistent (ex, cl_extract env))
09 |     with Not_found ->
10 |       MapL.add l1 (Ex.union ex1 dep) mapl
11 |   in
12 |   let nq_r1 = lookup_for_neqs env r1 in
13 |   let nq_r2 = lookup_for_neqs env r2 in
14 |   let mapl = MapL.fold merge_disjoint_maps nq_r1 nq_r2 in
15 |   MapX.add r2 mapl (MapX.add r1 mapl env.neqs)

Roughly speaking, the function above retrieves two maps nq_r1 and nq_r2 from env, and folds on the first one while providing the second map as an accumulator. The local function merge_disjoint_maps (passed to fold) raises Exception.Inconsistent if the original maps were not disjoint. Otherwise, it adds the current binding (after updating the corresponding value) to the accumulator. Finally, the result mapl of the fold is used to update the values of r1 and r2 in env.neqs.

After further debugging, we observed that one of the maps (nq_r1 and nq_r2) is always empty in our situation. A straightforward fix consists in testing whether one of these two maps is empty. If it is the case, we simply return the other map. Here is the corresponding code:

(*** first patch: testing if one of the maps is empty ***)

.. | ...
14 |   let mapl =
15 |      if MapL.is_empty nq_r1 then nq_r2
16 |      else
17 |        if MapL.is_empty nq_r2 then nq_r1
18 |        else
19 |          MapL.fold merge_disjoint_maps nq_r1 nq_r2
.. | ...

Of course, a more generic solution should not just test for emptiness, but should fold on the smallest map. In the second patch below, we used a slightly modified version of OCaml's maps that exports the height function (implemented in constant time). This way, we always fold on the smallest map while providing the biggest one as an accumulator.

(*** second (better) patch : folding on the smallest map ***)

01 | module MapL = Emap.Make(LX)
.. | ...
14 |   let small, big =
15 |     if MapL.height nq_r1 < MapL.height nq_r2 then nq_r1, nq_r2
16 |     else nq_r2, nq_r1
17 |   in
18 |   let mapl = MapL.fold merge_disjoint_maps small big in
.. |   ...

Checking the Efficiency of our Patch

Curious to see the result of the patch ? We regenerate the evolution and memory graphs of the patched code (fix 1), and we noticed:

Conclusion

We show in this post that ocp-memprof can also be used to optimize your code, not only by decreasing memory usage, but by improving the speed of your application. The interactive graphs are online in our gallery of examples if you want to see and explore them (without the patch and with the patch).

AE AE + patch Remarks 4.01.0 69.1 secs 16.4 secs substantial improvement on the example 4.01.0+ocp1 76.3 secs 17.1 secs when using the patched version of Alt-Ergo dumps generation 114.3 secs (+49%) 17.6 secs (+2.8%) (important) overhead when dumpingmemory snapshots # dumps (major collections) 612 GCs 31 GCs impressive GC activity without the patch dumps analysis(online ocp-memprof) 759 secs 24.3 secs dumps analysis(commercial ocp-memprof) 153 secs 3.7 secs analysis with commercial ocp-memprof is~ x5 faster than public version (above) AE memory footprint 26 MB 24 MB memory consumption is comparable minor collections 53K 19K fewer minor GCs thanks to the patch

Do not hesitate to use ocp-memprof on your applications. Of course, all feedback and suggestions are welcome, just email us !

More information:

Continue reading on www.ocamlpro.com