AMC script grinds to a complete halt

[finkille]

Hi,

Been using Filebot for a few years and sometime last year I started to get issues with that my old trusty script took longer than usual (as in from a minute or two up to 40 minutes or hours). Observing this a bit more it seemed like the Synology (DS415play) where thrashing the disk by swapping back and forth memory (kswap and the Java process for filebot taking turns on the NAS).

There was another helpful thread viewtopic.php?f=6&t=9542 , which I followed (my autoupdate of Java had stopped just like that case) but even though there were improvements, more often than not the script would just take ages. Is this due to Plex taking ever more memory leaving less for Filebot which then constrained gives up? Perhaps, in the past I have seen improved performance by restarting the NAS but even this seems to be helping less.

So I tried to do a "manual" AMC by running (and timing) Filebot with -r and running the cleaner script and manually curl:ing Plex for an update. This takes less than a minute to finish every time, indicating to me that the issue is not so much with Filebot as with the AMC script (the cleaner script also runs neatly).

I'd love to have this resolved/improved since my current workaround has limitations (I sometimes also have tv-shows in the mix, and would prefer .nfo files not to be moved as well for instance).

Attaching some outputs and code below with <REDACTED> for identifiable information.

Code: Select all

filebot -script fn:sysinfo
FileBot 4.8.5 (r5996)
JNA Native: 5.2.2
MediaInfo: 17.12
7-Zip-JBinding: 9.20
Chromaprint: java.io.IOException: Cannot run program "fpcalc": error=2, No such file or directory
Extended Attributes: OK
Unicode Filesystem: OK
Script Bundle: 2018-11-29 (r539)
Groovy: 2.5.4
JRE: Java(TM) SE Runtime Environment 1.8.0_191
JVM: 32-bit Java HotSpot(TM) Client VM
CPU/MEM: 4 Core / 170 MB Max Memory / 12 MB Used Memory
OS: Linux (i386)
HW: Linux Hyrule 3.2.40 #23824 SMP PREEMPT Fri Sep 7 12:49:23 CST 2018 i686 GNU/Linux synology_evansport_415play
DATA: /volume1/@appstore/filebot/data/<REDACTED>
Package: SPK
License: FileBot License <REDACTED> (Valid-Until: 2019-07-24)

Code: Select all

free -h
              total        used        free      shared  buff/cache   available
Mem:           699M        376M        125M         30M        197M        114M
Swap:          2.4G        578M        1.8G

The basic script that runs fine (although doesn't automatically differ between tv-shows and movies, and choose to keep .nfo files)

Code: Select all

filebot /volume1/Download/ -rename -r --format {plex.tail} -non-strict --action move --log all --db TheMovieDB --output /volume1/Video/Cinema/ --log-file fb-mov.log -no-xattr
curl -G http://<REDACTED>:32400/library/sections/all/refresh?X-Plex-Token=<REDACTED>
filebot -script fn:cleaner /volume1/Download/

The AMC script which most of the time grinds to a halt

Code: Select all

filebot -script fn:amc --output "/volume1/Video/" --action move -non-strict --def clean=y --conflict auto --def plex=<REDACTED> --def movieFormat="/volume1/Video/Cinema/{n} ({y})/{n} ({y}){' Pt'+pi}" --def seriesFormat="/volumeUSB1/usbshare/TV Shows/{n}/{n} - {s00e00} - {t}" "/volume1/Download" --log-file /var/services/homes/<REDACTED>/fbot-script.log --log-lock no --log all -no-xattr

[rednoah]

170 MB max memory may not be enough to run the amc script well depending on the input files:

Code: Select all

CPU/MEM: 4 Core / 170 MB Max Memory / 12 MB Used Memory

You can use the JAVA_OPTS environment variable to give the FileBot java process more memory to work with.

e.g.

Code: Select all

export JAVA_OPTS="-Xmx384m"

Presumably, if FileBot gets more memory, then there'll be more swap activity as well, processes not filebot being swapped out main memory, but ideally that should ensure that FileBot can do it's work quickly and exit and give memory back to all the other processes running in background at all times.

[finkille]

It made a difference since the script ran through completion but it takes a good amount of more time than running the "bare" filebot command.

Code: Select all

real	8m11.706s
user	1m21.189s
sys	0m17.017s

Is above indicating I should raise the RAM even higher? It just seems odd to me that the AMC script adds about an order of magnitude when running with the same input as "just filebot".

Can I get more insight in what "steps" or tasks AMC spends most of it time doing? Also, I haven't seen these timing say a year ago or so, so it seems there has been some performance degradation given same hardware and "similar" software setup although I don't unfortunately have exact numbers or ability to replicate the old environment. Is this something you measure in your test suite for each release?

[rednoah]

You can use standard Unix tools to add timestamps to each line of the filebot output:
https://unix.stackexchange.com/a/26729/78608

e.g.

Code: Select all

filebot -script fn:sysinfo | while IFS= read -r line; do printf '[%s] %s\n' "$(date '+%Y-%m-%d %H:%M:%S')" "$line"; done

CPU/MEM requirements can differ quite significantly just depending on wether or not the input files can easily be identified as either episode or movie. Very hard to say without spending some time on debugging. Maybe logs + timestamps will give us some clues as to what it's working on for most of that time.

Newer versions of FileBot certainly have higher requirements than older versions, especially for tricky files, since there's a lot more going on nowadays.

[rednoah]

Print timestamp for each log event: true | false

Code: Select all

-Dnet.filebot.logging.time=true

r6005 adds support for adding fine-grained timestamps to logging output directly.

[finkille]

I added

Code: Select all

export JAVA_OPTS="-Dnet.filebot.logging.debug=ALL -Dnet.filebot.logging.time=true -Dnet.filebot.web.WebRequest.log.response=true -Xmx384m"

And looked at the logfile. For five movies it took about 5 minutes which is I guess OK but in the past it has run significantly faster. The whole logfile is availabile here https://www.dropbox.com/s/5ogxvk2tx46ur ... 2.log?dl=0 (I didn't want to paste 700k in this post )

I don't really know what to expect here, more than that in my recollection this was faster in the past. That said, after specifying filebot should get 384m it completes and it's not the end of the world if it takes a few minutes but perhaps it can give some indication on what causes the performance to take a hit.

[rednoah]

There's an interesting time jump here:

Code: Select all

[2019-01-19 21:08:32.085] Rank [Theorem 1968] => [Teorema (1968)]
[2019-01-19 21:08:32.324] rovers-theorema1080p.mkv [series: theorem 1968, movie: Teorema (1968)]
[2019-01-19 21:08:58.018] Query Movie => [theorem 1968]
[2019-01-19 21:08:58.686] Rank [Theorem 1968] => [Teorema (1968)]
[2019-01-19 21:08:58.839] Exclude Series: theorem 1968

That's caused by badly named files, that are very unclear, can't even tell if its movie or series, and thus take exponentially longer to process.

Simple file names like Alias.1x01.mp4 or Avatar.2009.mp4 that make sense on first glance will probably take significantly less long.

Forcing movie / series mode via --def ut_label will also speed things up significantly, if you can make that assertion.

[finkille]

If I could specify in advance I’d more likely run two separate filebot commands, since that seems to give better performance for me.

I also registered that then cleaning part used quite some time, more than 30 seconds to determine which files are clutter sounds suscept.

[rednoah]

That one is odd for sure.

Have you tried running the cleaner script separately to see if you get different performance?
https://github.com/filebot/scripts/blob ... ner.groovy

There's not much going on in that script. Either it's slow because the amc code already gobbled up the memory, or maybe because of slow file system calls.

[finkille]

I resolved this by moving my Plex sever to another host and without the constrained memory situation the AMC runs in reasonably time so It just seems that over time my applications got more bloated and finally reached a point where they couldn’t fit smoothly any longer...

[rednoah]

Best to run the amc script on a machine with a little bit more memory anyway. Thought it seems like this particular issue could have been mitigated by running the cleaner script with a separate command-line call.