memory related test failed on v8 8.2

[gengjiawen]

I have checked v8/node repo, doesn't see related issue.

Full log: https://github.com/nodejs/node-v8/runs/472689076.

2020-02-27T16:48:19.9296902Z === release test-memory-usage ===
2020-02-27T16:48:19.9297364Z Path: parallel/test-memory-usage
2020-02-27T16:48:19.9297739Z --- stderr ---
2020-02-27T16:48:19.9297956Z assert.js:384
2020-02-27T16:48:19.9298138Z throw err;
2020-02-27T16:48:19.9298291Z ^
2020-02-27T16:48:19.9298428Z 
2020-02-27T16:48:19.9298814Z AssertionError [ERR_ASSERTION]: 11593703 - 1125202 >= 10485760
2020-02-27T16:48:19.9299247Z at Object.<anonymous> (/home/runner/work/node-v8/node-v8/test/parallel/test-memory-usage.js:42:3)
2020-02-27T16:48:19.9299490Z at Module._compile (internal/modules/cjs/loader.js:1202:30)
2020-02-27T16:48:19.9299720Z at Object.Module._extensions..js (internal/modules/cjs/loader.js:1222:10)
2020-02-27T16:48:19.9299912Z at Module.load (internal/modules/cjs/loader.js:1051:32)
2020-02-27T16:48:19.9300111Z at Function.Module._load (internal/modules/cjs/loader.js:947:14)
2020-02-27T16:48:19.9300286Z at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:71:12)
2020-02-27T16:48:19.9300479Z at internal/main/run_main_module.js:17:47{
2020-02-27T16:48:19.9300657Z generatedMessage: false,
2020-02-27T16:48:19.9300992Z code: 'ERR_ASSERTION',
2020-02-27T16:48:19.9301207Z actual: false,
2020-02-27T16:48:19.9301361Z expected: true,
2020-02-27T16:48:19.9301678Z operator: '=='
2020-02-27T16:48:19.9301906Z }
2020-02-27T16:48:19.9302334Z Command: out/Release/node --no-concurrent-array-buffer-freeing /home/runner/work/node-v8/node-v8/test/parallel/test-memory-usage.js
2020-02-27T16:48:19.9302741Z === release test-vm-measure-memory ===
2020-02-27T16:48:19.9303896Z Path: parallel/test-vm-measure-memory
2020-02-27T16:48:19.9304508Z --- stderr ---
2020-02-27T16:48:19.9304791Z (node:94581) ExperimentalWarning: vm.measureMemory is an experimental feature. This feature could change at any time
2020-02-27T16:48:19.9305251Z /home/runner/work/node-v8/node-v8/test/common/index.js:619
2020-02-27T16:48:19.9305505Z const crashOnUnhandledRejection = (err) =>{throw err};
2020-02-27T16:48:19.9305734Z ^
2020-02-27T16:48:19.9305872Z 
2020-02-27T16:48:19.9306068Z Error [ERR_CONTEXT_NOT_INITIALIZED]: context used is not initialized
2020-02-27T16:48:19.9306275Z at Object.measureMemory (vm.js:386:26)
2020-02-27T16:48:19.9306720Z at Object.<anonymous> (/home/runner/work/node-v8/node-v8/test/parallel/test-vm-measure-memory.js:29:6)
2020-02-27T16:48:19.9307022Z at Module._compile (internal/modules/cjs/loader.js:1202:30)
2020-02-27T16:48:19.9307241Z at Object.Module._extensions..js (internal/modules/cjs/loader.js:1222:10)
2020-02-27T16:48:19.9307465Z at Module.load (internal/modules/cjs/loader.js:1051:32)
2020-02-27T16:48:19.9308062Z at Function.Module._load (internal/modules/cjs/loader.js:947:14)
2020-02-27T16:48:19.9308929Z at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:71:12)
2020-02-27T16:48:19.9309325Z at internal/main/run_main_module.js:17:47{
2020-02-27T16:48:19.9310367Z code: 'ERR_CONTEXT_NOT_INITIALIZED'
2020-02-27T16:48:19.9310723Z }
2020-02-27T16:48:19.9311243Z Command: out/Release/node /home/runner/work/node-v8/node-v8/test/parallel/test-vm-measure-memory.js
2020-02-27T16:48:19.9311663Z === release test-zlib-unused-weak ===
2020-02-27T16:48:19.9312076Z Path: parallel/test-zlib-unused-weak
2020-02-27T16:48:19.9312461Z --- stderr ---
2020-02-27T16:48:19.9312812Z assert.js:384
2020-02-27T16:48:19.9313233Z throw err;
2020-02-27T16:48:19.9313386Z ^
2020-02-27T16:48:19.9313519Z 
2020-02-27T16:48:19.9313929Z AssertionError [ERR_ASSERTION]: Expected after-GC delta 1630992 to be less than 5 % of before-GC delta 1639240
2020-02-27T16:48:19.9314658Z at Object.<anonymous> (/home/runner/work/node-v8/node-v8/test/parallel/test-zlib-unused-weak.js:16:1)
2020-02-27T16:48:19.9314926Z at Module._compile (internal/modules/cjs/loader.js:1202:30)
2020-02-27T16:48:19.9315127Z at Object.Module._extensions..js (internal/modules/cjs/loader.js:1222:10)
2020-02-27T16:48:19.9315318Z at Module.load (internal/modules/cjs/loader.js:1051:32)
2020-02-27T16:48:19.9315505Z at Function.Module._load (internal/modules/cjs/loader.js:947:14)
2020-02-27T16:48:19.9315696Z at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:71:12)
2020-02-27T16:48:19.9315865Z at internal/main/run_main_module.js:17:47{
2020-02-27T16:48:19.9316044Z generatedMessage: false,
2020-02-27T16:48:19.9316383Z code: 'ERR_ASSERTION',
2020-02-27T16:48:19.9316599Z actual: false,
2020-02-27T16:48:19.9316752Z expected: true,
2020-02-27T16:48:19.9317094Z operator: '=='
2020-02-27T16:48:19.9317316Z }
2020-02-27T16:48:19.9317724Z Command: out/Release/node --expose-gc /home/runner/work/node-v8/node-v8/test/parallel/test-zlib-unused-weak.js

cc @addaleax @joyeecheung

[mmarchini]

FYI, parallel/test-memory-usage is 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-schedule seems to fix the issue, although I'm not sure this is the right approach.

[mmarchini]

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-sweeping was 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-schedule is a better choice.

[mmarchini]

test-zlib-unused-weak seems 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 sweep ArrayBuffer anymore (at least that's what seems to be happening here).

Passing --no-concurrent-array-buffer-sweeping, calling gc() twice or calling gc({type: 'minor'}) before gc() 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-sweeping works, 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.

[mmarchini]

https://github.com/v8/node/pull/109/files 🙃