Stuck at purs graph

[CGenie]

Hello,

I'm using spago 0.93.35 with purs 0.15.15. My project was building recently, but currently for some unknown reason, in --verbose mode it's stuck at:

[   94065ms] Called `purs graph`, decoding..

I tried to repeat that purs graph command, it does spit out a very large JSON object (containing 1185 keys).

Thing is, it's stuck for very long and CPU does crunch something.

Looking at source code, I think it might be decoding that large JSON for so long -- is it possible? And if so, is there a fix for this?

[f-f]

I wonder if you're hitting #1242 - a few questions to try to pinpoint the issue:

1. do you still experience the problem with version 0.93.32?
2. can you post debug output? (run with -v flag) oh I see you're already running with verbose output, can you post the last lines before it gets stuck?

[CGenie]

OK, I installed spago 0.93.32 from Nix and indeed, this worked now. So must be some bug in later versions.

The 0.93.32 output is this:

[    2626ms] Running command:
purs graph ../../../../../data/git-work/github/PURESCRIPT/purescript-var/src/**/*.purs .spago/p/aff-7.1.0/src/**/*.purs .spago/p/aff-promise-4.0.0/src/**/*.purs .spago/p/affjax-13.0.0/src/**/*.purs .spago/p/affjax-node-1.0.0/src/**/*.purs .spago/p/affjax-web-1.0.0/src/**/*.purs .spago/p/ansi-7.0.0/src/**/*.purs .spago/p/argonaut-9.0.0/src/**/*.purs .spago/p/argonaut-codecs-9.1.0/src/**/*.purs .spago/p/argonaut-core-7.0.0/src/**/*.purs .spago/p/argonaut-traversals-10.0.0/src/**/*.purs .spago/p/arraybuffer-types-3.0.2/src/**/*.purs .spago/p/arrays-7.3.0/src/**/*.purs .spago/p/assert-6.0.0/src/**/*.purs .spago/p/avar-5.0.0/src/**/*.purs .spago/p/bifunctors-6.0.0/src/**/*.purs .spago/p/catenable-lists-7.0.0/src/**/*.purs .spago/p/colors-7.0.1/src/**/*.purs .spago/p/console-6.1.0/src/**/*.purs .spago/p/const-6.0.0/src/**/*.purs .spago/p/contravariant-6.0.0/src/**/*.purs .spago/p/control-6.0.0/src/**/*.purs .spago/p/convertable-options-1.0.0/src/**/*.purs .spago/p/css-6.0.0/src/**/*.purs .spago/p/d3/37ad74a2933dc8cb07be121928054af6baecfba4/src/**/*.purs .spago/p/data-default/4b7a0b7f5f53f237dab7a55f362d4e775e847d89/src/**/*.purs .spago/p/datetime-6.1.0/src/**/*.purs .spago/p/debouncing-0.1.2/src/**/*.purs .spago/p/debug-6.0.2/src/**/*.purs .spago/p/distributive-6.0.0/src/**/*.purs .spago/p/dom-filereader-7.0.0/src/**/*.purs .spago/p/dom-simple-0.4.0/src/**/*.purs .spago/p/effect-4.0.0/src/**/*.purs .spago/p/either-6.1.0/src/**/*.purs .spago/p/enums-6.0.1/src/**/*.purs .spago/p/exceptions-6.1.0/src/**/*.purs .spago/p/exists-6.0.0/src/**/*.purs .spago/p/ffi-simple-0.5.1/src/**/*.purs .spago/p/filterable-5.0.0/src/**/*.purs .spago/p/fixed-points-7.0.0/src/**/*.purs .spago/p/foldable-traversable-6.0.0/src/**/*.purs .spago/p/foreign-7.0.0/src/**/*.purs .spago/p/foreign-object-4.1.0/src/**/*.purs .spago/p/fork-6.0.0/src/**/*.purs .spago/p/form-urlencoded-7.0.0/src/**/*.purs .spago/p/formatters-7.0.0/src/**/*.purs .spago/p/free-7.1.0/src/**/*.purs .spago/p/functions-6.0.0/src/**/*.purs .spago/p/functors-5.0.0/src/**/*.purs .spago/p/gen-4.0.0/src/**/*.purs .spago/p/graphql-client/051dc0fdef337980f615c29440a07f42c734de43/src/**/*.purs .spago/p/halogen-subscriptions-2.0.0/src/**/*.purs .spago/p/heterogeneous-0.6.0/src/**/*.purs .spago/p/http-methods-6.0.0/src/**/*.purs .spago/p/identity-6.0.0/src/**/*.purs .spago/p/int64-3.0.0/src/**/*.purs .spago/p/integers-6.0.0/src/**/*.purs .spago/p/invariant-6.0.0/src/**/*.purs .spago/p/js-date-8.0.0/src/**/*.purs .spago/p/js-timers-6.1.0/src/**/*.purs .spago/p/js-uri-3.1.0/src/**/*.purs .spago/p/lazy-6.0.0/src/**/*.purs .spago/p/lcg-4.0.0/src/**/*.purs .spago/p/lists-7.0.0/src/**/*.purs .spago/p/markdown-it/94075f6b017999d15b7b09f255e1d67c7750496f/src/**/*.purs .spago/p/maybe-6.0.0/src/**/*.purs .spago/p/media-types-6.0.0/src/**/*.purs .spago/p/milkis-9.0.0/src/**/*.purs .spago/p/mmorph-7.0.0/src/**/*.purs .spago/p/newtype-5.0.0/src/**/*.purs .spago/p/node-buffer-9.0.0/src/**/*.purs .spago/p/node-event-emitter-3.0.0/src/**/*.purs .spago/p/node-fs-9.2.0/src/**/*.purs .spago/p/node-path-5.0.0/src/**/*.purs .spago/p/node-streams-9.0.0/src/**/*.purs .spago/p/nonempty-7.0.0/src/**/*.purs .spago/p/now-6.0.0/src/**/*.purs .spago/p/nullable-6.0.0/src/**/*.purs .spago/p/numbers-9.0.1/src/**/*.purs .spago/p/options-7.0.0/src/**/*.purs .spago/p/ordered-collections-3.2.0/src/**/*.purs .spago/p/orders-6.0.0/src/**/*.purs .spago/p/parallel-7.0.0/src/**/*.purs .spago/p/parsing-10.2.0/src/**/*.purs .spago/p/partial-4.0.0/src/**/*.purs .spago/p/pipes-8.0.0/src/**/*.purs .spago/p/prelude-6.0.1/src/**/*.purs .spago/p/profunctor-6.0.1/src/**/*.purs .spago/p/profunctor-lenses-8.0.0/src/**/*.purs .spago/p/psci-support-6.0.0/src/**/*.purs .spago/p/quickcheck-8.0.1/src/**/*.purs .spago/p/quickcheck-laws-7.0.0/src/**/*.purs .spago/p/random-6.0.0/src/**/*.purs .spago/p/react-11.0.0/src/**/*.purs .spago/p/reactix-0.6.1/src/**/*.purs .spago/p/record-4.0.0/src/**/*.purs .spago/p/record-extra-5.0.1/src/**/*.purs .spago/p/refs-6.0.0/src/**/*.purs .spago/p/routing-11.0.0/src/**/*.purs .spago/p/safe-coerce-2.0.0/src/**/*.purs .spago/p/semirings-7.0.0/src/**/*.purs .spago/p/sequences/96e368b99927c295b5f9036c754518e2c67bd162/src/**/*.purs .spago/p/simple-json-9.0.0/src/**/*.purs .spago/p/simple-json-generics-0.2.1/src/**/*.purs .spago/p/small-ffi-4.0.1/src/**/*.purs .spago/p/spec-7.6.0/src/**/*.purs .spago/p/spec-discovery/8e1e85dea4b52c5b52f80003311226c327fbba64/src/**/*.purs .spago/p/spec-quickcheck-5.0.0/src/**/*.purs .spago/p/st-6.2.0/src/**/*.purs .spago/p/string-parsers-8.0.0/src/**/*.purs .spago/p/string-search/ac2a05d7c3728b6d26a979903c444049b4f53420/src/**/*.purs .spago/p/strings-6.0.1/src/**/*.purs .spago/p/strings-extra-4.0.0/src/**/*.purs .spago/p/stringutils-0.0.12/src/**/*.purs .spago/p/tailrec-6.1.0/src/**/*.purs .spago/p/these-6.0.0/src/**/*.purs .spago/p/toestand-0.9.0/src/**/*.purs .spago/p/transformers-6.1.0/src/**/*.purs .spago/p/tuples-7.0.0/src/**/*.purs .spago/p/tuples-native/72f097fb04c4ddb72d6994887ece856fdc59634f/src/**/*.purs .spago/p/type-equality-4.0.1/src/**/*.purs .spago/p/typelevel-6.0.0/src/**/*.purs .spago/p/typelevel-lists-2.1.0/src/**/*.purs .spago/p/typelevel-peano-1.0.1/src/**/*.purs .spago/p/typelevel-prelude-7.0.0/src/**/*.purs .spago/p/typisch-0.4.0/src/**/*.purs .spago/p/unfoldable-6.0.0/src/**/*.purs .spago/p/unicode-6.0.0/src/**/*.purs .spago/p/unordered-collections-3.1.0/src/**/*.purs .spago/p/unsafe-coerce-6.0.0/src/**/*.purs .spago/p/unsafe-reference-5.0.0/src/**/*.purs .spago/p/uri-9.0.0/src/**/*.purs .spago/p/uuid-9.0.0/src/**/*.purs .spago/p/validation-6.0.0/src/**/*.purs .spago/p/variant-8.0.0/src/**/*.purs .spago/p/web-dom-6.0.0/src/**/*.purs .spago/p/web-events-4.0.0/src/**/*.purs .spago/p/web-file-4.0.0/src/**/*.purs .spago/p/web-html-4.1.0/src/**/*.purs .spago/p/web-socket-4.0.0/src/**/*.purs .spago/p/web-storage-5.0.0/src/**/*.purs .spago/p/web-url-2.0.0/src/**/*.purs .spago/p/web-xhr-5.0.1/src/**/*.purs .spago/p/websocket-simple/e852afaa13ba406155e5097d56b5d2772f68496b/src/**/*.purs /home/przemek/GARGANTEXT/haskell-gargantext/purescript-gargantext/.spago/BuildInfo.purs src/**/*.purs test/**/*.purs
[    2883ms] Called `purs graph`, decoding..
[   12716ms] 

The output for 0.93.35 is the same except the last [ 12716ms] line because obviously it doesn't get there.

[CGenie]

BTW, the 0.93.32 build feels still slower than was was there previously. The purescript builds for me always were fast and now I'm visibly waiting for the purs graph step.

[f-f]

Ah I see - we switched json library in 0.93.31, can you try how's the performance with 0.93.30?

[f-f]

Btw I assume that you want the graph command to run, as you have pedantic-packages on, or some of the other options that require a graph. I guess we could do a better job at noting which of the options rely on the graph.

[CGenie]

Ah I see - we switched json library in 0.93.31, can you try how's the performance with 0.93.30?

I don't see a large time difference between 0.93.30 and 0.93.32, it's around 29 seconds for both and the transitive dependencies step is the longest.

Indeed I have pedanticPackages turned on as recommended in #1211 (comment) but I guess for dev builds it doesn't matter.

[f-f]

Do you happen to have a repo with many packages? I added additional logging, and I'm testing on purescript-core - it turns out the bottleneck is not the JSON decoding, but running the computations on the graph takes 1-2s per package:

[    3189ms] Called `purs graph`, decoding..
[    3195ms] Decoded the output of `purs graph` successfully. Analyzing dependencies...
[    3196ms] Checking imports for arrays
[    4471ms] Checking imports for assert
[    5696ms] Checking imports for console
[    6917ms] Checking imports for control
[    8144ms] Checking imports for datetime
[    9388ms] Checking imports for effect
[   10570ms] Checking imports for enums
[   11781ms] Checking imports for exceptions
[   12986ms] Checking imports for foldable-traversable
[   14189ms] Checking imports for foreign-object
[   15414ms] Checking imports for functions
[   16606ms] Checking imports for integers
[   17815ms] Checking imports for json
[   19027ms] Checking imports for lazy
[   20238ms] Checking imports for minibench
[   21496ms] Checking imports for numbers
[   22744ms] Checking imports for partial
[   24031ms] Checking imports for prelude
[   25256ms] Checking imports for quickcheck
[   26491ms] Checking imports for random
[   27738ms] Checking imports for record
[   28956ms] Checking imports for refs
[   30180ms] Checking imports for st
[   31429ms] Checking imports for strings
[   32664ms] Checking imports for unfoldable
[   33929ms] Checking imports for unsafe-coerce

[f-f]

@CGenie I just released 0.93.36 with additional logging - it looks like most of the time is being spent in getModuleGraphWithPackage

[CGenie]

I'm working on an open-source project:
https://gitlab.iscpif.fr/gargantext/purescript-gargantext

Please check out the dev branch.

You might be lucky just running:

yarn
yarn spago build

but if not, then try nix -L develop to use the flake.nix setup.

[peterbecich]

Here is another reproduction case for this:

https://github.com/peterbecich/purescript-bridge/tree/merge-iohk-3

$ nix develop

# in nix develop shell

$ spago graph modules --verbose
...
[    1565ms] Called `purs graph`, decoding..

spago build succeeds

$ spago build                  
Reading Spago workspace configuration...

✅ Selecting 3 packages to build:
    argonaut-round-trip-test
    example
    json-helpers-round-trip-test

Downloading dependencies...
Building...
           Src   Lib   All
Warnings     0     0     0
Errors       0     0     0

✅ Build succeeded.

spago 0.93.35
purs 0.15.15

, tools provided by https://github.com/thomashoneyman/purescript-overlay

Thanks

[f-f]

I narrowed it down to this line taking 50ms for each dependency:

spago/src/Spago/Purs/Graph.purs

Line 104 in f130b33

globMatches :: Array FilePath <- map Array.fold $ traverse compileGlob (Config.sourceGlob withTestGlobs name package)

I won't manage to have a look at this for a while, but this is a good pointer for anyone that would like to look at it - I suspect the glob code can be improved; we swapped it out for a different implementation in #1220, so 0.93.29 will have a different code path and might be faster - something to try out.
Something else to look at is that these few lines look very quadratic in complexity: we are iterating through all the paths and matching all of them through all the globs. We should be able to cut this time in half by using a fold instead, where we prune the paths that have already been matched.