Node: Performance issue with Array.prototype.shift() in v12.x.x

[mvcbox]

• v12.x.x:
• Darwin u 18.7.0 Darwin Kernel Version 18.7.0:

I noticed a pretty strong performance degradation since version 12.0.0
I have a very small library that provides queue functionality.
Starting with version 12.0.0, I noticed a rather large overhead for the work of the library itself (that is, I created a large number of empty tasks and measured their execution time).
Below I will give the measurement results for different versions:
(for each version, I ran the test several times and choose the best result)

• ### v8.16.1
  $ time node ./test.js

real 0m0.392s
user 0m0.427s
sys 0m0.069s

• ### v9.11.2
  $ time node ./test.js

real 0m0.387s
user 0m0.416s
sys 0m0.068s

• ### v10.16.3
  $ time node ./test.js

real 0m0.316s
user 0m0.392s
sys 0m0.071s

• ### v11.15.0
  $ time node ./test.js

real 0m0.317s
user 0m0.413s
sys 0m0.068s

• ### v12.0.0
  $ time node ./test.js

real 0m1.823s
user 0m2.190s
sys 0m0.115s

• ### v12.8.1
  $ time node ./test.js

real 0m1.858s
user 0m2.431s
sys 0m0.108s

As you can see, since version 12.0.0 runtime has grown significantly.
Moreover, the execution time is not very stable (between 1.8 and 2.7 seconds).

Below is the code I tested:
(for convenience, I put the library code and the code that uses it in one file)

'use strict';

/*------------------------------------ Source of library ------------------------------------*/
const Bluebird = require('bluebird');

class TimeoutError extends Error {}

class Queue {
    constructor(options) {
        this.tasks = [];
        this.isIdle = true;
        this.options = options || {};
    }

    async startLoop() {
        this.isIdle = false;

        while (this.tasks.length) {
            const task = this.tasks.shift();

            if (!task || !task.taskFunction || !task.onComplete) {
                continue;
            }

            const timeout = task.options && task.options.timeout || this.options.taskTimeout;

            try {
                let result = task.taskFunction();

                if (timeout) {
                    result = Bluebird.resolve(result).timeout(timeout, new TimeoutError(`Task timeout [${timeout}ms]`));
                }

                task.onComplete(undefined, await result);
            } catch (err) {
                task.onComplete(err);
            }

            // Trick for Node.js event loop
            // It is necessary for the Promise returned by the addTask method to be resolved before the next task starts.
            await Bluebird.resolve();
        }

        this.isIdle = true;
    }

    addTask(taskFunction, options) {
        return new Bluebird((resolve, reject) => {
            this.tasks.push({
                taskFunction,
                options,
                onComplete(err, result) {
                    err ? reject(err) : resolve(result);
                }
            });

            this.isIdle && this.startLoop();
        });
    }
}


/*------------------------------------ Usage example ------------------------------------*/
const queue = new Queue;

let counter = 0;

for (let i = 0; i < 50000; ++i) {
    queue.addTask(function () {
        ++counter;
    }).catch(console.error);
}

I also tried to roughly understand where the bottleneck is.
I tried to profile the application with --prof

• ### Result for v11.15.0

Statistical profiling result from isolate-0x10288c000-v8.log, (298 ticks, 7 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
      6    2.0%          /usr/lib/system/libsystem_kernel.dylib
      2    0.7%          /usr/lib/system/libsystem_platform.dylib
      2    0.7%          /usr/lib/libc++.1.dylib

 [JavaScript]:
   ticks  total  nonlib   name
      4    1.3%    1.4%  LazyCompile: *processImmediate internal/timers.js:400:28
      4    1.3%    1.4%  Builtin: Call_ReceiverIsNullOrUndefined
      4    1.3%    1.4%  Builtin: CallFunction_ReceiverIsAny
      3    1.0%    1.0%  LazyCompile: ~setImmediate timers.js:254:22
      3    1.0%    1.0%  LazyCompile: *Promise /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:70:17
      3    1.0%    1.0%  Builtin: PromiseResolveThenableJob
      3    1.0%    1.0%  Builtin: InterpreterEntryTrampoline
      3    1.0%    1.0%  Builtin: CompileLazy
      2    0.7%    0.7%  LazyCompile: ~Promise._settlePromises /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:688:46
      2    0.7%    0.7%  LazyCompile: ~Bluebird /Users/user/Projects/node-plain-queue/test.js:48:29
      2    0.7%    0.7%  LazyCompile: *startLoop /Users/user/Projects/node-plain-queue/test.js:15:20
      2    0.7%    0.7%  LazyCompile: *setImmediate timers.js:254:22
      2    0.7%    0.7%  LazyCompile: *Bluebird /Users/user/Projects/node-plain-queue/test.js:48:29
      2    0.7%    0.7%  LazyCompile: *<anonymous> /Users/user/Projects/node-plain-queue/test.js:1:1
      2    0.7%    0.7%  LazyCompile: *<anonymous> /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:488:45
      2    0.7%    0.7%  Builtin: StoreIC
      2    0.7%    0.7%  Builtin: RunMicrotasks
      2    0.7%    0.7%  Builtin: RecordWrite
      2    0.7%    0.7%  Builtin: GetProperty
      2    0.7%    0.7%  Builtin: FastNewObject
      2    0.7%    0.7%  Builtin: CallForwardVarargs
      1    0.3%    0.3%  LazyCompile: ~validatePath internal/fs/utils.js:450:22
      1    0.3%    0.3%  LazyCompile: ~validateAsyncId internal/async_hooks.js:112:25
      1    0.3%    0.3%  LazyCompile: ~tryCatcher /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/util.js:12:20
      1    0.3%    0.3%  LazyCompile: ~tryCatch /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/util.js:22:18
      1    0.3%    0.3%  LazyCompile: ~toString buffer.js:633:46
      1    0.3%    0.3%  LazyCompile: ~resolve path.js:971:10
      1    0.3%    0.3%  LazyCompile: ~emitBeforeScript internal/async_hooks.js:334:26
      1    0.3%    0.3%  LazyCompile: ~checkForgottenReturns /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/debuggability.js:435:31
      1    0.3%    0.3%  LazyCompile: ~Queue.push /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/queue.js:27:33
      1    0.3%    0.3%  LazyCompile: ~Promise._fulfill /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:630:39
      1    0.3%    0.3%  LazyCompile: ~Promise._addCallbacks /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:386:44
      1    0.3%    0.3%  LazyCompile: ~<anonymous> /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:488:45
      1    0.3%    0.3%  LazyCompile: *onComplete /Users/user/Projects/node-plain-queue/test.js:52:27
      1    0.3%    0.3%  LazyCompile: *normalizeString path.js:52:25
      1    0.3%    0.3%  LazyCompile: *Queue.push /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/queue.js:27:33
      1    0.3%    0.3%  LazyCompile: *Promise._settlePromiseFromHandler /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:501:56
      1    0.3%    0.3%  LazyCompile: *Promise._settlePromiseCtx /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:610:47
      1    0.3%    0.3%  Eval: ~<anonymous> internal/per_context/domexception.js:1:1
      1    0.3%    0.3%  Builtin: StringAdd_CheckNone_NotTenured
      1    0.3%    0.3%  Builtin: ResolvePromise
      1    0.3%    0.3%  Builtin: PerformPromiseThen
      1    0.3%    0.3%  Builtin: JSEntryTrampoline
      1    0.3%    0.3%  Builtin: HandleApiCall
      1    0.3%    0.3%  Builtin: FulfillPromise
      1    0.3%    0.3%  Builtin: FastNewClosure
      1    0.3%    0.3%  Builtin: EnqueueMicrotask
      1    0.3%    0.3%  Builtin: Call_ReceiverIsAny
      1    0.3%    0.3%  Builtin: CallFunction_ReceiverIsNotNullOrUndefined
      1    0.3%    0.3%  Builtin: CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit
      1    0.3%    0.3%  Builtin: AsyncFunctionAwaitCaught
      1    0.3%    0.3%  Builtin: ArrayPrototypePush

 [C++]:
   ticks  total  nonlib   name
     57   19.1%   19.8%  T _fcntl$NOCANCEL
     21    7.0%    7.3%  T node::native_module::NativeModuleLoader::CompileFunction(v8::FunctionCallbackInfo<v8::Value> const&)
      9    3.0%    3.1%  t v8::internal::Scavenger::ScavengeObject(v8::internal::HeapObjectReference**, v8::internal::HeapObject*)
      7    2.3%    2.4%  T node::contextify::ContextifyContext::CompileFunction(v8::FunctionCallbackInfo<v8::Value> const&)
      7    2.3%    2.4%  T __kernelrpc_vm_remap
      4    1.3%    1.4%  t void v8::internal::BodyDescriptorBase::IteratePointers<v8::internal::MarkingVisitor<(v8::internal::FixedArrayVisitationMode)1, (v8::internal::TraceRetainingPathMode)1, v8::internal::IncrementalMarkingState> >(v8::internal::HeapObject*, int, int, v8::internal::MarkingVisitor<(v8::internal::FixedArrayVisitationMode)1, (v8::internal::TraceRetainingPathMode)1, v8::internal::IncrementalMarkingState>*)
      3    1.0%    1.0%  T v8::internal::IncrementalMarking::Step(unsigned long, v8::internal::IncrementalMarking::CompletionAction, v8::internal::StepOrigin, v8::internal::WorklistToProcess)
      3    1.0%    1.0%  T ___pthread_init
      2    0.7%    0.7%  t void v8::internal::BodyDescriptorApply<v8::internal::CallIterateBody, void, v8::internal::Map*, v8::internal::HeapObject*, int, v8::internal::IterateAndScavengePromotedObjectsVisitor*>(v8::internal::InstanceType, v8::internal::Map*, v8::internal::HeapObject*, int, v8::internal::IterateAndScavengePromotedObjectsVisitor*)
      2    0.7%    0.7%  t v8::internal::IterateAndScavengePromotedObjectsVisitor::HandleSlot(v8::internal::HeapObject*, unsigned long, v8::internal::HeapObject*)
      2    0.7%    0.7%  t v8::internal::HeapObject::SizeFromMap(v8::internal::Map*) const
      2    0.7%    0.7%  T v8::internal::IncrementalMarking::WhiteToGreyAndPush(v8::internal::HeapObject*)
      2    0.7%    0.7%  T v8::internal::Heap::CreateFillerObjectAt(unsigned long, int, v8::internal::ClearRecordedSlots, v8::internal::ClearFreedMemoryMode)
      2    0.7%    0.7%  T v8::internal::Bitmap::Clear()
      2    0.7%    0.7%  T node::TTYWrap::New(v8::FunctionCallbackInfo<v8::Value> const&)
      1    0.3%    0.3%  t v8::internal::compiler::Typer::Visitor::Reduce(v8::internal::compiler::Node*)
      1    0.3%    0.3%  t v8::internal::Worklist<std::__1::pair<v8::internal::HeapObject*, int>, 256>::Pop(int, std::__1::pair<v8::internal::HeapObject*, int>*)
      1    0.3%    0.3%  t v8::internal::WeakObjects::WeakObjects()
      1    0.3%    0.3%  t v8::internal::ParserBase<v8::internal::Parser>::ParseFormalParameterList(v8::internal::ParserFormalParameters*, bool*)
      1    0.3%    0.3%  t v8::internal::ParserBase<v8::internal::Parser>::ParseAndClassifyIdentifier(bool*)
      1    0.3%    0.3%  t v8::internal::MarkingVisitor<(v8::internal::FixedArrayVisitationMode)1, (v8::internal::TraceRetainingPathMode)1, v8::internal::IncrementalMarkingState>::VisitCodeTarget(v8::internal::Code*, v8::internal::RelocInfo*)
      1    0.3%    0.3%  t v8::internal::MarkCompactCollector::RootMarkingVisitor::VisitRootPointer(v8::internal::Root, char const*, v8::internal::Object**)
      1    0.3%    0.3%  t v8::internal::FieldIndex::ForDescriptor(v8::internal::Map const*, int)
      1    0.3%    0.3%  t v8::internal::CompactionSpace::is_local()
      1    0.3%    0.3%  t v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*)
      1    0.3%    0.3%  t v8::internal::Builtin_Impl_ArrayShift(v8::internal::BuiltinArguments, v8::internal::Isolate*)
      1    0.3%    0.3%  t v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, bool, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, v8::internal::Handle<v8::internal::Object>, v8::internal::Execution::MessageHandling, v8::internal::Execution::Target)
      1    0.3%    0.3%  t std::__1::unordered_map<v8::internal::AllocationSite*, unsigned long, std::__1::hash<v8::internal::AllocationSite*>, std::__1::equal_to<v8::internal::AllocationSite*>, std::__1::allocator<std::__1::pair<v8::internal::AllocationSite* const, unsigned long> > >::operator[](v8::internal::AllocationSite*&&)
      1    0.3%    0.3%  t std::__1::basic_ostream<char, std::__1::char_traits<char> >& std::__1::__put_character_sequence<char, std::__1::char_traits<char> >(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, char const*, unsigned long)
      1    0.3%    0.3%  t node::fs::Open(v8::FunctionCallbackInfo<v8::Value> const&)
      1    0.3%    0.3%  t int v8::internal::SlotSet::Iterate<v8::internal::RememberedSetUpdatingItem<v8::internal::MajorNonAtomicMarkingState>::UpdateUntypedPointers()::'lambda'(unsigned long)>(v8::internal::RememberedSetUpdatingItem<v8::internal::MajorNonAtomicMarkingState>::UpdateUntypedPointers()::'lambda'(unsigned long), v8::internal::SlotSet::EmptyBucketMode)
      1    0.3%    0.3%  t _uv__io_poll
      1    0.3%    0.3%  t _uv__hrtime
      1    0.3%    0.3%  t _tiny_malloc_should_clear
      1    0.3%    0.3%  t _szone_calloc
      1    0.3%    0.3%  t _layout_string_create
      1    0.3%    0.3%  t _default_zone_free_definite_size
      1    0.3%    0.3%  t __read_images
      1    0.3%    0.3%  t ___vfprintf
      1    0.3%    0.3%  T v8::internal::interpreter::BytecodeRegisterOptimizer::RegisterTransfer(v8::internal::interpreter::BytecodeRegisterOptimizer::RegisterInfo*, v8::internal::interpreter::BytecodeRegisterOptimizer::RegisterInfo*)
      1    0.3%    0.3%  T v8::internal::interpreter::BytecodeGenerator::VisitUnaryOperation(v8::internal::UnaryOperation*)
      1    0.3%    0.3%  T v8::internal::interpreter::BytecodeArrayWriter::MaybeElideLastBytecode(v8::internal::interpreter::Bytecode, bool)
      1    0.3%    0.3%  T v8::internal::interpreter::BytecodeArrayBuilder::LoadNamedProperty(v8::internal::interpreter::Register, v8::internal::AstRawString const*, int)
      1    0.3%    0.3%  T v8::internal::compiler::Type::BitsetGlb() const
      1    0.3%    0.3%  T v8::internal::compiler::Node::RemoveUse(v8::internal::compiler::Node::Use*)
      1    0.3%    0.3%  T v8::internal::compiler::LoopVariableOptimizer::Run()
      1    0.3%    0.3%  T v8::internal::compiler::LinearScanAllocator::AllocateRegisters()
      1    0.3%    0.3%  T v8::internal::compiler::JSNativeContextSpecialization::Reduce(v8::internal::compiler::Node*)
      1    0.3%    0.3%  T v8::internal::compiler::GraphReducer::ReduceTop()
      1    0.3%    0.3%  T v8::internal::compiler::DeadCodeElimination::ReducePureNode(v8::internal::compiler::Node*)
      1    0.3%    0.3%  T v8::internal::compiler::CommonOperatorReducer::Reduce(v8::internal::compiler::Node*)
      1    0.3%    0.3%  T v8::internal::compiler::AccessInfoFactory::ComputePropertyAccessInfo(v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::Name>, v8::internal::compiler::AccessMode, v8::internal::compiler::PropertyAccessInfo*)
      1    0.3%    0.3%  T v8::internal::TransitionsAccessor::SearchTransition(v8::internal::Name*, v8::internal::PropertyKind, v8::internal::PropertyAttributes)
      1    0.3%    0.3%  T v8::internal::StackFrameIteratorBase::StackFrameIteratorBase(v8::internal::Isolate*, bool)
      1    0.3%    0.3%  T v8::internal::Scanner::Scan()
      1    0.3%    0.3%  T v8::internal::SaveContext::~SaveContext()
      1    0.3%    0.3%  T v8::internal::ParseInfo::ParseInfo(v8::internal::Isolate*, v8::internal::Handle<v8::internal::SharedFunctionInfo>)
      1    0.3%    0.3%  T v8::internal::Log::MessageBuilder& v8::internal::Log::MessageBuilder::operator<<<v8::internal::LogSeparator>(v8::internal::LogSeparator)
      1    0.3%    0.3%  T v8::internal::LoadIC::Load(v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Name>)
      1    0.3%    0.3%  T v8::internal::JSObject::OptimizeAsPrototype(v8::internal::Handle<v8::internal::JSObject>, bool)
      1    0.3%    0.3%  T v8::internal::JSObject::EnsureWritableFastElements(v8::internal::Handle<v8::internal::JSObject>)
      1    0.3%    0.3%  T v8::internal::JSFunction::SetInitialMap(v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::Object>)
      1    0.3%    0.3%  T v8::internal::Isolate::RunMicrotasks()
      1    0.3%    0.3%  T v8::internal::IncrementalMarking::RecordWriteSlow(v8::internal::HeapObject*, v8::internal::HeapObjectReference**, v8::internal::Object*)
      1    0.3%    0.3%  T v8::internal::Heap::MoveElements(v8::internal::FixedArray*, int, int, int, v8::internal::WriteBarrierMode)
      1    0.3%    0.3%  T v8::internal::Heap::LeftTrimFixedArray(v8::internal::FixedArrayBase*, int)
      1    0.3%    0.3%  T v8::internal::Handle<v8::internal::DescriptorArray> v8::internal::Factory::NewWeakFixedArrayWithMap<v8::internal::DescriptorArray>(v8::internal::Heap::RootListIndex, int, v8::internal::PretenureFlag)
      1    0.3%    0.3%  T v8::internal::Factory::NewPropertyArray(int, v8::internal::PretenureFlag)
      1    0.3%    0.3%  T v8::internal::Deserializer<v8::internal::DefaultDeserializerAllocator>::ReadData(v8::internal::MaybeObject**, v8::internal::MaybeObject**, int, unsigned long)
      1    0.3%    0.3%  T v8::internal::DescriptorArray::Sort()
      1    0.3%    0.3%  T v8::internal::AllocWithRetry(unsigned long)
      1    0.3%    0.3%  T v8::internal::Accessors::FunctionPrototypeGetter(v8::Local<v8::Name>, v8::PropertyCallbackInfo<v8::Value> const&)
      1    0.3%    0.3%  T v8::base::TimeTicks::HighResolutionNow()
      1    0.3%    0.3%  T v8::base::TimeDelta::InMillisecondsF() const
      1    0.3%    0.3%  T v8::base::Mutex::Unlock()
      1    0.3%    0.3%  T v8::Context::Exit()
      1    0.3%    0.3%  T std::__1::basic_ostream<char, std::__1::char_traits<char> >::sentry::~sentry()
      1    0.3%    0.3%  T node::binding::GetInternalBinding(v8::FunctionCallbackInfo<v8::Value> const&)
      1    0.3%    0.3%  T _tempnam
      1    0.3%    0.3%  T _task_set_special_port
      1    0.3%    0.3%  T _task_get_special_port
      1    0.3%    0.3%  T _putwc_l
      1    0.3%    0.3%  T _proc_set_dirty
      1    0.3%    0.3%  T _malloc_zone_malloc
      1    0.3%    0.3%  T _fgetwc_l
      1    0.3%    0.3%  T ___sysctl
      1    0.3%    0.3%  T ___CFInitialize

 [Summary]:
   ticks  total  nonlib   name
     84   28.2%   29.2%  JavaScript
    197   66.1%   68.4%  C++
     38   12.8%   13.2%  GC
     10    3.4%          Shared libraries
      7    2.3%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name
     33   39.3%   11.1%  T v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
     12   14.3%    4.0%  T v8::internal::Runtime_CompileLazy(int, v8::internal::Object**, v8::internal::Isolate*)
      9   10.7%    3.0%  T v8::internal::Runtime_CompileOptimized_Concurrent(int, v8::internal::Object**, v8::internal::Isolate*)
      5    6.0%    1.7%  T v8::internal::Runtime_InterpreterDeserializeLazy(int, v8::internal::Object**, v8::internal::Isolate*)
      4    4.8%    1.3%  T v8::internal::Runtime_StackGuard(int, v8::internal::Object**, v8::internal::Isolate*)
      4    4.8%    1.3%  T v8::internal::Builtin_ArrayShift(int, v8::internal::Object**, v8::internal::Isolate*)
      2    2.4%    0.7%  T v8::internal::Runtime_StoreIC_Miss(int, v8::internal::Object**, v8::internal::Isolate*)
      2    2.4%    0.7%  T v8::internal::Runtime_LoadIC_Miss(int, v8::internal::Object**, v8::internal::Isolate*)
      2    2.4%    0.7%  T v8::internal::Runtime_KeyedLoadIC_Miss(int, v8::internal::Object**, v8::internal::Isolate*)
      2    2.4%    0.7%  T v8::internal::Runtime_CompileForOnStackReplacement(int, v8::internal::Object**, v8::internal::Isolate*)
      1    1.2%    0.3%  T v8::internal::Runtime_KeyedStoreIC_Miss(int, v8::internal::Object**, v8::internal::Isolate*)
      1    1.2%    0.3%  T v8::internal::Runtime_DeserializeLazy(int, v8::internal::Object**, v8::internal::Isolate*)
      1    1.2%    0.3%  T v8::internal::Runtime_DefineClass(int, v8::internal::Object**, v8::internal::Isolate*)
      1    1.2%    0.3%  T v8::internal::Runtime_CreateObjectLiteral(int, v8::internal::Object**, v8::internal::Isolate*)
      1    1.2%    0.3%  T v8::internal::IncrementalMarking::WhiteToGreyAndPush(v8::internal::HeapObject*)
      1    1.2%    0.3%  T v8::internal::IncrementalMarking::RecordWriteSlow(v8::internal::HeapObject*, v8::internal::HeapObjectReference**, v8::internal::Object*)
      1    1.2%    0.3%  T v8::internal::Builtin_ReflectDefineProperty(int, v8::internal::Object**, v8::internal::Isolate*)
      1    1.2%    0.3%  T v8::internal::Builtin_JsonParse(int, v8::internal::Object**, v8::internal::Isolate*)
      1    1.2%    0.3%  T v8::internal::Builtin_FunctionConstructor(int, v8::internal::Object**, v8::internal::Isolate*)

 [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
     57   19.1%  T _fcntl$NOCANCEL

     21    7.0%  T node::native_module::NativeModuleLoader::CompileFunction(v8::FunctionCallbackInfo<v8::Value> const&)
     21  100.0%    T v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
     21  100.0%      LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:290:42
     21  100.0%        LazyCompile: ~nativeModuleRequire internal/bootstrap/loaders.js:185:29
      3   14.3%          Eval: ~<anonymous> internal/bootstrap/node.js:1:1
      2    9.5%          Eval: ~<anonymous> net.js:1:1
      2  100.0%            LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:290:42
      2    9.5%          Eval: ~<anonymous> internal/modules/cjs/loader.js:1:1
      2  100.0%            LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:290:42
      2    9.5%          Eval: ~<anonymous> buffer.js:1:1
      2  100.0%            LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:290:42
      1    4.8%          LazyCompile: ~setupBuffer internal/bootstrap/node.js:394:21
      1  100.0%            Eval: ~<anonymous> internal/bootstrap/node.js:1:1
      1    4.8%          LazyCompile: ~loadPreloadModules internal/bootstrap/pre_execution.js:356:28
      1  100.0%            LazyCompile: ~prepareMainThreadExecution internal/bootstrap/pre_execution.js:5:36
      1    4.8%          LazyCompile: ~createGlobalConsole internal/bootstrap/node.js:406:29
      1  100.0%            Eval: ~<anonymous> internal/bootstrap/node.js:1:1
      1    4.8%          Eval: ~<anonymous> vm.js:1:1
      1  100.0%            LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:290:42
      1    4.8%          Eval: ~<anonymous> tty.js:1:1
      1  100.0%            LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:290:42
      1    4.8%          Eval: ~<anonymous> stream.js:1:1
      1  100.0%            LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:290:42
      1    4.8%          Eval: ~<anonymous> internal/util.js:1:1
      1  100.0%            LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:290:42
      1    4.8%          Eval: ~<anonymous> internal/url.js:1:1
      1  100.0%            LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:290:42
      1    4.8%          Eval: ~<anonymous> internal/timers.js:1:1
      1  100.0%            LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:290:42
      1    4.8%          Eval: ~<anonymous> internal/modules/cjs/helpers.js:1:1
      1  100.0%            LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:290:42
      1    4.8%          Eval: ~<anonymous> internal/console/global.js:1:1
      1  100.0%            LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:290:42
      1    4.8%          Eval: ~<anonymous> _stream_readable.js:1:1
      1  100.0%            LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:290:42

      9    3.0%  t v8::internal::Scavenger::ScavengeObject(v8::internal::HeapObjectReference**, v8::internal::HeapObject*)

      7    2.3%  UNKNOWN

      7    2.3%  T node::contextify::ContextifyContext::CompileFunction(v8::FunctionCallbackInfo<v8::Value> const&)
      7  100.0%    T v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
      7  100.0%      LazyCompile: ~Module._compile internal/modules/cjs/loader.js:739:37
      7  100.0%        LazyCompile: ~Module._extensions..js internal/modules/cjs/loader.js:825:37
      7  100.0%          LazyCompile: ~Module.load internal/modules/cjs/loader.js:677:33
      7  100.0%            LazyCompile: ~Module._load internal/modules/cjs/loader.js:572:24

      7    2.3%  T __kernelrpc_vm_remap
      3   42.9%    T v8::internal::Runtime_InterpreterDeserializeLazy(int, v8::internal::Object**, v8::internal::Isolate*)
      1   33.3%      Eval: ~<anonymous> internal/util/types.js:1:1
      1  100.0%        LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:290:42
      1  100.0%          LazyCompile: ~nativeModuleRequire internal/bootstrap/loaders.js:185:29
      1  100.0%            Eval: ~<anonymous> buffer.js:1:1
      1   33.3%      Eval: ~<anonymous> internal/per_context/setup.js:1:1
      1   33.3%      Eval: ~<anonymous> internal/bootstrap/node.js:1:1
      1   14.3%    T v8::internal::Runtime_StackGuard(int, v8::internal::Object**, v8::internal::Isolate*)
      1  100.0%      LazyCompile: ~checkForgottenReturns /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/debuggability.js:435:31
      1  100.0%        LazyCompile: ~Promise._settlePromiseFromHandler /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:501:56
      1  100.0%          LazyCompile: *Promise._settlePromiseCtx /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:610:47
      1  100.0%            LazyCompile: *processImmediate internal/timers.js:400:28

      6    2.0%  /usr/lib/system/libsystem_kernel.dylib
      2   33.3%    T v8::internal::Runtime_InterpreterDeserializeLazy(int, v8::internal::Object**, v8::internal::Isolate*)
      1   50.0%      LazyCompile: ~resolve path.js:971:10
      1  100.0%        Eval: ~<anonymous> internal/main/run_main_module.js:1:1
      1   50.0%      Eval: ~<anonymous> internal/bootstrap/loaders.js:1:1
      1   16.7%    T v8::internal::Runtime_StackGuard(int, v8::internal::Object**, v8::internal::Isolate*)
      1  100.0%      LazyCompile: *processImmediate internal/timers.js:400:28
      1   16.7%    T v8::internal::Runtime_CompileOptimized_Concurrent(int, v8::internal::Object**, v8::internal::Isolate*)
      1  100.0%      LazyCompile: ~resolve path.js:971:10
      1  100.0%        LazyCompile: ~Module._findPath internal/modules/cjs/loader.js:287:28
      1  100.0%          LazyCompile: ~Module._resolveFilename internal/modules/cjs/loader.js:634:35
      1  100.0%            LazyCompile: ~Module._load internal/modules/cjs/loader.js:572:24

      4    1.3%  t void v8::internal::BodyDescriptorBase::IteratePointers<v8::internal::MarkingVisitor<(v8::internal::FixedArrayVisitationMode)1, (v8::internal::TraceRetainingPathMode)1, v8::internal::IncrementalMarkingState> >(v8::internal::HeapObject*, int, int, v8::internal::MarkingVisitor<(v8::internal::FixedArrayVisitationMode)1, (v8::internal::TraceRetainingPathMode)1, v8::internal::IncrementalMarkingState>*)

      4    1.3%  LazyCompile: *processImmediate internal/timers.js:400:28

      4    1.3%  Builtin: Call_ReceiverIsNullOrUndefined
      4  100.0%    LazyCompile: *onComplete /Users/user/Projects/node-plain-queue/test.js:52:27
      4  100.0%      LazyCompile: *startLoop /Users/user/Projects/node-plain-queue/test.js:15:20
      4  100.0%        Builtin: AsyncFunctionAwaitResolveClosure

      4    1.3%  Builtin: CallFunction_ReceiverIsAny
      1   25.0%    LazyCompile: ~startLoop /Users/user/Projects/node-plain-queue/test.js:15:20
      1  100.0%      Builtin: AsyncFunctionAwaitResolveClosure
      1   25.0%    LazyCompile: ~emitBeforeScript internal/async_hooks.js:334:26
      1  100.0%      LazyCompile: ~processImmediate internal/timers.js:400:28
      1   25.0%    LazyCompile: ~Promise._then /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:224:36
      1  100.0%      LazyCompile: ~Promise.then /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:119:35
      1   25.0%    LazyCompile: *Promise._settlePromiseFromHandler /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:501:56
      1  100.0%      LazyCompile: *Promise._settlePromiseCtx /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:610:47
      1  100.0%        LazyCompile: *processImmediate internal/timers.js:400:28

      3    1.0%  T v8::internal::IncrementalMarking::Step(unsigned long, v8::internal::IncrementalMarking::CompletionAction, v8::internal::StepOrigin, v8::internal::WorklistToProcess)

      3    1.0%  T ___pthread_init
      1   33.3%    T v8::internal::Runtime_StackGuard(int, v8::internal::Object**, v8::internal::Isolate*)
      1  100.0%      Builtin: AsyncFunctionAwaitResolveClosure

      3    1.0%  LazyCompile: ~setImmediate timers.js:254:22
      2   66.7%    LazyCompile: *Promise._resolveCallback /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:432:46
      2  100.0%      LazyCompile: ~<anonymous> /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:488:45
      2  100.0%        LazyCompile: ~onComplete /Users/user/Projects/node-plain-queue/test.js:52:27
      2  100.0%          LazyCompile: *startLoop /Users/user/Projects/node-plain-queue/test.js:15:20
      2  100.0%            Builtin: AsyncFunctionAwaitResolveClosure
      1   33.3%    LazyCompile: *<anonymous> /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:488:45
      1  100.0%      LazyCompile: *onComplete /Users/user/Projects/node-plain-queue/test.js:52:27
      1  100.0%        LazyCompile: *startLoop /Users/user/Projects/node-plain-queue/test.js:15:20
      1  100.0%          Builtin: AsyncFunctionAwaitResolveClosure

      3    1.0%  LazyCompile: *Promise /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:70:17
      3  100.0%    LazyCompile: *<anonymous> /Users/user/Projects/node-plain-queue/test.js:1:1
      3  100.0%      LazyCompile: ~Module._compile internal/modules/cjs/loader.js:739:37
      3  100.0%        LazyCompile: ~Module._extensions..js internal/modules/cjs/loader.js:825:37
      3  100.0%          LazyCompile: ~Module.load internal/modules/cjs/loader.js:677:33
      3  100.0%            LazyCompile: ~Module._load internal/modules/cjs/loader.js:572:24

      3    1.0%  Builtin: PromiseResolveThenableJob

      3    1.0%  Builtin: InterpreterEntryTrampoline
      1   33.3%    LazyCompile: ~Immediate timers.js:212:14
      1  100.0%      LazyCompile: ~setImmediate timers.js:254:22
      1  100.0%        LazyCompile: ~schedule /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/schedule.js:12:27
      1  100.0%          LazyCompile: ~Async._queueTick /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/async.js:153:39
      1  100.0%            LazyCompile: ~AsyncSettlePromises /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/async.js:86:29
      1   33.3%    LazyCompile: *Promise._settlePromiseFromHandler /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:501:56
      1  100.0%      LazyCompile: *Promise._settlePromiseCtx /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:610:47
      1  100.0%        LazyCompile: *processImmediate internal/timers.js:400:28
      1   33.3%    LazyCompile: *Promise /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:70:17
      1  100.0%      LazyCompile: ~addTask /Users/user/Projects/node-plain-queue/test.js:47:12
      1  100.0%        Eval: ~<anonymous> /Users/user/Projects/node-plain-queue/test.js:1:1
      1  100.0%          LazyCompile: ~Module._compile internal/modules/cjs/loader.js:739:37
      1  100.0%            LazyCompile: ~Module._extensions..js internal/modules/cjs/loader.js:825:37

      3    1.0%  Builtin: CompileLazy
      2   66.7%    LazyCompile: *startLoop /Users/user/Projects/node-plain-queue/test.js:15:20
      2  100.0%      Builtin: AsyncFunctionAwaitResolveClosure
      1   33.3%    LazyCompile: ~onComplete /Users/user/Projects/node-plain-queue/test.js:52:27
      1  100.0%      LazyCompile: *startLoop /Users/user/Projects/node-plain-queue/test.js:15:20
      1  100.0%        Builtin: AsyncFunctionAwaitResolveClosure

• ### Result for v12.8.1

Statistical profiling result from isolate-0x1027ea000-39301-v8.log, (2277 ticks, 6 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
     20    0.9%          /usr/lib/system/libsystem_platform.dylib
      8    0.4%          /usr/lib/system/libsystem_pthread.dylib
      7    0.3%          /usr/lib/system/libsystem_kernel.dylib
      2    0.1%          /usr/lib/system/libsystem_malloc.dylib

 [JavaScript]:
   ticks  total  nonlib   name
     17    0.7%    0.8%  LazyCompile: *startLoop /Users/user/Projects/node-plain-queue/test.js:15:20
      7    0.3%    0.3%  LazyCompile: *processImmediate internal/timers.js:396:28
      6    0.3%    0.3%  LazyCompile: *Promise._settlePromises /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:688:46
      6    0.3%    0.3%  LazyCompile: *Promise /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:70:17
      6    0.3%    0.3%  LazyCompile: *<anonymous> /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:488:45
      4    0.2%    0.2%  LazyCompile: *Queue.shift /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/queue.js:44:34
      3    0.1%    0.1%  LazyCompile: *onComplete /Users/user/Projects/node-plain-queue/test.js:52:27
      2    0.1%    0.1%  LazyCompile: *pushAsyncIds internal/async_hooks.js:394:22
      2    0.1%    0.1%  LazyCompile: *Promise._settlePromiseFromHandler /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:501:56
      2    0.1%    0.1%  LazyCompile: *Promise._settlePromiseCtx /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:610:47
      2    0.1%    0.1%  LazyCompile: *<anonymous> /Users/user/Projects/node-plain-queue/test.js:48:29
      1    0.0%    0.0%  LazyCompile: *Promise._resolveCallback /Users/user/Projects/node-plain-queue/src/node_modules/bluebird/js/release/promise.js:432:46
      1    0.0%    0.0%  LazyCompile: *<anonymous> /Users/user/Projects/node-plain-queue/test.js:1:1

 [C++]:
   ticks  total  nonlib   name
   1640   72.0%   73.2%  t __ZN2v88internal12_GLOBAL__N_128InstallFunctionWithBuiltinIdEPNS0_7IsolateENS0_6HandleINS0_8JSObjectEEEPKcNS0_8Builtins4NameEib
    229   10.1%   10.2%  T _fcntl$NOCANCEL
    193    8.5%    8.6%  T _read
     19    0.8%    0.8%  T node::native_module::NativeModuleEnv::CompileFunction(v8::FunctionCallbackInfo<v8::Value> const&)
     17    0.7%    0.8%  T _thread_get_state
      7    0.3%    0.3%  T ___pthread_init
      6    0.3%    0.3%  T _fstatfs64
      4    0.2%    0.2%  T _proc_set_dirty
      4    0.2%    0.2%  T __ZN2v88Function4CallENS_5LocalINS_7ContextEEENS1_INS_5ValueEEEiPS5_
      3    0.1%    0.1%  t node::TraceEventScope::TraceEventScope(char const*, char const*, void*)
      3    0.1%    0.1%  T node::contextify::ContextifyContext::CompileFunction(v8::FunctionCallbackInfo<v8::Value> const&)
      3    0.1%    0.1%  T node::InternalCallbackScope::InternalCallbackScope(node::Environment*, v8::Local<v8::Object>, node::async_context const&, node::InternalCallbackScope::ResourceExpectation)
      3    0.1%    0.1%  T _task_get_special_port
      3    0.1%    0.1%  T __ZN2v87Context29GetNumberOfEmbedderDataFieldsEv
      2    0.1%    0.1%  t node::TaskQueue<node::DelayedTask>::Push(std::__1::unique_ptr<node::DelayedTask, std::__1::default_delete<node::DelayedTask> >)
      2    0.1%    0.1%  t node::(anonymous namespace)::ToggleImmediateRef(v8::FunctionCallbackInfo<v8::Value> const&)
      2    0.1%    0.1%  t _small_malloc_should_clear
      2    0.1%    0.1%  t __malloc_initialize
      2    0.1%    0.1%  t __ZNSt3__124__put_character_sequenceIcNS_11char_traitsIcEEEERNS_13basic_ostreamIT_T0_EES7_PKS4_m
      2    0.1%    0.1%  T node::fs::Close(v8::FunctionCallbackInfo<v8::Value> const&)
      2    0.1%    0.1%  T node::binding::GetInternalBinding(v8::FunctionCallbackInfo<v8::Value> const&)
      2    0.1%    0.1%  T node::TTYWrap::New(v8::FunctionCallbackInfo<v8::Value> const&)
      2    0.1%    0.1%  T node::Environment::RunAndClearNativeImmediates()
      2    0.1%    0.1%  T __ZN2v811HandleScope10InitializeEPNS_7IsolateE
      1    0.0%    0.0%  t void std::__1::__inplace_merge<method_t::SortBySELAddress&, entsize_list_tt<method_t, method_list_t, 3u>::iterator>(entsize_list_tt<method_t, method_list_t, 3u>::iterator, entsize_list_tt<method_t, method_list_t, 3u>::iterator, entsize_list_tt<method_t, method_list_t, 3u>::iterator, method_t::SortBySELAddress&, std::__1::iterator_traits<entsize_list_tt<method_t, method_list_t, 3u>::iterator>::difference_type, std::__1::iterator_traits<entsize_list_tt<method_t, method_list_t, 3u>::iterator>::difference_type, std::__1::iterator_traits<entsize_list_tt<method_t, method_list_t, 3u>::iterator>::value_type*, long)
      1    0.0%    0.0%  t node::TraceEventScope::~TraceEventScope()
      1    0.0%    0.0%  t node::Environment::StartProfilerIdleNotifier()::$_3::__invoke(uv_prepare_s*)
      1    0.0%    0.0%  t node::AsyncHooks::pop_async_id(double)
      1    0.0%    0.0%  t _sel_init
      1    0.0%    0.0%  t __pthread_mutex_lock_init_slow
      1    0.0%    0.0%  t __ZN2v88internal22HandleScopeImplementer12EnterContextENS0_7ContextE
      1    0.0%    0.0%  t __ZN2v84base19TemplateHashMapImplIPvS2_NS0_26HashEqualityThenKeyMatcherIS2_PFbS2_S2_EEENS0_23DefaultAllocationPolicyEE6ResizeES7_
      1    0.0%    0.0%  T node::options_parser::GetOptions(v8::FunctionCallbackInfo<v8::Value> const&)
      1    0.0%    0.0%  T node::InternalMakeCallback(node::Environment*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context)
      1    0.0%    0.0%  T node::InternalCallbackScope::Close()
      1    0.0%    0.0%  T _pthread_setcanceltype
      1    0.0%    0.0%  T _malloc_zone_calloc
      1    0.0%    0.0%  T __ZNK2v88internal12RootIndexMap6LookupEmPNS0_9RootIndexE
      1    0.0%    0.0%  T __ZN2v88internal21PerIsolateAssertScopeILNS0_20PerIsolateAssertTypeE1ELb0EE9IsAllowedEPNS0_7IsolateE
      1    0.0%    0.0%  T __ZN2v87Isolate7SetIdleEb
      1    0.0%    0.0%  T __ZN2v87Isolate17GetCurrentContextEv
      1    0.0%    0.0%  T __ZN2v87Context5EnterEv
      1    0.0%    0.0%  T __ZN2v87Context4ExitEv
      1    0.0%    0.0%  T __ZN2v86Object15CreationContextEv
      1    0.0%    0.0%  T __ZN2v811HandleScopeD1Ev

 [Summary]:
   ticks  total  nonlib   name
     59    2.6%    2.6%  JavaScript
   2175   95.5%   97.1%  C++
     49    2.2%    2.2%  GC
     37    1.6%          Shared libraries
      6    0.3%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name
   1792   99.9%   78.7%  t __ZN2v88internal12_GLOBAL__N_128InstallFunctionWithBuiltinIdEPNS0_7IsolateENS0_6HandleINS0_8JSObjectEEEPKcNS0_8Builtins4NameEib
      2    0.1%    0.1%  t node::(anonymous namespace)::ToggleImmediateRef(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
   1640   72.0%  t __ZN2v88internal12_GLOBAL__N_128InstallFunctionWithBuiltinIdEPNS0_7IsolateENS0_6HandleINS0_8JSObjectEEEPKcNS0_8Builtins4NameEib
   1382   84.3%    t __ZN2v88internal12_GLOBAL__N_128InstallFunctionWithBuiltinIdEPNS0_7IsolateENS0_6HandleINS0_8JSObjectEEEPKcNS0_8Builtins4NameEib
   1200   86.8%      LazyCompile: *startLoop /Users/user/Projects/node-plain-queue/test.js:15:20
   1200  100.0%        t __ZN2v88internal12_GLOBAL__N_128InstallFunctionWithBuiltinIdEPNS0_7IsolateENS0_6HandleINS0_8JSObjectEEEPKcNS0_8Builtins4NameEib
    140   10.1%      LazyCompile: ~startLoop /Users/user/Projects/node-plain-queue/test.js:15:20
    140  100.0%        t __ZN2v88internal12_GLOBAL__N_128InstallFunctionWithBuiltinIdEPNS0_7IsolateENS0_6HandleINS0_8JSObjectEEEPKcNS0_8Builtins4NameEib
     27    1.6%    LazyCompile: *startLoop /Users/user/Projects/node-plain-queue/test.js:15:20
     27  100.0%      t __ZN2v88internal12_GLOBAL__N_128InstallFunctionWithBuiltinIdEPNS0_7IsolateENS0_6HandleINS0_8JSObjectEEEPKcNS0_8Builtins4NameEib

    229   10.1%  T _fcntl$NOCANCEL

    193    8.5%  T _read
    193  100.0%    t __ZN2v88internal12_GLOBAL__N_128InstallFunctionWithBuiltinIdEPNS0_7IsolateENS0_6HandleINS0_8JSObjectEEEPKcNS0_8Builtins4NameEib
    145   75.1%      LazyCompile: *startLoop /Users/user/Projects/node-plain-queue/test.js:15:20
    145  100.0%        t __ZN2v88internal12_GLOBAL__N_128InstallFunctionWithBuiltinIdEPNS0_7IsolateENS0_6HandleINS0_8JSObjectEEEPKcNS0_8Builtins4NameEib
     48   24.9%      LazyCompile: ~startLoop /Users/user/Projects/node-plain-queue/test.js:15:20
     48  100.0%        t __ZN2v88internal12_GLOBAL__N_128InstallFunctionWithBuiltinIdEPNS0_7IsolateENS0_6HandleINS0_8JSObjectEEEPKcNS0_8Builtins4NameEib

As you can see, for v12, almost all resources were spent on some internal mechanisms

[addaleax]

for convenience, I put the library code and the code that uses it in one file

I’d just really like to thank you for the nice reproduction here!

As you can see, for v12, almost all resources were spent on some internal mechanisms

Profiling with 0x --kernel-tracing, it looks like almost all time is spent on the .shift() call in startLoop(), and inside it, memmove() and v8::internal::Heap::GenerationalBarrierForElementsSlow() (v8::internal::Heap::WriteBarrierForRange() for V8 7.6). The good news is that V8 7.6 is already a bit better here, but it’s definitely not back to pre-Node-12 results.

Ultimately, this is an issue with V8 and it might be best to report it to https://bugs.chromium.org/p/v8/issues/, but I’ll also ping @nodejs/v8 here to see if somebody knows something. When you do, maybe leave Bluebird out of the reproduction too and use the built-in Promise instead.

[mvcbox]

@addaleax, thanks for such a quick reply!

When you do, maybe leave Bluebird out of the reproduction too and use the built-in Promise instead.

Yes, I tried using the built-in promise, the result is about the same (within the margin of error).

[mvcbox]

Created a report on - https://bugs.chromium.org/p/v8/issues/detail?id=9630

[mvcbox]

@addaleax, yes you were right. A problem with .shift()
For my code, I solved the problem this way - https://github.com/mvcbox/node-plain-queue/blob/4c2caae7dfc9a5b7cc7e3033b6f35c402b6ad923/src/Queue.ts#L22-L42
But still I think that we should not forget about this problem.

[StephenLynx]

btw, I noticed that 12.8.1 takes much longer to start than 12.8.0 did. Did anyone else notice it?

nvm: i was a dum dum there

[addaleax]

@stephenlynx That seems like a very unrelated issue. Could you open a separate one, and provide details about your system and relevant data (e.g. output for time node -p '1+1' for different versions), etc.?

[ChALkeR]

Doesn't look like the change in 12.x is the thing that matters most here...

For example, on v10.16.3, depending on the constant in the code:

• 10000: 0.3s
• 20000: 0.3s
• 50000: 0.5s
• 50500: 0.5s
• 50800: 0.5s
• 50900: 2.2s <- increase
• 51000: 2.3s
• 52000: 2.3s
• 60000: 2.9s

On v12.9.0:

• 10000: 0.2s
• 20000: 0.5s
• 30000: 1.6s <- increase
• 40000: 1.5s
• 50000: 1.9s
• 52000: 2.1s
• 60000: 2.3s

Roughly the same could be observed without Bluebird, with native Promises, btw. That is not a factor here.

[ChALkeR]

Shorter code for reproduction, without even Promise:

'use strict';

const num = Number(process.argv[2])
console.log(num)

const arr = [];
for (let i = 0; i < num; ++i) arr.push({})
while (arr.length > 0) arr.shift();

Run on v10.x, with: time node 3.js 50800; time node 3.js 50900 results: 0.1s and 21.6s.

On 12.x the results are worse for smaller numbers after a certain value (the bad-case scenario shifted?), but better for higher numbers, it seems?

On the v8.x the results the the same as on v10.x.

---

More interestingly:

| Node | length | time
-- | -- | --
| 8.16.1 | 50800 | 0.12
| 10.16.3 | 50800 | 0.12
| 12.9.0 | 50800 | 6.8
| 8.16.1 | 50900 | 16
| 10.16.3 | 50900 | 21
| 12.9.0 | 50900 | 0.45

Note the decrease between 50800 and 50900 in v12.

| Node | length | time
-- | -- | --
| 8.16.1 | 50855 | 0.10
| 10.16.3 | 50855 | 0.12
| 12.9.0 | 50855 | 6.6
| 8.16.1 | 50856 | 16
| 10.16.3 | 50856 | 22
| 12.9.0 | 50856 | 0.44

What's different between 50855/50856 and between 10.x/12.x there?

Upd: also might depend on random seed. For 12.x and --random-seed=1, another difference point seems to be between 38265/38266.

[ripsawridge]

Hi folks, I work on the V8 team and looked into this. It has to do with the amount of work required in the general case to implement shift(). Shift() removes the first element of an array, and this requires copying all the other elements over by one. We have an optimization ("left trimming") where we can avoid copying by re-writing the start of the backing store object attached to the array. However, for large arrays we don't do this.

All is still not lost, because if we are lucky (as ChALkeR's data points above show), we have a newly allocated backing store, which means it's in the young object space. We pay no write barrier costs for the shifting over of elements in that case. But sometimes the backing store has "graduated" to old space, and then there is a costly write barrier. The choice of values 50800 and 50900 in ChALkeR's example is playing in this space, however it's confusing because GC heuristics change across V8 versions.

This is a big cliff. There are some options for fixing it:

1. try to support left trimming for arrays in large object space. This means tweaking a feature that already shows up as about 1/2 of the bugs in GC, and the support could ever only be partial. The deal is that the object header "migrates" to the right as you invoke left trimming, and if it moves more than 1 page from the start, we'd have to recognize that and go slow again.
2. support a start index in the backing store of arrays. This would be great from a complexity point of view in the GC. But it would introduce complexity and performance issues elsewhere, and churn a lot of code.

It's on our backlog, but needs more thought. Here is some good news for the moment: Dominik recently re-wrote the store buffer code which reduced the worse case from 16 seconds to 4.5 seconds on my local runs.