pkg: on dune build start, lock dir parsing is slow

[v-gb]

Currently, a null build in my tiny repo is surprisingly slow (8s).

A significant fraction of that is caused by sexp parsing of the lock dir, specifically the fact that the error path of some combinators like Dune_sexp.Decoder.find_cstr is expensive (due to User_message.did_you_mean), and that Dune_sexp.Decoder.either means you can run a ton of error paths, instead of just one as would be normal.

With these depends in my dune-project:

(package
  ...
 (depends
   ocaml
   core
   core_unix
   markup
   uri
   uucp
   yojson
   http-lwt-client
   ppx_yojson_conv
   ppx_sexp_value
   ppx_sexp_conv
   ppx_compare
   ppx_hash
   ppx_pipebang
   ppx_let
   ppx_bin_prot
   ppx_partial
   lwt_ppx
   ocamlformat
 ))

I observe this:

$ time ~/code/dune/_build/default/bin/main.exe build --display=quiet

real 0m7,809s
user 0m7,363s
sys 0m0,450s

but when I comment out all the ~hints from Dune_sexp.Decoder:

$ time ~/code/dune/_build/default/bin/main.exe build --display=quiet

real 0m4,960s
user 0m4,512s
sys 0m0,450s

It seems to me that either the sexp decoding module shouldn't backtrack, or the errors should be lazy, i.e. only computed on display.

(even with that, the performance seems off by an order of magnitude, possibly two. There's 130kB of data in the lock dirs and 1 dune file and 2 .ml file. It's wild that this takes any noticeable time at all)

[Alizter]

Thank you for the report.

If you are able to, could you also try compiling and benching dune with flambda? The parser is written in continuation-passing-style which is probably my first suspect on the list of reasons it is slow. This is something that flambda should in theory be good at optimising.

We have plans to improve parsing by introducing a cache similar to the one in #12188. However before we do this, it would be good to see if we can improve the raw performance.

The idea of making the errors lazier sounds good to me. I'll see if I can experiment with that soon.

[v-gb]

Thanks for the quick answer.

I investigated this because the dune preview executable was slow, and it's built with flambda. Now, maybe flambda helps some, but I doubt you'd see more than, say, 20% improvement from that.
The problem I mentioned is the code computing expensive things and throwing them away, nothing to do with cps.

Ideally, I'd build a compiler with frame pointers, so I can actually profile. But enabling frame pointers is done in some completely baroque way that I'd need to figure out again, so I'm not rushing to do this.

I don't know if caching would help with the rest of the computation, but it seems like given the size of the data involved, that shouldn't be necessary.

[rgrinberg]

I think it's just all the backtracking that's been attempted to support portable lock directories.

@gridbugs do you mind fixing this? One idea might be to just add a field to lock.dune that tells the parser whether portable lock directories are enabled.

[gridbugs]

Hey @v-gb! I've started looking into this but I'm unable to reproduce what you're seeing. I've put my attempt to reproduce the conditions of your problem here: https://github.com/gridbugs/dune-12248-repro. Please let me know if I've missed something, and whether you see the same issue building that project.

A null build of that project for me on a linux x86_64 machine:

 $ time dune build -j1

real    0m0.384s
user    0m0.285s
sys     0m0.093s

Removing the ~hints from Dune_sexp.Decoder has no noticeable effect on these numbers for me.

Can you share the project where you see this problem and I'll attempt to reproduce it on my end.

[v-gb]

I submitted a pull request on that repo to demonstrate the slowdown.

In the meantime, I dug up how to get frame pointers, and profiled some more, and observed the following:

• dune build takes 4.7s with the change above
• the majority of the time is taken by some equality function in Dune_rules.Pkg_rules
• when changing Dune_rules.Resolve.Input.equal to check db last instead of first => 3.5s
• (probably no impact, but still worrisome) Dune_rules.Resolve.Input.hash is broken: Poly.hash t.db runs hashes Maps and Sets, which is never correct. If this sort of stuff is common place in dune, that might be a possible explanation for the spurious rebuilds from pkg: dune rebuilds dependent packages unpredictably #12244 (concurrent fs reads finishing in a different order => map is built in different order => marshalled map is different => digest is different).
• adding Memo to Dune_rules.DB.get + phys_equal check to bypass DB comparison => 0.9s

[gridbugs]

Thanks for the update! I'll take a closer look next week. Minor correction (I think!) to your comment in case someone digs into this before I do, but when you talk about the use of Poly.hash in Dune_rules.Resolve.Input.hash, I believe that should be Dune_rules.Pkg_rules.Input.hash instead.

[v-gb]

The remaining 0.9s seems more difficult. I suspect that dune is doing something excessively conservative, because some of that time is spent dealing with _build/.digest.db, and that file is 30MB despite the repo having ~0 files. Running strings on that file shows:

• seemingly all files under ~/.cache/dune/toolchains/ocaml-compiler.5.3.0-8bb9bf707e62bf55c9b779546930d161
• seemingly all files under _build/_private
• all then the "source files", which is mostly 100 lock files or whatever it is

An an approximation of how many files are listed:

$ strings _build/.digest-db  | wc -l
285480

IMO, dune should assume that both _build and ~/.cache/dune are under its control, and thus assume that they can only change when dune itself changes them, and of course in that case dune should leave some kind of mark so that changes can be checked cheaply.

Minor correction (I think!) to your comment in case someone digs into this before I do, but when you talk about the use of Poly.hash in Dune_rules.Resolve.Input.hash, I believe that should be Dune_rules.Pkg_rules.Input.hash instead.

Yes, sorry.

[gridbugs]

Ok confirming that I can reproduce the problem with a null build, and that removing the hints from Dune_sexp.Decoder gives a measurable speedup. I'll dig deeper next week.

[gridbugs]

I did a little poking around on this today. Leaving some notes for my future self:

• the performance impact only seems to be felt when parsing portable lockdirs, not regular lockdirs
• the solved_for_platforms field in lock.dune is present if and only if the lockdir is portable so it might let us avoid adding an explicit field to indicate a portable lockdir

[gridbugs]

I've raised #12487 which uses the presence of the solved_for_platforms field in the lockdir metadata file to determine whether to parse lockfiles using the portable or non-portable syntax. This removes most of the backtracking from the parsing logic. On my machine where a null build of the repro project took ~6s originally, following this change it now takes ~3.9s.