Extremely long link time

[mzukovec]

Running on version 3.1.60

We have a quite large repository that we build using Emscripten. The link time became quite time-consuming (~2min on Intel i7 12700F), which is unusually long since lld (and its port wasm-ld) should be very fast and typically not the bottleneck in the build process.

We went through the following issue #17019 and applied both flags -sERROR_ON_WASM_CHANGES_AFTER_LINK -sWASM_BIGINT. We build/link with -Og.

This is the EMPROFILE=2 verbose output for the final link stage:

...
profiler:INFO:   start block "link"
profiler:INFO:   block "link" took 147.589 seconds
profiler:INFO:   start block "post link"
profiler:INFO:     start block "emscript"
profiler:INFO:       start block "get_metadata"
profiler:INFO:       block "get_metadata" took 1.040 seconds
profiler:INFO:       start block "compile_javascript"
profiler:INFO:       block "compile_javascript" took 0.208 seconds
profiler:INFO:     block "emscript" took 3.278 seconds
profiler:INFO:     start block "binaryen"
profiler:INFO:       start block "use_unsigned_pointers_in_js"
profiler:INFO:       block "use_unsigned_pointers_in_js" took 0.598 seconds
profiler:INFO:       start block "apply_wasm_memory_growth"
profiler:INFO:       block "apply_wasm_memory_growth" took 1.007 seconds
profiler:INFO:     block "binaryen" took 3.300 seconds
profiler:INFO:     start block "final emitting"
profiler:INFO:     block "final emitting" took 1.497 seconds
profiler:INFO:   block "post link" took 8.077 seconds
profiler:INFO: block "main" took 155.752 seconds

These are our build flags:

FLAGS = -stdlib=libc++ -pthread -sSHARED_MEMORY=1 -sUSE_PTHREADS=1  LINK_FLAGS = -pthread -sSHARED_MEMORY=1 -sUSE_PTHREADS=1 -sMALLOC=mimalloc      "-S --allow-multiple-definition" --closure 1 --closure-args=--jscomp_off=* -sLEGACY_GL_EMULATION -sGL_UNSAFE_OPTS=0 -sGL_FFP_ONLY=1 -WASM=1 --bind -sDISABLE_DEPRECATED_FIND_EVENT_TARGET_BEHAVIOR=1 -sMODULARIZE=1 -sFORCE_FILESYSTEM=1 -sEXPORT_NAME=createModuleFactory -sALLOW_MEMORY_GROWTH=1 -sMALLOC=mimalloc -sINITIAL_MEMORY=1GB -sMAXIMUM_MEMORY=4GB -sPROXY_TO_PTHREAD -sEXIT_RUNTIME=1 -sALLOW_BLOCKING_ON_MAIN_THREAD=1 "-sEXPORTED_RUNTIME_METHODS=['FS','PATH','ERRNO_CODES']" "-sPTHREAD_POOL_SIZE='navigator.hardwareConcurrency*2+1'" -error-limit=0 -sASSERTIONS=1 -sNO_DISABLE_EXCEPTION_CATCHING -gseparate-dwarf -Og --profiling-funcs -sREVERSE_DEPS=all -sWASM_BIGINT -sERROR_ON_WASM_CHANGES_AFTER_LINK

Is there anything that you suggest can be done in order to decrease the link time?

[mzukovec]

It seems like there are some default LTO optimization enabled for wasm-ld, which can be overridden with

target_link_options(<executable_name> PRIVATE
        "-Wl,--threads=20"
        "-Wl,--lto-partitions=20"
        "-Wl,--lto-O0"
        "-Wl,--lto-CGO0")

The final link stage now takes a lot less, which is useful for quick debug iterations:

profiler:INFO:   start block "link"
profiler:INFO:   block "link" took 20.828 seconds
profiler:INFO:   start block "post link"
profiler:INFO:     start block "emscript"
profiler:INFO:       start block "get_metadata"
profiler:INFO:       block "get_metadata" took 0.487 seconds
profiler:INFO:       start block "compile_javascript"
profiler:INFO:       block "compile_javascript" took 0.176 seconds
profiler:INFO:     block "emscript" took 1.812 seconds
profiler:INFO:     start block "binaryen"
profiler:INFO:       start block "use_unsigned_pointers_in_js"
profiler:INFO:       block "use_unsigned_pointers_in_js" took 0.551 seconds
profiler:INFO:       start block "apply_wasm_memory_growth"
profiler:INFO:       block "apply_wasm_memory_growth" took 0.945 seconds
profiler:INFO:       start block "handle_final_wasm_symbols"
profiler:INFO:       block "handle_final_wasm_symbols" took 12.446 seconds
profiler:INFO:     block "binaryen" took 14.882 seconds
profiler:INFO:     start block "final emitting"
profiler:INFO:     block "final emitting" took 0.912 seconds
profiler:INFO:   block "post link" took 17.607 seconds
profiler:INFO: block "main" took 38.507 seconds

[sbc100]

So it looks like most all of the time is LTO? And it looks like you have found LTO flags to control how LTO runs, but you could also completely avoid LTO in your debug builds if you want the fastest possible link time (i.e. compile your object files without -flto)

[mzukovec]

An in-depth inspection revealed that one of the dependencies was mistakenly built with -flto, which resulted in such long link times. After we resolved that, link time is back to "normal". Binaryen still takes quite some time though, but it's better.

These are the final binrayen flags for the debug build now:
--print-function-map --mvp-features --enable-threads --enable-bulk-memory --enable-multivalue --enable-mutable-globals --enable-reference-types --enable-sign-ext --enable-simd.

If there is nothing else that can be done regarding speeding up the link time, you can close this issue.
Thanks for your time.

profiler:INFO:   start block "link"
profiler:INFO:   block "link" took 8.152 seconds
profiler:INFO:   start block "post link"
profiler:INFO:     start block "emscript"
profiler:INFO:       start block "get_metadata"
profiler:INFO:       block "get_metadata" took 0.325 seconds
profiler:INFO:       start block "compile_javascript"
profiler:INFO:       block "compile_javascript" took 0.243 seconds
profiler:INFO:     block "emscript" took 0.837 seconds
profiler:INFO:     start block "binaryen"
profiler:INFO:       start block "use_unsigned_pointers_in_js"
profiler:INFO:       block "use_unsigned_pointers_in_js" took 0.317 seconds
profiler:INFO:       start block "apply_wasm_memory_growth"
profiler:INFO:       block "apply_wasm_memory_growth" took 0.312 seconds
profiler:INFO:       start block "handle_final_wasm_symbols"
profiler:INFO:       block "handle_final_wasm_symbols" took 4.864 seconds
05:52:38.211188 run_wasm_opt finish
profiler:INFO:     block "binaryen" took 5.600 seconds
profiler:INFO:     start block "final emitting"
profiler:INFO:     block "final emitting" took 0.002 seconds
profiler:INFO:   block "post link" took 6.439 seconds
profiler:INFO: block "main" took 14.687 seconds

[kripken]

That last binaryen command is printing out the symbol map (list of function names), for which it reads the wasm. For a very large wasm file, taking a few seconds is normal there. (If this is a smaller file then maybe something odd is happening, and if you provide the file I can profile it.)

You can skip that stage by not providing --emit-symbol-map during link. Maybe in fast iteration builds you don't need the symbol map, for example.

[mzukovec]

This is quite large file (1.5GB) because we don't run any optimizations for the debug build. Therefore we need to run emstrip to reduce the size of the final binary and we need the --emit-symbol-map to use the enable the debugging.

Sadly I cannot share the wasm file itself due to the legal requirements.

[mzukovec]

After profiling, the most time-consuming par of the wasm-opt is in this case the WasmBinaryReader::read which by the quick look serially reads the wasm file and parses the individual sections. Are there any plans to maybe make this parallel?

[kripken]

@mzukovec funny you should mention that, @tlively just opened a draft PR for it!

WebAssembly/binaryen#7134