sdk
sdk copied to clipboard
dfinity
experiment: add logging for moc --print-dep calls
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.
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