Slow creation of vm contexts in Node 8

[resure]

• Version: v8.1.4
• Platform: Linux stbx-frontend-dev 3.13.0-35-generic #62-Ubuntu SMP Fri Aug 15 01:58:42 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
• Subsystem: VM

It looks like process of creating new contexts got much slower in recent nodejs release.

Consider following example:

const vm = require('vm');

for (let i = 0; i < 10; i++) {
    const execStart = process.hrtime();
    vm.runInNewContext('', {});
    const execEnd = process.hrtime(execStart);
    console.log(`${execEnd[0]}s ${execEnd[1] / 1000000}ms`);
}

Here we're creating new context for each run and executing empty code string.

Output for nodejs 8.1.4:

0s 15.532509ms
0s 16.45096ms
0s 14.373037ms
0s 19.49953ms
0s 15.372955ms
0s 15.158201ms
0s 17.679574ms
0s 14.971238ms
0s 15.189564ms
0s 15.245761ms

Output for nodejs 6:

0s 1.963924ms
0s 0.963834ms
0s 1.03562ms
0s 0.874986ms
0s 0.821775ms
0s 0.795037ms
0s 0.692259ms
0s 0.675377ms
0s 0.703469ms
0s 0.707926ms

However, if we're reusing one context instead of creating new ones (like this), everything except first run is ok in nodejs 8 too:

0s 20.257369ms
0s 0.068348ms
0s 0.052941ms
0s 0.0222ms
0s 0.028692ms
0s 0.021334ms
0s 0.021695ms
0s 0.029571ms
0s 0.019861ms
0s 0.020045ms

Basically, slow part is vm.createContext, code execution speed itself is fine (benchmark with just vm.createContext({}) shows similar timings).

It looks like this problem exists only on Linux (node v8.1.2 on Darwin resure-osx 16.6.0 Darwin Kernel Version 16.6.0: Fri Apr 14 16:21:16 PDT 2017; root:xnu-3789.60.24~6/RELEASE_X86_64 x86_64 is as fast as node 6).

[bnoordhuis]

Thanks for the bug report but this is a known issue that is currently under discussion in #14171. It's caused by the disabling of snapshots in the recent security release.

[AurelienRibon]

I don't want to be the sad party guy, but with node 8.4 we still get the same results as 8.1 for the test mentioned in this issue. I'm not sure we can consider this issue as closed. Can you update the status? Do we need to manually enable the snapshots?

[TimothyGu]

I can reproduce this.

On 8.1.2:

0s 0.795425ms
0s 0.444657ms
0s 0.490908ms
0s 0.361369ms
0s 0.375127ms
0s 0.37264ms
0s 0.389114ms
0s 0.416671ms
0s 0.418107ms
0s 0.74983ms

On 8.2.1:

0s 13.092423ms
0s 11.660271ms
0s 16.616345ms
0s 11.610915ms
0s 16.744768ms
0s 12.447443ms
0s 17.539571ms
0s 13.936142ms
0s 14.693775ms
0s 12.543202ms

On 8.4.0:

0s 10.069914ms
0s 11.56193ms
0s 16.3576ms
0s 11.73263ms
0s 12.540824ms
0s 11.446461ms
0s 13.451929ms
0s 13.972611ms
0s 11.094361ms
0s 15.203506ms

[TimothyGu]

Seems like it was a bug in our build system that caused this :(

It will be fixed in #14875.

[addaleax]

I am almost certain this is because of #14875, so I think this can be closed as a duplicate of #14870 (or, technically, that one is a duplicate of this one, but, you know, it doesn’t really matter and the PR has the Fixes: tag for the other issue).