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

memory related test failed on v8 8.2 #144

Closed
gengjiawen opened this issue Feb 28, 2020 · 5 comments
Closed

memory related test failed on v8 8.2 #144

gengjiawen opened this issue Feb 28, 2020 · 5 comments

Comments

@gengjiawen
Copy link
Member

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

@gengjiawen gengjiawen changed the title memory related test failed memory related test failed on v8 8.2 Feb 28, 2020
@mmarchini
Copy link

mmarchini commented Mar 11, 2020

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
Copy link

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 added a commit to mmarchini/node that referenced this issue Mar 12, 2020
The current test relies on undeterministic behavior from V8 GC, and on
newer versions of V8 this test ocasionally fails because that behavior
changed.  Prevent that from happening using --predictable-gc-schedule.
If this test fails in the future, it should fail consistently instead of
ocasionally, which should help debug.

Ref: nodejs/node-v8#144 (comment)
Signed-off-by: Matheus Marchini <mmarchini@netflix.com>
@mmarchini
Copy link

mmarchini commented Mar 14, 2020

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
Copy link

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

mmarchini added a commit to mmarchini/node-v8 that referenced this issue Mar 14, 2020
gireeshpunathil pushed a commit to nodejs/node that referenced this issue Mar 15, 2020
The current test relies on undeterministic behavior from V8 GC, and on
newer versions of V8 this test ocasionally fails because that behavior
changed.  Prevent that from happening using --predictable-gc-schedule.
If this test fails in the future, it should fail consistently instead of
ocasionally, which should help debug.

Ref: nodejs/node-v8#144 (comment)
Signed-off-by: Matheus Marchini <mmarchini@netflix.com>

PR-URL: #32239
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: Jiawen Geng <technicalcute@gmail.com>
Reviewed-By: Gireesh Punathil <gpunathi@in.ibm.com>
BridgeAR pushed a commit to nodejs/node that referenced this issue Mar 17, 2020
The current test relies on undeterministic behavior from V8 GC, and on
newer versions of V8 this test ocasionally fails because that behavior
changed.  Prevent that from happening using --predictable-gc-schedule.
If this test fails in the future, it should fail consistently instead of
ocasionally, which should help debug.

Ref: nodejs/node-v8#144 (comment)
Signed-off-by: Matheus Marchini <mmarchini@netflix.com>

PR-URL: #32239
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: Jiawen Geng <technicalcute@gmail.com>
Reviewed-By: Gireesh Punathil <gpunathi@in.ibm.com>
@gengjiawen
Copy link
Member Author

Fixed.

mmarchini added a commit to mmarchini/node that referenced this issue Mar 19, 2020
targos pushed a commit to nodejs/node that referenced this issue Mar 19, 2020
targos pushed a commit to nodejs/node that referenced this issue Apr 25, 2020
targos pushed a commit to targos/node that referenced this issue Apr 25, 2020
The current test relies on undeterministic behavior from V8 GC, and on
newer versions of V8 this test ocasionally fails because that behavior
changed.  Prevent that from happening using --predictable-gc-schedule.
If this test fails in the future, it should fail consistently instead of
ocasionally, which should help debug.

Ref: nodejs/node-v8#144 (comment)
Signed-off-by: Matheus Marchini <mmarchini@netflix.com>

PR-URL: nodejs#32239
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: Jiawen Geng <technicalcute@gmail.com>
Reviewed-By: Gireesh Punathil <gpunathi@in.ibm.com>
targos pushed a commit to nodejs/node that referenced this issue Apr 28, 2020
The current test relies on undeterministic behavior from V8 GC, and on
newer versions of V8 this test ocasionally fails because that behavior
changed.  Prevent that from happening using --predictable-gc-schedule.
If this test fails in the future, it should fail consistently instead of
ocasionally, which should help debug.

Ref: nodejs/node-v8#144 (comment)
Signed-off-by: Matheus Marchini <mmarchini@netflix.com>

PR-URL: #32239
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: Jiawen Geng <technicalcute@gmail.com>
Reviewed-By: Gireesh Punathil <gpunathi@in.ibm.com>
targos pushed a commit to mmarchini/node that referenced this issue May 7, 2020
targos pushed a commit to nodejs/node that referenced this issue May 9, 2020
targos pushed a commit to nodejs/node that referenced this issue May 12, 2020
Ref: https://chromium-review.googlesource.com/c/v8/v8/+/1997438
Ref: https://chromium-review.googlesource.com/c/v8/v8/+/2010107
Ref: nodejs/node-v8#144
Signed-off-by: Matheus Marchini <mmarchini@netflix.com>

PR-URL: #32831
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: Jiawen Geng <technicalcute@gmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
targos pushed a commit to targos/node that referenced this issue May 23, 2020
Ref: https://chromium-review.googlesource.com/c/v8/v8/+/1997438
Ref: https://chromium-review.googlesource.com/c/v8/v8/+/2010107
Ref: nodejs/node-v8#144
Signed-off-by: Matheus Marchini <mmarchini@netflix.com>

PR-URL: nodejs#32831
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: Jiawen Geng <technicalcute@gmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
targos pushed a commit to nodejs/node that referenced this issue May 26, 2020
Ref: https://chromium-review.googlesource.com/c/v8/v8/+/1997438
Ref: https://chromium-review.googlesource.com/c/v8/v8/+/2010107
Ref: nodejs/node-v8#144
Signed-off-by: Matheus Marchini <mmarchini@netflix.com>

Backport-PR-URL: #33376
PR-URL: #32831
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: Jiawen Geng <technicalcute@gmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants