Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

AbortController/AbortSignal memory leak #55328

Open
System233 opened this issue Sep 26, 2024 · 17 comments · May be fixed by #55827
Open

AbortController/AbortSignal memory leak #55328

System233 opened this issue Sep 26, 2024 · 17 comments · May be fixed by #55827
Labels
confirmed-bug Issues with confirmed bugs.

Comments

@System233
Copy link

System233 commented Sep 26, 2024

Bug Description

The memory of the Node process grows infinitely, ultimately resulting in an OOM error. Memory profiling revealed a memory leak related to AbortController.
Similar to #54614,but the difference is that if AbortSignal.any does not have an event listener added, AbortSignal.any will eventually be released and there will be no memory leak.

I am using fetch API with AbortController/AbortSignal in Node.js(not undici directly).
Sorry, I misremembered, I was using node:http+signal.

Reproducible By

const formatMemoryUsage = (data) =>
  `${Math.round((data / 1024 / 1024) * 100) / 100} MB`;
// let i = 0;
// const registry = new FinalizationRegistry((heldValue) => {
//   i += 1;
//   // console.debug("[registry]", heldValue);
// });
let memoryData = process.memoryUsage();
console.log("Mem before loop", formatMemoryUsage(memoryData.rss));

const run = () => {
  for (let i = 0; i < 100_000; i++) {
    const abortController = new AbortController();

    const signal = abortController.signal;

    const composedSignal = AbortSignal.any([signal]);
    composedSignal.addEventListener("abort", () => {
      // It looks like the closure reference in the callback function causes the signal to not be released?
      // console.log(signal); // Uncommenting this will aggravate the memory leak
    });

    // registry.register(signal, "signal");
  }
};
setImmediate(run);
setInterval(() => {
  if (typeof global.gc == "function") {
    global.gc(true);
  } else {
    console.warn("global.gc unavailable, need '--expose-gc' flag");
  }
  const memoryData = process.memoryUsage();
  console.log("Mem after 100K iteration", formatMemoryUsage(memoryData.rss));
  // console.log(i, "signals released");
}, 1000);
/app # node --trace-gc --expose-gc  test3.js
Mem before loop 43.78 MB
[380:0x7f3bd3df6000]       44 ms: Scavenge 3.9 (5.2) -> 3.5 (6.2) MB, pooled: 0 MB, 0.74 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure;
[380:0x7f3bd3df6000]       45 ms: Scavenge 3.9 (6.2) -> 3.8 (6.7) MB, pooled: 0 MB, 0.62 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure;
[380:0x7f3bd3df6000]       47 ms: Scavenge 4.5 (6.7) -> 4.3 (9.2) MB, pooled: 0 MB, 0.74 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure;
[380:0x7f3bd3df6000]       50 ms: Scavenge 5.9 (9.2) -> 5.4 (9.7) MB, pooled: 0 MB, 0.99 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure;
[380:0x7f3bd3df6000]       53 ms: Scavenge 6.3 (9.7) -> 6.0 (14.7) MB, pooled: 0 MB, 1.20 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure;
[380:0x7f3bd3df6000]       57 ms: Scavenge 9.5 (14.8) -> 8.4 (15.6) MB, pooled: 0 MB, 1.41 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure; 
[380:0x7f3bd3df6000]       65 ms: Scavenge 10.6 (16.1) -> 10.0 (26.1) MB, pooled: 0 MB, 3.05 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure;
[380:0x7f3bd3df6000]       80 ms: Scavenge 16.8 (26.1) -> 15.2 (27.6) MB, pooled: 0 MB, 2.62 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure; 
[380:0x7f3bd3df6000]       88 ms: Scavenge 18.9 (28.5) -> 18.3 (49.8) MB, pooled: 0 MB, 3.92 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure; 
[380:0x7f3bd3df6000]      104 ms: Scavenge 33.7 (51.7) -> 31.0 (53.7) MB, pooled: 0 MB, 4.48 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure; 
[380:0x7f3bd3df6000]      115 ms: Scavenge 35.8 (53.7) -> 34.8 (64.9) MB, pooled: 0 MB, 7.48 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure; 
[380:0x7f3bd3df6000]      127 ms: Mark-Compact 41.7 (64.9) -> 38.2 (73.8) MB, pooled: 0 MB, 2.82 / 0.00 ms  (+ 0.4 ms in 0 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 12 ms) (average mu = 0.977, current mu = 0.977) finalize incremental marking via stack guard; GC in old space requested
[380:0x7f3bd3df6000]      148 ms: Scavenge 57.7 (77.6) -> 54.6 (77.6) MB, pooled: 0 MB, 4.69 / 0.00 ms  (average mu = 0.977, current mu = 0.977) allocation failure; 
[380:0x7f3bd3df6000]      159 ms: Scavenge 57.7 (77.6) -> 57.1 (89.6) MB, pooled: 0 MB, 7.86 / 0.00 ms  (average mu = 0.977, current mu = 0.977) allocation failure;
[380:0x7f3bd3df6000]      172 ms: Scavenge 70.3 (89.6) -> 67.6 (91.6) MB, pooled: 0 MB, 3.94 / 0.00 ms  (average mu = 0.977, current mu = 0.977) allocation failure; 
[380:0x7f3bd3df6000]      182 ms: Scavenge 72.7 (91.6) -> 71.6 (102.1) MB, pooled: 0 MB, 5.92 / 0.00 ms  (average mu = 0.977, current mu = 0.977) allocation failure; 
[380:0x7f3bd3df6000]      194 ms: Scavenge 83.2 (102.1) -> 80.9 (106.3) MB, pooled: 0 MB, 4.03 / 0.00 ms  (average mu = 0.977, current mu = 0.977) allocation failure; 
[380:0x7f3bd3df6000]      204 ms: Scavenge 87.3 (106.3) -> 86.0 (115.6) MB, pooled: 0 MB, 4.54 / 0.00 ms  (average mu = 0.977, current mu = 0.977) allocation failure;
[380:0x7f3bd3df6000]      216 ms: Scavenge 96.5 (115.6) -> 94.4 (120.8) MB, pooled: 0 MB, 4.04 / 0.00 ms  (average mu = 0.977, current mu = 0.977) allocation failure; 
[380:0x7f3bd3df6000]      235 ms: Scavenge 109.2 (128.3) -> 107.7 (137.1) MB, pooled: 0 MB, 5.21 / 0.00 ms  (average mu = 0.977, current mu = 0.977) allocation failure; 
[380:0x7f3bd3df6000]      255 ms: Scavenge (interleaved) 117.6 (137.1) -> 115.6 (143.3) MB, pooled: 0 MB, 6.53 / 0.00 ms  (average mu = 0.977, current mu = 0.977) allocation failure; 
[380:0x7f3bd3df6000]      273 ms: Scavenge (interleaved) 123.4 (143.3) -> 121.8 (151.6) MB, pooled: 0 MB, 7.72 / 0.00 ms  (average mu = 0.977, current mu = 0.977) allocation failure; 
[380:0x7f3bd3df6000]      279 ms: Mark-Compact 123.1 (151.6) -> 117.2 (152.7) MB, pooled: 0 MB, 3.91 / 0.00 ms  (+ 0.7 ms in 0 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 44 ms) (average mu = 0.975, current mu = 0.973) finalize incremental marking via stack guard; GC in old space requested
[380:0x7f3bd3df6000]      296 ms: Scavenge 132.9 (152.7) -> 129.8 (152.7) MB, pooled: 0 MB, 4.28 / 0.00 ms  (average mu = 0.975, current mu = 0.973) allocation failure; 
[380:0x7f3bd3df6000]      308 ms: Scavenge 132.9 (152.7) -> 132.2 (165.4) MB, pooled: 0 MB, 7.98 / 0.00 ms  (average mu = 0.975, current mu = 0.973) allocation failure; 
[380:0x7f3bd3df6000]      322 ms: Scavenge 145.4 (165.4) -> 142.8 (167.9) MB, pooled: 0 MB, 4.07 / 0.00 ms  (average mu = 0.975, current mu = 0.973) allocation failure; 
[380:0x7f3bd3df6000]      333 ms: Scavenge 147.9 (167.9) -> 146.9 (178.7) MB, pooled: 0 MB, 6.16 / 0.00 ms  (average mu = 0.975, current mu = 0.973) allocation failure; 
[380:0x7f3bd3df6000]     1047 ms: Scavenge 149.1 (178.7) -> 148.6 (182.7) MB, pooled: 0 MB, 6.11 / 0.00 ms  (average mu = 0.975, current mu = 0.973) testing; 
Mem after 100K iteration 232.23 MB
[380:0x7f3bd3df6000]     2046 ms: Scavenge 148.7 (182.7) -> 148.6 (184.7) MB, pooled: 0 MB, 3.56 / 0.00 ms  (average mu = 0.975, current mu = 0.973) testing; 
Mem after 100K iteration 234.25 MB
[380:0x7f3bd3df6000]     3043 ms: Scavenge 148.6 (184.7) -> 148.6 (184.7) MB, pooled: 0 MB, 0.95 / 0.00 ms  (average mu = 0.975, current mu = 0.973) testing; 
Mem after 100K iteration 234.24 MB
[380:0x7f3bd3df6000]     4045 ms: Scavenge 148.6 (184.7) -> 148.6 (184.7) MB, pooled: 0 MB, 0.76 / 0.00 ms  (average mu = 0.975, current mu = 0.973) testing; 
Mem after 100K iteration 234.25 MB
[380:0x7f3bd3df6000]     5047 ms: Scavenge 148.6 (184.7) -> 148.6 (184.7) MB, pooled: 0 MB, 1.83 / 0.00 ms  (average mu = 0.975, current mu = 0.973) testing; 
Mem after 100K iteration 234.31 MB
[380:0x7f3bd3df6000]     6047 ms: Scavenge 148.6 (184.7) -> 148.7 (184.7) MB, pooled: 0 MB, 1.13 / 0.00 ms  (average mu = 0.975, current mu = 0.973) testing; 
Mem after 100K iteration 234.3 MB
[380:0x7f3bd3df6000]     7047 ms: Scavenge 148.7 (184.7) -> 148.6 (184.7) MB, pooled: 0 MB, 0.78 / 0.00 ms  (average mu = 0.975, current mu = 0.973) testing; 
Mem after 100K iteration 234.29 MB
[380:0x7f3bd3df6000]     8050 ms: Scavenge 148.7 (184.7) -> 148.7 (153.7) MB, pooled: 31 MB, 1.55 / 0.00 ms  (average mu = 0.975, current mu = 0.973) testing; 
Mem after 100K iteration 234.29 MB
[380:0x7f3bd3df6000]     8463 ms: Mark-Compact (reduce) 148.9 (153.7) -> 82.7 (143.4) MB, pooled: 0 MB, 10.03 / 0.00 ms  (+ 14.2 ms in 0 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 27 ms) (average mu = 0.997, current mu = 0.997) finalize incremental marking via task; GC in old space requested
[380:0x7f3bd3df6000]     9051 ms: Scavenge 82.7 (143.4) -> 82.7 (144.4) MB, pooled: 0 MB, 1.57 / 0.00 ms  (average mu = 0.997, current mu = 0.997) testing; 
Mem after 100K iteration 148.13 MB
[380:0x7f3bd3df6000]     9094 ms: Mark-Compact (reduce) 82.7 (144.4) -> 82.7 (101.4) MB, pooled: 0 MB, 9.94 / 0.00 ms  (+ 16.9 ms in 0 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 30 ms) (average mu = 0.992, current mu = 0.958) finalize incremental marking via task; GC in old space requested
[380:0x7f3bd3df6000]    10051 ms: Scavenge 82.7 (101.4) -> 82.7 (101.4) MB, pooled: 1 MB, 1.02 / 0.00 ms  (average mu = 0.992, current mu = 0.958) testing; 
Mem after 100K iteration 141.08 MB
[380:0x7f3bd3df6000]    11051 ms: Scavenge 82.7 (101.4) -> 82.7 (101.4) MB, pooled: 1 MB, 0.37 / 0.00 ms  (average mu = 0.992, current mu = 0.958) testing; 
Mem after 100K iteration 141.08 MB
[380:0x7f3bd3df6000]    12052 ms: Scavenge 82.7 (101.4) -> 82.7 (101.4) MB, pooled: 1 MB, 0.42 / 0.00 ms  (average mu = 0.992, current mu = 0.958) testing; 
Mem after 100K iteration 141.09 MB
[380:0x7f3bd3df6000]    13053 ms: Scavenge 82.7 (101.4) -> 82.7 (101.4) MB, pooled: 1 MB, 0.84 / 0.00 ms  (average mu = 0.992, current mu = 0.958) testing; 
Mem after 100K iteration 141.09 MB
[380:0x7f3bd3df6000]    14054 ms: Scavenge 82.7 (101.4) -> 82.7 (101.4) MB, pooled: 1 MB, 0.42 / 0.00 ms  (average mu = 0.992, current mu = 0.958) testing; 
Mem after 100K iteration 141.09 MB
[380:0x7f3bd3df6000]    15056 ms: Scavenge 82.7 (101.4) -> 82.7 (101.4) MB, pooled: 1 MB, 0.74 / 0.00 ms  (average mu = 0.992, current mu = 0.958) testing; 
Mem after 100K iteration 141.09 MB
[380:0x7f3bd3df6000]    16057 ms: Scavenge 82.7 (101.4) -> 82.7 (101.4) MB, pooled: 1 MB, 0.76 / 0.00 ms  (average mu = 0.992, current mu = 0.958) testing; 
Mem after 100K iteration 141.09 MB
[380:0x7f3bd3df6000]    17059 ms: Scavenge 82.7 (101.4) -> 82.7 (101.4) MB, pooled: 1 MB, 0.63 / 0.00 ms  (average mu = 0.992, current mu = 0.958) testing; 
Mem after 100K iteration 141.09 MB
[380:0x7f3bd3df6000]    18060 ms: Scavenge 82.7 (101.4) -> 82.7 (101.4) MB, pooled: 1 MB, 0.59 / 0.00 ms  (average mu = 0.992, current mu = 0.958) testing; 
Mem after 100K iteration 141.09 MB
[380:0x7f3bd3df6000]    19061 ms: Scavenge 82.7 (101.4) -> 82.7 (101.4) MB, pooled: 1 MB, 0.41 / 0.00 ms  (average mu = 0.992, current mu = 0.958) testing; 
Mem after 100K iteration 141.09 MB
[380:0x7f3bd3df6000]    20062 ms: Scavenge 82.7 (101.4) -> 82.7 (101.4) MB, pooled: 1 MB, 0.64 / 0.00 ms  (average mu = 0.992, current mu = 0.958) testing; 
Mem after 100K iteration 141.09 MB
[380:0x7f3bd3df6000]    21063 ms: Scavenge 82.7 (101.4) -> 82.7 (101.4) MB, pooled: 1 MB, 0.81 / 0.00 ms  (average mu = 0.992, current mu = 0.958) testing; 
Mem after 100K iteration 141.09 MB
[380:0x7f3bd3df6000]    22063 ms: Scavenge 82.7 (101.4) -> 82.7 (101.4) MB, pooled: 1 MB, 0.43 / 0.00 ms  (average mu = 0.992, current mu = 0.958) testing; 
Mem after 100K iteration 141.09 MB
/app #

Expected Behavior

All AbortController/AbortSignal should be destroyed.

Logs & Screenshots

image
image

Environment

Node: v22.3.0
Docker Image: node:apline

Additional context

@ronag
Copy link
Member

ronag commented Sep 26, 2024

Can you try with node 22.9? I believe this was fixed quite recently.

@mcollina
Copy link
Member

Can you please include a reproduction?

@System233
Copy link
Author

System233 commented Oct 8, 2024

@ronag @mcollina I have edited the issue, please see the minimal reproducible code.

@metcoder95
Copy link
Member

Shall we move this to Node?

@mcollina mcollina transferred this issue from nodejs/undici Oct 9, 2024
@mcollina
Copy link
Member

mcollina commented Oct 9, 2024

Transfered.

@geeksilva97
Copy link
Contributor

Interesting comment on this denoland/deno#24842 (comment)

@mcollina mcollina added the confirmed-bug Issues with confirmed bugs. label Oct 10, 2024
@geeksilva97
Copy link
Contributor

geeksilva97 commented Oct 10, 2024

if AbortSignal.any does not have an event listener added, AbortSignal.any will eventually be released and there will be no memory leak.

Part of the issue with this reproduction code may be that event listeners should be removed; otherwise, gcPersistentSignals will retain those.

If that's the case I think the issue becomes the same as reported for AbortSignal.any.

@System233
Copy link
Author

Part of the issue with this reproduction code may be that event listeners should be removed; otherwise, gcPersistentSignals will retain those.

If that's the case I think the issue becomes the same as reported for AbortSignal.any.

If you add an event listener directly to AbortSignal, no memory leak occurs, but only on AbortSignal.any.
I did fix the problem temporarily by removing the event listener on AbortSignal.any.

@mika-fischer
Copy link
Contributor

I can confirm that leaving a listener attached to the AbortSignal of an AbortController does not cause a leak, but leaving a handler attached to the AbortSignal returned by AbortSignal.any does cause a leak.

Better repro:

function printMemoryUsage(msg) {
    console.log(msg, `${(process.memoryUsage().rss / 1024 / 1024).toFixed(2)} MiB`);
}

printMemoryUsage('Mem before loop');
let i = 0;
const run = () => {
    const ac = new AbortController();
    // NOTE: Not removing this listener does not cause a leak
    ac.signal.addEventListener('abort', () => {});
    const composedSignal = AbortSignal.any([ac.signal]);
    const handler = () => {};
    // NOTE: Not removing this listener DOES cause a leak
    composedSignal.addEventListener('abort', handler);
    // NOTE: Properly removing the listener fixes the leak
    // composedSignal.removeEventListener('abort', handler);
    if (++i % 100_000 === 0) {
        printMemoryUsage(`Mem after ${i} iterations`);
    }
    setImmediate(run);
};
run();

@System233
Copy link
Author

System233 commented Oct 10, 2024

GC takes a while to trigger
Sorry, I ran the test and the GC triggers faster than I expected to keep the memory at a certain level

@mika-fischer
Copy link
Contributor

GC takes a while to trigger

Sure, but this seems to be a real leak. Run this with --expose-gc --trace-gc:

function printMemoryUsage(msg) {
    console.log(msg, `${(process.memoryUsage().rss / 1024 / 1024).toFixed(2)} MiB`);
}

printMemoryUsage('Mem before loop');
let i = 0;
const run = () => {
    const ac = new AbortController();
    // NOTE: Not removing this listener does not cause a leak
    ac.signal.addEventListener('abort', () => {});
    const composedSignal = AbortSignal.any([ac.signal]);
    const handler = () => {};
    // NOTE: Not removing this listener DOES cause a leak
    composedSignal.addEventListener('abort', handler);
    // NOTE: Properly removing the listener fixes the leak
    // composedSignal.removeEventListener('abort', handler);
    if (++i % 100_000 === 0) {
        if (globalThis.gc) {
            console.log('Running GC');
            globalThis.gc(true);
        }
        printMemoryUsage(`Mem after ${i} iterations`);
    }
    setImmediate(run);
};
run();

I pretty quickly come to:

...
Running GC
[345584:00000161757C1000]    51263 ms: Scavenge 3926.7 (4090.7) -> 3922.4 (4094.5) MB, pooled: 0 MB, 8.46 / 0.00 ms  (average mu = 0.348, current mu = 0.288) testing;
Mem after 4800000 iterations 4143.23 MiB
[345584:00000161757C1000]    51283 ms: Scavenge 3931.0 (4094.5) -> 3926.6 (4098.5) MB, pooled: 0 MB, 7.92 / 0.00 ms  (average mu = 0.348, current mu = 0.288) task; 
[345584:00000161757C1000]    51304 ms: Scavenge 3935.1 (4098.5) -> 3930.7 (4102.2) MB, pooled: 0 MB, 8.76 / 0.00 ms  (average mu = 0.348, current mu = 0.288) task; 
[345584:00000161757C1000]    51323 ms: Scavenge 3939.3 (4102.2) -> 3934.9 (4106.7) MB, pooled: 0 MB, 7.69 / 0.00 ms  (average mu = 0.348, current mu = 0.288) task; 
[345584:00000161757C1000]    51344 ms: Scavenge 3943.5 (4106.7) -> 3939.1 (4110.5) MB, pooled: 0 MB, 8.07 / 0.00 ms  (average mu = 0.348, current mu = 0.288) task; 
[345584:00000161757C1000]    54025 ms: Mark-Compact (reduce) 3939.1 (4110.5) -> 3870.3 (4079.5) MB, pooled: 0 MB, 2667.97 / 0.00 ms  (+ 0.9 ms in 0 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 2681 ms) (average mu = 0.296, current mu = 0.238) finalize incremental marking via task; GC in old space requested
[345584:00000161757C1000]    54035 ms: Scavenge (interleaved) 3871.3 (4079.5) -> 3870.8 (4082.5) MB, pooled: 0 MB, 7.10 / 0.00 ms  (average mu = 0.296, current mu = 0.238) allocation failure;
[345584:00000161757C1000]    54046 ms: Scavenge (interleaved) 3871.9 (4082.5) -> 3871.3 (4082.5) MB, pooled: 0 MB, 7.63 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54057 ms: Scavenge (interleaved) 3872.4 (4082.5) -> 3871.8 (4082.5) MB, pooled: 0 MB, 7.86 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task;
[345584:00000161757C1000]    54069 ms: Scavenge (interleaved) 3872.9 (4082.5) -> 3872.3 (4086.5) MB, pooled: 0 MB, 8.54 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54086 ms: Scavenge (interleaved) 3875.0 (4086.5) -> 3873.6 (4086.5) MB, pooled: 0 MB, 10.88 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54102 ms: Scavenge (interleaved) 3875.5 (4086.5) -> 3874.5 (4086.5) MB, pooled: 0 MB, 11.84 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54118 ms: Scavenge (interleaved) 3876.8 (4086.5) -> 3875.6 (4094.5) MB, pooled: 0 MB, 10.99 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54145 ms: Scavenge (interleaved) 3880.9 (4094.5) -> 3878.1 (4094.5) MB, pooled: 0 MB, 15.03 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54172 ms: Scavenge (interleaved) 3882.0 (4094.5) -> 3880.0 (4094.5) MB, pooled: 0 MB, 17.21 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54197 ms: Scavenge (interleaved) 3884.5 (4094.5) -> 3882.1 (4110.5) MB, pooled: 0 MB, 15.34 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54243 ms: Scavenge (interleaved) 3892.8 (4110.5) -> 3887.2 (4110.5) MB, pooled: 0 MB, 21.79 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54282 ms: Scavenge (interleaved) 3895.0 (4110.5) -> 3890.9 (4110.5) MB, pooled: 0 MB, 20.91 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54303 ms: Scavenge 3900.0 (4110.5) -> 3895.4 (4110.5) MB, pooled: 0 MB, 8.11 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54323 ms: Scavenge 3903.7 (4110.5) -> 3899.5 (4110.5) MB, pooled: 0 MB, 8.37 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54343 ms: Scavenge 3908.1 (4110.5) -> 3903.7 (4110.5) MB, pooled: 0 MB, 7.47 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54362 ms: Scavenge 3912.2 (4110.5) -> 3907.8 (4110.5) MB, pooled: 0 MB, 7.53 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54382 ms: Scavenge 3916.4 (4110.5) -> 3912.0 (4110.5) MB, pooled: 0 MB, 7.43 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54401 ms: Scavenge 3920.5 (4110.5) -> 3916.1 (4110.5) MB, pooled: 0 MB, 7.85 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54421 ms: Scavenge 3924.7 (4110.5) -> 3920.3 (4110.5) MB, pooled: 0 MB, 7.77 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54441 ms: Scavenge 3928.9 (4110.5) -> 3924.5 (4110.5) MB, pooled: 0 MB, 7.53 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54461 ms: Scavenge 3933.0 (4110.5) -> 3928.7 (4110.5) MB, pooled: 0 MB, 8.22 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54481 ms: Scavenge 3937.2 (4110.5) -> 3932.8 (4110.5) MB, pooled: 0 MB, 8.11 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54501 ms: Scavenge 3941.4 (4110.5) -> 3937.0 (4113.0) MB, pooled: 0 MB, 8.10 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54521 ms: Scavenge 3945.5 (4113.0) -> 3941.1 (4117.0) MB, pooled: 0 MB, 8.37 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54542 ms: Scavenge 3949.7 (4117.0) -> 3945.3 (4120.7) MB, pooled: 0 MB, 8.21 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54562 ms: Scavenge 3953.8 (4120.7) -> 3949.4 (4124.5) MB, pooled: 0 MB, 7.95 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    54582 ms: Scavenge 3958.0 (4124.5) -> 3953.6 (4128.7) MB, pooled: 0 MB, 7.96 / 0.00 ms  (average mu = 0.296, current mu = 0.238) task; 
[345584:00000161757C1000]    57366 ms: Mark-Compact 3962.2 (4128.7) -> 3914.0 (4128.5) MB, pooled: 0 MB, 2771.99 / 0.00 ms  (average mu = 0.236, current mu = 0.170) task; scavenge might not succeed
[345584:00000161757C1000]    60320 ms: Mark-Compact 3926.8 (4128.5) -> 3917.0 (4116.7) MB, pooled: 12 MB, 2924.26 / 0.00 ms  (average mu = 0.133, current mu = 0.010) task; scavenge might not succeed
[345584:00000161757C1000]    60358 ms: Scavenge (interleaved) 3929.8 (4116.7) -> 3923.1 (4116.7) MB, pooled: 12 MB, 13.40 / 0.00 ms  (average mu = 0.133, current mu = 0.010) task; 
[345584:00000161757C1000]    60408 ms: Scavenge (interleaved) 3929.8 (4116.7) -> 3926.3 (4116.7) MB, pooled: 12 MB, 37.48 / 0.00 ms  (average mu = 0.133, current mu = 0.010) task; 
[345584:00000161757C1000]    60450 ms: Scavenge (interleaved) 3935.9 (4116.7) -> 3930.9 (4116.7) MB, pooled: 12 MB, 24.14 / 0.00 ms  (average mu = 0.133, current mu = 0.010) task; 
[345584:00000161757C1000]    60489 ms: Scavenge (interleaved) 3939.1 (4116.7) -> 3934.8 (4116.7) MB, pooled: 12 MB, 22.74 / 0.00 ms  (average mu = 0.133, current mu = 0.010) task; 
[345584:00000161757C1000]    60530 ms: Scavenge (interleaved) 3943.7 (4116.7) -> 3939.1 (4116.7) MB, pooled: 12 MB, 24.70 / 0.00 ms  (average mu = 0.133, current mu = 0.010) task; 
[345584:00000161757C1000]    60553 ms: Scavenge 3947.6 (4116.7) -> 3943.3 (4121.0) MB, pooled: 8 MB, 8.18 / 0.00 ms  (average mu = 0.133, current mu = 0.010) task; 
[345584:00000161757C1000]    60572 ms: Scavenge 3951.9 (4121.0) -> 3947.5 (4124.7) MB, pooled: 4 MB, 7.43 / 0.00 ms  (average mu = 0.133, current mu = 0.010) task; 
[345584:00000161757C1000]    60592 ms: Scavenge 3956.0 (4124.7) -> 3951.6 (4128.5) MB, pooled: 0 MB, 7.97 / 0.00 ms  (average mu = 0.133, current mu = 0.010) task; 
[345584:00000161757C1000]    63380 ms: Mark-Compact 3960.2 (4128.5) -> 3936.4 (4128.2) MB, pooled: 0 MB, 2775.07 / 0.00 ms  (average mu = 0.114, current mu = 0.093) task; scavenge might not succeed

<--- Last few GCs --->

[345584:00000161757C1000]    60592 ms: Scavenge 3956.0 (4124.7) -> 3951.6 (4128.5) MB, pooled: 0 MB, 7.97 / 0.00 ms  (average mu = 0.133, current mu = 0.010) task;
[345584:00000161757C1000]    63380 ms: Mark-Compact 3960.2 (4128.5) -> 3936.4 (4128.2) MB, pooled: 0 MB, 2775.07 / 0.00 ms  (average mu = 0.114, current mu = 0.093) task; scavenge might not succeed


<--- JS stacktrace --->

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
----- Native stack trace -----

 1: 00007FF733B2C21B node::SetCppgcReference+15995
 2: 00007FF733A94BD8 DSA_meth_get_flags+93288
 3: 00007FF734620AA1 v8::Isolate::ReportExternalAllocationLimitReached+65
 4: 00007FF73460D8A6 v8::Function::Experimental_IsNopFunction+2918
 5: 00007FF734459560 v8::internal::StrongRootAllocatorBase::StrongRootAllocatorBase+31552
 6: 00007FF73445322D v8::internal::StrongRootAllocatorBase::StrongRootAllocatorBase+6157
 7: 00007FF73444EAC5 v8::internal::ThreadIsolation::JitPageReference::Size+190789
 8: 00007FF733DC803D BIO_ssl_shutdown+189

@System233
Copy link
Author

Sure, but this seems to be a real leak. Run this with

Yes, I can get the same test results here, I didn't make it clear just now that I was testing the GC speed after uncommenting the //composedSignal.removeEventListener('abort', handler); line, sorry.

@geeksilva97
Copy link
Contributor

I was looking into this. This is done by definition: https://github.com/nodejs/node/blob/main/lib/internal/abort_controller.js#L278-L281

I wonder if changing this would violate the spec

@System233
Copy link
Author

I was looking into this. This is done by definition: https://github.com/nodejs/node/blob/main/lib/internal/abort_controller.js#L278-L281

I wonder if changing this would violate the spec

It seems that gcPersistentSignals exists solely to address the issue where AbortSignal.timeout() would block the process from exiting?

https://dom.spec.whatwg.org/#abortsignal-abort-algorithms

For the duration of this timeout, if signal has any event listeners registered for its abort event, there must be a strong reference from global to signal.

I don't understand why this needs to be made so complicated. My intuition tells me that Node.js does not need to implement this functionality deliberately, as setTimeout itself can directly hold a strong reference to AbortSignal.timeout, thus preventing AbortSignal from being garbage collected due to the lack of a strong reference. Additionally, AbortSignal.any should also hold a strong reference to the signals.

Furthermore, I have another question: When AbortSignal.timeout is active and there are abort event listeners present, the DOM standard states that AbortSignal must not be garbage collected at this time. Since AbortSignal cannot be garbage collected during this period, shouldn't AbortSignal.timeout be able to block the process exit? Currently, AbortSignal.timeout does not block the process exit.

@mika-fischer
Copy link
Contributor

IMO the issue here and the issue with an AbortSignal.timeout that has not timed out yet are completely different. It helps to consider the "settled" concept for signals as defined here: chromium/chromium@d5b7539

  • With the AbortSignal.timeout, the signal will trigger in the future, therefore it is not "settled":
    • Because it has listeners and is not settled, it must not be GCed.
  • However in the case here, the source signal is "settled" as soon as the AbortController is GCed.
    • Because nobody can call abort on the AbortController, the signal cannot possibly trigger in the future.
    • Because all source signals are settled, the any signal is settled as well and will never trigger.
    • Therefore the handler can never be called.
    • Therefore all of them can be GCed.

@mika-fischer
Copy link
Contributor

@geeksilva97
Copy link
Contributor

See especially here for more details: https://docs.google.com/document/d/1LvmsBLV85p-PhSGvTH-YwgD6onuhh1VXLg8jPlH32H4/edit?pli=1#heading=h.7ut6obnf9fz0

Thanks for the reference, @mika-fischer . This week I'll take a look into this. I've got some ideas.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
confirmed-bug Issues with confirmed bugs.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants