Long Major GC events while using external buffers (Video Image Data)

[david-metrica]

Version

v23.1.0

Platform

23.1.0 Darwin Kernel Version 23.1.0

Subsystem

No response

What steps will reproduce the bug?

I am sharing data from a native node C++ plugin using node-addon-api: return Napi::ArrayBuffer::New(env, frame_->data[i], width*height);

I checked that the memory being accessed from JS was the same as the one from C++ (And can confirm it works as expected).

However, whenever I access this data I get some Major GC events taking more than 100+ms in total.

The memory is freed by the C++ process and there is not any crash or weird behavior apart from this.

The ArrayBuffer is exposed using node-addon-api: InstanceAccessor("data", &Frame::data, nullptr), .

Writing frame.data in javascript causes this events.

node-addon-api uses napi_create_external_buffer when creating a Napi::ArrayBuffer

How often does it reproduce? Is there a required condition?

This occurs multiple times every 1-2s. Depends on the size of the data and how often is sent from C++ to JS.

What is the expected behavior? Why is that the expected behavior?

As the memory collection is not handled by the Major GC it should not expend time trying to free this objects.

What do you see instead?

Major GC trying to collect external buffers and spending more time depending how big this external buffers are.

Additional information

No response

[avivkeller]

Node.js v21 is EoL. If you can reproduce this issue in v22 or v23, please leave a comment. Additionally, "a native node C++ plugin" isn't a minimal reproduction. Without a minimal reproduction, finding the root cause of the error is difficult.

[david-metrica]

Replicated in v23.1.0.
Minimal reproduction would be creating an ArrayBuffer with large malloc data every 20ms with a timer in a InstanceAccesor

[avivkeller]

Can you provide some code?

[david-metrica]

This is not our top priority right now and I can't provide the company's code. I will try to have a minimal reproducible example with code before end of next week.

Here is some pseudo-code until then.

JS:
setTimeout every 20ms accessing a wrapper field (Example frame.data)

C++:
Wrapper with InstanceAccessor("data", &Frame::data, nullptr)

Napi::Value Frame::data(const Napi::CallbackInfo &info)
{
  Napi::Env env = info.Env();
  -- Allocate Large Data (500kb or 1Mb) --
  return Napi::ArrayBuffer::New(env, data, data_size);
}

[david-metrica]

I did some modifications to this node-addon example for a minimal reproducible example:
https://github.com/nodejs/node-addon-examples/tree/main/src/2-js-to-native-conversion/object-wrap-demo/node-addon-api

Here's how to replicate the problem
Given the code below.
With:
auto buffer = Napi::ArrayBuffer::New(env, ptr, s); //If we set s to 0 the garbage collector no longer spends time.
The GC will expend a lot of time collecting the ArrayBuffer. (5 seconds of profiling)
node --inspect --napi-modules ./test/test_binding.js

Changing the 3rd arg in ArrayBuffer to 1 (as if the ptr had one byte):
auto buffer = Napi::ArrayBuffer::New(env, ptr, 1); //If we set s to 0 the garbage collector no longer spends time.
node --inspect --napi-modules ./test/test_binding.js

object_wrap_demo.cc

#include "object_wrap_demo.h"

using namespace Napi;

ObjectWrapDemo::ObjectWrapDemo(const Napi::CallbackInfo& info)
    : ObjectWrap(info) {
}

Napi::Value ObjectWrapDemo::TestData(const Napi::CallbackInfo& info) {
  Napi::Env env = info.Env();
  int width = 1280;
  int height = 720;
  size_t s = width * height * 1.5;
  ptr = (uint8_t *)malloc(s);
  memset(ptr, 2, s);
  auto buffer =  Napi::ArrayBuffer::New(env, ptr, s); //If we set s to 0 the garbage collector no longer spends time.
  //If we perform bufer.Detach(); we can not access this data but the garbage collector won't be triggered.
  return buffer;
}

Napi::Value ObjectWrapDemo::Free(const Napi::CallbackInfo& info) {
  Napi::Env env = info.Env();
  if(ptr){
    free(ptr);
    ptr = NULL;
  }
  return env.Undefined();
}


Napi::Function ObjectWrapDemo::GetClass(Napi::Env env) {
  return DefineClass(
      env,
      "ObjectWrapDemo",
      {
          ObjectWrapDemo::InstanceAccessor("testData", &ObjectWrapDemo::TestData, nullptr),
          ObjectWrapDemo::InstanceMethod("free", &ObjectWrapDemo::Free),
      });
}

Napi::Object Init(Napi::Env env, Napi::Object exports) {
  Napi::String name = Napi::String::New(env, "ObjectWrapDemo");
  exports.Set(name, ObjectWrapDemo::GetClass(env));
  return exports;
}

NODE_API_MODULE(addon, Init)

object_wrap_demo.h

#pragma once

#include <napi.h>
void cleanupHook(Napi::Env env, void *arg);
class ObjectWrapDemo : public Napi::ObjectWrap<ObjectWrapDemo> {
 public:
  ObjectWrapDemo(const Napi::CallbackInfo&);
  Napi::Value TestData(const Napi::CallbackInfo&);
  Napi::Value Free(const Napi::CallbackInfo&);

  static Napi::Function GetClass(Napi::Env);
  uint8_t * ptr = NULL;
};

bindings.js

const addon = require('../build/Release/object-wrap-demo-native');

function ObjectWrapDemo(name) {
    this.testData = function() {
        return _addonInstance.testData;
    }
    this.free = function() {
        return _addonInstance.free();
    }

    var _addonInstance = new addon.ObjectWrapDemo(name);
}

module.exports = ObjectWrapDemo;

test_bindings.js

const ObjectWrapDemo = require("../lib/binding.js");
const assert = require("assert");

assert(ObjectWrapDemo, "The expected module is undefined");

let instance;
function testBasic()
{
    instance = new ObjectWrapDemo();
    loop();
}

async function loop(){
    wait(10).then(() => {
        setCurrentFrame();
        loop();
    });
}

function setCurrentFrame(){
    instance.free()
    instance.testData()
    instance.free()
    instance.testData()
    instance.free()
    instance.testData()
    instance.free()
    instance.testData()
    instance.free()
    instance.testData()
    instance.free()
    instance.testData()
    instance.free()
    instance.testData()
    instance.free()
    instance.testData()
    instance.free()
    instance.testData()
    instance.free()
    instance.testData()
    instance.free()
    instance.testData()
    instance.free()
    const data = instance.testData();
    console.log("Data: " + new Uint8Array(data)[0])
    instance.testData()
}


function wait(waitTime){
    return new Promise(function (resolve) { return (setTimeout(resolve, waitTime)); });
}

testBasic();

node --version
v23.1.0

[KevinEady]

I think the underlying question in the post is "why does Node behave differently based on the size of my external array buffer"?

Did a little investigation on this particular line:

  auto buffer =  Napi::ArrayBuffer::New(env, ptr, s); // If we set s to 0 the garbage collector no longer spends time.

by indeed keeping s or setting it to 0 explicitly.

I am not too familiar with the internals of the V8 GC, but I did capture some some debug logs:

With ArrayBuffer::New, size = 1

BS:wrap   bs=0x1336298b0 mem=0x128cd0000 (length=1)
BS:wrap   bs=0x1336299e0 mem=0x128cd0000 (length=1)
BS:wrap   bs=0x133629b10 mem=0x128e28000 (length=1)
... repeated ...
BS:custom deleter bs=0x133761f30 mem=0x1380d0000 (length=1, capacity=1)
BS:custom deleter bs=0x133763b00 mem=0x1380d0000 (length=1, capacity=1)
BS:custom deleter bs=0x133763c30 mem=0x1380d0000 (length=1, capacity=1)
... repeated ...
[48647:0x138008000]     1189 ms: Scavenge 4.3 (6.0) -> 3.7 (7.0) MB, pooled: 0 MB, 2.38 / 0.00 ms  (average mu = 1.000, current mu = 1.000) task; 

... with this sequence constantly repeated. The Scavenge GC event happened once every ~1.5-2.5 seconds.

With ArrayBuffer::New, size = 1382400

It's similar to the previous, but the GC event type is different and happens more frequently:

BS:wrap   bs=0x128905050 mem=0x148008000 (length=1382400)
BS:wrap   bs=0x128905180 mem=0x148008000 (length=1382400)
BS:wrap   bs=0x1289052b0 mem=0x148008000 (length=1382400)
... repeated ...
BS:custom deleter bs=0x12f6882b0 mem=0x120160000 (length=1382400, capacity=1382400)
BS:custom deleter bs=0x12f687750 mem=0x120160000 (length=1382400, capacity=1382400)
BS:custom deleter bs=0x12f687880 mem=0x120160000 (length=1382400, capacity=1382400)
... repeated ...
[47539:0x120008000]       87 ms: Mark-Compact 3.9 (5.5) -> 3.5 (6.3) MB, pooled: 0 MB, 1.71 / 0.00 ms  (+ 1.3 ms in 0 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 4 ms) (average mu = 0.964, current mu = 0.964) finalize incremental marking via task; GC in old space requested

Here, the Mark-Compact GC event happens once every ~50-75ms.

I do not know why the GC event type is different based on the backing store size, maybe something to discuss in the weekly meeting.