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 #855 (comment). 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.