Jump to content

Erratic Scanning Issues


CassTG

Recommended Posts

CassTG

Hi

First off, the Library has been kept up to date for several months now so update scans should not take long at all and in fact on the 4.5 branch update scans did indeed only take a few minutes to update all the libraries.

Setup for info:

Root Server - 4 * Ryzen Epyc Cores / 16GB / SSD / 2.5G Network bandwidth

Emby - LinuxserverIO Docker 4.6.3.0 via LinuxserverIO Swag Reverse Proxy on Ubuntu Server OS

Library - Via Rclone GDrive mounts, separate Systemd files and api credentials for each mount

So initially i noticed that approx30% of the movie library was missing the trailer button newer items were fine older items is where it was missing, having looked around on the forums it seemed a common answer was to refresh metadata.

Process 1 - Refresh Metadata - Yesterday

I started a refresh missing meta data only yesterday morning on the Movie library only, this was ongoing for about 10 hours until it got stuck at 97%, at this point i noticed that Google had activated a temp folder ban, the api requests were a fraction of the allowance. At this point i had to cancel the refresh, and no items via that mount would play

Process 2 - Standard Scan - This Morning

To See if the gdrive folder ban was lifted i started a scan library from the library settings page heres what happened

  • Scan starts and percentage sign shown on Library covers in home page
  • Dashboard shows scan percentage
  • I Tailed the log to watch what was happening and scan was working fine
  • I monitored the API requests in Googles Console and noticed the Get requests were far exceding the List requests

After 30 mins, the scan progress progress bar in Dashboard had finished and no percentage was being shown on the Library covers in the home screen, i also checked the scheduled tasks settings page and it stated Scan was last run xx mins ago and took 30mins 22secs to complete

However this is not true i am looking at the GET api requests being hammered and the tail of the log is showing that the Scan is in fact FFMPEG every single Movie file again

To be fair i have never really trusted the scan percentage bar at all but why is it suddenly re analysing every file again?, this library has been ticking over nicely for many months now

I never saw these issues with scan on the 4.5 branch only seems to be very flakey on. the latest branch, for info this is nothing to do with Music rescan that library is fine and updated perfectly, and as stated the library had fully scanned fine months ago, and why would a refresh metadata for missing items take nearly a whole day?

Here is a short unlisted screencast showing Emby UI no Scanning in op and the tail of the logs

 

Edited by CassTG
Timeline
Link to comment
Share on other sites

CassTG

Update

Seems that FFMPEG went off on one on it's own, i rebooted the container and re did the scan and it has not reanalysed the files in the last two scans.

Link to comment
Share on other sites

CassTG
1 minute ago, Luke said:

Hi, so are you all set now?

Seems so, all trailer buttons are visible on items that weren't there before, not sure why the scan this morning triggered a full re-analysis of the video files, but as mentioned after i rebooted the docker container (stopping this scan) and started the scan again it completed in 15 minutes with no reanalysing of the files that time.

Link to comment
Share on other sites

CassTG

Actually, the Scan is becoming a right royal pain.

Yesterday it took half the day to complete a scan, i was tail the log file and literally zero entries regarding a scan for hours, then suddenly it goes from 25% to 86%

If i look on the home screen it will occasionally show you what library its scanning.

Anyways there was very little new media added, so i thought okay i will try a scan and this morning knowing that maybe one or two items will be added thus scan should be much quicker.

Nope I started the scan circa 9am, it was sat at 25% very few entries in the log file, no indicator on the home page of which library is being scanned, im watching the drive.files.list api increasing but very little in logs and no percentage increase.

So i Cancelled the scan. This was at circa 09:59, and that does not work either, it shows as stopping in Dashboard and Scheduled tasks, but it's now10:20 and its still scanning as i can see the rclone google api calls increasing.

I never had any of these issues prior to 4.6 a daily scan would take a few minutes at most, now its just unreliable. In fact thankfully i backed up my 4.5 docker volumes and image before the update, and think im just going to restore that and stay put

 

stopscan.txt

Edited by CassTG
Link to comment
Share on other sites

Hi, that log looks ok to me. You could try turning off the realtime monitor for each of your libraries and then restarting the server. It may have just been reacting to changes.

Link to comment
Share on other sites

thering1975
19 minutes ago, Luke said:

Hi, that log looks ok to me. You could try turning off the realtime monitor for each of your libraries and then restarting the server. It may have just been reacting to changes.

Thats not switched on, on any of my libraries,

I have a spare server with seperate credentials, so starting a fresh library to see what happens incase DB is knacikered

 

But a refresh scan that normally took 2 to 3 mins which now barely completes after hours does not seem ok to me to be fair plus the fact that cancelling a scan didnt actually cancel the scan at all until i rebooted the docker means something not right

Edited by thering1975
Link to comment
Share on other sites

2 minutes ago, thering1975 said:

But a refresh scan that normally took 2 to 3 mins which now barely completes after hours does not seem ok to me to be fair plus the fact that cancelling a scan didnt actually cancel the scan at all until i rebooted the docker means something not right

Hi, can you please provide the emby server log from when that happened? Thanks.

Link to comment
Share on other sites

Or rather, your server log shows the cancellation attempt, but can you please provide the previous server log? That will help tell us why it wasn't able to cancel. Thanks.

Link to comment
Share on other sites

thering1975

The log i attached was when the cancellation was done. i have a screengrab where it still shows stopping 34 minutes later yet the google developer console shows the api lists and gets increasing still

Link to comment
Share on other sites

can you please provide the previous server log? That will help tell us why it wasn't able to cancel. Thanks.

Link to comment
Share on other sites

thering1975

Okay I will check but as a test

I have set up a new server with the same Docker from LSIO, this server onl;y runs portainer and emby docker

I added the same libraries paths etc

I started a scan on this library, (no existing library) it got to 477 items and basically no progress updates, google apis were increasing however.

So i initiated a cancel on this server just know and have screencasted it. The video is about 10 mins long, the cancel scan didnt happen and the api counts were still increasing.

So thats a brand new server running only emby in docker, with fresh setup and no existing library and the stop scan issue is present there also

So unless its an issue with LSIO dockers theres an issue

 

I attach a log from this test server with the same cancel issue and an image thats showing now nearly 15 mins later it's not stopped

Screen Shot 2021-06-24 at 14.09.36.png

embyserver.txt

Link to comment
Share on other sites

If the scan is unable to cancel, then that means there is a part of the process that is actually stuck and that part doesn't support cancellation, thus the reason why you can't cancel.

There is really only one part of the scanning process that acts like this and that is getting the listings of files and folders in a directory. The .NET file api is synchronous and does not support cancellation.

So if i had to guess, you have request(s) going to your rclone drive that the server never gets a result from and that's why the scan doesn't continue. I can promise you now this situation could also happen with version 4.5 of the server.

Link to comment
Share on other sites

thering1975
24 minutes ago, Luke said:

If the scan is unable to cancel, then that means there is a part of the process that is actually stuck and that part doesn't support cancellation, thus the reason why you can't cancel.

There is really only one part of the scanning process that acts like this and that is getting the listings of files and folders in a directory. The .NET file api is synchronous and does not support cancellation.

So if i had to guess, you have request(s) going to your rclone drive that the server never gets a result from and that's why the scan doesn't continue. I can promise you now this situation could also happen with version 4.5 of the server.

It just seems odd that this never occured on 4.5 and only started on 4.6, and yep the scan still failed to stop nearly 45 mins later so i shut the docker down

Going to try a plex docker on that test server to see how the scan runs there for the content that can rule in or out, the rclone mount and or the emby docker

the google console shows no errors on api requests at all and drive.file.list requests were increasing during the whole time cancellation was placed but interestingly no drive.get requests and no analysing of files emby side i.e no ffmpeg seemed to be happening

Edited by thering1975
Link to comment
Share on other sites

CassTG

Okay so threw up a test plex docker.

In 20 mins it scanned in from the same rclone mounts 500 movies and had good get requests in api console.

Shut that down as not interested in plex and went back to the original Emby Docker which is linked to the same Libraries the plex docker was scanning from, This is the original docker which already has the whole library scanned in and upto date so doesent have much work todo

So far scan been running for 20 minutes and has managed a whopping 9.6% barely moving and when i check api requests they are increasing but at such a slow rate its untrue (compared to the api hits on plex scan)

Now going to throw up a 4.5 version docker and will test that

 

Link to comment
Share on other sites

CassTG

Okay 

So on the spare server i restored my 4.5 backup and booted her up

You were right the same issue with scanning is present on 4.5 in that it took 20 minutes or so to get to 4.8%

So i decided on that test docker to upgrade it to beta 4.7, after a restart i started a scan (this library DB is about 2 weeks out of date plus obviously would need a full music rescan as well)

After 5 minutes of scanning it was at 11.8% and ffmpeg analysing files as it should. The api requests were fast and hard how they should be and unlike on 4.6 version

Link to comment
Share on other sites

I think it's just luck and not anything specific to the 4.7 version because it's so early that at this point it's nearly identical to 4.6.

Unfortunately it might be bad news if I'm right that it's .net core file methods getting stuck. We will be updating from .net core 3.1 to 5 within the next couple weeks so there's a chance that might help with it 

Link to comment
Share on other sites

CassTG

Final note on main server 4.6

I tried a scan again, it sat at 4.8% for 30 mins or so, i noticed also 2 other things this time

  • rclone api requests did not increase for the last 10 or 15 minutes of this partial scan
  • when looking at TOP i noticed cpu usage as follows When i triggered a Metadata refresh from scheduled menu item the cpu hit 98%  of one core for the duration, however when i clicked scan library the Cpu fluctuated only between 0.5 and 3% of one core so its definitely not doing something right.

 

 

Link to comment
Share on other sites

Quote
  • when looking at TOP i noticed cpu usage as follows When i triggered a Metadata refresh from scheduled menu item the cpu hit 98%  of one core for the duration, however when i clicked scan library the Cpu fluctuated only between 0.5 and 3% of one core so its definitely not doing something right.

No that sounds normal. The regular library scan is only looking for changes. A metadata refresh will do quite a bit more and can have moments of high cpu usage.

Link to comment
Share on other sites

CassTG
3 minutes ago, Luke said:

No that sounds normal. The regular library scan is only looking for changes. A metadata refresh will do quite a bit more and can have moments of high cpu usage.

Okay fair enough

Well as scans are out of action and a no go for now and no solution possible based on a maybe possibly or might not be .net update which may or may not be the issue / resolution, ill fire back up the plex instance to have as a backup incase for now

Thanks for the responses

Link to comment
Share on other sites

CassTG

Redid a scan and observed the following

Tv library scans first and completes

Music library scans next and completes

These are both big libraries 

Movies starts scanning and it hangs only on this library. I think it gets stuck at a root folded as after 4 hours being stuck at 25% I get a temp folder ban from Google even though the drive.list api requests are constantly raising its obviously getting stuck on one high level folder

This then makes playing any files from this folder unplayable as the ban is in effect which triggers emby into transcoding mode as it can't read the file so it starts up transcoding.

I'm gonna not bother with scans on this server and let it die slowly so to speak until I can get me backup server upto full speed and transition across.

Link to comment
Share on other sites

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now
×
×
  • Create New...