Frequent buffering on iOS and tvOS clients' new player (not old player)

Plex Players
, ,
1

I run Synology DSM 7 Plex server and various client devices.

The problem is that on iOS and tvOS, even 1080p (also 4K) video direct plays make constant buffering. I believe the network bandwidth is not the problem since the old player works well. Also, direct plays on the same devices with another app (Infuse) works also fine.

I monitored the debugging mode on iOS clients and it shows fluctuating cache from 0 to a few seconds. It does not keep the constant cache length of more than 10 seconds.

I hope the tvOS and iOSā€™s new player has a more aggressive cache strategy. Is there any way to force iOS and tvOS apps to maintain a longer cache?

2

Can you please do the following:

  1. Verify DEBUG logging enabled and VERBOSE disabled (server)
  2. Recreate the problem (play for 20 seconds)
  3. Stop playback
  4. Wait 20 seconds (logs to flush)
  5. Download logs ZIP file
  6. Attach for review.
3

Do what @ChuckPa says, obviously.

What does the Speed line on the Enhanced Debugging screen show when this is occurring?

If you disable Direct Play does that resolve the issue?

Itā€™s very common for poorly muxed files to defeat the buffer cache. If the video and audio arenā€™t interleaved properly, the client must fetch a chunk of video from one part of the file, but then dumps the cache to fetch a chunk of audio from another part of the file, and so on.

If you disable Direct Play Plex will remux the file on the fly. This is a good diagnostic for poorly muxed (*) files.

(*) poorly muxed for streaming

1 Like
4

Plex Media Server Logs_2022-02-03_05-31-48.zip (4.2 MB)

Thanks. Hereā€™s the log dump.

5

The cache ā€œSpeedā€ fluctuate between 1,000,000-3,000,000.
And I just recognized that when this happens, ā€œBufferingā€ suddenly drops from 100 to 0.
If I pause the player and cumulate the cache, the cache ā€œSecondsā€ reach up to nearly 50 seconds then stop.
The player maintains this cumulated cache for a few minutes but soon decreased and the same problem occurs.

The problem happens over most of the well-muxed videos and most of all, I want to stream them only as direct video play.

Thank you very much!

6

@jiwanjeong

What you are showing me here (the clean sequence of Request & Completed), tells me the server is doing exactly as asked when asked.

There is nothing holding back the server.

This is a networking / end-to-end throughput problem.

Feb 03, 2022 01:08:42.233 [0x7f74b3517b38] DEBUG - [Now] Device is iPadOS (Jiwan).
Feb 03, 2022 01:08:42.233 [0x7f74b3517b38] ERROR - Unable to find client profile for device; platform=iPadOS, platformVersion=, device=iPad, model=
Feb 03, 2022 01:08:42.233 [0x7f74b3517b38] DEBUG - [Now] Updated play state for /library/metadata/6290.
Feb 03, 2022 01:08:42.233 [0x7f74b3517b38] DEBUG - Statistics: (65232C63-40BB-40AB-8274-0C3F32614B27) Reporting active playback in state 0 of type 1 (scrobble: 0) for account 1
Feb 03, 2022 01:08:42.236 [0x7f74b505eb38] DEBUG - Completed: [100.10.14.235:51041] 200 POST /:/timeline?key=/library/metadata/6290&ratingKey=6290&state=playing&time=0&duration=7588000 (8 live) TLS GZIP 4ms 433 bytes (pipelined: 11)
Feb 03, 2022 01:08:42.448 [0x7f74b325ab38] DEBUG - Request: [100.10.14.235:50240 (WAN)] GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:42.454 [0x7f74b5081b38] DEBUG - Completed: [100.10.14.235:50240] 200 GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP 5ms 2369 bytes (pipelined: 61)
Feb 03, 2022 01:08:43.206 [0x7f74b3517b38] DEBUG - Request: [100.10.14.235:50240 (WAN)] GET /status/sessions (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:43.206 [0x7f74b3517b38] DEBUG - [Now] Adding 1 sessions.
Feb 03, 2022 01:08:43.207 [0x7f74b505eb38] DEBUG - Completed: [100.10.14.235:50240] 200 GET /status/sessions (8 live) TLS GZIP 1ms 3624 bytes (pipelined: 62)
Feb 03, 2022 01:08:43.449 [0x7f74b325ab38] DEBUG - Request: [100.10.14.235:50240 (WAN)] GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:43.455 [0x7f74b505eb38] DEBUG - Completed: [100.10.14.235:50240] 200 GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP 5ms 2390 bytes (pipelined: 63)
Feb 03, 2022 01:08:44.452 [0x7f74b325ab38] DEBUG - Request: [100.10.14.235:50240 (WAN)] GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:44.457 [0x7f74b505eb38] DEBUG - Completed: [100.10.14.235:50240] 200 GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP 5ms 2398 bytes (pipelined: 64)
Feb 03, 2022 01:08:45.458 [0x7f74b36f4b38] DEBUG - Request: [100.10.14.235:50240 (WAN)] GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:45.464 [0x7f74b5081b38] DEBUG - Completed: [100.10.14.235:50240] 200 GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP 6ms 2408 bytes (pipelined: 65)
Feb 03, 2022 01:08:45.567 [0x7f74b3517b38] DEBUG - Request: [100.10.14.235:50203 (WAN)] GET /statistics/resources?timespan=6 (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:45.570 [0x7f74b505eb38] DEBUG - Completed: [100.10.14.235:50203] 200 GET /statistics/resources?timespan=6 (8 live) TLS GZIP 2ms 863 bytes (pipelined: 435)
Feb 03, 2022 01:08:46.453 [0x7f74b325ab38] DEBUG - Request: [100.10.14.235:50203 (WAN)] GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:46.459 [0x7f74b505eb38] DEBUG - Completed: [100.10.14.235:50203] 200 GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP 6ms 2423 bytes (pipelined: 436)
Feb 03, 2022 01:08:47.234 [0x7f74b325ab38] DEBUG - Request: [100.10.14.235:51041 (WAN)] POST /:/timeline?key=/library/metadata/6290&ratingKey=6290&state=playing&time=0&duration=7588000 (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:47.234 [0x7f74b325ab38] DEBUG - Client [65232C63-40BB-40AB-8274-0C3F32614B27] reporting timeline state playing, progress of 0/7588000ms for guid=, playbackTime=0ms ratingKey=6290 url=, key=/library/metadata/6290, containerKey=, metadataId=6290, source=
Feb 03, 2022 01:08:47.235 [0x7f74b325ab38] DEBUG - [Now] User is jiwanjeong (ID: 1)
Feb 03, 2022 01:08:47.235 [0x7f74b325ab38] DEBUG - [Now] Device is iPadOS (Jiwan).
Feb 03, 2022 01:08:47.235 [0x7f74b325ab38] ERROR - Unable to find client profile for device; platform=iPadOS, platformVersion=, device=iPad, model=
Feb 03, 2022 01:08:47.235 [0x7f74b325ab38] DEBUG - [Now] Updated play state for /library/metadata/6290.
Feb 03, 2022 01:08:47.236 [0x7f74b325ab38] DEBUG - Statistics: (65232C63-40BB-40AB-8274-0C3F32614B27) Reporting active playback in state 0 of type 1 (scrobble: 0) for account 1
Feb 03, 2022 01:08:47.238 [0x7f74b5081b38] DEBUG - Completed: [100.10.14.235:51041] 200 POST /:/timeline?key=/library/metadata/6290&ratingKey=6290&state=playing&time=0&duration=7588000 (8 live) TLS GZIP 4ms 433 bytes (pipelined: 12)
Feb 03, 2022 01:08:47.455 [0x7f74b36f4b38] DEBUG - Request: [100.10.14.235:50203 (WAN)] GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:47.461 [0x7f74b505eb38] DEBUG - Completed: [100.10.14.235:50203] 200 GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP 6ms 2435 bytes (pipelined: 437)
Feb 03, 2022 01:08:48.203 [0x7f74b325ab38] DEBUG - Request: [100.10.14.235:50203 (WAN)] GET /status/sessions (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:48.203 [0x7f74b325ab38] DEBUG - [Now] Adding 1 sessions.
Feb 03, 2022 01:08:48.204 [0x7f74b505eb38] DEBUG - Completed: [100.10.14.235:50203] 200 GET /status/sessions (8 live) TLS GZIP 1ms 3624 bytes (pipelined: 438)
Feb 03, 2022 01:08:48.453 [0x7f74b36f4b38] DEBUG - Request: [100.10.14.235:50203 (WAN)] GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:48.459 [0x7f74b505eb38] DEBUG - Completed: [100.10.14.235:50203] 200 GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP 5ms 2453 bytes (pipelined: 439)
Feb 03, 2022 01:08:49.452 [0x7f74b36f4b38] DEBUG - Request: [100.10.14.235:50203 (WAN)] GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:49.458 [0x7f74b505eb38] DEBUG - Completed: [100.10.14.235:50203] 200 GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP 6ms 2458 bytes (pipelined: 440)
Feb 03, 2022 01:08:50.457 [0x7f74b36f4b38] DEBUG - Request: [100.10.14.235:50203 (WAN)] GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:50.463 [0x7f74b505eb38] DEBUG - Completed: [100.10.14.235:50203] 200 GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP 5ms 2470 bytes (pipelined: 441)
Feb 03, 2022 01:08:50.580 [0x7f74b325ab38] DEBUG - Request: [100.10.14.235:50240 (WAN)] GET /statistics/resources?timespan=6 (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:50.583 [0x7f74b505eb38] DEBUG - Completed: [100.10.14.235:50240] 200 GET /statistics/resources?timespan=6 (8 live) TLS GZIP 2ms 880 bytes (pipelined: 66)
Feb 03, 2022 01:08:51.473 [0x7f74b3517b38] DEBUG - Request: [100.10.14.235:50240 (WAN)] GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:51.480 [0x7f74b505eb38] DEBUG - Completed: [100.10.14.235:50240] 200 GET /statistics/bandwidth?timespan=6 (8 live) TLS GZIP 8ms 2481 bytes (pipelined: 67)
Feb 03, 2022 01:08:52.226 [0x7f74b36f4b38] DEBUG - Request: [100.10.14.235:51041 (WAN)] POST /:/timeline?key=/library/metadata/6290&ratingKey=6290&state=playing&time=60018&duration=7588000 (8 live) TLS GZIP Signed-in Token (jiwanjeong)
Feb 03, 2022 01:08:52.226 [0x7f74b36f4b38] DEBUG - Client [65232C63-40BB-40AB-8274-0C3F32614B27] reporting timeline state playing, progress of 60018/7588000ms for guid=, playbackTime=0ms ratingKey=6290 url=, key=/library/metadata/6290, containerKey=, metadataId=6290, source=
Feb 03, 2022 01:08:52.229 [0x7f74b36f4b38] DEBUG - Play progress on 6290 'Jurassic Park' - got played 60018 ms by account 1!
Feb 03, 2022 01:08:52.229 [0x7f74b36f4b38] DEBUG - HubCache: Expiring '1/continueWatching/1/hubs/continueWatching/en-US,en;q=0.9/' because of event plex.event.play.session.state.update.
Feb 03, 2022 01:08:52.229 [0x7f74b36f4b38] DEBUG - HubCache: Expiring '1/continueWatching/1/hubs/continueWatching/items/enexternal-media,indirect-media/contentDirectoryID=5%2C6%2C7%2C2%2C1%2C10' because of event plex.event.play.session.state.update.

Notice PMS is responding with data an average of 6 milliseconds after the request.

1 Like
7

How do you know theyā€™re currently well muxed and interleaved for streaming?

Direct Play means the player has to play the file, exactly as it is. This means the file format, video track, all audio tracks - even those not being played, and all subtitle tracks, are sent intact.

Direct Stream is sometimes superior. The server extracts the appropriate video and active (only) audio track, and remuxes them into the best format for the client.

Thereā€™s no transcoding or loss of quality. Bandwidth isnā€™t wasted on unnecessary audio tracks.

And itā€™s a good troubleshooting tool.

8

Recommend use of iperf3 to test the end-to-end network performance.
(Server on the Synology, add the client to the ATV / iPad)

1 Like
9

Sorry for the confusion. I mean ā€˜no video transcodingā€™ as ā€œdirect play.ā€ In the problem setting, the video transcoding was disabled and audio transcoding was enabled. Now I also tested with direct play allow off, and video transcoding enabled, but everything happens the same.

I think the video files are well-muxed because the exact same video and audio tracks with the same bitrate work just fine with the old player and other devices in the same network.

10

I certainly also mean ā€˜no video transcodingā€™. :slight_smile: Sorry, Direct Play and Direct Stream are what Plex calls those two variants of ā€˜no transcodingā€™ playback.

Those ā€œSpeedā€ numbers seem awfully low. These clients are remote to the server, correct? It would be interesting to try with a local client.

Even my AppleTV HD sucks down 10+ MB/s over WiFi until the cache is full. Thatā€™s whatā€™s reported in the debug player screen and the Plex Dashboard.

Can you put a sample file somewhere and send a link? Iā€™m happy to try to duplicate. Iā€™ve seen a few files that really do have structure/timestamp/container/stream problems that Plex doesnā€™t like.

If thereā€™s a repeatable problem with a specific file @ChuckPa can probably file it as an issue.

11

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.