experiment: add logging for moc --print-dep calls

[crusso]

Used to debug issue https://dfinity.atlassian.net/browse/SDKTG-319.

Using this branch, when compiling https://github.com/luc-blaeser/dfx-long-building I get the following output:

crusso@vm:~$ cd dfx-long-building/
crusso@vm:~/dfx-long-building$ dfx build -vvvv
Trace mode enabled. Lots of logs coming up.
Checking if identity 'default' exists.
Building canisters...
No canister of type 'rust' found. Not trying to run 'cargo audit'.
get_dependenciestest
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/test.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module1.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module2.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module3.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module4.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module5.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module6.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module7.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module8.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module9.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module10.mo"...
Building canister 'test'.
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/test.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module1.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module2.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module3.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module4.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module5.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module6.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module7.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module8.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module9.mo"...
Running "moc-wrapper" "--print-deps" "/home/crusso/dfx-long-building/src/extra/module10.mo"...
Running "moc-wrapper" "/home/crusso/dfx-long-building/src/test.mo" "-o" "/home/crusso/dfx-long-building/.dfx/local/canisters/test/test.wasm" "-c" "--debug" "--idl" "--stable-types" "--public-metadata" "candid:service" "--public-metadata" "candid:args" "--actor-idl" "/home/crusso/dfx-long-building/.dfx/local/canisters/idl/" "--actor-alias" "test" "bkyz2-fmaaa-aaaaa-qaaaq-cai" "--package" "base" "/home/crusso/.cache/dfinity/versions/0.19.0+rev15.dirty-0a1d4696/base"...
WARN: /home/crusso/dfx-long-building/src/test.mo:1.8-1.15: warning [M0194], unused identifier Module1 (delete or rename to wildcard `_` or `_Module1`)
/home/crusso/dfx-long-building/src/test.mo:2.8-2.15: warning [M0194], unused identifier Module2 (delete or rename to wildcard `_` or `_Module2`)
/home/crusso/dfx-long-building/src/test.mo:3.8-3.15: warning [M0194], unused identifier Module3 (delete or rename to wildcard `_` or `_Module3`)
/home/crusso/dfx-long-building/src/test.mo:4.8-4.15: warning [M0194], unused identifier Module4 (delete or rename to wildcard `_` or `_Module4`)
/home/crusso/dfx-long-building/src/test.mo:5.8-5.15: warning [M0194], unused identifier Module5 (delete or rename to wildcard `_` or `_Module5`)
/home/crusso/dfx-long-building/src/test.mo:6.8-6.15: warning [M0194], unused identifier Module6 (delete or rename to wildcard `_` or `_Module6`)
/home/crusso/dfx-long-building/src/test.mo:7.8-7.15: warning [M0194], unused identifier Module7 (delete or rename to wildcard `_` or `_Module7`)
/home/crusso/dfx-long-building/src/test.mo:8.8-8.15: warning [M0194], unused identifier Module8 (delete or rename to wildcard `_` or `_Module8`)
/home/crusso/dfx-long-building/src/test.mo:9.8-9.15: warning [M0194], unused identifier Module9 (delete or rename to wildcard `_` or `_Module9`)
/home/crusso/dfx-long-building/src/test.mo:10.8-10.16: warning [M0194], unused identifier Module10 (delete or rename to wildcard `_` or `_Module10`)

Post processing candid file
Shrinking WASM
Attaching metadata

Each call to moc-wrapper is noticebly slow, presumably because it invokes first bash, then node and finally moc.

crusso@vm:~/dfx-long-building$ cat $(which moc-wrapper)
#!/bin/bash
mocPath="$(mops toolchain bin moc --fallback)"
$mocPath "$@"

Also, the dependencies for the canister are computed twice, once for a good reason, the second time to detect whether the management canister is referenced.

It could just be super-slow on my VM and fine elsewhere, but certainly, on my VM, the deps calculation dominates the rest of the work.

[crusso]

I’ve noticed on my machine that moc is somehow aliased to moc-wrapper (installed by ic-mops via DFX_MOC_PATH) and this hugely slowly down builds.

The cost of doing one --print-deps via moc-wrapper is much higher (50x) than invoking moc directly:

crusso@vm:~/dfx-long-building$ time moc-wrapper --print-deps src/test.mo
extra/module1 src/extra/module1.mo
extra/module2 src/extra/module2.mo
extra/module3 src/extra/module3.mo
extra/module4 src/extra/module4.mo
extra/module5 src/extra/module5.mo
extra/module6 src/extra/module6.mo
extra/module7 src/extra/module7.mo
extra/module8 src/extra/module8.mo
extra/module9 src/extra/module9.mo
extra/module10 src/extra/module10.mo
mo:prim

real	0m0.704s
user	0m0.724s
sys	0m0.149s

Here's the cost of doing this directly:

crusso@vm:~/dfx-long-building$ time /home/crusso/.cache/dfinity/versions/0.19.0+rev15.dirty-0a1d4696/moc --print-deps src/test.mo
extra/module1 src/extra/module1.mo
extra/module2 src/extra/module2.mo
extra/module3 src/extra/module3.mo
extra/module4 src/extra/module4.mo
extra/module5 src/extra/module5.mo
extra/module6 src/extra/module6.mo
extra/module7 src/extra/module7.mo
extra/module8 src/extra/module8.mo
extra/module9 src/extra/module9.mo
extra/module10 src/extra/module10.mo
mo:prim

real	0m0.017s
user	0m0.016s
sys	0m0.000s

On a full build with several calls to moc --print-deps, this adds up:

russo@vm:~/dfx-long-building$ time dfx build
Building canisters...
...
real	0m16.328s
user	0m16.686s
sys	0m3.511s

crusso@vm:~/dfx-long-building$ time DFX_MOC_PATH=$(mops toolchain bin moc --fallback) dfx build
...
real	0m1.458s
user	0m1.325s
sys	0m0.297s

[crusso]

Opened mops issue ZenVoich/mops#222