Memory leak? Getting OutOfMemoryError even with 3GB+ Java Heap

[inzeph]

I'm on a Synology DS918+ and I'm consistently seeing FileBot fn:amc run out of memory as it attempts process the extraction phase of a few large folders (65GB / 112GB) even as I throw gigs of memory at it.

I've seen this problem both before and after a recent upgrade of the Synology FileBot package, and I keep bumping -Xmx and still running out of heap space.

This makes me feel like there must be a memory leak somewhere in the extraction code.

Here's my sysinfo:

Code: Select all

$ JAVA_OPTS="-Xmx3G" filebot -script fn:sysinfo
FileBot 4.8.2 (r5710)
JNA Native: 5.2.0
MediaInfo: net.filebot.mediainfo.MediaInfoException: Unable to load amd64 (64-bit) native library libmediainfo.so: Unable to load library 'mediainfo': Native library (linux-x86-64/libmediainfo.so) not found in resource path ([file:/volume1/@appstore/filebot/jar/filebot.jar])
Apache Commons VFS: [zip, rar]
Chromaprint: java.io.IOException: Cannot run program "fpcalc": error=2, No such file or directory
Extended Attributes: OK
Unicode Filesystem: OK
Script Bundle: 2018-07-15 (r530)
Groovy: 2.5.0
JRE: OpenJDK Runtime Environment 1.8.0_161
JVM: 64-bit OpenJDK 64-Bit Server VM
CPU/MEM: 4 Core / 2 GB Max Memory / 27 MB Used Memory
OS: Linux (amd64)
HW: Linux libobab 4.4.59+ #23739 SMP PREEMPT Tue Jul 10 00:18:17 CST 2018 x86_64 GNU/Linux synology_apollolake_918+
DATA: [redacted]
Package: SPK
License: UNREGISTERED

Here's the command that keeps running out of memory:

Code: Select all

JAVA_OPTS="-Xmx3G" filebot -script fn:amc --output [redacted] --action copy --conflict skip --def deleteAfterExtract=y --def extractFolder=[redacted] .

And here's the stack traces I start seeing after 5-10m of runtime:

Code: Select all

Exception in thread "Thread-482" java.lang.OutOfMemoryError: Java heap space
	at com.github.junrar.unpack.ppm.SubAllocator.startSubAllocator(SubAllocator.java:146)
	at com.github.junrar.unpack.ppm.ModelPPM.decodeInit(ModelPPM.java:215)
	at com.github.junrar.unpack.Unpack.readTables(Unpack.java:652)
	at com.github.junrar.unpack.Unpack.unpack29(Unpack.java:161)
	at com.github.junrar.unpack.Unpack.doUnpack(Unpack.java:116)
	at com.github.junrar.Archive.doExtractFile(Archive.java:553)
	at com.github.junrar.Archive.extractFile(Archive.java:492)
	at com.github.junrar.Archive$1.run(Archive.java:526)
	at java.lang.Thread.run(Thread.java:748)

Code: Select all

Exception in thread "Thread-483" java.lang.OutOfMemoryError: Java heap space
	at com.github.junrar.unpack.Unpack.init(Unpack.java:93)
	at com.github.junrar.Archive.doExtractFile(Archive.java:549)
	at com.github.junrar.Archive.extractFile(Archive.java:492)
	at com.github.junrar.Archive$1.run(Archive.java:526)
	at java.lang.Thread.run(Thread.java:748)

I'll see if I can find time to point a few JVM debugging tools at this scenario to try and solve this myself, but I'm reporting it here in case anybody else has this same problem and/or makes progress on diagnosing it.

[inzeph]

Alright I snagged a heap dump and tossed it into Eclipse Memory Analyzer Tool and the problem became immediately clear:

Code: Select all

73 instances of "com.github.junrar.Archive", loaded by "sun.misc.Launcher$AppClassLoader @ 0x700373100" occupy 2,160,735,776 (98.87%) bytes.

Biggest instances:

com.github.junrar.Archive @ 0x723462390 - 30,588,472 (1.40%) bytes.
com.github.junrar.Archive @ 0x723cb1a30 - 30,588,472 (1.40%) bytes.
com.github.junrar.Archive @ 0x72944ec98 - 30,588,472 (1.40%) bytes.
com.github.junrar.Archive @ 0x72a0e1918 - 30,588,472 (1.40%) bytes.
com.github.junrar.Archive @ 0x72f8803c8 - 30,588,472 (1.40%) bytes.
com.github.junrar.Archive @ 0x73092fb98 - 30,588,472 (1.40%) bytes.
[ ... etc ... ]

It looks like either FileBot or AMC is hanging onto instances of ApacheVFS.

I noticed that there are two other 7Z-based extractor implementations. I tried flopping out the "SevenZipExecutable" one, as I had "7-Zip [64] 9.20" on my path. This fell over pretty hard with errors like this:

Code: Select all

IOException: 7z failed with exit code 2: Error: /path/to/.../file.rar: Can not open file as archive Errors: 1

This may very well be due to the fact that 7z 9.20 is super old (circa 2010). I'll keep digging on both the memory leak and the alternate extractor workaround. Stay tuned!

[inzeph]

Progress on both fronts:

1. SevenZipNativeBindings seem to be functioning nicely for me as a workaround.
2. I think I've zeroed in on the leak for ApacheVFS: the FileSystemManager is a singleton with a default cache implementation that "caches every file with no expire or limit. All files and filesystems are hard reachable references."

Fixing this should just be a matter of flopping in the NullFilesCache to turn off the cache altogether.

[rednoah]

1.
I recall trying to use 7z a falling flat on my face when actually trying on my DSM, since they compile 7z without non-free components, on DSM you get 7z but without RAR support.

2.
I recall junrar not playing nicely with large RAR files. Pretty sure it's junrar itself not scaling well, not VFS, but it's abandoned, and I'm not inclined in fixing / maintaining it. But in any case, I'll look into turning of caching in VFS and see if it makes a difference.


EDIT:

Applied recommended changes with r4571. Untested. May or may not work. Updated jar can be found here.

[inzeph]

Thanks for the quick response, rednoah! That looks very close to the patch I was cooking up over here.

Let me rebuild from master and re-test.

[rednoah]

Upload complete. Please give it a whirl. Let's hope it fixes the memory leak, though I kinda doubt it.

[inzeph]

Hm dang now getting:

Code: Select all

FileSystemException: Could not find a file provider which can handle local files.

Looks like the FileSystemManager needs a bit more setup than a straight initializer will give us.

I'm staring at createManager now trying to figure out what else getManager() does that your commit does not.

[rednoah]

I was worried about that. Not using the default manager (so we can have our own caching strategy) isn't as straight forward. I guess we'll need to copy the init code from the default manager. That sucks.


EDIT:

Had a quick look at the VFS sources. Should work now. Or at least work exactly the same as before.

r5745 has been uploaded. Please give it a try.

[inzeph]

It's working! Made it through the extraction phase with no memory errors and holding steady at just under 630MB resident as it's chewing on the copy phase.

Thanks so much for all your help with this! Picked up my license the other day; will upgrade to lifetime license if this keeps going well. :)

[rednoah]

Nice. Thanks for helping fix a long standing issues. Didn't think it'd be such an easy fix.


EDIT:

AFAIK, This is the first meaningful code contribution in 10 years, like someone actually looking at the code and figuring things out with debugging tools. Keep it up! Much appreciated. Hit me up for a free license anytime.