opam is utterly slow on basic errors

[dbuenzli]

A basic command line typo takes more than 3s to respond. Not very pleasant.

> opam --version 
2.1.4
> time opam sitch
opam: unknown command `sitch', did you mean `switch' ?
Usage: opam COMMAND ...
Try `opam --help' for more information.
opam sitch  3.66s user 0.82s system 93% cpu 4.810 total

[avsm]

Looks like it's the 2.1.x depexts probing that's causing the slowdown.

% OPAMDEBUG=1 opam sitch
00:00.024  GSTATE                 LOAD-GLOBAL-STATE @ /Users/avsm/.opam
00:00.025  RSTATE                 LOAD-REPOSITORY-STATE @ /Users/avsm/.opam
00:00.069  CACHE(repository)      Loaded /Users/avsm/.opam/repo/state-323C573F.cache in 0.044s
00:00.069  RSTATE                 Cache found
00:00.069  STATE                  LOAD-SWITCH-STATE @ 5.0b2
00:00.070  CACHE(installed)       Loaded /Users/avsm/.opam/5.0b2/.opam-switch/packages/cache in 0.000s
00:00.282  STATE                  Switch state loaded in 0.212s
00:00.286  SYSTEM                 mkdir /var/folders/pv/2n59f7453qq5fn5c_vxkb0pm0000gn/T/opam-avsm-59418
00:00.298  GSTATE                 Failed to evaluate global variable sys-ocaml-version: "ocamlc": command not found.
00:00.357  XSYS                   Adding to env { LC_ALL=C }
00:01.061  STATE                  depexts loaded in 0.703s

and with depexts disabled

% OPAMDEBUG=1 OPAMNODEPEXTS=1 opam sitch
00:00.022  GSTATE                 LOAD-GLOBAL-STATE @ /Users/avsm/.opam
00:00.023  RSTATE                 LOAD-REPOSITORY-STATE @ /Users/avsm/.opam
00:00.069  CACHE(repository)      Loaded /Users/avsm/.opam/repo/state-323C573F.cache in 0.045s
00:00.069  RSTATE                 Cache found
00:00.069  STATE                  LOAD-SWITCH-STATE @ 5.0b2
00:00.069  CACHE(installed)       Loaded /Users/avsm/.opam/5.0b2/.opam-switch/packages/cache in 0.000s
00:00.282  STATE                  Switch state loaded in 0.213s
00:00.287  SYSTEM                 mkdir /var/folders/pv/2n59f7453qq5fn5c_vxkb0pm0000gn/T/opam-avsm-59655
00:00.299  GSTATE                 Failed to evaluate global variable sys-ocaml-version: "ocamlc": command not found.
opam: unknown command `sitch', did you mean `switch' ?
Usage: opam COMMAND ...

[dbuenzli]

Indeed. Here:

00:04.024 STATE depexts loaded in 3.344s

Your machine looks faster. My soon to be replaced computer is old, a 2015 model – it's still the laptop paid for by ocamlabs seven years ago!

[avsm]

My RISC-V board feels the pain a lot worse -- it takes 10s sometimes to pass the same startup time!

[rjbou]

Can you try with master? #5297 speeds up plugin lookup, cf #5296 (comment)
Related to #5296

[dbuenzli]

Using brew install --HEAD opam. Still feel a bit hangy but much better (0.57s).

> time OPAMDEBUG=1 opam sitch
00:00.028  GSTATE                 LOAD-GLOBAL-STATE @ /Users/dbuenzli/.opam
00:00.029  FMT_UPG                On-the-fly config upgrade, from 2.1 to 2.2~alpha
00:00.029  FMT_UPG                Format upgrade done
00:00.029  RSTATE                 LOAD-REPOSITORY-STATE @ /Users/dbuenzli/.opam
00:00.166  CACHE(repository)      Loaded /Users/dbuenzli/.opam/repo/state-3733FAEC.cache in 0.136s
00:00.166  RSTATE                 Cache found
00:00.166  STATE                  LOAD-SWITCH-STATE @ 4.14.0
00:00.172  CACHE(installed)       Loaded /Users/dbuenzli/.opam/4.14.0/.opam-switch/packages/cache in 0.001s
00:00.521  STATE                  Switch state loaded in 0.355s
opam: unknown command 'sitch', did you mean 'switch'?
Usage: opam [COMMAND] …
Try 'opam --help' for more information.
OPAMDEBUG=1 opam sitch  0.45s user 0.10s system 97% cpu 0.571 total

[dbuenzli]

(Since it may have influenced the timing note that I did not upgrade the state in order to be able to go back to the previous version, I have too much switches I don't want to nuke right now and need a stable opam)

[kit-ty-kate]

(Since it may have influenced the timing note that I did not upgrade the state in order to be able to go back to the previous version, I have too much switches I don't want to nuke right now and need a stable opam)

I just tested locally and this has no influence (if anything, for me it was 0.005s faster 😅)

To compare here is the timing information i got on a freshly upgrade opam on a fast machine (M1Pro):

$ time OPAMDEBUG=1 ./opam sitch
00:00.003  GSTATE                 LOAD-GLOBAL-STATE @ /home/ocaml/.opam
00:00.003  FMT_UPG                On-the-fly config upgrade, from 2.1 to 2.2~alpha
00:00.003  FMT_UPG                Format upgrade done
00:00.003  RSTATE                 LOAD-REPOSITORY-STATE @ /home/ocaml/.opam
00:00.045  CACHE(repository)      Loaded /home/ocaml/.opam/repo/state-3733FAEC.cache in 0.042s
00:00.045  RSTATE                 Cache found
00:00.045  STATE                  LOAD-SWITCH-STATE @ ocaml-base-compiler.5.0.0
00:00.045  CACHE(installed)       Loaded /home/ocaml/.opam/ocaml-base-compiler.5.0.0/.opam-switch/packages/cache in 0.000s
00:00.254  STATE                  Switch state loaded in 0.208s
opam: unknown command 'sitch', did you mean 'switch'?
Usage: opam [COMMAND] …
Try 'opam --help' for more information.

real	0m0.259s
user	0m0.245s
sys	0m0.012s

Loading switch state still takes 0.2s even on a fairly fast machine.

Testing on the second slowest machine i have (Late 2012 Mac Mini) the same thing gets me:

$ time OPAMDEBUG=1 opam sitch
00:00.028  GSTATE                 LOAD-GLOBAL-STATE @ /Users/admin/.opam
00:00.029  FMT_UPG                On-the-fly config upgrade, from 2.1 to 2.2~alpha
00:00.029  FMT_UPG                Format upgrade done
00:00.029  RSTATE                 LOAD-REPOSITORY-STATE @ /Users/admin/.opam
00:00.158  CACHE(repository)      Loaded /Users/admin/.opam/repo/state-3733FAEC.cache in 0.129s
00:00.158  RSTATE                 Cache found
00:00.158  STATE                  LOAD-SWITCH-STATE @ 5.0
00:00.159  CACHE(installed)       Loaded /Users/admin/.opam/5.0/.opam-switch/packages/cache in 0.000s
00:00.508  STATE                  Switch state loaded in 0.350s
opam: unknown command 'sitch', did you mean 'switch'?
Usage: opam [COMMAND] …
Try 'opam --help' for more information.
OPAMDEBUG=1 opam sitch  0.46s user 0.09s system 97% cpu 0.555 total

I have several RPi4 that might be a bit slower but they're not cooperating at the moment.

To me, 2.5x slower on a 10 years old machine seems to be a reasonable expectation.

That said, now we could try to explore further and try to improve the performance of the cache and switch loading code but this seems quite tricky. For example, from what I can see, the bulk of the time is spent here converting the entire map of opam packages to its definition to a set for ease of use and memory print reduction further down the line:

opam/src/state/opamSwitchState.ml

Line 348 in 334cf68

let packages = OpamPackage.keys opams in

[dbuenzli]

I have several RPi4 that might be a bit slower but they're not cooperating at the moment.

It's spring, you need to water them.