devbox: [Bug]: devbox shell startup occassionally ~20-30s

Current Behavior (bug) I frequently get devbox shell times of 20-30s. MOST of the time startup is very short, e.g. I just ran time devbox run echo hello and got 0.1s. But occasionally, usually after not using my computer for a day or two, my first devbox shell will take a really long time.

➜  devbox shell
Ensuring packages are installed.
Starting a devbox shell...
dockedirenv: loading ~/src/docker/.envrc
direnv: using devbox
direnv: using nix .devbox/gen/shell.nix
r compose up -d --build
direnv: ([/opt/homebrew/bin/direnv export zsh]) is taking a while to execute. Use CTRL-C to give up.

… ~20-30 second pause …

direnv: export +NIX_BUILD_TOP +TEMP +TEMPDIR +TMP ~LD_LIBRARY_PATH ~LIBRARY_PATH ~TMPDIR ~buildPhase
direnv: loading ~/src/docker/everace/.envrc
direnv: export +DOCKER_CONTEXT +DOCKER_HOST

Expected Behavior (fix) <1s shell startup, consistently

Additional context

(devbox) ➜  devbox version -v
Version:     0.4.6
Platform:    darwin_arm64
Commit:      2ddf1856034dd544c5ff966e20e7bef1f3897fbb
Commit Time: 2023-03-31T19:14:57Z
Go Version:  go1.19.7

devbox.json

{
  "packages": ["docker-client"],
  "shell": {
    "init_hook": null
  },
  "nixpkgs": {
    "commit": "f80ac848e3d6f0c12c52758c0f25c10c97ca3b62"
  }
}

.envrc

# Automatically sets up your devbox environment whenever you cd into this
# directory via our direnv integration:

use_devbox() {
    watch_file devbox.json
    if [ -f .devbox/gen/shell.nix ]; then
        DEVBOX_SHELL_ENABLED_BACKUP=$DEVBOX_SHELL_ENABLED
        use nix .devbox/gen/shell.nix
        eval $(devbox shell --print-env)
        export DEVBOX_SHELL_ENABLED=$DEVBOX_SHELL_ENABLED_BACKUP
    fi
}
use devbox

# check out https://www.jetpack.io/devbox/docs/ide_configuration/direnv/
# for more details

About this issue

Original URL
State: closed
Created a year ago
Reactions: 2
Comments: 27 (2 by maintainers)

Commits related to this issue

[wrappers] Improve wrappers in multi-project env (#1067) ## Summary This is a possible cause of https://github.com/jetpack-io/devbox/issues/881#issuecomment-1565764159 bin wrappers belong to a... — committed to jetpack-io/devbox by mikeland73 a year ago
[bug] Added abs path ref. to devbox binary in wrappers (#1260) ## Summary This fixes an issue where if you install `coreutils` devbox shell in some cases gets stuck in infinite loop due this sequen... — committed to jetpack-io/devbox by mohsenari a year ago

Most upvoted comments

@altano yeah, I think the git wrapping may be the issue (exposing an existing devbox bug). Devbox creates wrappers for binaries to ensure nix setup hooks run (and any other environment that needs to be setup).

This PR addresses a bug in the wrappers but I don’t think it caused your issue.

The devbox bin wrappers are only needed when the environment doesn’t match. In that case they call eval "$(devbox shellenv)" to compute the correct environment. The problem is that if that call uses any devbox wrapped binaries, we may get stuck in an infinite loop. I’m not entirely sure where the infinite loop was triggered in your setup, but it’s definitely theoretically possible to trigger one.

One relatively simple fix is prevent shellenv-ception via environment variables. We’re trying to understand the implications of doing this since it could prevent binaries from running in the expected environment.

mikeland73 on May 31, 2023

@altano thanks! Glad it is working fine now.

@mstruebing lets track slow coreutils package in https://github.com/jetpack-io/devbox/issues/1350

savil on Aug 7, 2023

Closing since I’m not hearing anyone wanting me to leave this open. Thanks again!

altano on Aug 7, 2023

FWIW I haven’t hit either issue (slow startups or runaway process spawning) in at least many weeks. It’s been totally smooth sailing for me.

I have upgraded both devbox and the direnv script in all my active projects so I assume something got fixed and I’m now benefiting from it.

thank you all for your hard work on this great project

altano on Jul 7, 2023

Also, in case this is worth noting:

this project had the old style .envrc. I just force updated it to the eval "$(devbox generate direnv --print-envrc)" style.
I’m on devbox 0.5.2:

Version:     0.5.2
Platform:    darwin_arm64
Commit:      8f579b2c45c730742cbf9b7c400f247abf902775
Commit Time: 2023-05-18T16:18:52Z
Go Version:  go1.20.4
Launcher:    0.2.0

altano on May 28, 2023

I am reporting back with more clues. I haven’t touched my personal machine in many days, came back, tried to cd into my project and hit an indefinite hang in devbox (still have no shell after 20+ minutes). I noticed Activity Monitor was very unresponsive and using a ton of CPU when I opened it, which was very suspect. I checked how many devbox processes I have and this is what I see:

➜  src ps ax | grep devbox | wc -l
    4562

It looks like I have 4,562 devbox processes, evenly split between these two:

➜  src ps ax | grep devbox | head -n 100
16709 s002  S+     0:00.00 grep --color=auto --exclude-dir=.bzr --exclude-dir=CVS --exclude-dir=.git --exclude-dir=.hg --exclude-dir=.svn --exclude-dir=.idea --exclude-dir=.tox devbox
  134 s005  S+     0:00.00 /bin/bash /Users/alan/src/alan.norbauer.com/.devbox/virtenv/.wrappers/bin/git -C /Users/alan/src/alan.norbauer.com/.devbox/gen/flake init
  135 s005  S+     0:00.05 /Users/alan/.cache/devbox/bin/0.5.2_darwin_arm64/devbox shellenv --use-cached-print-dev-env
  193 s005  S+     0:00.00 /bin/bash /Users/alan/src/alan.norbauer.com/.devbox/virtenv/.wrappers/bin/git -C /Users/alan/src/alan.norbauer.com/.devbox/gen/flake init
  194 s005  S+     0:00.05 /Users/alan/.cache/devbox/bin/0.5.2_darwin_arm64/devbox shellenv --use-cached-print-dev-env
  252 s005  S+     0:00.00 /bin/bash /Users/alan/src/alan.norbauer.com/.devbox/virtenv/.wrappers/bin/git -C /Users/alan/src/alan.norbauer.com/.devbox/gen/flake init
  253 s005  S+     0:00.05 /Users/alan/.cache/devbox/bin/0.5.2_darwin_arm64/devbox shellenv --use-cached-print-dev-env
  331 s005  S+     0:00.00 /bin/bash /Users/alan/src/alan.norbauer.com/.devbox/virtenv/.wrappers/bin/git -C /Users/alan/src/alan.norbauer.com/.devbox/gen/flake init
  340 s005  S+     0:00.05 /Users/alan/.cache/devbox/bin/0.5.2_darwin_arm64/devbox shellenv --use-cached-print-dev-env
  445 s005  S+     0:00.00 /bin/bash /Users/alan/src/alan.norbauer.com/.devbox/virtenv/.wrappers/bin/git -C /Users/alan/src/alan.norbauer.com/.devbox/gen/flake init
...

This number is slowly shrinking: I waited a couple minutes and it was down to 4,454 processes, ~100 fewer than earlier.

I did a killall -KILL devbox and the hung devbox shell aborted initialization and iTerm was responsive again. I could immediately cd back into the directory and have devbox spin up.

So, more specifically, it looks like every so often devbox shell causes a huge number of devbox processes spin up and make initialization somewhere between very slow and unfathomably slow.

altano on May 28, 2023

Sorry for the delay in replying!

From the output you pasted above, something I don’t quite understand: why does doing devbox shell print the direnv: … output? I would expect that doing cd <directory of devbox project> would print the direnv: … output.

I’m opening these shells in VS Code w/ the devbox extension (that makes new terminals start a devbox shell) so I guess that’s all happening at the same time?

When it’s fast it looks like this

Note that I didn’t type devbox shell, that was done by the extension.

@altano this is unlikely, but thought I’d double check whether you have some job which periodically runs the nix garbage-collector in the background? That may explain the delay in your case.

Not one I’ve manually setup. I’m using the Determinate Systems nix installer (upon recommendations from the devbox team in another github issue). Perhaps it comes with some automatic gc they don’t prominently advertise on their front page?

altano on May 11, 2023