Repository navigation
memory related test failed on v8 8.2 #144
Description
Activity
- changed the title
[-]memory related test failed[/-][+]memory related test failed on v8 8.2[/+]on Feb 28, 2020 FYI,
parallel/test-memory-usageis also failing (less frequently) on 8.1. Even on 8.2 the test is flaky (but it fails almost always).Seems related to GC:
$ ./node --no-concurrent-array-buffer-freeing --trace-gc test/parallel/test-memory-usage.js [30711:0x5644d1a5f780] 51 ms: Scavenge 2.4 (3.0) -> 1.9 (4.0) MB, 0.5 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure [30711:0x5644d1a5f780] 67 ms: Scavenge 3.1 (4.7) -> 2.8 (5.5) MB, 0.6 / 0.0 ms (average mu = 1.000, current mu = 1.000) task $ ./node --no-concurrent-array-buffer-freeing --trace-gc test/parallel/test-memory-usage.js [30775:0x5608d85c9780] 21 ms: Scavenge 2.4 (3.0) -> 1.9 (4.0) MB, 0.4 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure [30775:0x5608d85c9780] 35 ms: Scavenge 2.8 (4.5) -> 2.5 (5.2) MB, 0.5 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure assert.js:384 throw err; ^ AssertionError [ERR_ASSERTION]: 11595615 - 1126582 >= 10485760 at Object.<anonymous> (/home/mmarchini/workspace/nodejs/node-canary-base-cherrypicks/test/parallel/test-memory-usage.js:42:3) at Module._compile (internal/modules/cjs/loader.js:1202:30) at Object.Module._extensions..js (internal/modules/cjs/loader.js:1222:10) at Module.load (internal/modules/cjs/loader.js:1051:32) at Function.Module._load (internal/modules/cjs/loader.js:947:14) at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:71:12) at internal/main/run_main_module.js:17:47 { generatedMessage: false, code: 'ERR_ASSERTION', actual: false, expected: true, operator: '==' }
Note how when the test fails, the second Scanvenge reporting "allocation failure", whereas when the test succeeds it's reporting "task".
--predictable-gc-scheduleseems to fix the issue, although I'm not sure this is the right approach.Ok, there has been some changes to ArrayBuffer upstream. Now V8 keeps two lists for young and old JSArrayBuffers and sweeps ArrayBufferExtensions concurrently.
--no-concurrent-array-buffer-sweepingwas introduced, but adding it to the test doesn't fix it. Adding this flag and making the following change seems to do the trick though:diff --git a/test/parallel/test-memory-usage.js b/test/parallel/test-memory-usage.js index abd5bba7bb..214f798be5 100644 --- a/test/parallel/test-memory-usage.js +++ b/test/parallel/test-memory-usage.js @@ -19,12 +19,17 @@ // OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE // USE OR OTHER DEALINGS IN THE SOFTWARE. -// Flags: --no-concurrent-array-buffer-freeing +// Flags: --no-concurrent-array-buffer-freeing --no-concurrent-array-buffer-sweeping 'use strict'; const common = require('../common'); const assert = require('assert'); const r = process.memoryUsage(); +const size = 10 * 1024 * 1024; +// eslint-disable-next-line no-unused-vars +const ab = new ArrayBuffer(size); +const after = process.memoryUsage(); + // On IBMi, the rss memory always returns zero if (!common.isIBMi) assert.ok(r.rss > 0); @@ -34,11 +39,6 @@ assert.ok(r.external > 0); assert.strictEqual(typeof r.arrayBuffers, 'number'); if (r.arrayBuffers > 0) { - const size = 10 * 1024 * 1024; - // eslint-disable-next-line no-unused-vars - const ab = new ArrayBuffer(size); - - const after = process.memoryUsage(); assert(after.external - r.external >= size, `${after.external} - ${r.external} >= ${size}`); assert.strictEqual(after.arrayBuffers - r.arrayBuffers, size,
But I think we're relying on unpredictable behavior here, and using
--predictable-gc-scheduleis a better choice.Reacted by Jiawen Geng and Anna Henningsen- added 2 commits that reference this issue
on Mar 12, 2020 test-zlib-unused-weakseems related to the same upstream changes to ArrayBuffer:$ node --version v13.10.1 $ git diff diff --git a/test/parallel/test-zlib-unused-weak.js b/test/parallel/test-zlib-unused-weak.js index 7a5a672853..22558fa943 100644 --- a/test/parallel/test-zlib-unused-weak.js +++ b/test/parallel/test-zlib-unused-weak.js @@ -13,6 +13,9 @@ const afterCreation = process.memoryUsage().external; global.gc(); const afterGC = process.memoryUsage().external; +console.log(`before: ${before}`); +console.log(`afterCreation: ${afterCreation}`); +console.log(`afterGC: ${afterGC}`); assert((afterGC - before) / (afterCreation - before) <= 0.05, `Expected after-GC delta ${afterGC - before} to be less than 5 %` + ` of before-GC delta ${afterCreation - before}`); $ node --trace-gc --expose-gc test/parallel/test-zlib-unused-weak.js [7010:0x5d2a830] 20 ms: Scavenge 2.4 (3.2) -> 2.0 (4.2) MB, 0.5 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure [7010:0x5d2a830] 32 ms: Scavenge 2.8 (4.7) -> 2.5 (5.4) MB, 0.6 / 0.0 ms (average mu = 1.000, current mu = 1.000) allocation failure [7010:0x5d2a830] 41 ms: Mark-sweep 3.1 (5.4) -> 2.1 (7.4) MB, 1.4 / 0.1 ms (average mu = 1.000, current mu = 1.000) testing GC in old space requested before: 1122723 afterCreation: 2761963 afterGC: 1114488 $ ./out/Release/node --trace-gc --expose-gc test/parallel/test-zlib-unused-weak.js [7115:0x1ee500000000] 39 ms: Mark-sweep 2.1 (2.8) -> 1.2 (4.0) MB, 2.0 / 0.2 ms (average mu = 1.000, current mu = 1.000) testing GC in old space requested before: 1155307 afterCreation: 2794547 afterGC: 2786255 assert.js:384 throw err; ^ AssertionError [ERR_ASSERTION]: Expected after-GC delta 1630948 to be less than 5 % of before-GC delta 1639240 at Object.<anonymous> (/home/mmarchini/workspace/nodejs/node-v8/test/parallel/test-zlib-unused-weak.js:19:1) at Module._compile (internal/modules/cjs/loader.js:1202:30) at Object.Module._extensions..js (internal/modules/cjs/loader.js:1222:10) at Module.load (internal/modules/cjs/loader.js:1051:32) at Function.Module._load (internal/modules/cjs/loader.js:947:14) at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:71:12) at internal/main/run_main_module.js:17:47 { generatedMessage: false, code: 'ERR_ASSERTION', actual: false, expected: true, operator: '==' } $ ./out/Release/node --trace-gc --expose-gc --no-concurrent-array-buffer-sweeping test/parallel/test-zlib-unused-weak.js [7192:0xeb400000000] 70 ms: Mark-sweep 2.1 (2.8) -> 1.2 (4.0) MB, 1.6 / 0.0 ms (average mu = 1.000, current mu = 1.000) testing GC in old space requested before: 1155307 afterCreation: 2794547 afterGC: 1122808
The test will succeed with--no-concurrent-array-buffer-sweeping. I'm not sure how this new V8 behavior will work in practice though. It's kinda surprising that forcing a mark-sweep in the main thread won't sweepArrayBufferanymore (at least that's what seems to be happening here).Passing
--no-concurrent-array-buffer-sweeping, callinggc()twice or callinggc({type: 'minor'})beforegc()will fix the test. The last two options work because objects (probably ArrayBuffers or ArrayBufferExtensions) will be promoted to OLD_SPACE on the first GC, and they will be collected on full GC. I'll stop trying to guess why--no-concurrent-array-buffer-sweepingworks, I have a vague idea but I'm not sure, but since this was also suggested on v8/node I'll go along with it.- Reacted by Jiawen Geng
- added a commit that references this issue
on Mar 14, 2020 - added a commit that references this issue
on Mar 15, 2020 - added a commit that references this issue
on Mar 16, 2020 - added a commit that references this issue
on Mar 16, 2020 - added a commit that references this issue
on Mar 17, 2020 - added a commit that references this issue
on Mar 17, 2020 Fixed.
66 remaining items
- added 2 commits that reference this issue
on May 10, 2020 - added a commit that references this issue
on May 12, 2020 - added a commit that references this issue
on May 12, 2020 - added a commit that references this issue
on May 12, 2020 - added a commit that references this issue
on May 26, 2020 - added a commit that references this issue
on Apr 19, 2025
I have checked
v8/noderepo, doesn't see related issue.Full log: https://github.com/nodejs/node-v8/runs/472689076.
cc @addaleax @joyeecheung