dizquetv icon indicating copy to clipboard operation
dizquetv copied to clipboard

FATAL ERROR: MarkCompactCollector: semi-space copy, fallback in old gen Allocation failed - JavaScript heap out of memory

Open ghost opened this issue 3 years ago • 10 comments

dizqueTV 1.2.3 The total size channel json files is 502M.

When creating a channel from a playlist using 'playlist_to_channel.py' from dizqueTV-scripts, I am receiving, on some occasions, the following error:

<--- Last few GCs --->

[1:0x495ed70]    40059 ms: Scavenge 2038.2 (2041.5) -> 2038.4 (2050.5) MB, 10.2 / 0.0 ms  (average mu = 0.161, current mu = 0.028) allocation failure


<--- JS stacktrace --->
Cannot get stack trace in GC.
FATAL ERROR: MarkCompactCollector: semi-space copy, fallback in old gen Allocation failed - JavaScript heap out of memory
 1: 0xa37f40 node::Abort() [./dizquetv]
 2: 0xa38381 node::OnFatalError(char const*, char const*) [./dizquetv]
 3: 0xbb4a4e v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [./dizquetv]
 4: 0xbb4ca2 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [./dizquetv]
 5: 0xd73935  [./dizquetv]
 6: 0xda6fb8 v8::internal::EvacuateNewSpaceVisitor::Visit(v8::internal::HeapObject, int) [./dizquetv]
 7: 0xdaa54e void v8::internal::LiveObjectVisitor::VisitBlackObjectsNoFail<v8::internal::EvacuateNewSpaceVisitor, v8::internal::MajorNonAtomicMarkingState>(v8::internal::MemoryChunk*, v8::internal::MajorNonAtomicMarkingState*, v8::internal::EvacuateNewSpaceVisitor*, v8::internal::LiveObjectVisitor::IterationMode) [./dizquetv]
 8: 0xdb5157 v8::internal::FullEvacuator::RawEvacuatePage(v8::internal::MemoryChunk*, long*) [./dizquetv]
 9: 0xd9cf59 v8::internal::Evacuator::EvacuatePage(v8::internal::MemoryChunk*) [./dizquetv]
10: 0xd9d250 v8::internal::PageEvacuationTask::RunInParallel(v8::internal::ItemParallelJob::Task::Runner) [./dizquetv]
11: 0xd92955 v8::internal::ItemParallelJob::Task::RunInternal() [./dizquetv]
12: 0xd92d94 v8::internal::ItemParallelJob::Run() [./dizquetv]
13: 0xdb90de v8::internal::MarkCompactCollector::EvacuatePagesInParallel() [./dizquetv]
14: 0xdba481  [./dizquetv]
15: 0xdbf777 v8::internal::MarkCompactCollector::CollectGarbage() [./dizquetv]
16: 0xd80c49 v8::internal::Heap::MarkCompact() [./dizquetv]
17: 0xd818b3 v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [./dizquetv]
18: 0xd823de v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [./dizquetv]
19: 0xd8512d v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [./dizquetv]
20: 0xd55a94 v8::internal::Factory::NewJSObjectFromMap(v8::internal::Handle<v8::internal::Map>, v8::internal::AllocationType, v8::internal::Handle<v8::internal::AllocationSite>) [./dizquetv]
21: 0xe6673e v8::internal::JsonParser<unsigned short>::BuildJsonObject(v8::internal::JsonParser<unsigned short>::JsonContinuation const&, std::vector<v8::internal::JsonProperty, std::allocator<v8::internal::JsonProperty> > const&, v8::internal::Handle<v8::internal::Map>) [./dizquetv]
22: 0xe68063 v8::internal::JsonParser<unsigned short>::ParseJsonValue() [./dizquetv]
23: 0xe68f0f v8::internal::JsonParser<unsigned short>::ParseJson() [./dizquetv]
24: 0xc6deb8 v8::internal::Builtin_JsonParse(int, unsigned long*, v8::internal::Isolate*) [./dizquetv]
25: 0x141ae99  [./dizquetv]

ghost avatar Jan 19 '21 14:01 ghost

What's the maximum memory assigned to dizqueTV (or your system memory)

What's your EPG cache setting?

vexorian avatar Jan 19 '21 15:01 vexorian

              total        used        free      shared  buff/cache   available
Mem:           62Gi       8.4Gi        12Gi        10Gi        41Gi        43Gi
Swap:         8.0Gi       1.4Gi       6.6Gi

System memory is 64GB EPG Cache (hours): 12 Refresh Timer (hours): 4

dizquetv Docker container is using 660MB idle / 1.5GB+ peak according to ctop.

ghost avatar Jan 19 '21 15:01 ghost

I had a similar issue here: https://github.com/vexorian/dizquetv/issues/103

Container usage idles around 660M and increases as content is added. On restart of container it returns to idle usage.

ghost avatar Jan 19 '21 15:01 ghost

With a 500M channels json , it's normal that it would take 1.5 G of RAM. There's multiple caches to make things work without long delays.

Is your container limited in RAM in any way? Sounds hard to believe you'd get an out of memory with 64 GB of RAM

vexorian avatar Jan 19 '21 16:01 vexorian

The container isn’t using any memory switches which would limit the usage. Using Docker version 19.03.14.

I’ll attempt to mirror the configuration on a fresh system to see whether the issue is system or Docker related.

ghost avatar Jan 19 '21 16:01 ghost

~~I've narrowed the issue down to the use of nexe and the version of node used to compile the project.~~

edit: Seems to be related with node version than nexe.

Test environment: Virtualbox 6.1 / Debian Server 10.7 / 32GB RAM

The error was reproducible when I ran the same container and dizquetv configuration.

To rule out Docker, I extracted and executed the dizquetv binary from the container with the same configuration and again the error was reproducible.

On the base system, I installed npm (5.8.0) & node (10.23.1) and followed to build and run the project using the main branch. Using the same configuration as before I was not able to reproduce the error after many attempts.

I compiled the project using nexe (3.3.7) using the closest version of node to 10.23.1 which was 10.3.0 (-t linux-x64-10.3.0) and I was not able to reproduce the error. However, there were occasions when the script could not find the channel but did so after attempting again after some period of time; it also failed to create a channel JSON by leaving one 1KB in size - this behaviour was also noted before a crash in the other scenarios.

I compiled it again using linux-x64-12.16.2 which is used in the build script and the error was reproducible as before.

My next step is to modify the Docker image to run the project directly from node rather than using nexe.

ghost avatar Jan 20 '21 14:01 ghost

What about running with node 12.16.2 without nexe?

vexorian avatar Jan 20 '21 21:01 vexorian

Using node 12.16.2 gives the error:

<--- Last few GCs --->

[4799:0x4852790]   150707 ms: Mark-sweep 2054.2 (2057.9) -> 2041.0 (2052.7) MB, 134.8 / 0.0 ms  (+ 243.2 ms in 96 steps since start of marking, biggest step 11.6 ms, walltime since start of marking 410 ms) (average mu = 0.125, current mu = 0.093) allocati

<--- JS stacktrace --->
Cannot get stack trace in GC.
FATAL ERROR: MarkCompactCollector: semi-space copy, fallback in old gen Allocation failed - JavaScript heap out of memory
 1: 0xa02f90 node::Abort() [node]
 2: 0xa033b5 node::OnFatalError(char const*, char const*) [node]
 3: 0xb76ffe v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [node]
 4: 0xb77379 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [node]
 5: 0xd23ad5  [node]
 6: 0xd52dea v8::internal::EvacuateNewSpaceVisitor::Visit(v8::internal::HeapObject, int) [node]
 7: 0xd5a2a0 void v8::internal::LiveObjectVisitor::VisitBlackObjectsNoFail<v8::internal::EvacuateNewSpaceVisitor, v8::internal::MajorNonAtomicMarkingState>(v8::internal::MemoryChunk*, v8::internal::MajorNonAtomicMarkingState*, v8::internal::EvacuateNewSpaceVisitor*, v8::internal::LiveObjectVisitor::IterationMode) [node]
 8: 0xd696a8 v8::internal::FullEvacuator::RawEvacuatePage(v8::internal::MemoryChunk*, long*) [node]
 9: 0xd4c0ee v8::internal::Evacuator::EvacuatePage(v8::internal::MemoryChunk*) [node]
10: 0xd4c3b4 v8::internal::PageEvacuationTask::RunInParallel(v8::internal::ItemParallelJob::Task::Runner) [node]
11: 0xd41695 v8::internal::ItemParallelJob::Task::RunInternal() [node]
12: 0xd41aa4 v8::internal::ItemParallelJob::Run() [node]
13: 0xd5b757 void v8::internal::MarkCompactCollectorBase::CreateAndExecuteEvacuationTasks<v8::internal::FullEvacuator, v8::internal::MarkCompactCollector>(v8::internal::MarkCompactCollector*, v8::internal::ItemParallelJob*, v8::internal::MigrationObserver*, long) [node]
14: 0xd6bc84 v8::internal::MarkCompactCollector::EvacuatePagesInParallel() [node]
15: 0xd6c89a  [node]
16: 0xd71b17 v8::internal::MarkCompactCollector::CollectGarbage() [node]
17: 0xd30049 v8::internal::Heap::MarkCompact() [node]
18: 0xd30d63 v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [node]
19: 0xd31895 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [node]
20: 0xd3434c v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [node]
21: 0xd021fc v8::internal::Factory::NewRawOneByteString(int, v8::internal::AllocationType) [node]
22: 0xe1146b v8::internal::JsonParser<unsigned short>::MakeString(v8::internal::JsonString const&, v8::internal::Handle<v8::internal::String>) [node]
23: 0xe13d0e v8::internal::JsonParser<unsigned short>::ParseJsonValue() [node]
24: 0xe144df v8::internal::JsonParser<unsigned short>::ParseJson() [node]
25: 0xc28595 v8::internal::Builtin_JsonParse(int, unsigned long*, v8::internal::Isolate*) [node]
26: 0x13c04d9  [node]
Aborted
npm ERR! code ELIFECYCLE
npm ERR! errno 134
npm ERR! [email protected] start: `node index.js`
npm ERR! Exit status 134
npm ERR!
npm ERR! Failed at the [email protected] start script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /root/.npm/_logs/2021-01-21T11_31_15_662Z-debug.log

Contents of /root/.npm/_logs/2021-01-21T11_31_15_662Z-debug.log:

0 info it worked if it ends with ok
1 verbose cli [
1 verbose cli   '/root/.nvm/versions/node/v12.16.2/bin/node',
1 verbose cli   '/root/.nvm/versions/node/v12.16.2/bin/npm',
1 verbose cli   'run',
1 verbose cli   'start'
1 verbose cli ]
2 info using [email protected]
3 info using [email protected]
4 verbose run-script [ 'prestart', 'start', 'poststart' ]
5 info lifecycle [email protected]~prestart: [email protected]
6 info lifecycle [email protected]~start: [email protected]
7 verbose lifecycle [email protected]~start: unsafe-perm in lifecycle true
8 verbose lifecycle [email protected]~start: PATH: /root/.nvm/versions/node/v12.16.2/lib/node_modules/npm/node_modules/npm-lifecycle/node-gyp-bin:/root/dizquetv/node_modules/.bin:/root/.nvm/versions/node/v12.16.2/bin:/etc/miniconda3/bin:/etc/miniconda3/condabin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
9 verbose lifecycle [email protected]~start: CWD: /root/dizquetv
10 silly lifecycle [email protected]~start: Args: [ '-c', 'node index.js' ]
11 silly lifecycle [email protected]~start: Returned: code: 134  signal: null
12 info lifecycle [email protected]~start: Failed to exec start script
13 verbose stack Error: [email protected] start: `node index.js`
13 verbose stack Exit status 134
13 verbose stack     at EventEmitter.<anonymous> (/root/.nvm/versions/node/v12.16.2/lib/node_modules/npm/node_modules/npm-lifecycle/index.js:332:16)
13 verbose stack     at EventEmitter.emit (events.js:310:20)
13 verbose stack     at ChildProcess.<anonymous> (/root/.nvm/versions/node/v12.16.2/lib/node_modules/npm/node_modules/npm-lifecycle/lib/spawn.js:55:14)
13 verbose stack     at ChildProcess.emit (events.js:310:20)
13 verbose stack     at maybeClose (internal/child_process.js:1021:16)
13 verbose stack     at Process.ChildProcess._handle.onexit (internal/child_process.js:286:5)
14 verbose pkgid [email protected]
15 verbose cwd /root/dizquetv
16 verbose Linux 4.19.0-13-amd64
17 verbose argv "/root/.nvm/versions/node/v12.16.2/bin/node" "/root/.nvm/versions/node/v12.16.2/bin/npm" "run" "start"
18 verbose node v12.16.2
19 verbose npm  v6.14.4
20 error code ELIFECYCLE
21 error errno 134
22 error [email protected] start: `node index.js`
22 error Exit status 134
23 error Failed at the [email protected] start script.
23 error This is probably not a problem with npm. There is likely additional logging output above.
24 verbose exit [ 134, true ]

I can reproduce this by running 'playlist_to_channel.py' 5 or 6 times. 1KB JSON files will start to be created after the third or fourth and finally the crash occurs.

ghost avatar Jan 21 '21 11:01 ghost

After experimenting with node 10.23.1 both with and without nexe, it seems that the crashes are still occurring but just not terminating the process. Instead, the channel can't be found when running the script.

This issue doesn't arise if I wait until dizquetv's cpu usage returns to 0 after running each consecutive script. The script adds a playlist to a channel, shuffles the content and then stops, after which dizquetv's cpu usage rises.

ghost avatar Jan 21 '21 14:01 ghost

My current suspicion is that with 500 MB of channels.json, it is super easy to reach the default heap limits on nodejs. So maybe running nodejs with --max-old-space-size would help. Since you are in docker, give it a try with this page: https://developer.ibm.com/languages/node-js/articles/nodejs-memory-management-in-container-environments/

vexorian avatar Jan 22 '21 14:01 vexorian