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.
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
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
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 have approximately 10 MB of hash-tables allocated since the beginning of the execution, which is expected;
the second most allocated data in the major heap are maps, and they keep growing during the execution of Alt-Ergo.
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:
a bunch of these maps are still in the stack: the item
Map_at_192_offset_1in the first column means that most of the memory is retained by the
foldfunction, at line 192 of the
Mapmodule (resolution of stack frames is only available in the commercial version of
the "kind" column corresponding to
Map_at_192_offset_1gives better information. It provides the signature of the function passed to fold. This information is already provided by the online version.
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
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
After further debugging, we observed that one of the maps (
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:
a better resolution time: from 69 seconds to 16 seconds;
less garbage collection : from 53,000 minor collections to 19,000;
a smaller memory footprint : from 26 MB to 24 MB;
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 dumping
|# dumps (major collections)||612 GCs||31 GCs||impressive GC activity without the patch|
|759 secs||24.3 secs|
|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 !