Roku Ultra buffering on BluRay Rip

Plex Players Streaming Devices
,
1

Server Version#: very recent
Player Version#: Roku Ultra (weeks old)

Juts got this Roku Ultra - top of the line, hard wired to ethernet. I was hoping to replace my very functional RasPlex, which never ever had a single problem on any file I gave it.

Plex server is a Synology with no transcode CPU, local, same ethernet segment. Again, RasPlex played everything great.

Files in question are Blu-ray rips, direct, no transcode.

Roku Plex app spends more time buffering than playing. It buffers for 30 seconds, plays for 5, then repeats.

Roku people won’t help at all.

Is there something obvious to try? Is this supposed to work?

Tim

2

Synology boxes (depending on model), are great. The X18+ boxes have good HW transcoding capability.

Your Forum profile doesn’t show as a PlexPass holder. If you have a PlexPass, and you have a Syno with the HW transcoding, You could turn it on and let it resolve the problem.

Most Syno CPUs are too weak to transcode any video without the hardware boost. They are a nice NAS (I have an 1815+) but that’s about it. “Just a NAS”.

As I state, With a Plex Pass, and the right models, you won’t have buffering.

which model do you have?

3

I am a PlexPass holder for years (though maybe on a different email than I used here, oops). My Synology (model 414, I think) is a few years old and does NOT have hardware transcode.

My point, though, is that it shouldn’t need to transcode - RasPlex of several years ago decodes BluRay and streams from this Synology with zero problems. I was just hoping to consolidate devices - I am out of HDMI inputs :slight_smile:

I don’t feel inclined to spend hundreds of dollars on a transcoding server when I shouldn’t need to transcode at all. I started with Roku forums, saying “hey, Plex works fine on other devices”, but they say it’s a channel problem and to talk to Plex people.

:frowning:

4

Since 2014, a lot has changed – most notably 4K and HEVC encoding.

Given your supplemental information, I would like to assert (please correct me where I am in error):

  1. The quality and encoding of your source material has increased and now might indeed include 4K and/or HEVC encoded content.
  2. The Raspberry, which was 100% solid with 1080p H.264, direct playing from PMS, can’t keep up with this.
  3. PMS, knowing the source material playback requirements, and what the Raspberry informs it’s capable of, makes the decision a transcode is required.
  4. PMS decides to transcode, but because there is no hardware support, is forced to do everything in software because the CPU in the DS414, is an ARM v7 CPU which doesn’t have the capability.
DS414	Marvell Armada XP MV78230	Dual Core	2	Yes	Armadaxp	DDR3 1 GB
  1. It does the best it can in software.
  2. You experience these playback issues because it can’t keep up with the transcoding playback requirements for your newer, higher quality, video.

What’s the solution here? There are two plausible, and one undesirable, choices:

  1. A more capable NAS as I first mentioned.
  2. Now that I know you are using ARM processors for playback, how about an ARMv8 Raspberry as the player ? ARMv8 players can do more. It still may not be enough but it’s an option to investigate
  3. The lesser desired would be to make certain not to have HEVC or 2160p (4K) content which the existing solution set (NAS + Raspberry) can’t handle.
5

I’ll add, that the Roku can direct play H265 HEVC in most scenarios. Transcoding can definitely cause buffering issues, but we should determine if you are in fact transcoding or direct playing.

Please follow these steps to allow us to inspect the logs.

  • Open the Plex channel
  • Enable remote logging in the settings
  • Play the affected video
  • Wait for it to start playback
  • Stop playback
  • Disable remote logging
  • Report back with the time/timezone and username after you complete the test.
6

Hi again!

  1. The quality and encoding of your source material has increased

Nope, these are the exact same MKV files. I do not have any 4K. I unplugged my perfectly operational RasPlex and plugged in a brand new Roku Ultra. RasPlex plays everything I have

  1. PMS…makes the decision a transcode is required.

I am 99% certain I have PMS transcode disabled because I don’t want this exact scenario. I bought RasPlex precisely so I would not need to transcode. I am at work now, so I will have to double-check that when I get home.

Thanks for the debug steps - I will attempt to walk through them this evening.

7

May I see the log files (ZIP) - DEBUG logging enabled; VERBOSE disabled

of the recreation of one of these cases?

The logs will show me definitively what’s happening.

8

Report back with the time/timezone and username after you complete the test.

I am thockin@hockin.org, US West Coast time 6:40-6:50pm

I just tried to play “Spider Man: Into The Spider-Verse”. It hung at 65% for several minutes, and then said it couldn’t play the video at all: “This video isn’t supported for Direct Play”.

This same hang - always 65% - appears in other files, but not all. I was able to play Dark Knight and Hobbit, but not Lord Of The Rings or Solo. Infinity War works, but Last Jedi hangs.

10

Updated PMS to Version 1.18.2.2015 and retried - still can not play some titles.

11

I’m sorry, but without logs, I cannot be of any further help.
I need to see, through the logs, what you’re seeing.

Sorry.

12

I followed the steps listed above - enable logging, run the test, post the timezones and username.

Was that not what you wanted?

13

I had also asked for the above please.

14

Oops, I missed that, so sorry. Will repeat tonight.

15

I turned on non-verbose debug logging and tried again to play Spider-Man. It failed the same way. Here is the log.

debug-log.zip (8.9 KB)

Thanks!

16

Would you try that again please?

It’s not the ZIP file from Settings - Server - Troubleshooting - Download Logs
nor is it complete.

It’s only 8.9 KB

17

Cool, I had no idea that existed. I just tailed the log and copied it out. Here is a much larger log

Plex Media Server Logs_2019-11-12_22-37-50.zip (5.8 MB)

18

AH! That’s what I need. Thanks. I will review and reply (maybe tomorrow as it’s almost 2am here)

19

I found two major issues:

  1. There’s another, unaccounted for, certificate floating around which is making the communications stutter badly. It has to reset each time causing delays.
Nov 12, 2019 21:26:20.976 [0x35b6f450] DEBUG - Created thumbnail of size 283x159, has pixels: 1
Nov 12, 2019 21:26:20.991 [0x2fd33450] DEBUG - Completed: [10.5.69.33:33972] 200 GET /photo/:/transcode?url=%2Flibrary%2Fmetadata%2F67986%2Fthumb%2F1553237933 (11 live) TLS 839ms 13209 bytes (pipelined: 1)
Nov 12, 2019 21:26:33.969 [0x2f9d3450] DEBUG - CERT: incomplete TLS handshake: sslv3 alert bad certificate
Nov 12, 2019 21:26:33.972 [0x2fd33450] DEBUG - CERT: incomplete TLS handshake: sslv3 alert bad certificate
Nov 12, 2019 21:26:34.167 [0x2f9d3450] DEBUG - CERT: incomplete TLS handshake: sslv3 alert bad certificate
Nov 12, 2019 21:26:34.174 [0x2fd33450] DEBUG - CERT: incomplete TLS handshake: sslv3 alert bad certificate
Nov 12, 2019 21:26:35.237 [0x313c3450] ERROR - Error issuing curl_easy_perform(handle): 28
Nov 12, 2019 21:26:35.237 [0x313c3450] DEBUG - HTTP simulating 408 after curl timeout
Nov 12, 2019 21:26:35.237 [0x313c3450] ERROR - SSDP: Error parsing device schema for http://169.254.11.27:63444/upnp/xml/devices/ManageableDevice1.xml
Nov 12, 2019 21:26:35.245 [0x313c3450] DEBUG - NetworkServiceBrowser: Parsing SSDP schema for http://169.254.10.229:49153/description.xml
Nov 12, 2019 21:26:35.246 [0x313c3450] DEBUG - HTTP requesting GET http://169.254.10.229:49153/description.xml
Nov 12, 2019 21:26:35.454 [0x2fd33450] DEBUG - CERT: incomplete TLS handshake: sslv3 alert bad certificate
Nov 12, 2019 21:26:39.227 [0x2f9d3450] DEBUG - Completed: [10.5.69.37:37410] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (15 live) TLS GZIP 20017ms 5 bytes (pipelined: 16)
Nov 12, 2019 21:26:39.422 [0x2f9d3450] DEBUG - Auth: authenticated user 1 as thockin
Nov 12, 2019 21:26:39.423 [0x398bf450] DEBUG - Request: [10.5.69.37:37410 (Subnet)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (15 live) TLS GZIP Signed-in Token (thockin)
Nov 12, 2019 21:26:39.426 [0x398bf450] DEBUG - Content-Length is -1 (of total: -1).
Nov 12, 2019 21:26:40.689 [0x2f9d3450] DEBUG - CERT: incomplete TLS handshake: sslv3 alert bad certificate
Nov 12, 2019 21:26:40.702 [0x2fd33450] DEBUG - CERT: incomplete TLS handshake: sslv3 alert bad certificate
Nov 12, 2019 21:26:40.897 [0x2f9d3450] DEBUG - CERT: incomplete TLS handshake: sslv3 alert bad certificate
Nov 12, 2019 21:26:40.908 [0x2fd33450] DEBUG - CERT: incomplete TLS handshake: sslv3 alert bad certificate
Nov 12, 2019 21:26:50.257 [0x313c3450] ERROR - Error issuing curl_easy_perform(handle): 28
Nov 12, 2019 21:26:50.257 [0x313c3450] DEBUG - HTTP simulating 408 after curl timeout
  1. There is other activity, Transcoding perhaps(?), which is causing the whole NAS to slow down. These are occurring while it’s attempting to stream.
Nov 12, 2019 22:36:03.852 [0x334ed450] DEBUG - Setting container serialization range to [0, -1] (total=307)
Nov 12, 2019 22:36:03.869 [0x2f9d3450] DEBUG - Completed: [10.5.69.33:34337] 200 GET /hubs/home/recentlyAdded?type=1 (16 live) TLS GZIP Page 0--1 93ms 526 bytes (pipelined: 4)
Nov 12, 2019 22:36:03.877 [0x2fd33450] DEBUG - Auth: authenticated user 1 as thockin
Nov 12, 2019 22:36:03.881 [0x37c8d450] DEBUG - Request: [10.5.69.33:34337 (Subnet)] GET /hubs/home/recentlyAdded?type=1 (16 live) TLS Page 0-11 GZIP Signed-in Token (thockin)
Nov 12, 2019 22:36:03.881 [0x307a8450] DEBUG - It took 140.000000 ms to retrieve 200 items.
Nov 12, 2019 22:36:03.888 [0x37c8d450] DEBUG - Setting container serialization range to [0, 11] (total=-1)
Nov 12, 2019 22:36:03.957 [0x3387a450] WARN - SLOW QUERY: It took 260.000000 ms to retrieve 10 items.
Nov 12, 2019 22:36:03.981 [0x398bf450] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 10 items.
Nov 12, 2019 22:36:04.011 [0x3387a450] DEBUG - Setting container serialization range to [0, -1] (total=-1)
Nov 12, 2019 22:36:04.015 [0x2f9d3450] DEBUG - Completed: [10.5.69.33:34334] 200 GET /hubs/home/continueWatching (16 live) TLS GZIP Page 0--1 254ms 522 bytes (pipelined: 5)
Nov 12, 2019 22:36:04.042 [0x2fd33450] DEBUG - Auth: authenticated user 1 as thockin
Nov 12, 2019 22:36:04.045 [0x3ba5b450] DEBUG - Request: [10.5.69.33:34334 (Subnet)] GET /hubs/home/continueWatching (16 live) TLS Page 0-2 GZIP Signed-in Token (thockin)
Nov 12, 2019 22:36:04.046 [0x398bf450] DEBUG - Setting container serialization range to [0, -1] (total=-1)
Nov 12, 2019 22:36:04.059 [0x2fd33450] DEBUG - Completed: [10.5.69.33:34336] 200 GET /hubs/home/onDeck (16 live) TLS GZIP Page 0--1 289ms 520 bytes (pipelined: 4)
Nov 12, 2019 22:36:04.060 [0x37c8d450] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 12 items.
Nov 12, 2019 22:36:04.062 [0x316b1450] DEBUG - Setting container serialization range to [0, -1] (total=1088)
Nov 12, 2019 22:36:04.063 [0x37c8d450] DEBUG - Setting container serialization range to [0, 11] (total=307)
Nov 12, 2019 22:36:04.068 [0x2f9d3450] DEBUG - Auth: authenticated user 1 as thockin
Nov 12, 2019 22:36:04.071 [0x3387a450] DEBUG - Request: [10.5.69.33:34336 (Subnet)] GET /hubs/home/onDeck (16 live) TLS Page 0-0 GZIP Signed-in Token (thockin)
Nov 12, 2019 22:36:04.071 [0x2f9d3450] DEBUG - Completed: [10.5.69.33:34339] 200 GET /hubs/home/recentlyAdded?type=8 (16 live) TLS GZIP Page 0--1 280ms 527 bytes (pipelined: 2)
Nov 12, 2019 22:36:04.077 [0x2fd33450] DEBUG - Auth: authenticated user 1 as thockin
Nov 12, 2019 22:36:04.080 [0x334ed450] DEBUG - Request: [10.5.69.33:34339 (Subnet)] GET /hubs/home/recentlyAdded?type=8 (16 live) TLS Page 0-11 GZIP Signed-in Token (thockin)
Nov 12, 2019 22:36:04.086 [0x334ed450] DEBUG - Setting container serialization range to [0, 11] (total=-1)
Nov 12, 2019 22:36:04.117 [0x2f9d3450] DEBUG - Completed: [10.5.69.33:34337] 200 GET /hubs/home/recentlyAdded?type=1 (16 live) TLS GZIP Page 0-11 238ms 3340 bytes (pipelined: 5)
Nov 12, 2019 22:36:04.158 [0x307a8450] DEBUG - It took 530.000000 ms to retrieve 414 items.
Nov 12, 2019 22:36:04.197 [0x3ba5b450] DEBUG - It took 200.000000 ms to retrieve 10 items.
Nov 12, 2019 22:36:04.253 [0x3ba5b450] DEBUG - Setting container serialization range to [0, 2] (total=-1)
Nov 12, 2019 22:36:04.255 [0x3387a450] WARN - SLOW QUERY: It took 210.000000 ms to retrieve 10 items.
Nov 12, 2019 22:36:04.273 [0x2f9d3450] DEBUG - Completed: [10.5.69.33:34334] 200 GET /hubs/home/continueWatching (16 live) TLS GZIP Page 0-2 229ms 1581 bytes (pipelined: 6)
Nov 12, 2019 22:36:04.287 [0x3387a450] DEBUG - Setting container serialization range to [0, 0] (total=-1)
Nov 12, 2019 22:36:04.293 [0x2f9d3450] DEBUG - Completed: [10.5.69.33:34336] 200 GET /hubs/home/onDeck (16 live) TLS GZIP Page 0-0 224ms 1401 bytes (pipelined: 5)
Nov 12, 2019 22:36:04.316 [0x334ed450] DEBUG - Setting container serialization range to [0, 11] (total=1088)
Nov 12, 2019 22:36:04.328 [0x2f9d3450] DEBUG - Completed: [10.5.69.33:34339] 200 GET /hubs/home/recentlyAdded?type=8 (16 live) TLS GZIP Page 0-11 249ms 6096 bytes (pipelined: 3)
Nov 12, 2019 22:36:04.358 [0x307a8450] DEBUG - It took 340.000000 ms to retrieve 322 items.

That little ARMv7 CPU is working as hard as it can. The scanner is also running.

I believe the SSL resets are inducing enough delay to push it over the edge.

All these photos are being added. It can’t do everything.

Nov 12, 2019 19:36:54.845 [0x30021450] VERBOSE - Adding file for scanner: "/volume1/photo/2003/2003_Burning_Man/BM03-012.jpg"
Nov 12, 2019 19:36:54.845 [0x30021450] VERBOSE - Adding file for scanner: "/volume1/photo/2003/2003_Burning_Man/BM03-119.jpg"
Nov 12, 2019 19:36:54.846 [0x30021450] VERBOSE - Adding file for scanner: "/volume1/photo/2003/2003_Burning_Man/BM03-128.jpg"
Nov 12, 2019 19:36:54.846 [0x30021450] VERBOSE - Adding file for scanner: "/volume1/photo/2003/2003_Burning_Man/BM03-102.jpg"
Nov 12, 2019 19:36:54.846 [0x30021450] VERBOSE - Adding file for scanner: "/volume1/photo/2003/2003_Burning_Man/BM03-067.jpg"
Nov 12, 2019 19:36:54.846 [0x30021450] VERBOSE - Adding file for scanner: "/volume1/photo/2003/2003_Burning_Man/BM03-039.jpg"
Nov 12, 2019 19:36:54.851 [0x3274b450] DEBUG - Streaming Resource: Usage: 0kbps of WAN bandwidth, 0 streaming transcode slots, and 0 static transcode slots across 0 sessions
Nov 12, 2019 19:36:54.896 [0x30021450] DEBUG - Skipping over directory '2003/2003_Burning_Man', as nothing has changed; removing 141 media items from map.
Nov 12, 2019 19:36:54.897 [0x30021450] DEBUG - Activity: updated activity 360e8461-7d4d-401e-ae19-ee8b85770567 - completed 50.0% - Scanning Photos
Nov 12, 2019 19:36:54.897 [0x30021450] DEBUG - Scanner: Processing directory /volume1/photo/1996 (parent: yes)
Nov 12, 2019 19:36:54.897 [0x30021450] VERBOSE -     * Noting that '1996' was updated at 2015-10-18 14:26:20
Nov 12, 2019 19:36:54.898 [0x30021450] VERBOSE -     * Taking directory '1996' (651) out of the map (120 left)
Nov 12, 2019 19:36:54.908 [0x30021450] VERBOSE - Adding subdirectory for scanner: "/volume1/photo/1996/2nd_Suburb_Players_Evita"
Nov 12, 2019 19:36:54.909 [0x30021450] DEBUG - Skipping over directory '1996', as nothing has changed; removing 0 media items from map.
Nov 12, 2019 19:36:54.910 [0x30021450] DEBUG - Scanner: Processing directory /volume1/photo/1996/2nd_Suburb_Players_Evita (parent: yes)
Nov 12, 2019 19:36:54.911 [0x30021450] VERBOSE -     * Noting that '1996/2nd_Suburb_Players_Evita' was updated at 2015-10-18 14:26:20
Nov 12, 2019 19:36:54.911 [0x30021450] VERBOSE -     * Taking directory '1996/2nd_Suburb_Players_Evita' (652) out of the map (119 left)
Nov 12, 2019 19:36:54.911 [0x30021450] VERBOSE - Adding file for scanner: "/volume1/photo/1996/2nd_Suburb_Players_Evita/ADAMHAIR.JPG"
Nov 12, 2019 19:36:54.911 [0x30021450] VERBOSE - Adding file for scanner: "/volume1/photo/1996/2nd_Suburb_Players_Evita/LOGO1.JPG"
Nov 12, 2019 19:36:54.912 [0x30021450] VERBOSE - Adding file for scanner: "/volume1/photo/1996/2nd_Suburb_Players_Evita/ALLTHREE.JPG"
Nov 12, 2019 19:36:54.912 [0x30021450] VERBOSE - Adding file for scanner: "/volume1/photo/1996/2nd_Suburb_Players_Evita/RAINBOW1.JPG"
Nov 12, 2019 19:36:54.912 [0x30021450] VERBOSE - Adding file for scanner: "/volume1/photo/1996/2nd_Suburb_Players_Evita/THE_END2.JPG"
Nov 12, 2019 19:36:54.912 [0x30021450] VERBOSE - Adding file for scanner: "/volume1/photo/1996/2nd_Suburb_Players_Evita/FOUNDATN.JPG"
Nov 12, 2019 19:36:54.912 [0x30021450] VERBOSE - Adding file for scanner: "/volume1/photo/1996/2nd_Suburb_Players_Evita/CHE_EVA.JPG"
20

I think the phots being “added” must have been a daily scan, but they are all added already. There’s nothing else going on. My whole household was asleep.

I can try to repeat the process at a different time when there is no scan happening?

About this cert - how did that happen and how do I fix?

The Synology console did not show the CPU being pegged at all.

Lastly - it always hangs at exactly 65% on multiple files. It is 100% repeatable for those files, yet other files (also Blu-ray 1080p) play fine 100% repeatably. That doesn’t pass the smell test to me.

I will try again tonight with scan disabled, try playing a file successfully then failing some, and keep a close eye on CPU.

21

Also worth noting - RasPlex plays these files. I can try to plug that back in and catch the log.