Playback on android TV takes a long time to start

[pcjones]

Jellyfin android TV debug logs

Code:

06-22 01:35:28.947  262 10200 D perfstatsd: PerfEvent: DELIVER_INPUT_EVENT,{"BooleanValue":{"KEY_DOWN":false},"StringValue":{"TARGET_PACKAGE":"org.jellyfin.androidtv","KEY_EVENT_NAME":"KEYCODE_DPAD_CENTER"},"LongValue":{"KEY_EVENT_TIME":3410940},"Timestamp":3410942}
06-22 01:35:28.953  6336  6336 I org.jellyfin.sdk.api.ktor.KtorClient: GET https://domain.tld/Shows/b9068e0a-fa8d-4914-9fe4-df1c40f024bc/Episodes?fields=MediaSources&fields=MediaStreams&fields=Chapters&fields=Path&fields=Overview&fields=PrimaryImageAspectRatio&fields=Child
Count&fields=Trickplay&isMissing=false&startItemId=92b6cc07-c642-ac74-c949-a93863b023b1&limit=150
06-22 01:35:30.282  6336  6336 D NavigationRepositoryImp: Navigating to Fragment(fragment=class org.jellyfin.androidtv.ui.playback.CustomPlaybackOverlayFragment (Kotlin reflection is not available), arguments=Bundle[{Position=0}]) (via navigate function)
06-22 01:35:30.434  6336  6336 D jellyfin-apiclient: Adding request to queue: https://domain.tld/Items/92b6cc07-c642-ac74-c949-a93863b023b1/PlaybackInfo?format=json
06-22 01:35:30.443  6336  6336 V FragmentManager: Clearing focus org.jellyfin.androidtv.ui.TextUnderButton{d8a9914 VFE...C.. .F...... 0,0-170,117} on view android.widget.RelativeLayout{3bb1291 V.E...... ........ 0,0-1920,1080} for Fragment FullDetailsFragment{1089817}
(77927aad-8178-4deb-ba1a-ca6b3dd6b15c id=0x7f0b00be tag=content)
06-22 01:35:30.451  618  2846 I MediaFocusControl:  AudioFocus  requestAudioFocus() from uid/pid 10176/6336 clientId=com.amazon.media.AmazonAudioManager@34c4a65org.jellyfin.androidtv.ui.playback.CustomPlaybackOverlayFragment$6@1311303 req=1 flags=0x0
06-22 01:35:30.453  1428  1428 D DTM/provid/AudioFocusEventProvider: Audio focus acquired: org.jellyfin.androidtv type: 2 usage: 1
06-22 01:35:44.271  6336  8222 D org.jellyfin.sdk.api.sockets.OkHttpSocketConnection: Sending (raw) message {"MessageType":"KeepAlive"}
06-22 01:35:44.271  6336  8222 W org.jellyfin.sdk.api.sockets.OkHttpSocketConnection: Unable to send message: webSocket is null
06-22 01:36:00.935  6336  6336 I jellyfin-apiclient: Response received from: https://domain.tld/Items/92b6cc07-c642-ac74-c949-a93863b023b1/PlaybackInfo?format=json
06-22 01:36:01.003  6336  6336 I org.jellyfin.sdk.api.ktor.KtorClient: GET
https://domain.tld/MediaSegments/92b6cc07-c642-ac74-c949-a93863b023b1?includeSegmentTypes=Intro&includeSegmentTypes=Outro&includeSegmentTypes=Preview&includeSegmentTypes=Recap&includeSegmentTypes=Commercial
06-22 01:36:01.125  6336  6336 I org.jellyfin.sdk.api.ktor.KtorClient: POST https://domain.tld/Sessions/Playing
06-22 01:36:02.370  1472  2951 I whad-MediaSessionClient: onVideoSessionStart:Window with provider: Jellyfin

Jellyfin Server debug logs:

Code:

[01:35:28] [DBG] [23] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:28] [DBG] [23] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:28] [DBG] [23] Emby.Server.Implementations.Data.SqliteItemRepository: GetItemList query time (slow): 11.0456ms. Query: select type,data,EndDate,ChannelId,CommunityRating,IndexNumber,Width,Height,Name,Path,PremiereDate,Overview,ParentIndexNumber,ProductionYear,OfficialRating,RunTimeTicks,Size,DateModified,guid,ParentId,Audio,IsInMixedFolder,PrimaryVersionId,Album,LUFS,NormalizationGain,CriticRating,IsVirtualItem,SeriesName,SeasonName,SeasonId,SeriesId,ProviderIds,Images,TotalBitrate,ExtraType,ExternalId,OwnerId from TypedBaseItems A where type in ('MediaBrowser.Controller.Entities.TV.Episode','MediaBrowser.Controller.Entities.TV.Season') AND SeriesPresentationUniqueKey=@SeriesPresentationUniqueKey Group by PresentationUniqueKey ORDER BY SortName ASC
[01:35:29] [DBG] [23] Jellyfin.Api.Middleware.ResponseTimeMiddleware: Slow HTTP Response from https://domain.tld/Shows/b9068e0a-fa8d-4914-9fe4-df1c40f024bc/Episodes?fields=MediaSources&fields=MediaStreams&fields=Chapters&fields=Path&fields=Overview&fields=PrimaryImageAspectRatio&fields=ChildCount&fields=Trickplay&isMissing=false&startItemId=92b6cc07-c642-ac74-c949-a93863b023b1&limit=150 to xxx.xxx.xxx.xxx in 0:00:00.5499961 with Status Code 200
[01:35:29] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:29] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:30] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:30] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:31] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:31] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:34] [DBG] [28] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:34] [DBG] [28] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:35] [DBG] [28] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:35] [DBG] [28] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:36] [DBG] [28] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:36] [DBG] [28] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:40] [DBG] [28] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:40] [DBG] [28] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:41] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:41] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:42] [DBG] [28] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:42] [DBG] [28] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:45] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:45] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:46] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:46] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:47] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:47] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:50] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:50] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:51] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:51] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:52] [DBG] [29] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:52] [DBG] [29] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:55] [DBG] [29] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:55] [DBG] [29] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:56] [DBG] [29] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:56] [DBG] [29] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:57] [DBG] [29] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:35:57] [DBG] [29] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:36:00] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:36:00] [DBG] [9] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:36:00] [DBG] [29] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:36:00] [DBG] [29] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: CustomAuthentication was successfully authenticated.
[01:36:00] [DBG] [9] Jellyfin.Api.Controllers.MediaInfoController: GetPostedPlaybackInfo profile: {"Name": "AndroidTV-ExoPlayer", "Id": null, "MaxStreamingBitrate": 20000000, "MaxStaticBitrate": 100000000, "MusicStreamingTranscodingBitrate": 128000, "MaxStaticMusicBitrate": 8000000, "DirectPlayProfiles": [{"Container": "m4v,mov,xvid,vob,mkv,wmv,asf,ogm,ogv,mp4,webm,ts,hls", "AudioCodec": "aac,mp3,mp2", "VideoCodec": "h264,hevc,vp8,vp9,mpeg,mpeg2video,av1", "Type": "Video", "$type": "DirectPlayProfile"}, {"Container": "aac,mp3,mp2,aac_latm,alac,ac3,eac3,dca,dts,mlp,truehd,pcm_alaw,pcm_mulaw,pcm_s16le,pcm_s20le,pcm_s24le,opus,flac,vorbis,mpa,wav,wma,ogg,oga,webma,ape", "AudioCodec": null, "VideoCodec": null, "Type": "Audio", "$type": "DirectPlayProfile"}, {"Container": "jpg,jpeg,png,gif,webp", "AudioCodec": null, "VideoCodec": null, "Type": "Photo", "$type": "DirectPlayProfile"}], "TranscodingProfiles": [{"Container": "ts", "Type": "Video", "VideoCodec": "hevc,h264", "AudioCodec": "aac,mp3,mp2", "Protocol": "hls", "EstimateContentLength": false, "EnableMpegtsM2TsMode": false, "TranscodeSeekInfo": "Auto", "CopyTimestamps": false, "Context": "Streaming", "EnableSubtitlesInManifest": true, "MaxAudioChannels": null, "MinSegments": 0, "SegmentLength": 0, "BreakOnNonKeyFrames": false, "Conditions": [], "EnableAudioVbrEncoding": true, "$type": "TranscodingProfile"}, {"Container": "mp3", "Type": "Audio", "VideoCodec": "", "AudioCodec": "mp3", "Protocol": "http", "EstimateContentLength": false, "EnableMpegtsM2TsMode": false, "TranscodeSeekInfo": "Auto", "CopyTimestamps": false, "Context": "Streaming", "EnableSubtitlesInManifest": false, "MaxAudioChannels": null, "MinSegments": 0, "SegmentLength": 0, "BreakOnNonKeyFrames": false, "Conditions": [], "EnableAudioVbrEncoding": true, "$type": "TranscodingProfile"}], "ContainerProfiles": [], "CodecProfiles": [{"Type": "Video", "Conditions": [{"Condition": "EqualsAny", "Property": "VideoProfile", "Value": "high|main|baseline|constrained baseline", "IsRequired": false, "$type": "ProfileCondition"}], "ApplyConditions": [], "Codec": "h264", "Container": null, "SubContainer": null, "$type": "CodecProfile"}, {"Type": "Video", "Conditions": [{"Condition": "LessThanEqual", "Property": "VideoLevel", "Value": "52", "IsRequired": false, "$type": "ProfileCondition"}], "ApplyConditions": [{"Condition": "EqualsAny", "Property": "VideoProfile", "Value": "high|main|baseline|constrained baseline", "IsRequired": false, "$type": "ProfileCondition"}], "Codec": "h264", "Container": null, "SubContainer": null, "$type": "CodecProfile"}, {"Type": "Video", "Conditions": [{"Condition": "LessThanEqual", "Property": "RefFrames", "Value": "12", "IsRequired": false, "$type": "ProfileCondition"}], "ApplyConditions": [{"Condition": "GreaterThanEqual", "Property": "Width", "Value": "1200", "IsRequired": false, "$type": "ProfileCondition"}], "Codec": "h264", "Container": null, "SubContainer": null, "$type": "CodecProfile"}, {"Type": "Video", "Conditions": [{"Condition": "LessThanEqual", "Property": "RefFrames", "Value": "4", "IsRequired": false, "$type": "ProfileCondition"}], "ApplyConditions": [{"Condition": "GreaterThanEqual", "Property": "Width", "Value": "1900", "IsRequired": false, "$type": "ProfileCondition"}], "Codec": "h264", "Container": null, "SubContainer": null, "$type": "CodecProfile"}, {"Type": "Video", "Conditions": [{"Condition": "EqualsAny", "Property": "VideoProfile", "Value": "main|main 10", "IsRequired": false, "$type": "ProfileCondition"}], "ApplyConditions": [], "Codec": "hevc", "Container": null, "SubContainer": null, "$type": "CodecProfile"}, {"Type": "Video", "Conditions": [{"Condition": "LessThanEqual", "Property": "VideoLevel", "Value": "153", "IsRequired": false, "$type": "ProfileCondition"}], "ApplyConditions": [{"Condition": "Equals", "Property": "VideoProfile", "Value": "main", "IsRequired": false, "$type": "ProfileCondition"}], "Codec": "hevc", "Container": null, "SubContainer": null, "$type": "CodecProfile"}, {"Type": "Video", "Conditions": [{"Condition": "LessThanEqual", "Property": "VideoLevel", "Value": "153", "IsRequired": false, "$type": "ProfileCondition"}], "ApplyConditions": [{"Condition": "Equals", "Property": "VideoProfile", "Value": "main 10", "IsRequired": false, "$type": "ProfileCondition"}], "Codec": "hevc", "Container": null, "SubContainer": null, "$type": "CodecProfile"}, {"Type": "Video", "Conditions": [{"Condition": "Equals", "Property": "VideoProfile", "Value": "none", "IsRequired": false, "$type": "ProfileCondition"}], "ApplyConditions": [], "Codec": "av1", "Container": null, "SubContainer": null, "$type": "CodecProfile"}, {"Type": "Video", "Conditions": [{"Condition": "LessThanEqual", "Property": "Width", "Value": "4096", "IsRequired": false, "$type": "ProfileCondition"}, {"Condition": "LessThanEqual", "Property": "Height", "Value": "2304", "IsRequired": false, "$type": "ProfileCondition"}], "ApplyConditions": [], "Codec": null, "Container": null, "SubContainer": null, "$type": "CodecProfile"}, {"Type": "VideoAudio", "Conditions": [{"Condition": "LessThanEqual", "Property": "AudioChannels", "Value": "2", "IsRequired": false, "$type": "ProfileCondition"}], "ApplyConditions": [], "Codec": null, "Container": null, "SubContainer": null, "$type": "CodecProfile"}], "SubtitleProfiles": [{"Format": "vtt", "Method": "Embed", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "vtt", "Method": "External", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "vtt", "Method": "Hls", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "webvtt", "Method": "Embed", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "webvtt", "Method": "External", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "webvtt", "Method": "Hls", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "srt", "Method": "Embed", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "srt", "Method": "External", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "subrip", "Method": "Embed", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "subrip", "Method": "External", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "ttml", "Method": "Embed", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "ttml", "Method": "External", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "dvbsub", "Method": "Embed", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "dvbsub", "Method": "Encode", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "idx", "Method": "Embed", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "idx", "Method": "Encode", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "pgs", "Method": "Embed", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "pgs", "Method": "Encode", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "pgssub", "Method": "Embed", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "pgssub", "Method": "Encode", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "ass", "Method": "Encode", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "ssa", "Method": "Encode", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}, {"Format": "dvdsub", "Method": "Encode", "DidlMode": null, "Language": null, "Container": null, "$type": "SubtitleProfile"}], "$type": "DeviceProfile"}

You can clearly see the 30 second gap in the Android TV client logs (ignoring websocket messages):

Code:

06-22 01:35:30.453  1428  1428 D DTM/provid/AudioFocusEventProvider: Audio focus acquired: org.jellyfin.androidtv type: 2 usage: 1
06-22 01:36:00.935  6336  6336 I jellyfin-apiclient: Response received from: https://domain.tld/Items/92b6cc07-c642-ac74-c949-a93863b023b1/PlaybackInfo?format=json

I don't see anything obvious in the Jellyfin server logs aside from the large amount of authentications - I don't know if this is normal or not.

- This problem is only happening for Android TV clients, all other clients are starting playback immediately
- The problem happens consistently and every time, regardless of system load, transcoding/direct play, user, network or device (TV with Android TV, Chromecast, Fire TV etc)
- CPU load is basically nonexistent, no core has even close to full load during the 30 seconds
- iotop shows only minimal read and write during the 30 seconds
- 100+GB RAM available
- Traefik access logs show no requests taking longer than half a second

Jellyfin Info:
LSIO Docker 10.10.7
~ 15 Users
~2000 movies, 22.000 episodes

System specs:
AMD Ryzen 7 3700X
2x SAMSUNG MZQL2960HCJR-00A07 (Raid1) - this is where all Jellyfin db and config files are located
128GB RAM
10x16TB HDD RAIDz1

Thanks for anyone having a look at this!