AMC Script execution extremely slow

[sabinder62]

I just upgraded my system to Ubuntu 22.04 a few days back. Filebot has been reinstalled using the APT package and both app and amc script started working fine. However very suddenly yesterday afternoon, its execution time ground to a complete halt. I removed and reinstalled Filebot, restarted the machine many times but this has had no effect. I left it running yesterday and it took over 10 hours to complete execution for just 32 files, which usually would be a mere matter of minutes before. No errors were shown in error.log or amc.log for me to investigate.

I run filebot via a straightforward bash script which i have barely changed in over 6 years:

Code: Select all

#!/bin/bash

filebot -script fn:amc --output "/mnt/data/torrents/processed" --action hardlink --conflict auto -non-strict "/mnt/data/torrents/complete" --log-file /mnt/data/torrents/processed/amc.log --def excludeList=amc.txt clean=y unsorted=n artwork=n subtitles=en deleteAfterExtract=n storeReport=reports reportError=y pushover=u2d3uvztef3j3ki8vz29mb5gdhr4fa "seriesFormat=/mnt/data/media/{plex.id} [{vf}, {vs}, {vc}, {bitrate}]" "movieFormat=/mnt/data/media/{plex.id} (edition-{tags[0]}) [{vf}, {vs}, {vc}, {bitrate}]"

sysinfo:

Code: Select all

FileBot 4.9.6 (r9125)
JNA Native: 6.1.1
MediaInfo: 21.09
Tools: fpcalc/1.5.1 7z/16.02 unrar/6.11
Extended Attributes: OK
Unicode Filesystem: OK
GVFS: PlatformGVFS [/run/user/1000/gvfs]
Script Bundle: 2022-08-15 (r836)
Groovy: 3.0.9
JRE: OpenJDK Runtime Environment 11.0.16
JVM: OpenJDK 64-Bit Server VM
CPU/MEM: 4 Core / 4.2 GB Max Memory / 45 MB Used Memory
OS: Linux (amd64)
HW: Linux houseofel 5.15.0-48-generic #54-Ubuntu SMP Fri Aug 26 13:26:29 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
CPU/MEM: Intel(R) Core(TM) i3-8300T CPU @ 3.20GHz [MemTotal: 16 GB | MemFree: 445 MB | MemAvailable: 10 GB | SwapCached: 135 MB | SwapTotal: 2.1 GB | SwapFree: 989 MB]
STORAGE: NONE
USER: houseofel
DATA: /home/houseofel/.filebot
Package: DEB
License: FileBot License PX21730371 (Valid-Until: 2070-12-28)
[2022-10-08 15:02:57.382] Done ヾ(＠⌒ー⌒＠)ノ

error.log

Code: Select all

Oct 07, 2022 3:15:56 PM net.filebot.ui.transfer.FileTransferable lambda$getFilesFromTransferable$0
WARNING: GVFS: file:///home/houseofel/licence => java.io.FileNotFoundException: /home/houseofel/licence
Oct 07, 2022 3:15:56 PM net.filebot.ui.transfer.FileTransferable lambda$getFilesFromTransferable$0
WARNING: GVFS: file:///home/houseofel/licence => java.io.FileNotFoundException: /home/houseofel/licence
Oct 07, 2022 4:13:04 PM net.filebot.DiskStore acquireDiskStore
WARNING: Initialize new disk cache: /home/houseofel/.filebot/cache/1
Oct 07, 2022 4:17:55 PM net.filebot.License lambda$verifyLicense$1
WARNING: Activate License [PX21730371] on [Fri Oct 07 16:17:55 BST 2022]
Oct 07, 2022 4:21:41 PM net.filebot.DiskStore acquireDiskStore
WARNING: Initialize new disk cache: /home/houseofel/.filebot/cache/0
Oct 07, 2022 4:21:43 PM net.filebot.License lambda$verifyLicense$1
WARNING: Activate License [PX21730371] on [Fri Oct 07 16:21:43 BST 2022]
Oct 08, 2022 2:02:25 PM net.filebot.License lambda$verifyLicense$1
WARNING: Activate License [PX21730371] on [Sat Oct 08 14:02:25 BST 2022]

amc.log
https://pastebin.com/wbJkj5mJ

I turned on time logging so I could demonstrate the problem and just re-ran the script. As you can see from the console output, after reading parameters, it doesnt start unarchiving files until well over 30 mins later.

Code: Select all

houseofel@houseofel:~$ bash Documents/filebotScript.bash 
[2022-10-08 14:25:10.258] Run script [fn:amc] at [Sat Oct 08 14:25:10 BST 2022]
[2022-10-08 14:25:10.283] Parameter: excludeList = amc.txt
[2022-10-08 14:25:10.284] Parameter: clean = y
[2022-10-08 14:25:10.284] Parameter: unsorted = n
[2022-10-08 14:25:10.284] Parameter: artwork = n
[2022-10-08 14:25:10.284] Parameter: subtitles = en
[2022-10-08 14:25:10.285] Parameter: deleteAfterExtract = n
[2022-10-08 14:25:10.285] Parameter: storeReport = reports
[2022-10-08 14:25:10.285] Parameter: reportError = y
[2022-10-08 14:25:10.285] Parameter: pushover = *****
[2022-10-08 14:25:10.286] Parameter: seriesFormat = /mnt/data/media/{plex.id} [{vf}, {vs}, {vc}, {bitrate}]
[2022-10-08 14:25:10.286] Parameter: movieFormat = /mnt/data/media/{plex.id} (edition-{tags[0]}) [{vf}, {vs}, {vc}, {bitrate}]
[2022-10-08 14:25:10.290] Argument[0]: /mnt/data/torrents/complete
[2022-10-08 14:25:10.599] Use excludes: /mnt/data/torrents/processed/amc.txt (28)
[2022-10-08 15:02:15.632] Read archive [day.shift.2022.proper.1080p.web.h264-rumour.rar] and extract to [/mnt/data/torrents/complete/Day.Shift.2022.PROPER.1080p.WEB.h264-RUMOUR/day.shift.2022.proper.1080p.web.h264-rumour/Day.Shift.2022.PROPER.1080p.WEB.h264-RUMOUR]
[2022-10-08 15:02:20.475] Include [/mnt/data/torrents/complete/Day.Shift.2022.PROPER.1080p.WEB.h264-RUMOUR/day.shift.2022.proper.1080p.web.h264-rumour/Day.Shift.2022.PROPER.1080p.WEB.h264-RUMOUR/Day.Shift.2022.PROPER.1080p.WEB.h264-RUMOUR.mkv]
[2022-10-08 15:02:20.475] Skipped [/mnt/data/torrents/complete/Day.Shift.2022.PROPER.1080p.WEB.h264-RUMOUR/day.shift.2022.proper.1080p.web.h264-rumour/Day.Shift.2022.PROPER.1080p.WEB.h264-RUMOUR/Day.Shift.2022.PROPER.1080p.WEB.h264-RUMOUR.mkv] because [/mnt/data/torrents/complete/Day.Shift.2022.PROPER.1080p.WEB.h264-RUMOUR/day.shift.2022.proper.1080p.web.h264-rumour/Day.Shift.2022.PROPER.1080p.WEB.h264-RUMOUR/Day.Shift.2022.PROPER.1080p.WEB.h264-RUMOUR.mkv] already exists (6 GB)
[2022-10-08 15:02:42.850] Read archive [elementary.s03e11.1080p.web.h264-dimepiece.rar] and extract to [/mnt/data/torrents/complete/Elementary.S03E11.1080p.WEB.H264-DiMEPiECE/elementary.s03e11.1080p.web.h264-dimepiece/Elementary.S03E11.1080p.WEB.H264-DiMEPiECE]

I even investigated system monitor while the script is running and neither openjdk, filebot or bash seem to be using much memory or CPU to indicate a leak or runaway process. I cannot for the life of me figure out what is wrong since it started off working fine. As you can see from my sysinfo, system resources for RAM or CPU are clearly not an issue.

I thought it could be some corrupted files in the target folder, but i cleared the folder to one file and though it got through a few more steps, it has been stuck on the last step for over 10 minutes (current time is 2022-10-08 16:20).

Code: Select all

houseofel@houseofel:~$ bash Documents/filebotScript.bash 
[2022-10-08 16:07:43.468] Run script [fn:amc] at [Sat Oct 08 16:07:43 BST 2022]
[2022-10-08 16:07:43.489] Parameter: excludeList = amc.txt
[2022-10-08 16:07:43.490] Parameter: clean = y
[2022-10-08 16:07:43.490] Parameter: unsorted = n
[2022-10-08 16:07:43.490] Parameter: artwork = n
[2022-10-08 16:07:43.490] Parameter: subtitles = en
[2022-10-08 16:07:43.491] Parameter: deleteAfterExtract = n
[2022-10-08 16:07:43.491] Parameter: storeReport = reports
[2022-10-08 16:07:43.491] Parameter: reportError = y
[2022-10-08 16:07:43.491] Parameter: pushover = *****
[2022-10-08 16:07:43.491] Parameter: seriesFormat = /mnt/data/media/{plex.id} [{vf}, {vs}, {vc}, {bitrate}]
[2022-10-08 16:07:43.492] Parameter: movieFormat = /mnt/data/media/{plex.id} (edition-{tags[0]}) [{vf}, {vs}, {vc}, {bitrate}]
[2022-10-08 16:07:43.495] Argument[0]: /mnt/data/torrents/complete
[2022-10-08 16:07:43.677] Use excludes: /mnt/data/torrents/processed/amc.txt (0)
[2022-10-08 16:08:05.058] Input: /mnt/data/torrents/complete/The Lost City 2022 1080p Blu-ray Remux AVC TrueHD 7.1-HDT.mkv
[2022-10-08 16:08:05.116]        └─ Metadata: The Lost City (2022)
[2022-10-08 16:08:07.986] Group: {Movie=The Lost City (2022)} => [The Lost City 2022 1080p Blu-ray Remux AVC TrueHD 7.1-HDT.mkv]
[2022-10-08 16:08:07.995] Get [English] subtitles for 1 file
[2022-10-08 16:08:07.995] Looking up subtitles by hash via OpenSubtitles
[2022-10-08 16:08:08.898] No subtitle match by hash: /mnt/data/torrents/complete/The Lost City 2022 1080p Blu-ray Remux AVC TrueHD 7.1-HDT.mkv
[2022-10-08 16:08:08.910] Rename movies using [TheMovieDB]
[2022-10-08 16:08:08.911] Auto-detect movie from context [/mnt/data/torrents/complete/The Lost City 2022 1080p Blu-ray Remux AVC TrueHD 7.1-HDT.mkv]

The only app writing to the target folder is qbittorrent via a docker container. I have also tried renaming from the GUI, and once I click my preset the files selected take over 5 mins to appear correctly in the right window.

Any ideas on what I can investigate next would be very welcome! Thanks so much for your help in advance.

[rednoah]

1.
Do lots of trial and error and see if there's specific things that are slow, e.g. network requests? file read/write operations? You can do different filebot commands (i.e. not the amc script) to test different aspects, e.g. -extract to extract archives, -mediainfo to read files, -list --db TheTVDB to test database connectivity, -rename --db TheTVDB to test renaming, etc.


2.
Memory shouldn't be an issue. But you also seem to be using 95% already, so it's probably worth a try to just turn off everything, and then see what happens if you run filebot while nothing else is running.


3.
You could also try the latest JDK.


4.
You could do kill -3 <pid> to make the filebot process dump current stack traces so you can see where each thread is currently stuck at.



EDIT:

Does your system start using SWAP when running filebot? It's configured to use up to 4.2 GB Max Memory so it could easily exceed your MemFree: 445 MB as soon as it's doing memory-intensive work. You can use export JAVA_OPTS=-Xmx256m to set the appropriate amount of RAM yo have allocated for running the filebot process.

[sabinder62]

Thanks so much for the rapid response!

So I updated to the latest OpenJDK (18), which had no effect.

On the memory suggestion, my understanding is that Free memory is unused in Linux and Available memory is the amount which is available for processes (in my case 10GB) - reference.

That being said I tried to reduce it using export JAVA_OPTS=-Xmx500m anyway which also did nothing for performance. I confirmed swap does not start being used after filebot is running.

I must admit I am not sure how to find the core dump after I kill the filebot process using kill -3 <pid> and what I can even do with the data.

I have gone through some different filebot commands as you suggested however, and it appears that -mediainfo is taking a very long time = 42m for 17 files

Command

Code: Select all

time filebot -mediainfo /mnt/data/torrents/complete/

output

Code: Select all

/mnt/data/torrents/complete/Ambulance.2022.1080p.BluRay.REMUX.AVC.Atmos-TRiToN.mkv [1920x1080 AVC 7.1 MLP 2∶16 31 Mbps]
/mnt/data/torrents/complete/Beast.2022.1080p.BluRay.REMUX.AVC.DTS-HD.MA.7.1-TRiToN.mkv [1920x1080 AVC 7.1 DTS 1∶32 37 Mbps]
/mnt/data/torrents/complete/Bullet.Train.1080p.WEB-DL.DDP5.1.H.264-EVO.mkv [1920x1080 x264 5.1 EAC3 2∶06 5.5 Mbps]
/mnt/data/torrents/complete/Bullet.Train.2022.1080p.AMZN.WEB-DL.DDP5.1.H.264-FLUX.mkv [1920x800 AVC 5.1 EAC3 2∶06 9.1 Mbps]
/mnt/data/torrents/complete/DC.League.of.Super-Pets.2022.1080p.BluRay.REMUX.AVC.Atmos-PiRaTeS.mkv [1920x1080 AVC 7.1 MLP 1∶45 31 Mbps]
/mnt/data/torrents/complete/Dune.2021.PROPER.UHD.BluRay.2160p.10bit.DoVi.2Audio.TrueHD(Atmos).7.1.x265-b.mkv [3840x1606 x265 7.1 MLP 2∶35 33 Mbps]
/mnt/data/torrents/complete/Elvis.2022.1080p.BluRay.REMUX.AVC.Atmos-TRiToN.mkv [1920x1080 AVC 7.1 MLP 2∶39 28 Mbps]
/mnt/data/torrents/complete/Ghostbusters.Afterlife.2021.1080p.Remux.AVC.DTS-HD.MA.5.1-playBD.mkv [1920x1080 AVC 5.1 DTS 2∶03 30 Mbps]
/mnt/data/torrents/complete/House.of.the.Dragon.S01E07.1080p.HMAX.WEB-DL.DDP5.1.Atmos.x264-CMRG.mkv [1920x1080 x264 5.1 EAC3 0∶58 9.0 Mbps]
/mnt/data/torrents/complete/Indiana.Jones.and.the.Last.Crusade.1989.108p.BluRay.REMUX.AVC.DTS.HDMA.5.1.mkv [1920x1080 AVC 5.1 DTS 2∶06 39 Mbps]
/mnt/data/torrents/complete/Minions.The.Rise.of.Gru.2022.1080p.BluRay.REMUX.AVC.Atmos-PiRaTeS.mkv [1920x1080 AVC 7.1 MLP 1∶27 32 Mbps]
/mnt/data/torrents/complete/Promising Young Woman 2020 1080p BluRay REMUX AVC DTS-HD MA 7.1-BdC..mkv [1920x1080 AVC 7.1 DTS 1∶53 37 Mbps]
/mnt/data/torrents/complete/The.Batman.2022.UHD.BluRay.2160p.10bit.HDR.2Audio.TrueHD(Atmos).7.1.x265-beAst.mkv [3840x1608 x265 7.1 MLP 2∶56 33 Mbps]
/mnt/data/torrents/complete/The.Lord.of.the.Rings.The.Rings.of.Power.S01E06.Udun.1080p.AMZN.WEB-DL.DDP5.1.Atmos.H.264-CMRG.mkv [1920x800 AVC 5.1 EAC3 1∶09 7.9 Mbps]
/mnt/data/torrents/complete/The.Lord.of.the.Rings.The.Rings.of.Power.S01E07.The.Eye.1080p.AMZN.WEB-DL.DDP5.1.Atmos.H.264-CMRG.mkv [1920x800 AVC 5.1 EAC3 1∶12 7.8 Mbps]
/mnt/data/torrents/complete/The.Reef.Stalked.2022.1080p.BluRay.REMUX.AVC.DTS-HD.MA.5.1-TRiToN.mkv [1920x1080 AVC 5.1 DTS 1∶32 25 Mbps]
/mnt/data/torrents/complete/The Lost City 2022 1080p Blu-ray Remux AVC TrueHD 7.1-HDT.mkv [1920x1080 AVC 7.1 MLP 1∶51 34 Mbps]

real	42m54.181s
user	0m4.080s
sys	0m3.545s

EDIT: Having run a few commands, it appears that all filebot commands are running slowly not just the -mediainfo one. I started to suspect it was something to do with the folder itself. Next reply reveals more

Any suggestions on what to look for as the underlying issue?

[sabinder62]

I decided to move some of the downloaded files from the current target directory into my home Documents folder to see if this helped at all. My current target directory is on a mounted drive at /mnt/data.

I re-ran the filebot script on my home Documents folder and it ran perfectly with no delays so something is wrong with my mounted drive.

The only thing I can think is perhaps the permissions on the mounted drive have gotten messed up causing the slow responses?
The only thing I could think to do is use find & chmod to ensure all my directories had 775 permissions.

Example

Code: Select all

find /mnt/data/torrents/ -type d -exec chmod 775 {} \;

Code: Select all

find /mnt/data/torrents/ -type f -exec chmod 664 {} \;

I verified all permission changes using ls -la

However, this still made no difference to the performance. SMART checks dont reveal any bad sectors or issues with the drive itself either.
Any clue what I can check next? I feel like I am getting very close and really want to avoid having to format the whole drive and redownloading my entire library of TV & Movies as it is 4TB big.

Thanks in advance!

[rednoah]

1.
Ups, sorry about the RAM theory. 10 GB is more than enough. I didn't see MemTotal and confused it with MemAvailable. So things should be good in this regard.



2.
When you do -mediainfo is it slow at startup, and then prints lots of lines in rapid succession? Or is it constantly printing lines, one at a time, with lots of wait time before each line is printed? The latter would indicate a underlying file system issue.


Is your mounted drive a local disk or a remote network share? If you do something generic - like computing md5 checksums for some files - is that also unexpectedly slow?

You can do further trial and error testing with the -mediainfo command by using different --format options to test different aspects, e.g. --format "{f}" requires no File I/O and should thus be fast, --format "{f} {vc}" will require libmediainfo calls and reading the file content thus much slower, --format "{f} {crc32}" -no-xattr will require the entire file to be read, and thus be the slowest by far, etc.



3.
kill -3 <pid> sends the SIGQUIT (3) signal to the process with the given process ID number. The java process happens to use this signal to just dump current process information (i.e. thread stack traces that tell us exactly what each thread is doing at this point in time) and so that would tell us in which method / function the process is currently stuck at. That would allow us to confirm that it's stuck doing file I/O or network I/O or something else.

kill -3 <pid> output will be printed to the console output. You will not find the information in a log file unless you are redirecting output. If you have filebot running in an interactive console, and send the signal from another console, then the output will appear immediately on the console that is running the filebot process.



EDIT:

STORAGE: NONE output could be a potential clue, or not. I just noticed it because we're talking about potential file system issues. I usually only see that line in SNAP packages that are sandboxed and have limited file system access. I'd expect something like STORAGE: ext4 [/] @ 7 GB | ext4 [/volume1] @ 611 GB on a normal Linux system.

[sabinder62]

After a few days of testing all your great suggestions, it became obvious that I have completely screwed up the mounted drive permissions. I couldn’t get any I/O speeds above 2MB/s. I have learnt the hard way not to mess with drive permissions at 4am when tired!

I went ahead and just formatted the whole drive and Filebot performance has returned to its expected behaviour. After re downloading a large part of my library, Filebot processed the 200 or so torrents within a few hours with a number of RAR extractions, so back to its usual epic self.

Thanks for all your help and advice here, managed to learn a lot more about process dumps and the other parts of filebot which is very much appreciated!

You can consider this topic closed off.

For anyone landing here - don’t make my mistake and install Plex on Ubuntu as APT, messing with permissions of drives is a total pain to get right, the docker container works straight out the door with appropriate PUID & PGID (1000) defined on mounted volumes.