Out of memory

[jsmouret]

Hello,

Our cache server is still running out of memory after a few hours.

Cacher server version: 6.3.0
Nodejs version: v10.15.3
Command line: nodejs --max-old-space-size=4096 /usr/lib/node_modules/unity-cache-server/main.js

Thanks for any help

Mar  7 17:18:49 unity3d-cache nodejs[17265]: <--- Last few GCs --->
Mar  7 17:18:49 unity3d-cache nodejs[17265]: [17265:0x397e270]  5318523 ms: Scavenge 4078.3 (4163.3) -> 4077.5 (4163.8) MB, 9.9 / 0.0 ms  (average mu = 0.184, current mu = 0.137) allocation failure
Mar  7 17:18:49 unity3d-cache nodejs[17265]: [17265:0x397e270]  5318537 ms: Scavenge 4078.4 (4163.8) -> 4077.6 (4164.3) MB, 10.1 / 0.0 ms  (average mu = 0.184, current mu = 0.137) allocation failure
Mar  7 17:18:49 unity3d-cache nodejs[17265]: [17265:0x397e270]  5318550 ms: Scavenge 4078.5 (4164.3) -> 4077.8 (4165.3) MB, 10.3 / 0.0 ms  (average mu = 0.184, current mu = 0.137) allocation failure
Mar  7 17:18:49 unity3d-cache nodejs[17265]: <--- JS stacktrace --->
Mar  7 17:18:49 unity3d-cache nodejs[17265]: ==== JS stack trace =========================================
Mar  7 17:18:49 unity3d-cache nodejs[17265]:     0: ExitFrame [pc: 0x13c4ff9dbe1d]
Mar  7 17:18:49 unity3d-cache nodejs[17265]: Security context: 0x00109993c7a9 <JSObject>
Mar  7 17:18:49 unity3d-cache nodejs[17265]:     1: _handleCommand [0x493819da881] [/usr/lib/node_modules/unity-cache-server/lib/server/command_processor.js:~266] [pc=0x13c5001b369f](this=0x029fe723fdf9 <Duplex map = 0xc5c50dcae49>,data=0x05a1d5961f79 <Uint8Array map = 0xe651a1d3771>)
Mar  7 17:18:49 unity3d-cache nodejs[17265]:     2: _write [0x493819da639] [/usr/lib/node_modules/unity-cache-server/lib/server/command_processor.js:~104] [pc=0x13c...
Mar  7 17:18:49 unity3d-cache nodejs[17265]: FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
Mar  7 17:18:49 unity3d-cache nodejs[17265]:  1: 0x8dc510 node::Abort() [/usr/bin/nodejs]
Mar  7 17:18:49 unity3d-cache nodejs[17265]:  2: 0x8dc55c  [/usr/bin/nodejs]
Mar  7 17:18:49 unity3d-cache nodejs[17265]:  3: 0xad9b5e v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [/usr/bin/nodejs]
Mar  7 17:18:49 unity3d-cache nodejs[17265]:  4: 0xad9d94 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/usr/bin/nodejs]
Mar  7 17:18:49 unity3d-cache nodejs[17265]:  5: 0xec7bf2  [/usr/bin/nodejs]
Mar  7 17:18:49 unity3d-cache nodejs[17265]:  6: 0xec7cf8 v8::internal::Heap::CheckIneffectiveMarkCompact(unsigned long, double) [/usr/bin/nodejs]
Mar  7 17:18:49 unity3d-cache nodejs[17265]:  7: 0xed3dd2 v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [/usr/bin/nodejs]
Mar  7 17:18:49 unity3d-cache nodejs[17265]:  8: 0xed4704 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/usr/bin/nodejs]
Mar  7 17:18:49 unity3d-cache nodejs[17265]:  9: 0xed7371 v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [/usr/bin/nodejs]
Mar  7 17:18:49 unity3d-cache nodejs[17265]: 10: 0xea07f4 v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationSpace) [/usr/bin/nodejs]
Mar  7 17:18:49 unity3d-cache nodejs[17265]: 11: 0x114018e v8::internal::Runtime_AllocateInNewSpace(int, v8::internal::Object**, v8::internal::Isolate*) [/usr/bin/nodejs]
Mar  7 17:18:49 unity3d-cache nodejs[17265]: 12: 0x13c4ff9dbe1d

[stephen-palmer]

can you please also post your config using node main.js --dump-config?

[jsmouret]

Using cache_ram seems to make the problem show up more quickly than cache_fs.
Here is the config;

Cache:
  defaultModule: cache_fs
  options:
    processor:
      putWhitelist: []
    cache_ram:
      cachePath: .cache_ram
      pageSize: 200000000
      maxPageCount: 227
      minFreeBlockSize: 1024
      persistence: false
      persistenceOptions:
        autosave: true
        autosaveInterval: 10000
        throttledSaves: false
      highReliability: false
      highReliabilityOptions:
        reliabilityThreshold: 2
        saveUnreliableVersionArtifacts: true
        multiClient: false
    cache_fs:
      cachePath: .cache_fs
      cleanupOptions:
        expireTimeSpan: P30D
        maxCacheSize: 0
      persistence: true
      persistenceOptions:
        autosave: true
        autosaveInterval: 10000
        throttledSaves: false
      highReliability: false
      highReliabilityOptions:
        reliabilityThreshold: 2
        saveUnreliableVersionArtifacts: true
        multiClient: false
Mirror:
  addresses: []
  options:
    queueProcessDelay: 2000
    connectionIdleTimeout: 10000
Server:
  port: 8126
  options:
    allowIpv6: false
Global:
  logLevel: 3

[corngood]

Hey @stephen-palmer,

As suggested in the other thread, here's a heap snapshot for the process:

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
13337 unityca+  20   0 3321028 2.149g  11604 S   0.0 13.8   2:58.25 node

Heap-20190327T085422.heapsnapshot.txt

Maybe you can see some sort of problem in there, but to me it doesn't seem to account for anywhere near 2g of physical memory.

[stephen-palmer]

Yeah I don't see evidence of a heap/javascript memory leak. I'm also not yet convinced this is a general/widespread issue based on a relatively small number of problem reports, relative to install base.

I've been searching for similar issues from other node users/apps of native/non-heap memory leaks. This one might be relevant: nodejs/help#1518

[timezombi]

Just to add one to the list, we give Unity Cache Server 49GB of RAM for oldspacesize and we still receive the same errors occasionally. Granted our project size is totally ridiculous.

We just recently switched over to UCS 6.3.0 and node v10.15.3. We haven't experienced a crash yet, but I can report back if we do.

To the original poster: We ended up "solving" the heap space issues by running it in a wrapper script that restarts the unity-cache-server whenever it exits with a non-zero exit code, then it sends me an email alert and starts a new log. It didn't stop the crashes but it did provide a way to rapidly recover when we had problems.

[jsmouret]

@timezombi I am using --workers to get the "autorestart" feature :)
48GB of RAM and it crashes once a week when a worker gets killed by the oom-killer.
No email notification, just jenkins aborting builds because of timeout.

[corngood]

I've been running for a bit with mtrace, but as with the v8 snapshot it only accounts for a tiny fraction of the total physical memory in libc allocations.

pmap shows a single large physical page range that seems to match up with the unaccounted for memory, but I haven't been able to track down exactly what it is... It's hard to imagine fragmentation causing this serious a problem, but who knows.

That's all the investigation I have time for this week. I'll try to get back to it at some point.

[timezombi]

Just to follow up on this, we did experience a crash again this morning. Total uptime was 17h 47m 56s. Each time this happens, millions of lines of Adding file to send queue, size <some_number> appear in the logs immediately before the GC failure. After it crashed, our recovery/restart script kicked in and everything has been stable since then.

This is the first time this has happened since upgrading to this version of node / Unity Cache server, but we have experienced this many times in older versions.

If there is anything else we can do to try to help you troubleshoot this problem, please let me know!

...............
[2019-04-11 08:23:48] Adding file to send queue, size 4308
[2019-04-11 08:23:48] Adding file to send queue, size 15837
[2019-04-11 08:23:48] Adding file to send queue, size 2809824
[2019-04-11 08:23:48] Adding file to send queue, size 663
[2019-04-11 08:23:48] Adding file to send queue, size 4276
[2019-04-11 08:23:48] Adding file to send queue, size 18739
[2019-04-11 08:23:48] Adding file to send queue, size 4412
[2019-04-11 08:23:48] Adding file to send queue, size 2824
[2019-04-11 08:24:06]
[2019-04-11 08:24:06] <--- Last few GCs --->
[2019-04-11 08:24:06]
[2019-04-11 08:24:06] [2647:0x36b1210] 64054016 ms: Scavenge 32672.3 (33245.9) -> 32661.7 (33245.9) MB, 403.0 / 0.0 ms (average mu = 0.915, current mu = 0.949) allocation failure
[2019-04-11 08:24:06] [2647:0x36b1210] 64054512 ms: Scavenge 32672.4 (33245.9) -> 32662.2 (33245.9) MB, 425.0 / 0.0 ms (average mu = 0.915, current mu = 0.949) allocation failure
[2019-04-11 08:24:06] [2647:0x36b1210] 64055016 ms: Scavenge 32672.4 (33245.9) -> 32662.4 (33245.9) MB, 432.7 / 0.0 ms (average mu = 0.915, current mu = 0.949) allocation failure
[2019-04-11 08:24:06]
[2019-04-11 08:24:06]
[2019-04-11 08:24:06] <--- JS stacktrace --->

Cacher server version: 6.3.0
Nodejs version: v10.15.3

Command Line: node --max-old-space-size=49152 /usr/local/bin/unity-cache-server -l 5 --NODE_CONFIG_DIR=/usr/local/bin/config

Config Dump:

Cache:
defaultModule: cache_fs
options:
processor:
putWhitelist: []
cache_ram:
cachePath: .cache_ram
pageSize: 100000000
maxPageCount: 10
minFreeBlockSize: 1024
persistence: true
persistenceOptions:
autosave: true
autosaveInterval: 10000
throttledSaves: false
highReliability: false
highReliabilityOptions:
reliabilityThreshold: 2
saveUnreliableVersionArtifacts: true
multiClient: false
cache_fs:
cachePath: .cache_fs
cleanupOptions:
expireTimeSpan: P30D
maxCacheSize: 0
persistence: true
persistenceOptions:
autosave: true
autosaveInterval: 10000
throttledSaves: false
highReliability: false
highReliabilityOptions:
reliabilityThreshold: 2
saveUnreliableVersionArtifacts: true
multiClient: false
Mirror:
addresses: []
options:
queueProcessDelay: 2000
connectionIdleTimeout: 10000
Server:
port: 8126
options:
allowIpv6: false
Global:
logLevel: 3

[stephen-palmer]

ok, this is the best clue yet. While millions of queued downloads will incur allocations per request, it should only be about 64 bytes per item. I'm actually thinking that debug logging might be the real culprit here. The logging strings are copied around in memory at least a couple of times I'm sure, and though they do eventually garbage collect, it takes some cycles.

Can you take your logging level down one notch and see how it runs for a while?

[timezombi]

No problem! I set the logging level to 3 instead of 5.

With our current oldspacesize, it usually takes several weeks for us to encounter any problems. I'll post here again if/when it happens.

[stephen-palmer]

This new branch takes a pass at minimizing string allocs during logging, and especially when the log level is below 5 (debug).