Extremely slow startup time in Node environment
692 views
Skip to first unread message
Александр Гурьянов
Feb 8, 2021, 4:40:32 AM2/8/21
to emscripte...@googlegroups.com
Hi. I created a test program to estimate performance of my program. I
am trying to use it both in browser and node environment. Test program
works fine in both environments. However startups in node took up to
30 sec, while in browser it starts instantly. I don’t understand why.
I use an release build with -s ASYNCIFY = 1, my node.js script:
```
const { performance } = require('perf_hooks');
const dhry2 = require("./dhry2.js");
const startedAt = performance.now();
const Module = {
log: console.log,
performance,
onRuntimeInitialized: () => {
console.log("Runtime initialized after", performance.now() -
startedAt, "ms");
Module.callMain([]);
},
};
dhry2(Module);
```
And for browser:
```
<!DOCTYPE html>
<html>
<head>
<script src="dhry2.js"></script>
<meta name="viewport" content="width=device-width,
initial-scale=1.0, maximum-scale=1.0, user-scalable=no" />
</head>
<body>
<button onclick="javascript:start()">Start</button>
<br/>
<div id="stdout"></div>
<script>
var stdout = document.getElementById("stdout");
function start() {
WDHRY2({
log: function(message) {
},
print: function(message) {
if (message.startsWith("dhry2")) {
console.log(message);
stdout.innerHTML = stdout.innerHTML + "<br/>"
+ message;
}
},
}).then(function(m) {
m.callMain([]);
});
};
</script>
</body>
</html>
```
Node.js version starts in 30 sec, while browser versions starts
immediately. Node hangs after leaving instantiateArrayBuffer and
before entering receiveInstantiatedSource.
I think it doing something, but I don't understand what. I profiled
node but results is no obvious:
```
Statistical profiling result from isolate-0x36df400-1353021-v8.log,
(28109 ticks, 0 unaccounted, 0 excluded).
[Shared libraries]:
ticks total nonlib name
44 0.2% /home/caiiiycuk/sdk/emsdk/node/12.18.1_64bit/bin/node
5 0.0% /usr/lib/x86_64-linux-gnu/libc-2.31.so
1 0.0% /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.28
[JavaScript]:
ticks total nonlib name
1 0.0% 0.0% Function: *wasm-function[2219]
[C++]:
ticks total nonlib name
27974 99.5% 99.7% __pthread_cond_wait
35 0.1% 0.1%
node::native_module::NativeModuleEnv::CompileFunction(v8::FunctionCallbackInfo<v8::Value>
const&)
...
[Summary]:
ticks total nonlib name
1 0.0% 0.0% JavaScript
28058 99.8% 100.0% C++
...
[C++ entry points]:
ticks cpp total name
45 76.3% 0.2% v8::internal::Builtin_HandleApiCall(int,
unsigned long*, v8::internal::Isolate*)
3 5.1% 0.0% node::inspector::(anonymous
namespace)::InspectorConsoleCall(v8::FunctionCallbackInfo<v8::Value>
const&)
[Bottom up (heavy) profile]:
Note: percentage shows a share of a particular caller in the total
amount of its parent calls.
Callers occupying less than 1.0% are not shown.
ticks parent name
27974 99.5% __pthread_cond_wait
```
I attached the build with -g you can test it both in browser and node.
(link: https://drive.google.com/file/d/1lucme6dv-9D5yB-Wu9PieUjY5ag0YvxY/view?usp=sharing)
borwser: dhry2.html
node: node dhry2_node.js
am trying to use it both in browser and node environment. Test program
works fine in both environments. However startups in node took up to
30 sec, while in browser it starts instantly. I don’t understand why.
I use an release build with -s ASYNCIFY = 1, my node.js script:
```
const { performance } = require('perf_hooks');
const dhry2 = require("./dhry2.js");
const startedAt = performance.now();
const Module = {
log: console.log,
performance,
onRuntimeInitialized: () => {
console.log("Runtime initialized after", performance.now() -
startedAt, "ms");
Module.callMain([]);
},
};
dhry2(Module);
```
And for browser:
```
<!DOCTYPE html>
<html>
<head>
<script src="dhry2.js"></script>
<meta name="viewport" content="width=device-width,
initial-scale=1.0, maximum-scale=1.0, user-scalable=no" />
</head>
<body>
<button onclick="javascript:start()">Start</button>
<br/>
<div id="stdout"></div>
<script>
var stdout = document.getElementById("stdout");
function start() {
WDHRY2({
log: function(message) {
},
print: function(message) {
if (message.startsWith("dhry2")) {
console.log(message);
stdout.innerHTML = stdout.innerHTML + "<br/>"
+ message;
}
},
}).then(function(m) {
m.callMain([]);
});
};
</script>
</body>
</html>
```
Node.js version starts in 30 sec, while browser versions starts
immediately. Node hangs after leaving instantiateArrayBuffer and
before entering receiveInstantiatedSource.
I think it doing something, but I don't understand what. I profiled
node but results is no obvious:
```
Statistical profiling result from isolate-0x36df400-1353021-v8.log,
(28109 ticks, 0 unaccounted, 0 excluded).
[Shared libraries]:
ticks total nonlib name
44 0.2% /home/caiiiycuk/sdk/emsdk/node/12.18.1_64bit/bin/node
5 0.0% /usr/lib/x86_64-linux-gnu/libc-2.31.so
1 0.0% /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.28
[JavaScript]:
ticks total nonlib name
1 0.0% 0.0% Function: *wasm-function[2219]
[C++]:
ticks total nonlib name
27974 99.5% 99.7% __pthread_cond_wait
35 0.1% 0.1%
node::native_module::NativeModuleEnv::CompileFunction(v8::FunctionCallbackInfo<v8::Value>
const&)
...
[Summary]:
ticks total nonlib name
1 0.0% 0.0% JavaScript
28058 99.8% 100.0% C++
...
[C++ entry points]:
ticks cpp total name
45 76.3% 0.2% v8::internal::Builtin_HandleApiCall(int,
unsigned long*, v8::internal::Isolate*)
3 5.1% 0.0% node::inspector::(anonymous
namespace)::InspectorConsoleCall(v8::FunctionCallbackInfo<v8::Value>
const&)
[Bottom up (heavy) profile]:
Note: percentage shows a share of a particular caller in the total
amount of its parent calls.
Callers occupying less than 1.0% are not shown.
ticks parent name
27974 99.5% __pthread_cond_wait
```
I attached the build with -g you can test it both in browser and node.
(link: https://drive.google.com/file/d/1lucme6dv-9D5yB-Wu9PieUjY5ag0YvxY/view?usp=sharing)
borwser: dhry2.html
node: node dhry2_node.js
Александр Гурьянов
Feb 28, 2021, 10:59:35 PM2/28/21
to emscripte...@googlegroups.com
I found something, this huge loading time only happens in -s ASYNCIFY=1 and only if I add CPU_Core_Normal_Run to ASYNCIFY_WHITELIST, i think it happens
because of function size.
-s ASYNCIFY=1 +CPU_Core_Normal_Run
Runtime initialized after 32175.474978000857 ms (32 sec)
func: CPU_Core_Normal_Run\28\29
[binary-bytes] : 245307 (239kb)
[total] : 114037
[vars] : 22
Binary : 15203
Block : 8136
Break : 4471
Call : 1250
CallIndirect : 1120
Const : 20921
Drop : 1693
GlobalGet : 7836
GlobalSet : 2
If : 6666
Load : 7368
LocalGet : 17195
LocalSet : 13046
Loop : 6
Return : 1
Select : 1908
Store : 3193
Switch : 48
Unary : 3968
Unreachable : 6
[binary-bytes] : 245307 (239kb)
[total] : 114037
[vars] : 22
Binary : 15203
Block : 8136
Break : 4471
Call : 1250
CallIndirect : 1120
Const : 20921
Drop : 1693
GlobalGet : 7836
GlobalSet : 2
If : 6666
Load : 7368
LocalGet : 17195
LocalSet : 13046
Loop : 6
Return : 1
Select : 1908
Store : 3193
Switch : 48
Unary : 3968
Unreachable : 6
-s ASYNCIFY=1 -CPU_Core_Normal_Run
Runtime initialized after 689.4367050006986 ms (0.6 sec)
func: CPU_Core_Normal_Run\28\29
[binary-bytes] : 157675 (153k)
[total] : 64879
[vars] : 14
Binary : 10832
Block : 3166
Break : 2815
Call : 1250
CallIndirect : 1120
Const : 13764
Drop : 37
GlobalGet : 1
GlobalSet : 2
If : 1803
Load : 7342
LocalGet : 11878
LocalSet : 7304
Loop : 6
Select : 54
Store : 3171
Switch : 48
Unary : 281
Unreachable : 5
[binary-bytes] : 157675 (153k)
[total] : 64879
[vars] : 14
Binary : 10832
Block : 3166
Break : 2815
Call : 1250
CallIndirect : 1120
Const : 13764
Drop : 37
GlobalGet : 1
GlobalSet : 2
If : 1803
Load : 7342
LocalGet : 11878
LocalSet : 7304
Loop : 6
Select : 54
Store : 3171
Switch : 48
Unary : 281
Unreachable : 5
Is it possible to do something automatically? Maybe split this function to chunks?
пн, 8 февр. 2021 г. в 16:40, Александр Гурьянов <caii...@gmail.com>:
Alon Zakai
Mar 1, 2021, 2:43:59 PM3/1/21
to emscripte...@googlegroups.com
IMaybe node 12 did not yet have baseline compiler support for wasm. That could explain the 30 seconds delay, as it fully optimizes all the code before it runs. Asyncify can generate bigger code, which makes this worse.
A newer node may not have the problem, and should run the baseline compiler by default, like on the web. You can force a newer node to use the optimizing compiler with --liftoff --no-wasm-tier-up and that should be slow once more, as a test to verify this is the issue.
--
You received this message because you are subscribed to the Google Groups "emscripten-discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to emscripten-disc...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/emscripten-discuss/CAKOm%3DVGUUqxv0m_4JSr-TF-z%3D7Bfxe6-M9iaF6HESGMhguHgsQ%40mail.gmail.com.
Александр Гурьянов
Mar 1, 2021, 9:11:33 PM3/1/21
to emscripte...@googlegroups.com
Yeah...
~/Загрузки/node-v14.16.0-linux-x64/bin/node dhry2_node.js
Runtime initialized after 16328.03651200002 ms
dhry2: 10000 181.949037 31.280845
dhry2: 20000 353.980880 32.157215
dhry2: 40000 720.280341 31.607247
dhry2: 80000 1366.479560 33.320774
dhry2: 160000 2578.543112 35.316188
~/Загрузки/node-v14.16.0-linux-x64/bin/node dhry2_node.js
Runtime initialized after 16328.03651200002 ms
dhry2: 10000 181.949037 31.280845
dhry2: 20000 353.980880 32.157215
dhry2: 40000 720.280341 31.607247
dhry2: 80000 1366.479560 33.320774
dhry2: 160000 2578.543112 35.316188
dhry2: 320000 5049.154954 36.071111
~/Загрузки/node-v14.16.0-linux-x64/bin/node --liftoff --no-wasm-tier-up dhry2_node.js
dhry2: 10000 236.612041 24.054227
dhry2: 20000 500.253110 22.754560
dhry2: 40000 900.747170 25.274660
dhry2: 80000 1808.096051 25.182377
dhry2: 160000 3842.752959 23.697676
dhry2: 20000 500.253110 22.754560
dhry2: 40000 900.747170 25.274660
dhry2: 80000 1808.096051 25.182377
dhry2: 160000 3842.752959 23.697676
вт, 2 мар. 2021 г. в 02:43, Alon Zakai <alon...@gmail.com>:
To view this discussion on the web visit https://groups.google.com/d/msgid/emscripten-discuss/CAEX4NpT-BQ3fQqzrZz%3DJzWC2RRFdoKkdL%2Bm36iCL15ErtR_Bbg%40mail.gmail.com.
Александр Гурьянов
Mar 1, 2021, 9:12:03 PM3/1/21
to emscripte...@googlegroups.com
node --liftoff --no-wasm-tier-up dhry2_node.js
Runtime initialized after 49.41098399995826 ms
Runtime initialized after 49.41098399995826 ms
вт, 2 мар. 2021 г. в 09:11, Александр Гурьянов <caii...@gmail.com>:
Reply all
Reply to author
Forward
0 new messages