Investigate flaky addons/stringbytes-external-exceed-max/test-stringbytes-external-exceed-max-by-1-binary on FreeBSD 11

[joyeecheung]

Refs: nodejs/reliability#12

Example stack:

  not ok 2137 addons/stringbytes-external-exceed-max/test-stringbytes-external-exceed-max-by-1-binary
    ---
    duration_ms: 40.934
    severity: crashed
    exitcode: -9
    stack: |-
    ...

This only happens on FreeBSD 11 nodes. The process gets killed when allocating the external string so it's probably our code hitting the resource limit and killed by the system - but it's supposed to check carefully not to hit the limit and throw proper errors instead of crashing.

See output of `--trace_gc --trace_gc_verbose`

[iojs@test-digitalocean-freebsd11-x64-2 /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64]$ time ./node --trace_gc --trace_gc_verbose test/addons/stringbytes-external-exceed-max/test-stringbytes-external-exceed-max-by-1-bina
ryjs
[85803:0x803e34380] Shrinking page 0x162787d00000: end 0x162787d80000 -> 0x162787d39000
[85803:0x803e34380] Shrinking page 0x1d2c15f00000: end 0x1d2c15f80000 -> 0x1d2c15f03000
[85803:0x803e34380] Fast promotion mode: false survival rate: 71%
[85803:0x803e34380]       62 ms: Scavenge 2.6 (4.2) -> 2.3 (5.2) MB, 1.8 / 0.0 ms  (average mu = 1.000, current mu = 1.000) allocation failure
[85803:0x803e34380] Memory allocator,   used:   5360 KB, available: 1486096 KB
[85803:0x803e34380] Read-only space,    used:     34 KB, available:    469 KB, committed:    512 KB
[85803:0x803e34380] New space,          used:    748 KB, available:    258 KB, committed:   2048 KB
[85803:0x803e34380] Old space,          used:    919 KB, available:      0 KB, committed:   1252 KB
[85803:0x803e34380] Code space,         used:    475 KB, available:      0 KB, committed:   1024KB
[85803:0x803e34380] Map space,          used:    213 KB, available:      0 KB, committed:    524 KB
[85803:0x803e34380] Large object space, used:      0 KB, available: 1485575 KB, committed:      0 KB
[85803:0x803e34380] All spaces,         used:   2390 KB, available: 1486303 KB, committed:   5360KB
[85803:0x803e34380] External memory reported:      8 KB
[85803:0x803e34380] External memory global 0 KB
[85803:0x803e34380] Total time spent in GC  : 1.8 ms
[85803:0x803e34380] Fast promotion mode: false survival rate: 87%
[85803:0x803e34380]       77 ms: Scavenge 2.8 (5.2) -> 2.7 (6.2) MB, 1.9 / 0.0 ms  (average mu = 1.000, current mu = 1.000) allocation failure
[85803:0x803e34380] Memory allocator,   used:   6384 KB, available: 1485072 KB
[85803:0x803e34380] Read-only space,    used:     34 KB, available:    469 KB, committed:    512 KB
[85803:0x803e34380] New space,          used:    192 KB, available:    814 KB, committed:   2048 KB
[85803:0x803e34380] Old space,          used:   1751 KB, available:    290 KB, committed:   2276 KB
[85803:0x803e34380] Code space,         used:    490 KB, available:      0 KB, committed:   1024KB
[85803:0x803e34380] Map space,          used:    266 KB, available:      0 KB, committed:    524 KB
[85803:0x803e34380] Large object space, used:      0 KB, available: 1484551 KB, committed:      0 KB
[85803:0x803e34380] All spaces,         used:   2735 KB, available: 1486125 KB, committed:   6384KB
[85803:0x803e34380] External memory reported:      8 KB
[85803:0x803e34380] External memory global 0 KB
[85803:0x803e34380] Total time spent in GC  : 3.7 ms
[85803:0x803e34380] Fast promotion mode: false survival rate: 39%
[85803:0x803e34380]      141 ms: Scavenge 4.2 (6.7) -> 4.0 (9.7) MB, 1.3 / 0.0 ms  (average mu = 1.000, current mu = 1.000) allocation failure
[85803:0x803e34380] Memory allocator,   used:   9968 KB, available: 1481488 KB
[85803:0x803e34380] Read-only space,    used:     34 KB, available:    469 KB, committed:    512 KB
[85803:0x803e34380] New space,          used:    673 KB, available:   1340 KB, committed:   4096 KB
[85803:0x803e34380] Old space,          used:   2544 KB, available:    889 KB, committed:   3812 KB
[85803:0x803e34380] Code space,         used:    541 KB, available:      0 KB, committed:   1024KB
[85803:0x803e34380] Map space,          used:    328 KB, available:      0 KB, committed:    524 KB
[85803:0x803e34380] Large object space, used:      0 KB, available: 1480967 KB, committed:      0 KB
[85803:0x803e34380] All spaces,         used:   4122 KB, available: 1483666 KB, committed:   9968KB
[85803:0x803e34380] External memory reported:      8 KB
[85803:0x803e34380] External memory global 0 KB
[85803:0x803e34380] Total time spent in GC  : 5.0 ms
could allocate 1073741799
[85803:0x803e34380] Fast promotion mode: false survival rate: 7%
[85803:0x803e34380]      161 ms: Heap growing factor 1.7 based on mu=0.970, speed_ratio=0 (gc=0, mutator=21874)
[85803:0x803e34380]      161 ms: Grow: old size: 3691 KB, new limit: 13897 KB (1.1)
[85803:0x803e34380]      161 ms: Mark-sweep 4.2 (9.7) -> 3.6 (6.7) MB, 7.0 / 0.0 ms  (average mu = 1.000, current mu = 1.000) external memory pressure GC in old space requested
[85803:0x803e34380] Memory allocator,   used:   6896 KB, available: 1484560 KB
[85803:0x803e34380] Read-only space,    used:     34 KB, available:    469 KB, committed:    512 KB
[85803:0x803e34380] New space,          used:     15 KB, available:    991 KB, committed:   1024 KB
[85803:0x803e34380] Old space,          used:   2828 KB, available:    735 KB, committed:   3812 KB
[85803:0x803e34380] Code space,         used:    557 KB, available:      0 KB, committed:   1024KB
[85803:0x803e34380] Map space,          used:    271 KB, available:      0 KB, committed:    524 KB
[85803:0x803e34380] Large object space, used:      0 KB, available: 1484039 KB, committed:      0 KB
[85803:0x803e34380] All spaces,         used:   3706 KB, available: 1486236 KB, committed:   6896KB
[85803:0x803e34380] External memory reported: 1048584 KB
[85803:0x803e34380] External memory global 0 KB
[85803:0x803e34380] Total time spent in GC  : 12.0 ms
could allocate
in expectsError - before
[85803:0x803e34380] Fast promotion mode: false survival rate: 0%
[85803:0x803e34380]    12874 ms: Heap growing factor 1.1 based on mu=0.970, speed_ratio=13376 (gc=627068, mutator=47)
[85803:0x803e34380]    12875 ms: Grow: old size: 3692 KB, new limit: 13898 KB (1.1)
[85803:0x803e34380]    12876 ms: Mark-sweep 3.6 (6.7) -> 3.6 (6.7) MB, 109.2 / 1.1 ms  (average mu = 0.991, current mu = 0.991) external memory pressure GC in old space requested
[85803:0x803e34380] Memory allocator,   used:   6896 KB, available: 1484560 KB
[85803:0x803e34380] Read-only space,    used:     34 KB, available:    469 KB, committed:    512 KB
[85803:0x803e34380] New space,          used:      4 KB, available:   1002 KB, committed:   1024 KB
[85803:0x803e34380] Old space,          used:   2828 KB, available:    896 KB, committed:   3812 KB
[85803:0x803e34380] Code space,         used:    557 KB, available:      0 KB, committed:   1024KB
[85803:0x803e34380] Map space,          used:    271 KB, available:      0 KB, committed:    524 KB
[85803:0x803e34380] Large object space, used:      0 KB, available: 1484039 KB, committed:      0 KB
[85803:0x803e34380] All spaces,         used:   3697 KB, available: 1486407 KB, committed:   6896KB
[85803:0x803e34380] External memory reported: 2097160 KB
[85803:0x803e34380] External memory global 0 KB
[85803:0x803e34380] Total time spent in GC  : 121.1 ms
in global - before
in global - after
in global - before slice
Killed

real    0m46.301s
user    0m0.863s
sys     0m8.106s

#22301 fixes it temporarily by calling global.gc() to force V8 release the string along with the external memory so that it does not hit the resource limit, hence it won't be killed by the system even though that's what we are supposed to test (that it returns early before being killed).

[joyeecheung]

Also note that this only happens when the encoding is latin1, given that it's killed by the system I think it's not caused by bad pointers or any other aborts..it's probably caused somewhere in ExternOneByteString::NewFromCopy

[joyeecheung]

This one is still alive

Reason	addons/stringbytes-external-exceed-max/test-stringbytes-external-exceed-max-by-1-binary
Type	JS_TEST_FAILURE
Failed PR	2 (#22880, #22731)
Appeared	test-digitalocean-freebsd11-x64-1, test-digitalocean-freebsd11-x64-2
First CI	https://ci.nodejs.org/job/node-test-pull-request/17437/
Last CI	https://ci.nodejs.org/job/node-test-pull-request/17439/

Example

not ok 1905 addons/stringbytes-external-exceed-max/test-stringbytes-external-exceed-max-by-1-binary
  ---
  duration_ms: 47.178
  severity: crashed
  exitcode: -9
  stack: |-
  ...

[Trott]

Stress test on master (1000 runs on FreeBSD 11 x64): https://ci.nodejs.org/job/node-stress-single-test/2081/

[Trott]

Stress test came back clean. We've gone a month and a half without this being reported. Close-able?

[apapirovski]

Sounds like we should close and reopen if we see it again.