Slow `vm.runInNewContext()`

[indutny]

$ ~/.node/0.10.36/bin/node -e "console.time();require('vm').runInNewContext('123');console.timeEnd();"
undefined: 1ms
$ iojs -e "console.time();require('vm').runInNewContext('123');console.timeEnd();"
undefined: 16ms

cc @domenic

[domenic]

I am not really surprised given that iojs actually creates a real context whereas 0.10 was doing a weird fake-out. But anyway my best hope for fixing this (without profiling) is to get rid of the proxy global stuff; see https://github.com/iojs/io.js/issues/855#issuecomment-74768454. I want to at least try that anyway since it could simplify things a lot.

[ChALkeR]

http://oserv.org/bugs/iojs/1631/ — callgrind output for vm.runInNewContext('123') inside a loop.

[trevnorris]

@domenic How is an additional 15ms acceptable? That's a cray amount of time to setup and tear down. It's not creating a new process, or even a new thread. Crap, I can bring my entire process up and down in a measly 60ms:

$ /usr/bin/time ./iojs -e ''
0.06user 0.00system 0:00.06elapsed 96%CPU

[domenic]

Given the overhead of a context (e.g. they're per-iframe in Blink) that seems totally acceptable as a startup cost. One extra frame (at 60fps) to load an iframe? Seems fine.

[indutny]

me and @ChALkeR has investigated the problem and it seems that it has roots in the snapshot serializer. @domenic said that V8 team was going to look into it...

[trevnorris]

Are we a browser, or a server? Devs use vm for a lot of different things. Including to execute templates, of which they could be doing hundreds a second (well, not anymore). That type of reasoning would lead to the performance destruction of core.

[domenic]

IMO people shouldn't be using vm for things they want to do more often than a typical web page would want to boot up an iframe. And that was a pretty crazy slippery-slope fallacy. But anyway, no use debating about this.

/cc @jeisinger who is the one working on making the snapshot-related parts of the startup faster. Maybe he can help give an overview. Since new VM contexts don't have any node code in them (right? no require or anything?) we should be able to benefit from the work pretty directly.

[trevnorris]

Right. No use debating because you have the answer. There's no fallacy. It's a fact. vm has gotten slower, Buffer will soon be getting noticeably slower. And TBH your opinion doesn't matter. It's our job to make core as light weight as possible so we stay out of the way of our users.

[domenic]

No, please don't put words in my mouth. No debating because it doesn't change what we can or can't do about this; we're going to make it faster if we can, obviously.

[indutny]

Mmmm... I think we are going in wrong direction with this. There is clearly some stuff that we need to figure out together, I suggest to do it in some different way ;)

[ChALkeR]

Most of the time it's inside v8::Context::New(env->isolate(), nullptr, object_template), called through static void MakeContext→ new ContextifyContext → CreateV8Context → Context::New. From there, part of the stack that stays the same most of the time looks like this:

   [32]  v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool) (244 x)
   [33]  v8::internal::Genesis::CompileScriptCached(v8::internal::Isolate*, v8::internal::Vector<char const>, v8::internal::Handle<v8::internal::String>, v8::internal::SourceCodeCache*, v8::Extension*, v8::internal::Handle<v8::internal::Context>, bool) (268 x)
   [34]  v8::internal::Genesis::CompileNative(v8::internal::Isolate*, v8::internal::Vector<char const>, v8::internal::Handle<v8::internal::String>) (246 x)
   [35]  v8::internal::Genesis::InstallNatives() (12 x)
   [36]  v8::internal::Genesis::Genesis(v8::internal::Isolate*, v8::internal::MaybeHandle<v8::internal::JSGlobalProxy>, v8::Handle<v8::ObjectTemplate>, v8::ExtensionConfiguration*) (12 x)
   [37]  v8::internal::Bootstrapper::CreateEnvironment(v8::internal::MaybeHandle<v8::internal::JSGlobalProxy>, v8::Handle<v8::ObjectTemplate>, v8::ExtensionConfiguration*) (10 x)
   [38]  v8::Context::New(v8::Isolate*, v8::ExtensionConfiguration*, v8::Handle<v8::ObjectTemplate>, v8::Handle<v8::Value>) (10 x)
   [39]  node::ContextifyContext::MakeContext(v8::FunctionCallbackInfo<v8::Value> const&) (10 x)

[trevnorris]

Here's a flame graph: https://cloudup.com/i-ZNuRsJu6i Code that generated that flame graph:

var vm = require('vm');
for (var i = 0; i < 1e3; i++)
  vm.runInNewContext('42');

• 36% v8::internal::Parser::Parse()
• 32% Builtin:JSEntryTrampoline

Not sure what these two are doing, but they're taking up a significant amount of time.

[jeisinger]

So the fact that you fall run into InstallNatives at all means that io.js doesn't use a context snapshot. Is there any specific reason you don't use that one?

[ChALkeR]

vm.runInNewContext is not necessary for reproducing this, vm.createContext is also slow. Apart from being slow, those contexts consume all the available memory. I am not sure if this has to go in a separate issue, so I'll mention it here for now.

1. Stale contexts can be destroyed only by full gc runs.
2. Each full gc run (even manually triggered by gc()) does not remove all the stale contexts but only a part of them (about 40-60%).
3. Automatic full gc runs are not frequent enough to keep the memory low, and rss goes up to 1.4 GiB (heapUsed to 880 MiB).

Each context consumes about 0.8 MiB.

Testcase:

var vm = require('vm');

var count = 0;
function foo() {
    count++;
    var x = {};
    vm.createContext(x);
    setTimeout(foo, 0);
}
foo();

/*
/// Manual gc calls limit the heapUsed depending on the frequency of garbage collections
function collect() {
    console.log(count + '? ' + JSON.stringify(process.memoryUsage()));
    gc();
    console.log(count + ': ' + JSON.stringify(process.memoryUsage()));
    setTimeout(collect, 10000);
}
collect();
*/

var gcs = new (require('gc-stats'))();
gcs.on('stats', function (stats) {
    console.log(count + ': [' + stats.gctype + '] ' + JSON.stringify(process.memoryUsage()));
});

On the irc @bnoordhuis and @domenic mentioned something about not calling ContextDisposedNotification() in src/node_contextify.cc.

[jeisinger]

when the embedder no longer uses a context, this is usually a sign that a lot of previously live memory becomes garbage. V8 uses these notifications as one input to its GC heuristics.

Another thing is that v8::Persistent<> handles only die after two full GCs:

• for a persistent handle to be collectible during a minor GC, it needs to be marked as partially depend during the minor gc prolog
• the first round of gc triggers the weak callback which then clears the persistent. Only the second gc can then actual free the memory
• 4.4 introduces a new kind of weakness for persistent handles (that are by then also renamed to Global), where the memory can be reclaimed with only one round of gc

as I mentioned before, if you want fast context creation, you should use a context snapshot.

[ChALkeR]

Ah, and some heapUsed stats regarding manually triggered subsequent gc() runs (like gc();gc();gc();):

1. 824 MB ⇒ gc() ⇒ 370 MB ⇒ gc() ⇒ 200 MB ⇒ gc() ⇒ 37 MB
2. 751 MB ⇒ gc() ⇒ 319 MB ⇒ gc() ⇒ 172 MB ⇒ gc() ⇒ 19 MB
3. 1090 MB ⇒ gc() ⇒ 574 MB ⇒ gc() ⇒ 226 MB ⇒ gc() ⇒ 92 MB ⇒ gc() ⇒ 7.3 MB ⇒ gc() ⇒ 6.5 MB

[mathiask88]

as I mentioned before, if you want fast context creation, you should use a context snapshot.

@jeisinger Yes, enabling snapshots does help, but @indutny compared node 0.10 and iojs both without snapshotting and iojs has become 16 times slower. I think snapshots have been disabled due to possible collision DoS attacks.

[jeisinger]

well, but the comparison is between a small shim, and executing almost a MB of script, so not sure what the point is?

what kind of collision DoS attack would that be? Note that the deserializer puts in a fresh random seed on every run...

[mathiask88]

Where is the MB of script in "console.time();require('vm').runInNewContext('123');console.timeEnd();"? But maybe I mistook something.

Take a look at this issue https://github.com/iojs/io.js/issues/528

[trevnorris]

@jeisinger Is the random seed you're talking about and the one @bnoordhuis mentions here the same? https://github.com/iojs/io.js/issues/528#issuecomment-71009086

[jeisinger]

@trevnorris that seed is independent of the snapshot and should change every startup if you provide a entropy source via v8::V8::SetEntropySource()

the per-context random seed is generated here: https://code.google.com/p/chromium/codesearch#chromium/src/v8/src/bootstrapper.cc&rcl=1431042794&l=2942 - every context gets a fresh one based on the same RNG that heap uses (which in turn relies on the embedder providing an entropy source)

[jeisinger]

@mathiask88 runInNewContext() invokes v8::Context::New in io.js and that runs all the .js files in v8/src (and some..)

[mathiask88]

@jeisinger Thanks for explaining. Iojs already sets an entropy source via v8::V8::SetEntropySource() if it is compiled with OpenSSL. So the seed should change on every startup and is not fixed per build? Therefore the snapshot feature could be re-enabled safely?

[jeisinger]

yes, you'll get a fresh global seed at startup, and every v8::Context gets it's own seed.

[trevnorris]

@bnoordhuis so, thoughts on re-enabling snapshots?

[bnoordhuis]

@trevnorris I think it should be safe.

[trevnorris]

@domenic apologizes for the rant. i'm peeved that buffer performance will be suffering, but it had nothing to do w/ what's going on with vm slowness. re-enabling snapshots have made everything much faster again.

[trevnorris]

This should be fixed by 36cdc7c8acda.

[idoby]

Hi guys, I know this issue was closed, but context creation seems to be slow again. I'm using a node executable compiled with v8_use_snapshot = 1. Any advice?