Significant slowdown of createContext and runInContext #29842

Activity

1. bnoordhuis

   added

   performanceIssues and PRs related to the performance of Node.js.Issues and PRs related to the performance of Node.js.

   vmIssues and PRs related to the vm subsystem.Issues and PRs related to the vm subsystem.

   on Oct 4, 2019
2. bnoordhuis commented on Oct 4, 2019

   

   bnoordhuis

   on Oct 4, 2019

   Member

   More actions

   Reproducing here for posterity:

   const vm = require('vm')
   
   const ctxFn = new vm.Script(`
     var b = Math.random();
     var c = a + b;
   `);
   
   function run(m) {
     const ctx = {a: 'a'};
     vm.createContext(ctx);
     for (let i = 0; i < m; i++) {
       ctxFn.runInContext(ctx);
     }
   }
   
   function test(n, m) {
     const s = Date.now();
     for (let i = 0; i < m; i++) {
       run(m);
     }
     console.log(Date.now() - s);
   }
   
   test(1000, 10);

   Are you sure you're testing what you think you're testing? n is never used in test().
3. joyeecheung commented on Oct 4, 2019

   

   joyeecheung

   on Oct 4, 2019

   Member

   More actions

   This is what I get from our vm benchmarks using

   node benchmark/compare.js --new /Users/joyee/.nvm/versions/node/v12.5.0/bin/node --old /Users/joyee/.nvm/versions/node/v10.16.0/bin/node vm > out.csv
   

                                                                       confidence improvement accuracy (*)   (**)  (***)
    vm/run-in-context.js withSigintListener=0 breakOnSigint=0 n=1             ***     53.32 %       ±4.14% ±5.50% ±7.16%
    vm/run-in-context.js withSigintListener=0 breakOnSigint=1 n=1             ***     40.84 %       ±2.24% ±2.99% ±3.90%
    vm/run-in-context.js withSigintListener=1 breakOnSigint=0 n=1             ***     51.84 %       ±2.00% ±2.67% ±3.48%
    vm/run-in-context.js withSigintListener=1 breakOnSigint=1 n=1             ***     45.36 %       ±2.52% ±3.37% ±4.41%
    vm/run-in-this-context.js withSigintListener=0 breakOnSigint=0 n=1        ***     41.50 %       ±2.72% ±3.64% ±4.77%
    vm/run-in-this-context.js withSigintListener=0 breakOnSigint=1 n=1        ***     32.68 %       ±3.90% ±5.19% ±6.76%
    vm/run-in-this-context.js withSigintListener=1 breakOnSigint=0 n=1        ***     41.44 %       ±4.25% ±5.67% ±7.40%
    vm/run-in-this-context.js withSigintListener=1 breakOnSigint=1 n=1        ***     34.43 %       ±4.27% ±5.69% ±7.41%
   

   The slowdown may come from createContext instead
4. joyeecheung commented on Oct 4, 2019

   

   joyeecheung

   on Oct 4, 2019

   Last edited by joyeecheung

   Member

   More actions

   I tried with this benchmark

   'use strict';
   
   const common = require('../common.js');
   
   const bench = common.createBenchmark(main, {
     n: [100]
   });
   
   const vm = require('vm');
   
   const ctxFn = new vm.Script(`
     var b = Math.random();
     var c = a + b;
   `);
   
   function main({ n }) {
     bench.start();
     let context;
     for (var i = 0; i < n; i++) {
       context = vm.createContext({ a: 'a' });
     }
     bench.end(n);
     ctxFn.runInContext(context);
   }

   There is a -75.07% performance regression on master with --without-node-snapshot, and the result is similar from comparison between v12.5.0 (with the embedded snapshot) and v10.16.0
5. joyeecheung

   added a commit that references this issue on Oct 10, 2019

   benchmark: add benchmark for vm.createContext

   ...

   1294c7e
6. joyeecheung commented on Oct 10, 2019

   

   joyeecheung

   on Oct 10, 2019

   Last edited by joyeecheung

   Member

   More actions

   I proflied the benchmark (stripped out into a separate script).

   Output of --prof:

   Statistical profiling result from isolate-0x1040dd000-5581-v8.log, (194 ticks, 0 unaccounted, 0 excluded).
   
    [Shared libraries]:
      ticks  total  nonlib   name
         3    1.5%          /usr/lib/system/libsystem_platform.dylib
         1    0.5%          /usr/lib/system/libsystem_kernel.dylib
         1    0.5%          /usr/lib/libc++abi.dylib
         1    0.5%          /usr/lib/libc++.1.dylib
   
    [JavaScript]:
      ticks  total  nonlib   name
   
    [C++]:
      ticks  total  nonlib   name
        89   45.9%   47.3%  T __ZNK2v818PropertyDescriptor3setEv
        44   22.7%   23.4%  T node::contextify::ContextifyContext::MakeContext(v8::FunctionCallbackInfo<v8::Value> const&)
        19    9.8%   10.1%  T __kernelrpc_vm_remap
        18    9.3%    9.6%  T node::native_module::NativeModuleEnv::CompileFunction(v8::FunctionCallbackInfo<v8::Value> const&)
         2    1.0%    1.1%  t _tiny_malloc_should_clear
         2    1.0%    1.1%  T _read
         1    0.5%    0.5%  t _rack_region_insert
         1    0.5%    0.5%  t _mvm_aslr_init
         1    0.5%    0.5%  T node::contextify::ContextifyContext::PropertyGetterCallback(v8::Local<v8::Name>, v8::PropertyCallbackInfo<v8::Value> const&)
         1    0.5%    0.5%  T node::binding::GetInternalBinding(v8::FunctionCallbackInfo<v8::Value> const&)
         1    0.5%    0.5%  T node::PatchProcessObject(v8::FunctionCallbackInfo<v8::Value> const&)
         1    0.5%    0.5%  T _semaphore_create
         1    0.5%    0.5%  T _proc_set_dirty
         1    0.5%    0.5%  T _malloc_zone_malloc
         1    0.5%    0.5%  T _malloc_set_zone_name
         1    0.5%    0.5%  T _fstatfs64
         1    0.5%    0.5%  T _fscanf
         1    0.5%    0.5%  T _freopen
         1    0.5%    0.5%  T _free
         1    0.5%    0.5%  T ___pthread_init
   
    [Summary]:
      ticks  total  nonlib   name
         0    0.0%    0.0%  JavaScript
       188   96.9%  100.0%  C++
         8    4.1%    4.3%  GC
         6    3.1%          Shared libraries
   
    [C++ entry points]:
      ticks    cpp   total   name
       165  100.0%   85.1%  T __ZNK2v818PropertyDescriptor3setEv
   

   And of --cpu-prof

   

   I suspect this is related to #29766 - one possibility is to make primordials behind a configure-time flag until we fix the performance issues.
7. joyeecheung commented on Oct 11, 2019

   

   joyeecheung

   on Oct 11, 2019

   Member

   More actions

   Oh, wait, I realized that the screenshot in #29842 (comment) should not contain frames of primordials.js at all - these can be deserialized instead.
8. targos

   added a commit that references this issue on Nov 8, 2019

   benchmark: add benchmark for vm.createContext

   ...

   dcdb96c
9. joyeecheung commented on Jan 6, 2020

   

   joyeecheung

   on Jan 6, 2020

   Last edited by joyeecheung

   Member

   More actions

   Reposted from #29925

   I realized that we cannot actually deserialize the default context from the snapshot if the user uses the sandbox argument of vm.createContext, since the context would be different from the one we have for our own Node.js instances. We could still do this for contexts created without the sandbox argument and the users can work around the limitation by setting up the sandbox though property setters after the call to vm.createContext, though.
10. joyeecheung commented on Jan 6, 2020

    

    joyeecheung

    on Jan 6, 2020

    Member

    More actions

    Hmm, or maybe we could include one more context with the interceptors in the embedded snapshot (however we have to register the interceptors as external references first), and use it in ContextifyContext::CreateV8Context. Then fix up the context object's Symbol.toStringTag property and set up the embedded data slot.
11. spasam commented on Feb 10, 2020

    

    spasam

    on Feb 10, 2020

    More actions

    This is also locking up the event loop in version 12. Any more info on the availability of a configure-time flag until this is fixed? Or is the only option to revert to Node 8/10? Thanks
12. joyeecheung commented on Feb 11, 2020

    

    joyeecheung

    on Feb 11, 2020

    Last edited by joyeecheung

    Member

    More actions

    It seems rather difficult to make a toggle for the primordials at configure-time at this point, but another idea would be to lazily initialize the primoridals only when they are necessary for vm contexts - in most cases, there should be no need because it's used by builtin modules that probably will have their own set of primordials when being passed into a context. I am still looking into whether this is safe to do - it does impose some requirements for cross-context support of builtins (e.g. worker_threads.moveMessagePortToContext()) which @addaleax is working on.
13. joyeecheung

    closed this as completedin e6c2277on Feb 19, 2020
14. codebytere

    added a commit that references this issue on Feb 27, 2020

    vm: lazily initialize primordials for vm contexts

    ...

    a86cb0e
15. targos

    added 2 commits that reference this issue on Apr 25, 2020

    vm: lazily initialize primordials for vm contexts

    ...

    c648729

    vm: lazily initialize primordials for vm contexts

    ...

    02de66a
16. sjarmak

    added a commit that references this issue on Jul 27, 2026

    vm: lazily initialize primordials for vm contexts

    ...

    e6c2277