Jump to content

Photo thumbnail creation in one folder is incredibly slow 15000ms vs 50ms in other - need help in debugging please


bigcookie
 Share

Recommended Posts

bigcookie

Hello,

 

running Emby 4.5.4 on a QNAP NAS (installed the QPKG). I do have a large collection of photos. They are organized as follows:

photos
- album-1
 |_photo-files.jpg
- album-2
 |_subfolder-1
 | |_photo-files.jpg
 |_subfolder-2
   |_photo-files.jpg

For one folder, the thumbnail generation is way of . e.g. 15000ms vs 50ms in other folders

Here is a log snippet of the "bad ones" after enabling debug logging - there are a lot of those entries.

2021-01-20 12:23:28.818 Debug ImageProcessor: Image encoding to /share/CE_CACHEDEV1_DATA/.qpkg/EmbyServer/programdata/cache/images/resized-images/e/e6ca8522-d110-e989-efd3-c056bc02c700.webp took 15305ms for /share/Multimedia/Bilder/0001 - Kita Elia/Fotos/20190417_083426.jpg
2021-01-20 12:23:28.823 Info Server: http/1.1 Response 200 to 192.168.20.38. Time: 15311ms. http://192.168.20.201:8096/emby/Items/1901/Images/Primary?maxHeight=402&maxWidth=536&tag=99aecaefa4ef3ca0641c3fcc51d802dc&quality=90
2021-01-20 12:23:28.838 Info Server: http/1.1 GET http://192.168.20.201:8096/emby/Shows/NextUp?Limit=24&Fields=PrimaryImageAspectRatio,SeriesInfo,DateCreated,BasicSyncInfo,CanDelete&UserId=3a9f52e6bee44f3d9a64905a3747f7b3&ImageTypeLimit=1&EnableImageTypes=Primary,Backdrop,Banner,Thumb&EnableTotalRecordCount=false&X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=9338ec6d-560f-4712-9779-72decc4795fc&X-Emby-Client-Version=4.5.4.0. UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:84.0) Gecko/20100101 Firefox/84.0
2021-01-20 12:23:28.915 Debug ImageProcessor: Image encoding to /share/CE_CACHEDEV1_DATA/.qpkg/EmbyServer/programdata/cache/images/resized-images/5/51418746-845f-7c34-663c-e1199d08cf41.webp took 7734ms for /share/Multimedia/Bilder/0001 - Kita Elia/Fotos/20190515_105751.jpg
2021-01-20 12:23:28.916 Info Server: http/1.1 Response 200 to 192.168.20.38. Time: 13974ms. http://192.168.20.201:8096/emby/Items/1332/Images/Primary?maxHeight=402&maxWidth=536&tag=005f85d5e1c3948a54e5d8c73b94fae4&quality=90
2021-01-20 12:23:28.917 Info Server: http/1.1 GET http://192.168.20.201:8096/emby/Users/3a9f52e6bee44f3d9a64905a3747f7b3/Items/Latest?Limit=16&Fields=PrimaryImageAspectRatio,BasicSyncInfo,ProductionYear,Status,EndDate,CanDelete&ImageTypeLimit=1&EnableImageTypes=Primary,Backdrop,Thumb&ParentId=d28622d6e0964adea39c5655ae42ebf0&X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=9338ec6d-560f-4712-9779-72decc4795fc&X-Emby-Client-Version=4.5.4.0. UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:84.0) Gecko/20100101 Firefox/84.0
2021-01-20 12:23:28.918 Info Server: http/1.1 GET http://192.168.20.201:8096/emby/Users/3a9f52e6bee44f3d9a64905a3747f7b3/Items/Latest?Limit=16&Fields=PrimaryImageAspectRatio,BasicSyncInfo,ProductionYear,Status,EndDate,CanDelete&ImageTypeLimit=1&EnableImageTypes=Primary,Backdrop,Thumb&ParentId=edae26323168f18aa689be99f2f84e42&X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=9338ec6d-560f-4712-9779-72decc4795fc&X-Emby-Client-Version=4.5.4.0. UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:84.0) Gecko/20100101 Firefox/84.0

The difference is that the photos in this folder are created by mobile phones out of my reach (daycare teachers). I deleted and readded the library and no change.

ALSO I noticed that the thumbs are recreated on other devices. I scrolled through the folder and thumbs are shown on my MacBook/PC then I moved to a FireTV and the thumbs had to be created again (took a looooong time to see one). In comparison to other folders, which go fast, this is weird.

I now moved the cache path from standard to an external one to have faster and better access.

Any idea how can help debugging this further? Weirdly I used Jellyfin shortly prior to moving to Emby (dont want to open "wounds" here) and Jellyfin even cannot create thumbs of the images in this folder. With both solutions I can watch them though. But in Emby the server gets busy creating thumbs and the experience degradates while watching this album/folder.

 

I searched the forum and didnt find a solution. Any help - for debugging or fixing it?

 

 

 

 

Link to comment
Share on other sites

Hi,

How many images do you have that are like this?
When the process was going on was the machine free or busy doing other things?

Link to comment
Share on other sites

bigcookie

Actually this happens in only one folder as it seems so far. The folder contains 1300 images. I cannot tell if this happens to all files in this folder. Let me say it this way, using the Emby app to generate thumbnails it takes definitely an hour or more to scroll through the folder and have thumbnails generated.

What I notice as well - I generated all thumbnails in the Emby app. When I now login on a computer, some thumbs still need to be recreated... I didnt get this behavior. But at the end, the issue the required time. I can share a full log with those, if required. Before doing so, any hint is appreciated what helps best. Simply debug log? For this, can I temporarily exclude other libraries/folders? I dont want to delete the whole library and rescan being honest as the system is in use and this takes a while ;-)... E.G. backup library definitions and database?

Link to comment
Share on other sites

If these aren't personal pictures you can zip up 50 to 100 of them and PM me with them and I'll add them to my system to test with and let you know what kind of times I see.

These can get rendered different ways to the cache based on the client, small, medium, large as an example.
Once rendered the cached item is used after that until rebuilt in the cache.

 

Link to comment
Share on other sites

bigcookie

They are somehow personal, but I can share a password protected download link later on, which will only be available for a bit of time... Might be able to do this tomorrow.

Or if I can send you the password through another channel (Threema, email etc) - also happy to do that.

Link to comment
Share on other sites

bigcookie

Done - I took 39 photos. I noticed also other folders to be problematic... Thank for your help. I amhappy to provide more via PM.

Link to comment
Share on other sites

Just tested the archive zip file sent me. I added these to an SSD drive and I'm see 2ms to 37ms per image to generate the thumbnails during the scan.

So it doesn't appear to be a problem with the files, not the ones sent to me anyway.

Link to comment
Share on other sites

@bigcookie Do you have another location you could move these to for a recheck?

Maybe there's a bad spot on a disc that's retrying or maybe has cross linked files or something that could make reading harder.

Link to comment
Share on other sites

bigcookie

Thanks for checking. I didnt think of the disks (bad me) - yes, will try: I can delete the whole folder, make a file system scan and get them back to the network storage (It is a 6 bay RAID5 system - QNAP). Will let you know asap.

 

 

 

Link to comment
Share on other sites

I can't hurt to try that for sure.

Let us know how you make out and what the file times look like on a new scan in Emby.

Link to comment
Share on other sites

bigcookie

So, what I did  (in order):

1. Deleted the original photo folder "0001 - Kita Elia" (after backing it up outside the server)

2. Scanned all hard drives for bad blocks -> nothing specific came out

3. Checking the full file system -> no problem  identified

4. Copied the backup of photo folder "0001 - Kita Elia" back into place

5. Rescanned the photo library

6. Visit the photos via Web UI

>>> Still thumbnail creation is >15s for picture which are not yet in the cache

 

Protocol extract:

2021-01-26 11:44:49.659 Info Server: http/1.1 Response 200 to 192.168.20.38. Time: 2ms. http://192.168.20.201:8096/emby/System/Info?X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=203b242b-6293-4520-a7b0-b20d98ebf821&X-Emby-Client-Version=4.5.4.0
2021-01-26 11:44:49.659 Info Server: http/1.1 GET http://192.168.20.201:8096/emby/News/Product?StartIndex=0&Limit=4&X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=203b242b-6293-4520-a7b0-b20d98ebf821&X-Emby-Client-Version=4.5.4.0. UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:84.0) Gecko/20100101 Firefox/84.0
2021-01-26 11:44:49.663 Info Server: http/1.1 Response 200 to 192.168.20.38. Time: 5ms. http://192.168.20.201:8096/emby/web/configurationpages?pageType=PluginConfiguration&EnableInMainMenu=true&X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=203b242b-6293-4520-a7b0-b20d98ebf821&X-Emby-Client-Version=4.5.4.0
2021-01-26 11:44:49.680 Info Server: http/1.1 Response 200 to 192.168.20.38. Time: 21ms. http://192.168.20.201:8096/emby/News/Product?StartIndex=0&Limit=4&X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=203b242b-6293-4520-a7b0-b20d98ebf821&X-Emby-Client-Version=4.5.4.0
2021-01-26 11:44:57.859 Info Server: http/1.1 GET http://192.168.20.201:8096/emby/System/Configuration?X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=203b242b-6293-4520-a7b0-b20d98ebf821&X-Emby-Client-Version=4.5.4.0. UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:84.0) Gecko/20100101 Firefox/84.0
2021-01-26 11:44:58.033 Info Server: http/1.1 Response 200 to 192.168.20.38. Time: 174ms. http://192.168.20.201:8096/emby/System/Configuration?X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=203b242b-6293-4520-a7b0-b20d98ebf821&X-Emby-Client-Version=4.5.4.0
2021-01-26 11:44:58.038 Info Server: http/1.1 GET http://192.168.20.201:8096/emby/System/Logs?SortBy=IsFolder,SortName&SortOrder=Ascending&Fields=BasicSyncInfo,CanDelete&ImageTypeLimit=1&EnableImageTypes=Primary,Backdrop,Thumb&StartIndex=0&Limit=50&X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=203b242b-6293-4520-a7b0-b20d98ebf821&X-Emby-Client-Version=4.5.4.0. UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:84.0) Gecko/20100101 Firefox/84.0
2021-01-26 11:44:58.100 Info Server: http/1.1 Response 200 to 192.168.20.38. Time: 62ms. http://192.168.20.201:8096/emby/System/Logs?SortBy=IsFolder,SortName&SortOrder=Ascending&Fields=BasicSyncInfo,CanDelete&ImageTypeLimit=1&EnableImageTypes=Primary,Backdrop,Thumb&StartIndex=0&Limit=50&X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=203b242b-6293-4520-a7b0-b20d98ebf821&X-Emby-Client-Version=4.5.4.0
2021-01-26 11:44:58.271 Info Server: http/1.1 Response 200 to 192.168.20.38. Time: 16025ms. http://192.168.20.201:8096/emby/Items/315407/Images/Primary?maxHeight=402&maxWidth=536&tag=1e6bca8c7c90071dfbfe9b1453c7dfbf&quality=90
2021-01-26 11:44:58.285 Info Server: http/1.1 GET http://192.168.20.201:8096/emby/Items/315349/Images/Primary?maxHeight=402&maxWidth=536&tag=a7c160967c36c340ef84e8b92792785a&quality=90. UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:84.0) Gecko/20100101 Firefox/84.0
2021-01-26 11:44:59.352 Info Server: http/1.1 Response 200 to 192.168.20.38. Time: 16767ms. http://192.168.20.201:8096/emby/Items/315749/Images/Primary?maxHeight=402&maxWidth=536&tag=30d4a7d8b933598440460d3f88d8b429&quality=90
2021-01-26 11:44:59.366 Info Server: http/1.1 GET http://192.168.20.201:8096/emby/Items/315118/Images/Primary?maxHeight=402&maxWidth=536&tag=93bcad00d5d9d3a8feacc427c35f8a61&quality=90. UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:84.0) Gecko/20100101 Firefox/84.0
2021-01-26 11:45:00.912 Info Server: http/1.1 Response 200 to 192.168.20.38. Time: 17245ms. http://192.168.20.201:8096/emby/Items/315478/Images/Primary?maxHeight=402&maxWidth=536&tag=6564083e29086eaa8bf29c0815ed3172&quality=90
2021-01-26 11:45:00.917 Info Server: http/1.1 Response 200 to 192.168.20.38. Time: 16858ms. http://192.168.20.201:8096/emby/Items/315825/Images/Primary?maxHeight=402&maxWidth=536&tag=5fc078ab0aa9de8a71873ec82eef74db&quality=90
2021-01-26 11:45:00.917 Info Server: http/1.1 GET http://192.168.20.201:8096/emby/Items/315851/Images/Primary?maxHeight=402&maxWidth=536&tag=5136e6957bb2d3dd857f4eeca496d609&quality=90. UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:84.0) Gecko/20100101 Firefox/84.0
2021-01-26 11:45:00.919 Info Server: http/1.1 Response 200 to 192.168.20.38. Time: 16797ms. http://192.168.20.201:8096/emby/Items/315001/Images/Primary?maxHeight=402&maxWidth=536&tag=afe50830cc4909d0d3007741ae911471&quality=90
2021-01-26 11:45:00.924 Info Server: http/1.1 GET http://192.168.20.201:8096/emby/Items/315932/Images/Primary?maxHeight=402&maxWidth=536&tag=98af34d9ef23d293cd083ffce9db3ba2&quality=90. UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:84.0) Gecko/20100101 Firefox/84.0
2021-01-26 11:45:00.924 Info Server: http/1.1 GET http://192.168.20.201:8096/emby/Items/315267/Images/Primary?maxHeight=402&maxWidth=536&tag=3a9e9cea1f8cb15c827186f19d060f60&quality=90. UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:84.0) Gecko/20100101 Firefox/84.0
2021-01-26 11:45:01.211 Info Server: http/1.1 GET http://192.168.20.201:8096/emby/System/Logs/embyserver.txt. UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:84.0) Gecko/20100101 Firefox/84.0

 

> Debug log attached (embyserver.log)

Additionally I visited another folder (after folder pictures have been created) - went much faster...

> Debug log attached (embyserver(2).log)

Based on the difference, I dont think that it is the connection, nor the filesystem - I assume I did the correct tasks above to move the files around... Hints are welcome.

I am happy to share specific files, or - via  PM - many more...

 

embyserver.txt embyserver(2).txt

Link to comment
Share on other sites

bigcookie

The more I test, I dont think it is really connected to a specific photo. I have situations in which all photos load fast, except a few - sometimes even made with the same camera as well. Probably in some combinations of setup, suddenly the execution is much slower... E.g. other thumbnail creation ongoing or whatever???

I am running the server on a TS-653B NAS with 16GB RAM from QNAP. That should have sufficient power.

Link to comment
Share on other sites

bigcookie

Might be connected to the host system - will test that more...

Edit: Under a few circumstances, it seems that the system is getting to 100% CPU level. It seems to be caused by Emby? Unsure Probably this is a hint? So it is not the images directly slowing the system down, but some actions causing the CPU to get fully loaded.

I am not experienced in further debugging in that direction. Any hints? And MANY MANY THANKS for your help!

 

Edit: I could confirm the following: CPU <15% load. When opening an image folder with thumbnails to be created, suddenly the load goes to 100% (emby caused). This seems not to be the case prior. The first thumbs are created really fast, then suddenly it locks to 100%... I didnt see that before

Edited by bigcookie
Link to comment
Share on other sites

4 hours ago, bigcookie said:

Edit: I could confirm the following: CPU <15% load. When opening an image folder with thumbnails to be created, suddenly the load goes to 100% (emby caused). This seems not to be the case prior. The first thumbs are created really fast, then suddenly it locks to 100%... I didnt see that before

It would make sense once the CPU is at 100% that things relying on will take longer to process.  On your system is the CPU slowly rising more and more or does it just skyrocket to 100%?

Link to comment
Share on other sites

bigcookie

I restarted Emby on QNAP and in this case CPU load gets to 100% when thumbnails are generated. It is "sky rocketing" from <7% to 100% and then after the job quickly jumps back.

For completeness:

CPU: Intel® Celeron® J3455 Quad-Core 1,5 GHz Prozessor (Turbo up to 2,3 GHz)

Architecture: 64-Bit x86

RAM: 16G

 

Not sure why this is now always happening. When starting with Emby, the CPU didnt fire up that quickly. Otherwise I wouldnt have noticed it only with one folder... But I cannot tell in detail.

I will check soon a restart of the full server to see if there is an impact.

   
Link to comment
Share on other sites

bigcookie

Ok, I restarted the whole server. As a result, all thumbnail generation/displaying become really normally quick. THEN after testing about 10 bigger folders, I checked out the problematic folder "0001 - Kita Elia", the already generated cached images got displayed in milli seconds. BUT when getting further down to images which have not been cached yet, things slowed down heavily and CPU spiked to 100%. After it got down to normal again, I started to check out other folders and it immediately spiked to 100% and no fast thumbnail generation was possible.

Log is attached. You see the first thumbnails to be produced very fast, then slowing down.

It looks to me that somehow one step creates a situation in which too many things are sent in parallel to the CPU and they are not queued/handled properly? But I am not sure.

Question:

To check further, I would like to backup all settings and libraries. Is it sufficient to back up the "programdata"-folder entirely? And for restoring, starting emby, shutting it down and copying all back?

 

embyserver.txt

Edited by bigcookie
Link to comment
Share on other sites

bigcookie

Checked again. Now again only the specific folder is slow. All others are fast. When moving to that folder, CPU jumps to 100%. In this case, after "cooling down", other folders still work as expected.

On Jellyfin, the very same folder/images gave problems with aborting library scans. Probably a similar cause? https://github.com/jellyfin/jellyfin/issues/5038

 

 

Link to comment
Share on other sites

This sure sounds like a bad spot or problem in the IO chain.  Not saying it is but sure sounds like it.

Try using ROBOCOPY to COPY the files in this folder to a different location and look at the times reported and see if you notice high times on any of these files.

Link to comment
Share on other sites

If you don't know how to use ROBOCOPY (built into windows) let me know.

Just give the source location of the problem files and an area on any disc we can copy to for testing.  With that info I'll give you the command line to use.

Link to comment
Share on other sites

bigcookie

Well, might be - cannot tell. The images in the folder are jpg only.

Will check I/O, though I dont think that this is the issue. For Samba copy no specific problems showed up. And the folder alone is 10GB.

@cayars I am aware of robocopy, though I didnt use Win system for a while. I used it mainly for syncing (didnt it use rsync in the background?). ANyway, if you can give me the commandline, I can do that - I am not aware of howto copy to specifically other sectors on a drive. Please also note that the data is stored on a RAID5 system. So in this case it is split between 4 disks, so I dont think  you can specifically define where the data will be as this is done by the RAID controller (not hardware) as I understand...

 

 

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
 Share

×
×
  • Create New...