Slow compilation on MacOS

[Adam_Haber]

Hi,

I’m just starting to learn OCaml and I’m having problems with compilation times on my Mac.

I’ve installed OCaml using this dev setup script. Installation completed successfully, and utop seems to be working fine. I’ve followed the (excellent) guided tour from Real World OCaml, and created a simple script called sum.ml:

open Base
open Stdio

let rec read_and_accumulate accum =
  let line = In_channel.input_line In_channel.stdin in
  match line with
  | None -> accum
  | Some x -> read_and_accumulate (accum +. Float.of_string x)

let () =
  printf "Total: %F\n" (read_and_accumulate 0.)

Then, I created a dune file:

(executable
 (name      sum)
 (libraries base stdio))

And ran dune build sum.exe. This took more than 5 minutes; I then changed "Total" to "Total123", and tried to recompile; still took several minutes.

Just to make sure, I’ve followed the same dev setup instructions on WSL (on a different machine), and compilation was very fast. This happened both before and after I installed Mojave.

Any help would be much appreciated!

[Chet_Murthy]

just for starters, you might want to try compiling that program “manually” using ocamlc. Just to cleave apart “the ocaml system” from “dune”. E.g.

ocamlc -o sum sum.ml

or

ocamlc -c sum.ml
ocamlc -o sum sum.cmo

[ivg]

Extending Chet’s answer, first of all let’s time that ocamlfind works fine,

time ocamlfind query base
time ocamlfind query stdio

if those commands terminate in a reasonable time (should be much less than a second), then we can try bisecting the rest, e.g.,

time ocamlfind ocamlopt -package base -package stdio  -c sum.ml

This will time the actual compiler. Now let’s pin the linker to the wall:

time ocamlfind ocamlopt -linkpkg -package base -package stdio sum.ml -o exe

Now, if the times are OK (less than a second), then we can blame Dune.

[Adam_Haber]

Thanks! This is very helpful. All these times are indeed less than a second. Any ideas on what might be the problem with Dune?

[Chet_Murthy]

Excellent! Next, do you know how to do the equivalent of strace on MacOS? IIRC, it’s called dtruss but hey, I’m not a Mac user. This would give you a systemcall trace. Give the enormous times you cite, it is likely you’re seeing slow system-calls of some sort. So:

(1) maybe simplify your program (start with “hello, world”) ; I recognize that your program is already pretty simple, but making it simpler, while preserving your observed bug, is always useful. [Sherlock Holmes says: “exonerate the innocent to implicate the guilty”]

(2) then use dtruss or some such, to (maybe) see what’s running slow.

(3) BTW, another thing: I don’t know how to ask dune to “clean” all its built-files, but you could write a shell-script loop that did “dune build; clean all build files” in a loop, and see if that uses a lot of CPU. If it does NOT, you could see if the system is in I/O wait. This might help you to differentiate between:

(a) some sort of CPU usage anomaly (heck, maybe you’re running on an encrypted+compressed FS? grin)
(b) maybe a disk I/O issue? (again, hard to believe, but hey, “exonerate the innocent …”)
© a network operation issue (no idea why, but hey, good to rule it out)

ETA: dune spawns child processes. No idea how many, but on Linux there are flags to tell strace to follow child processes and strace them, too. I’d guess there’s something similar for dtruss.

ETA2: Also, I have no idea how (b/c I don’t use dune – Makefiles+autoconf but there’s probably a way to turn on dune’s verbose logging. This might help, esp. if each log-line comes with a timestamp. Again, with the times you cite, it’s likely that there’ll be some operation that takes a LOTTA time, and with sufficiently verbose logging, that’ll manifest as a big-ass gap in times between two successive log-lines.

[bcc32]

@Chet_Murthy

I don’t know how to ask dune to “clean” all its built-files

There is a dune clean subcommand, which I think is basically just rm -rf _build.

[Adam_Haber]

I ran dune clean followed by:
sudo dtruss dune build hello.exe
when hello.ml is just print_string "Hello world!\n"

I got a very very long log I ctrl-c’d after a couple of seconds, when it started outputting things about my conda env… hope this helps:

(base) adamhaber-s-macbookpro1:~ adamhaber$ sudo dtruss dune build hello.exe
dtrace: system integrity protection is on, some features will not be available

SYSCALL(args) 		 = return
dtrace: 141192 dynamic variable drops with non-empty dirty list
open("/dev/dtracehelper\0", 0x2, 0xFFFFFFFFE4EC4100)		 = 3 0
ioctl(0x3, 0x80086804, 0x7FFEE4EC3F10)		 = 0 0
close(0x3)		 = 0 0
madvise(0x10B0FD000, 0x12000, 0x5)		 = 0 0
access("/AppleInternal/XBS/.isChrooted\0", 0x0, 0x0)		 = -1 Err#2
bsdthread_register(0x7FFF5F86D418, 0x7FFF5F86D408, 0x2000)		 = 1073742047 0
sysctlbyname(kern.bootargs, 0xD, 0x7FFEE4EC3360, 0x7FFEE4EC3358, 0x0)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
ioctl(0x2, 0x4004667A, 0x7FFEE4EC2B74)		 = 0 0
mprotect(0x10B2B4000, 0x1000, 0x0)		 = 0 0
mprotect(0x10B2BB000, 0x1000, 0x0)		 = 0 0
mprotect(0x10B2BC000, 0x1000, 0x0)		 = 0 0
mprotect(0x10B2C3000, 0x1000, 0x0)		 = 0 0
mprotect(0x10B2B2000, 0x90, 0x1)		 = 0 0
mprotect(0x10B2C4000, 0x1000, 0x1)		 = 0 0
mprotect(0x10B2B2000, 0x90, 0x3)		 = 0 0
mprotect(0x10B2B2000, 0x90, 0x1)		 = 0 0
getpid(0x0, 0x0, 0x0)		 = 27235 0
stat64("/AppleInternal\0", 0x7FFEE4EC37D0, 0x0)		 = -1 Err#2
csops(0x6A63, 0x7, 0x7FFEE4EC3300)		 = -1 Err#22
proc_info(0x2, 0x6A63, 0xD)		 = 64 0
csops(0x6A63, 0x7, 0x7FFEE4EC2B50)		 = -1 Err#22
issetugid(0x0, 0x0, 0x0)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
sigaltstack(0x7FFEE4EC4AB8, 0x0, 0x0)		 = 0 0
sigaction(0xB, 0x7FFEE4EC4A88, 0x0)		 = 0 0
lseek(0x0, 0x0, 0x1)		 = 5514 0
lseek(0x1, 0x0, 0x1)		 = 5514 0
lseek(0x2, 0x0, 0x1)		 = 5514 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
open_nocancel(".\0", 0x0, 0x1)		 = 3 0
fstat64(0x3, 0x7FFEE4EC3790, 0x0)		 = 0 0
fcntl_nocancel(0x3, 0x32, 0x7FFEE4EC3990)		 = 0 0
close_nocancel(0x3)		 = 0 0
stat64("/Users/adamhaber\0", 0x7FFEE4EC3700, 0x0)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
sigaction(0x1A, 0x7FFEE4EC4928, 0x7FFEE4EC4950)		 = 0 0
open_nocancel(".\0", 0x0, 0x1)		 = 3 0
fstat64(0x3, 0x7FFEE4EC3840, 0x0)		 = 0 0
fcntl_nocancel(0x3, 0x32, 0x7FFEE4EC3A40)		 = 0 0
close_nocancel(0x3)		 = 0 0
stat64("/Users/adamhaber\0", 0x7FFEE4EC37B0, 0x0)		 = 0 0
ioctl(0x2, 0x4004667A, 0x7FFEE4EC4984)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
issetugid(0x0, 0x0, 0x0)		 = 0 0
open_nocancel(".\0", 0x0, 0x1)		 = 3 0
fstat64(0x3, 0x7FFEE4EC3570, 0x0)		 = 0 0
fcntl_nocancel(0x3, 0x32, 0x7FFEE4EC3770)		 = 0 0
close_nocancel(0x3)		 = 0 0
stat64("/Users/adamhaber\0", 0x7FFEE4EC34E0, 0x0)		 = 0 0
open_nocancel("/Users/adamhaber\0", 0x1100004, 0x0)		 = 3 0
dtrace: error on enabled probe ID 2198 (ID 557: syscall::sysctl:return): invalid kernel access in action #10 at DIF offset 28
fstatfs64(0x3, 0x7FFEE4EC3D58, 0x0)		 = 0 0
getdirentries64(0x3, 0x7FEACD800000, 0x1000)		 = 4072 0
getdirentries64(0x3, 0x7FEACD800000, 0x1000)		 = 104 0
getdirentries64(0x3, 0x7FEACD800000, 0x1000)		 = 0 0
close_nocancel(0x3)		 = 0 0
open_nocancel("/Users\0", 0x1100004, 0x0)		 = 3 0
fstatfs64(0x3, 0x7FFEE4EC3D58, 0x0)		 = 0 0
getdirentries64(0x3, 0x7FEACD800000, 0x1000)		 = 208 0
getdirentries64(0x3, 0x7FEACD800000, 0x1000)		 = 0 0
close_nocancel(0x3)		 = 0 0
open_nocancel("/\0", 0x1100004, 0x0)		 = 3 0
fstatfs64(0x3, 0x7FFEE4EC3D58, 0x0)		 = 0 0
getdirentries64(0x3, 0x7FEACD800000, 0x1000)		 = 1192 0
getdirentries64(0x3, 0x7FEACD800000, 0x1000)		 = 0 0
close_nocancel(0x3)		 = 0 0
stat64("/Users/adamhaber/.config/dune/config\0", 0x7FFEE4EC46C0, 0x0)		 = -1 Err#2
chdir("/Users/adamhaber\0", 0x0, 0x0)		 = 0 0
open_nocancel(".\0", 0x0, 0x1)		 = 3 0
fstat64(0x3, 0x7FFEE4EC36F0, 0x0)		 = 0 0
fcntl_nocancel(0x3, 0x32, 0x7FFEE4EC38F0)		 = 0 0
close_nocancel(0x3)		 = 0 0
stat64("/Users/adamhaber\0", 0x7FFEE4EC3660, 0x0)		 = 0 0
mkdir("_build\0", 0x1FF, 0x0)		 = 0 0
open("_build/log\0", 0x1000601, 0x1B6)		 = 3 0
lseek(0x3, 0x0, 0x1)		 = 0 0
dtrace: error on enabled probe ID 2172 (ID 161: syscall::write:return): invalid kernel access in action #12 at DIF offset 68
sigprocmask(0x1, 0x7FFEE4EC484C, 0x7FFEE4EC483C)		 = 0x0 0
bsdthread_create(0x10AEC5DA0, 0x7FEACC600050, 0x70000ABD9000)		 = 180195328 0
thread_selfid(0x0, 0x0, 0x0)		 = 652535 0
bsdthread_create(0x10AEC5E20, 0x0, 0x70000AC5C000)		 = 180731904 0
thread_selfid(0x0, 0x0, 0x0)		 = 652536 0
bsdthread_create(0x10AEC5DA0, 0x7FEACC600140, 0x70000ACDF000)		 = 181268480 0
thread_selfid(0x0, 0x0, 0x0)		 = 652537 0
__pthread_sigmask(0x1, 0x70000AC5BF04, 0x0)		 = 0 0
open_nocancel(".\0", 0x0, 0x1)		 = 4 0
fstat64(0x4, 0x7FFEE4EC3700, 0x0)		 = 0 0
fcntl_nocancel(0x4, 0x32, 0x7FFEE4EC3900)		 = 0 0
close_nocancel(0x4)		 = 0 0
stat64("/Users/adamhaber\0", 0x7FFEE4EC3670, 0x0)		 = 0 0
psynch_cvsignal(0x10B0CBD00, 0x200, 0x0)		 = 256 0
psynch_cvwait(0x10B0CBD00, 0x100000100, 0x0)		 = 0 0
stat64("/Users/adamhaber/.opam/4.07.0/bin/nproc.opt\0", 0x7FFEE4EC4608, 0x0)		 = -1 Err#2
psynch_cvsignal(0x10B0CBD00, 0x10000000200, 0x100)		 = 257 0
psynch_cvwait(0x10B0CBD00, 0x200, 0x0)		 = 0 0
psynch_cvsignal(0x10B0CBD00, 0x20000000300, 0x200)		 = 257 0
psynch_cvwait(0x10B0CBD00, 0x20100000300, 0x200)		 = 0 0
stat64("/Users/adamhaber/.opam/4.07.0/bin/nproc\0", 0x7FFEE4EC4608, 0x0)		 = -1 Err#2
stat64("/Users/adamhaber/miniconda3/bin/nproc.opt\0", 0x7FFEE4EC4608, 0x0)		 = -1 Err#2
stat64("/Users/adamhaber/miniconda3/bin/nproc\0", 0x7FFEE4EC4608, 0x0)		 = -1 Err#2
stat64("/Users/adamhaber/miniconda3/condabin/nproc.opt\0", 0x7FFEE4EC4608, 0x0)		 = -1 Err#2

I can append longer outputs if it helps…

[Chet_Murthy]

Sorry, I should have been clearer about what to do with the dtruss output.

(1) there’s probably an option to add timestamps to each line; enable this. If you can make the timestamps “absolute time”, that’s better (e.g. strace can do either “seconds since start of program” or “actual time”)

(2) save the entire thing to a file

(3) also run it (tee it to a file too) and just -watch-; see if at some points it stops moving for a few sec. If you can, try to see around what time that happens.

(4) then in the file, use “binary search with the eyes” to see if you can find multi-second gaps between log-lines.

All of this can be automated; but OTOH, for a one-off bug, it’s often enough to just use the ol’ eyeballs.

[Adam_Haber]

There’s a specific line which seems to take orders-of-magnitude more times than the others:
select(0x0, 0x0, 0x0, 0x0, 0x70000786AEF0) = 0 0
and repeats every second or so. Is this somehow related to Dune?

[Chet_Murthy]

Unless I’m mistaken, that’s a way of doing a “sleep” (empty fd-sets, non-zero time). I don’t know how Dune is implemented, so can’t go further. Though, let’s try … were you able to enable timestamps? It would be useful to know how long the “wait” is for. Also, since you have a logfile, you could (a) see if a number of different instances sleep the same amount of time, and then count how many there are? If their contribution to the time ends up coming close to your top-line number, that’d be useful to know.

[echowuhao]

@Adam_Haber

(executable (name sum) (libraries base stdio))

time dune build sum.exe
dune build sum.exe  0.28s user 0.23s system 31% cpu 1.607 total

fine in my machine. ( Mojave 10.14.15, ocaml 4.08)

[avsm]

@Adam_Haber

Thanks! This is very helpful. All these times are indeed less than a second. Any ideas on what might be the problem with Dune?

Adam, is there anything in your login shell that might be executing code upon forking new shells? That’s the most likely culprit here.

If you have Chrome, try following the profiling instructions here to generate a --trace-file from dune and inspect the timeline with Chrome to see what’s taking so long.

[Adam_Haber]

I’m not sure I understand the all of the tracing output, but it seems like there’s something called fds that’s taking all the time:

this is the output from dune build hello.exe --trace-file trace

[emillon]

Hi,
The tracing output has two parts: the top one is a set of counters, and the commands are at the bottom (getconf, ocamlc.opt). fds tracks how many file descriptors are open, here it’s flat so it seems to be ok! You can see the ocamlc.opt invokation at the far right, at that scale it looks like a tiny spike. There does not seem to be a long running command, though I’m not seeing getconf in that output (it should even faster than ocamlc.opt).

It seems strange that it’s using ocamlc (ie, building bytecode) rather than ocamlopt (native code). That might indicate an error in the setup. Also, can you try running the build command with an extra -j 1 flag?

[Adam_Haber]

Hmm - I ran time dune build hello.exe --tracing-file trace -j 1 and got this:

According to the trace, the wall time for ocamlc.opt is 800 ms; however, the entire thing took 7 minutes:

(base) adamhaber-s-macbookpro1:~ adamhaber$ time dune build hello.exe --trace-file trace -j 1
                   
real	8m59.602s
user	1m28.770s
sys	7m0.114s

[ivg]

Mmm… are you building in your home folder? Then it starts to make sense. Dune is probably scanning your whole home folder. I think it is expected that you are creating a separate folder for each project and store there only project related files. (The same is true for ocamlbuild and probably all other automated build systems).

Can you try to create an empty folder, put your files there and check the time?

[Adam_Haber]

When I do everything in a different folder, I get Entering directory '/Users/adamhaber' and compilation still takes a couple of minutes.

[ivg]

Aha, now we are on track. And let me guess, you’re not having a dune-project file in the toplevel folder of your project?

Hint: this is how it should look like, in case if you don’t have one

[Adam_Haber]

I now have a folder ~/dune_tmp with the following files: sum.ml (from the original post), dune, which contains:

(executable
 (name      sum)
 (libraries base stdio))

and a dune-project file that contains:

(lang dune 1.8)

But when I run dune build sum.exe I still get Entering directory '/Users/adamhaber', and long compilation times. Am I putting the files in the right places?

[emillon]

You can try removing ~/dune-project and ~/_build. If you created a workspace file, you’ll want to remove it. Another way to make sure it’s not scanning other directories (to debug this) is to cd into dune_tmp and call dune with the --root . flag.