Emby database hammering / extreme slowness

[Edrock200 49]

Recently I've been getting excessive DB hammering on Emby and I'm not sure the cause. I suspect it might be infuse clients, as I added some friends and a few are coming in with infuse, but I can't be certain. I have the infuse plugin installed and active, and am on the latest .13 emby prod release. When the db hammering happens, Emby slows to a crawl, and the debug logs show these massive queries that can take 20+ seconds to complete. I have DB cache cranked up to 4000MB, and the DB resides on a drive that consists of 2 NVME's in RAID 0.

Here's an example from the debug logs:

 

2023-06-05 15:13:17.419 Info Server: http/1.1 POST http://emby_remote_ip:443/emby/Sessions/Playing/Progress?X-Emby-Client=Emby for Apple TV&X-Emby-Device-Name=Apple TV&X-Emby-Device-Id=redacted&X-Emby-Client-Version=1.7.3 (2)&reqformat=json. UserAgent: Emby/2 CFNetwork/1406.0.4 Darwin/22.4.0
2023-06-05 15:13:17.420 Debug SessionManager: OnPlaybackProgress TimeUpdate 64abb70dfab84437b8f04dd7926e7327
2023-06-05 15:13:17.842 Debug SqliteItemRepository: GetItems query time (slow): 2938ms. Query: select A.type,A.Id,A.IndexNumber,A.Name,A.Path,A.ParentIndexNumber,A.ProductionYear,A.RunTimeTicks,A.Container,A.ParentId,A.IsVirtualItem,A.SeriesName,A.Album,A.AlbumId,A.SeriesId,A.PresentationUniqueKey,A.Images,A.ExternalId,A.SortIndexNumber,A.SortParentIndexNumber,A.IndexNumberEnd,UserDatas.IsFavorite,UserDatas.Played,UserDatas.PlayCount,UserDatas.PlaybackPositionTicks,UserDatas.LastPlayedDateInt,UserDatas.AudioStreamIndex,UserDatas.SubtitleStreamIndex,((Coalesce(SortParentIndexNumber,ParentIndexNumber, 1) * 1000000) + Coalesce(SortIndexNumber, IndexNumber, 0) + (Select Case When Coalesce(ParentIndexNumber,1)=0 Then 0 Else 0.5 End) + (Select Case When Coalesce(ParentIndexNumber,1)=0 Then (Cast(Coalesce(IndexNumber, 0) as REAL) / 100000) Else 0 End)) EpisodeAbsoluteIndexNumber from MediaItems A left join (Select N.SeriesPresentationUniqueKey,((Coalesce(N.SortParentIndexNumber,N.ParentIndexNumber, 1) * 1000000) + Coalesce(N.SortIndexNumber, N.IndexNumber, 0) + (Select Case When Coalesce(N.ParentIndexNumber,1)=0 Then 0 Else 0.5 End) + (Select Case When Coalesce(N.ParentIndexNumber,1)=0 Then (Cast(Coalesce(N.IndexNumber, 0) as REAL) / 100000) Else 0 End)) AbsoluteIndexNumber,UserDatas_N.LastPlayedDateInt LastPlayedDateInt,UserDatas_N.playbackPositionTicks playbackPositionTicks from MediaItems N join UserDatas UserDatas_N on N.UserDataKeyId=UserDatas_N.UserDataKeyId And (UserDatas_N.UserId=@UserId) where Type=8 and (UserDatas_N.Played=1 or UserDatas_N.playbackPositionTicks > 0) Group By N.SeriesPresentationUniqueKey ORDER BY MAX(UserDatas_N.LastPlayedDateInt) desc, Coalesce(SortParentIndexNumber,ParentIndexNumber) desc, Coalesce(SortIndexNumber,IndexNumber) desc) LastWatchedEpisodes on LastWatchedEpisodes.SeriesPresentationUniqueKey=A.SeriesPresentationUniqueKey left join UserDatas on A.UserDataKeyId=UserDatas.UserDataKeyId And (UserDatas.UserId=@UserId) where ((UserDatas.playbackPositionTicks > 0) OR (A.Type=8 and Coalesce(UserDatas.Played,0)=0 and EpisodeAbsoluteIndexNumber > LastWatchedEpisodes.AbsoluteIndexNumber and LastWatchedEpisodes.LastPlayedDateInt not null)) AND (A.Type <> 8 or UserDatas.playbackPositionTicks > 0 or Coalesce(A.SortParentIndexNumber, A.ParentIndexNumber, -1) <> 0) AND IsVirtualItem=@IsVirtualItem AND Coalesce(HideFromResume,0)=@HideFromResume AND Coalesce((select HideFromResume from UserDatas where UserDataKeyId=(Select UserDataKeyId from MediaItems MediaItemsHideFromResumeInner where MediaItemsHideFromResumeInner.Id=A.SeriesId) and UserId=@UserId),0)=@HideFromResume AND MediaType=@MediaTypes AND TopParentId in (598548,703748,213717,213718,213719,213720,213721,224171,4445007,4445008,4445009,4445010,5092903,3341,224168,4570,4917,4746544,703751,6277,5551508,7613,5517319,2778295,2778296,2778297,2778298,2778299,2778300,2778301,3969704,4445278,4445279,26175,224170,36628,224169,77370,224173,72765) Group by coalesce(A.SeriesPresentationUniqueKey, A.PresentationUniqueKey) ORDER BY coalesce(LastWatchedEpisodes.LastPlayedDateInt, Max(UserDatas.LastPlayedDateInt)) DESC,Max(UserDatas.LastPlayedDateInt) DESC,Min(EpisodeAbsoluteIndexNumber) ASC LIMIT 12

 

Any idea what would cause these large queries? Could it be infuse? Is there anything than can be done to remediate? Thanks in advance.

[Luke 40070]

That one is Emby for Apple TV.

 Only way to know what software is hammering your server is to shut things down.

[Edrock200 49]

Can you elaborate on what you mean by "shut things down?" Also, that query above, is it normal for a new client coming in to create such a query?

[Luke 40070]

7 minutes ago, Edrock200 said:

Can you elaborate on what you mean by "shut things down?" Also, that query above, is it normal for a new client coming in to create such a query?

By stopping all of your client software.

The query is for resuming video, and it’s the largest in the system, so it’s an exceptional case. It’s what happens when you have a lot of features to support, things get complicated.

[Edrock200 49]

5 minutes ago, Luke said:

By stopping all of your client software.

The query is for resuming video, and it’s the largest in the system, so it’s an exceptional case. It’s what happens when you have a lot of features to support, things get complicated.

Thank you for the reply. This is interesting. Any reason why resuming a video would require such a query?

 

One other data point, I had installed the auto version grouping plugin for movies, however it seemed to cause emby to freeze for a few seconds during scan triggers so I removed it. After removing it, the items it already processed still have versions grouped. Could this be contributing to the hammering? 

[Luke 40070]

I guess you’ll have to be more specific about what you mean by hammering and providing an example.

[Edrock200 49]

7 minutes ago, Luke said:

I guess you’ll have to be more specific about what you mean by hammering and providing an example.

That query I posted above, in the above example it was 3 seconds. But sometimes it can be 30s+. I guess having a better understanding of why it's doing such a massive query on resume would be helpful. E.g. is it looking for all versions of said movie/show, and attempting to play the best version based on the client settings? E.g. of client is set to 8mbs streaming, and there's 2 versions of a movie, is it querying to find the version that most closely matches the clients capabilities? Or is it querying for some other reason? 

When these queries occur, emby becomes unresponsive until the query completes, which sort of causes a cascading effect due to the backlog of client requests in queue. 

[Luke 40070]

Again full context is needed rather than looking at a single query.

[Edrock200 49]

1 minute ago, Luke said:

Again full context is needed rather than looking at a single query.

Sorry I'm not trying to be dense, I'm just not sure what other context to provide, but I'll try to summarize as best I can.

Since version .11 or so, emby will randomly slow to a crawl, even give connect failed errors to clients. When turning on debug logging, I see the massive queries as noted in the example above. These queries take anywhere from a few seconds to 30+s. During this time, emby becomes unresponsive. I'm trying to figure out what changed or why these queries are occuring. Did they always happen? Did something change in the way emby resumes videos? I guess I'm just trying to figure out how to narrow the issue further.

I understand that one step is to remove clients but I'm not sure that will help me narrow the issue, because less clients means less streaming/load on the server, which the inherent side effect would be more responsiveness but not necessarily point to a root cause.

[Edrock200 49]

any tips to narrow?

[Luke 40070]

Please attach the complete server log file. Thanks.

[Edrock200 49]

On 6/13/2023 at 4:14 PM, Luke said:

Please attach the complete server log file. Thanks.

Thank you for the reply. I may have found something. Let me know if this makes sense as a potential cause.

Added ~20 friends or so over the course of several days. Started seeing the lengthy db queries which were hammering the db, emby would slow to a crawl.

Upon looking into it, I noticed something odd. For whatever reason, my template user no longer had "all libraries" ticked for sharing. That was unticked, but every single root path was ticked. This had replicated to the 20 new users.

I went back and ticked "all libraries" for the newly added users, then restarted emby.

Within the first hour, the db hammering kept happening. But after about an hour or so, it stopped, and has been stable for about an hour or so.

Could this have been the issue? My thought is it was enumerating content from every root path vs just everything. The only thing I can't figure is why it didn't resolve after ticking All Libraries and restarting, unless Emby takes some time to process those changes?

If this doesn't make sense, please let me know if you'd like "normal" logs or debug logs. The normal logs don't show any of the db queries.

[Luke 40070]

No, I don't see how that could have been an issue.

[Edrock200 49]

2 hours ago, Luke said:

No, I don't see how that could have been an issue.

Ok. Normal logs or debug?

[Luke 40070]

Debug please and thanks.

[Edrock200 49]

Sorry for the delay. was waiting for it to happen again, and when it did, I realized I couldn't get to the gui to enable debug logging. I spoke with another friend who has emby as well, and he's seeing the same behavior. From a user perspetive, if you go to emby.tld.com, the libraries will load at the top, but then it hangs at loading all the content underneath. As a test, I rolled back to 4.7.9.0. So far, it's ok but only been a few hours. I am wondering if this change in 4.9.10.0 is causing the issue:

Delay triggering new item additions under after metadata download. This should help improve the experience with Trakt, Webhooks, notifications, etc.

The loading behavior seems different now. Before, even when working, nothing would load under libraries for a few seconds, then everything would "pop in" all at once. On 4.7.9.0, the objects pop in near instantly, even if empty shells, then the posters start to pop in a few seconds later.

If it happens again, will grab debug and post. Will also see if I can reproduce on another test box and post those logs.

Edited June 26, 2023 by Edrock200

[Luke 40070]

3 hours ago, Edrock200 said:

Sorry for the delay. was waiting for it to happen again, and when it did, I realized I couldn't get to the gui to enable debug logging. I spoke with another friend who has emby as well, and he's seeing the same behavior. From a user perspetive, if you go to emby.tld.com, the libraries will load at the top, but then it hangs at loading all the content underneath. As a test, I rolled back to 4.7.9.0. So far, it's ok but only been a few hours. I am wondering if this change in 4.9.10.0 is causing the issue:

Delay triggering new item additions under after metadata download. This should help improve the experience with Trakt, Webhooks, notifications, etc.

The loading behavior seems different now. Before, even when working, nothing would load under libraries for a few seconds, then everything would "pop in" all at once. On 4.7.9.0, the objects pop in near instantly, even if empty shells, then the posters start to pop in a few seconds later.

If it happens again, will grab debug and post. Will also see if I can reproduce on another test box and post those logs.

Hi, no, that will not be related.

[Edrock200 49]

happened on 4.7.9 as well, just not as frequent. RAM bloated to 40GB used by emby. Debug logs attached.

logs.zip

[Luke 40070]

1 hour ago, Edrock200 said:

happened on 4.7.9 as well, just not as frequent. RAM bloated to 40GB used by emby. Debug logs attached.

logs.zip 9.22 MB · 0 downloads

Are you able to update to 4.7.13?

[Edrock200 49]

I can get it back to .13 but the behavior was the same.

[Luke 40070]

Ok we'll take a look at it. Thanks for reporting.

[Edrock200 49]

On 6/28/2023 at 9:42 PM, Luke said:

Ok we'll take a look at it. Thanks for reporting.

Thank you. After some troubleshooting it seems the image caches aren't generating. I copied the cache folder from another emby instance and now the main page loads instantly vs take 10-20 seconds. (Images are sideloaded with media, but not by emby.)

[Edrock200 49]

Should have noted, backed up dbs and tried rolling forward to latest beta, same issue. Restored dbs and rolled back to 4.7.9 as it seems to happen less on this version for some reason. 

[Edrock200 49]

Set up Syncthing to sync cache from "good" server to "bad" server and issue hasn't resurfaced. I suspect there is some issue caching and/or fetching images. E.g. it's not building the cache properly, so it goes out to the San to pull every sideloaded image and hangs for a while in the process. Was any image processing/handling changed between 4.7.9 and 4.7.13?

[Luke 40070]

1 hour ago, Edrock200 said:

Set up Syncthing to sync cache from "good" server to "bad" server and issue hasn't resurfaced. I suspect there is some issue caching and/or fetching images. E.g. it's not building the cache properly, so it goes out to the San to pull every sideloaded image and hangs for a while in the process. Was any image processing/handling changed between 4.7.9 and 4.7.13?

I don’t think there are any, no.