`dune` process hangs on macos

[jchavarri]

Recently, we updated Ahrefs codebase to the latest version of Dune (to be more specific, commit 71024ef) from the previous version we were using from back in April (7bb6de7), which was working fine.

After upgrading, all our Linux CI agents work perfectly fine, but on the macOS agents we have noticed that dune processes stay running forever, with CPU usage over 90%.

Here is some example of a dune process running for 55+minutes and with CPU at 100%:

$ ps aux | grep dune
USER              PID  %CPU %MEM      VSZ    RSS   TT  STAT STARTED      TIME COMMAND
user              3759 100.0  0.0 34302304    448   ??  R     3:20PM  55:12.57 /Users/user/builds/macvm100/ahrefs/monorepo-extra/_opam/bin/dune build -p dune-private-libs -j 7 @install
user              3737   0.0  1.1 34302560  93844   ??  S     3:19PM   0:04.48 /Users/user/builds/macvm100/ahrefs/monorepo-extra/_opam/bin/dune build -p dune-private-libs -j 7 @install
user             36569   0.0  0.0 34122844    856 s000  S+    4:15PM   0:00.00 grep dune

Looking at different occurrences of the issue, I couldn't find any pattern, on the packages where it appears. What I can say is that it happens on different versions of macos. In particular, the one in the agent used in the command above is 12.3.1, but it also happens on 12.6.1 and 13.0.1.

I have tried to gather some information about what the hanging dune process is exactly doing. Calling sample 3759 with the process id gathered with ps aux above shows a lot of nested callbacks with camlDune_engine__Process__fun_4514, not sure if this is expected. You can find the full output of that command here:

sample-3759.txt

Is there anything I could do to help diagnose the problem?

[jchavarri]

Here is another result from running ps aux and then sample on one pid from a different case, in a different agent, in case it helps, multiple processes can be seen due to different retries (seems they don't get killed properly on timeout either):

ps aux | grep dune
USER              PID  %CPU %MEM      VSZ    RSS   TT  STAT STARTED      TIME COMMAND
user            51794  54.8  0.0  4369616    140   ??  R    Wed12PM 714:10.99 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p extunix -j 7 @install
user            63680  49.1  0.0  4381524    140   ??  R    Wed12PM 713:24.35 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p atdgen -j 7 @install
user            82840  49.0  0.0  4389020    128   ??  R    Tue08PM 1571:55.95 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p base_quickcheck -j 7
user            70042  48.9  0.0  4413384    128   ??  R    Tue08PM 1574:25.93 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p odoc -j 7
user            65598  48.9  0.0  4385204    140   ??  R    Tue08PM 1576:08.01 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p ocamlgraph -j 7 @install
user            43954  48.9  0.0  4417832    128   ??  R    Tue08PM 1575:22.95 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p merlin-lib -j 7
user            60861  48.8  0.0  4384232    140   ??  R    Wed12PM 704:43.24 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p base_quickcheck -j 7
user            73751  48.7  0.0  4420104    416 s000  R+    8:32AM 185:55.48 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p camomile -j 7 --promote-install-files=false @install
user            55107  40.5  0.0  4410496    424   ??  R    Wed03PM 603:09.13 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p ocamlformat -j 7 @install
user            27690  40.3  0.0  4414336    428   ??  R    Wed03PM 612:21.65 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p ocamlformat -j 7 @install
user            69702  40.2  0.0  4376748    140   ??  R    Tue08PM 1570:39.99 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p extunix -j 7 @install
user            37138  40.0  0.0  4377368    384   ??  R    Wed03PM 608:47.87 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p atdgen-www -j 7
user            63794  39.6  0.0  4377456    140   ??  R    Wed12PM 713:28.93 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p atdgen-www -j 7
user            60278  39.5  0.0  4377096    132   ??  R    Wed01PM 647:21.11 /Users/user/builds/macvm202/ahrefs/dune-trim/_opam/.opam-switch/build/dune.20230627.git/./_boot/dune.exe build dune.install --release --profile dune-bootstrap -j 7
user            79056  39.0  0.0  4383864    128   ??  R    Tue08PM 1573:04.25 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p ppx_deriving -j 7
user            42147  37.3  0.0  4418300    140   ??  R    Tue08PM 1577:02.57 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p camomile -j 7 @install
user            40195  36.7  0.0  4381080    424   ??  R    Wed03PM 608:59.14 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p devkit -j 7 @install
user            43079  36.6  0.0  4410240    384   ??  R     5:35PM 550:35.02 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p ocamlformat -j 7 @install
user            83921  36.3  0.0  4377224    400   ??  R    Wed03PM 592:26.90 /Users/user/builds/macvm202/ahrefs/dune-trim/_opam/.opam-switch/build/dune.20230627.git/./_boot/dune.exe build dune.install --release --profile dune-bootstrap -j 7
user            44929  35.5  0.0  4419452    140   ??  R    Wed12PM 714:35.21 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p camomile -j 7 @install
user            73733   0.1  0.8  4419836  64652 s000  S+    8:32AM   0:34.97 /Users/user/builds/macvm202/ahrefs/monorepo-extra/_opam/bin/dune build -p camomile -j 7 --promote-install-files=false @install
user            10302   0.0  0.0  4334020    736 s001  R+    4:29PM   0:00.00 grep dune

sample-27690.txt

[nojb]

Bisecting is probably your best bet. Before doing that you may want to test commit 886ff3b that caused some issues (on Windows, but you never know).

[jchavarri]

Ok, I am trying to bisect now with older commits, it will take a while as the issue doesn't happen always.

Before doing that you may want to test commit 886ff3b that caused some issues (on Windows, but you never know).

Hm, I tested this commit and its parent, and both seemed to work fine. Then I noticed the commit is not actually on the main branch, is that right?

[nojb]

Hm, I tested this commit and its parent, and both seemed to work fine. Then I noticed the commit is not actually on the main branch, is that right?

Yes, it is, but it is not the same commit because it was cherry-picked to the release 3.8 branch.

[rgrinberg]

Are these builds hanging in watch mode?

Could you run dtruss -p to see which syscalls are being invoked?

[jchavarri]

Are these builds hanging in watch mode?

They happen in regular, non-watch mode, mostly when installing many packages with opam (where dune is invoked a lot). I am not sure it might happen in watch mode, but I haven't been able to reproduce in watch mode, and I have not received any reports from other developers about that mode.

Could you run dtruss -p to see which syscalls are being invoked?

$ sudo dtruss -p 24983
dtrace: system integrity protection is on, some features will not be available

SYSCALL(args) 		 = return
select(0x0, 0x0, 0x0, 0x0, 0x700005DD7F90)		 = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x700005DD7F90)		 = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x700005DD7F90)		 = 0 0
....

continues forever (around 10-15 new lines / second).

[rgrinberg]

I don't even understand how this is possible:

select(0x0, 0x0, 0x0, 0x0, 0x700005DD7F90) = 0

From the manual:

select() returns the number of ready descriptors that are contained in the
descriptor sets, or -1 if an error occurred. If the time limit expires,
select() returns 0

How can the time limit expire if I set it to block indefinitely.

I also don't understand why they stay running forever. If select is constantly returning, it should eventually be shut off by the finalizer.

[rgrinberg]

Try this patch, see if it makes a difference:

diff --git a/src/dune_async_io/async_io.ml b/src/dune_async_io/async_io.ml
index 501a5d2f5..c8f465b70 100644
--- a/src/dune_async_io/async_io.ml
+++ b/src/dune_async_io/async_io.ml
@@ -242,13 +242,7 @@ let with_io scheduler f =
           ~f:(fun () -> select_loop t)
           ~finally:(fun () -> Mutex.unlock t.mutex))
   in
-  Fiber.Var.set t_var t (fun () ->
-      Fiber.finalize f ~finally:(fun () ->
-          Mutex.lock t.mutex;
-          t.running <- false;
-          interrupt t;
-          Mutex.unlock t.mutex;
-          Fiber.return ()))
+  Fiber.Var.set t_var t (fun () -> f)
 
 let with_ f =
   let+ t = Fiber.Var.get_exn t_var in

[jchavarri]

I can confirm that I've been able to run multiple successful installations of packages (1000+ pkgs are installed each time, most of them using dune) without issues by pinning the version of Dune to e1f3e19 (the commit before 12a0268).

So, while we can't confirm that 12a0268 is the offender, I think it's quite sure that something changed between that commit and 71024ef that caused the regression.

Try this patch, see if it makes a difference:

I will try this next.

[jchavarri]

Maybe related? https://beesbuzz.biz/code/5739-The-problem-with-select-vs-poll

Fwiw we set ulimit -n to a very high value (65536) on the CI agents where we are seeing the problems.

[rgrinberg]

OCaml's select will error if we go over the fd limit.

Also, dune doesn't use that many fd's concurrently anyway so it's unlikely we'll ever run in the issues in that article.

Finally, if that was the problem, it wouldn't be macos specific.

Another piece of advice would be to print all the fd's returned by select when it's looping. You can print them as integers after doing Obj.magic.

[jchavarri]

Another piece of advice would be to print all the fd's returned by select when it's looping. You can print them as integers after doing Obj.magic.

You mean something like this?

diff --git a/src/dune_async_io/async_io.ml b/src/dune_async_io/async_io.ml
index bbfa01011..a7d6aa4c0 100644
--- a/src/dune_async_io/async_io.ml
+++ b/src/dune_async_io/async_io.ml
@@ -190,6 +190,10 @@ let rec select_loop t =
          [t.pipe_write] will interrupt this select *)
       Unix.select read write [] (-1.0)
     in
+    print_endline
+      (Printf.sprintf "Readers: %s\nWriters: %s"
+         (String.concat ~sep:", " (List.map ~f:Obj.magic readers))
+         (String.concat ~sep:", " (List.map ~f:Obj.magic writers)));
     assert (ex = []);
     (* Before we acquire the lock, it's possible that new tasks were added.
        This is fine. *)

I want to be sure I log the right things, as it takes me ~1h for each one of these experiments.

[emillon]

Also, dune doesn't use that many fd's concurrently anyway so it's unlikely we'll ever run in the issues in that article.

If I understand correctly, the problem with select is not only that you can't use it with many fds; it's also that you can't use it with fds that have a high value. So it can be an issue even if there's no fd leak or many concurrently open fds.

[nojb]

select(0x0, 0x0, 0x0, 0x0, 0x700005DD7F90) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x700005DD7F90) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x700005DD7F90) = 0 0

Another odd thing: there are two uses of Unix.select in Dune, and both have a non-empty set of read descriptors, which is inconsistent with these calls.