Server Version#: Ubuntu 16
Player Version#: Version 1.18.1.1973
Recently I have problems where I can see the buffer for a movie or tv show is well ahead of my current position and then it’s gone. The client spins while buffering, CPU jumps…the buffer is rebuilt and playback continues.
What can I look for in the logs to help pinpoint what’s going on.
thanks…
Is Hardware Transcoding acceleration enabled?
(Settings - Server - Transcoder - Show Advanced)
I’m running on a headless VP and saw the warning about how it could reduce video compatibility and have never enabled it.
Hardware transcoding does not reduce compatibility.
In those cases where the input bitrate is very low and arguably questionable, if the CPU is a -3xxx -> -5xxx series, it is possible for the quality to decrease.
This is because the hardware wasn’t as sophisticated as it is now which meant software would produce a better image in those lower-input-quality cases.
Now, with the newer generation processors 5xxx->8xxx, Transcoding good bitrate input H.264 in hardware is nearly indistinguishable from software. You would need to know what you’re looking for.
@ChuckPa, still happening. What I have seen is that I start a show, and the buffer builds, the show is playing fine, then boom…it just quits playing and starts to buffer then picks up and plays again.
I’ve downloaded the server logs within a few minutes after it occurred but am unable to identify a problem. Any ideas? If I wanted to upload the logs for someone to look at, where would I do that?
thank you,
May I see those logs?
To be best viable,
Anything in the file “Plex Media Server.log” that should be redacted before uploading?
@ChuckPa,
The .zip file is attached, hopefully you can tell me what’s going on. Thanks.
Thanks.
Your logs show remote streaming to a Roku and an iPad.
The conclusion I arrive at is: network latency from the server to the remote player. When the player (presumably the roku) buffer gets low, it will ask for more. If transit latency is too high
Your observations of the CPU spinning high to refill the buffer is indicative of this.
Messages from the player to refill the buffer are slow to arrive but when they do, the server kicks into high gear to refill the buffers as best it can again. Under normal conditions, it should have an initial full-speed surge and then smooth out.
At this point, I suggest watching the bandwidth graph and seeing how the network is behaving. See if there are routine pulses of data or large ‘block dumps’ of data.
Chuck,
One more if you would please.
This again is another HEVC file, with a bitrate of 1661 kbps.
The buffer is built, the CPU drops (as usual) and the playback begins. Playback continues and then suddenly the file stops playing and the buffer disappears. The buffer was not used and then failed to refill, it just disappears.
In this instance the file quit playing and would not resume. I had to Stop, then restart.
Thanks for the updated logs.
I’m seeing something in the logs which is disturbing.
PMS thinks it has 15 transcode streams active. Your logs show only 2.
Can you enlighten?
Dec 03, 2019 09:12:06.203 [0x7f7d371b8700] ERROR - Session 0x7f7c280157a0 terminated
Dec 03, 2019 09:12:06.205 [0x7f7ceffff700] DEBUG - Streaming Resource: Terminated session 0x7f7c280157a0:c5ca69687be176fe03f43f826d86b3b5 with reason Client stopped playback.
Dec 03, 2019 09:12:06.205 [0x7f7ceffff700] DEBUG - Streaming Resource: Removing session 0x7f7c280157a0:c5ca69687be176fe03f43f826d86b3b5
Dec 03, 2019 09:12:06.207 [0x7f7d371b8700] DEBUG - Removed transcode data consumer, active count 15 => 14
Dec 03, 2019 09:12:06.207 [0x7f7d0bfff700] DEBUG - Killing job.
Dec 03, 2019 09:12:06.207 [0x7f7d0bfff700] DEBUG - Signalling job ID 20107 with 9
Dec 03, 2019 09:12:06.207 [0x7f7d0bfff700] DEBUG - Job was already killed, not killing again.
Dec 03, 2019 09:12:06.207 [0x7f7d0bfff700] DEBUG - Stopping transcode session 1f07aa05-5bac-4d31-843b-7ebadd0022ee-1
Dec 03, 2019 09:12:06.212 [0x7f7d369b7700] DEBUG - Completed: [69.255.121.90:35141] 200 GET /:/timeline?playbackTime=140000&time=144593&duration=3402656&state=stopped&ratingKey=33970&key=%2Flibrary%2Fmetadata%2F33970&continuing=0&playQueueItemID=89116 (22 live) TLS GZIP 23ms 747 bytes (pipelined: 37)
Dec 03, 2019 09:12:06.219 [0x7f7d0bfff700] DEBUG - Transcoder: Cleaning old transcode directories.
Dec 03, 2019 09:12:06.245 [0x7f7d3e79f700] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 20107 is -9 (signal: Killed)
Dec 03, 2019 09:12:06.246 [0x7f7cc27fc700] DEBUG - Notifying consumer that data is complete.
Dec 03, 2019 09:12:06.246 [0x7f7cc27fc700] DEBUG - Notifying consumer that data is complete.
Dec 03, 2019 09:12:06.246 [0x7f7cc27fc700] DEBUG - Notifying consumer that data is complete.
Dec 03, 2019 09:12:06.246 [0x7f7cc27fc700] DEBUG - Notifying consumer that data is complete.
Dec 03, 2019 09:12:06.246 [0x7f7cc27fc700] DEBUG - Notifying consumer that data is complete.
Dec 03, 2019 09:12:06.246 [0x7f7cc27fc700] DEBUG - Notifying consumer that data is complete.
Dec 03, 2019 09:12:06.246 [0x7f7cc27fc700] DEBUG - Notifying consumer that data is complete.
Dec 03, 2019 09:12:06.246 [0x7f7cc27fc700] DEBUG - Notifying consumer that data is complete.
Dec 03, 2019 09:12:06.246 [0x7f7cc27fc700] DEBUG - Notifying consumer that data is complete.
Dec 03, 2019 09:12:06.246 [0x7f7cc27fc700] DEBUG - Notifying consumer that data is complete.
Dec 03, 2019 09:12:06.246 [0x7f7cc27fc700] DEBUG - Notifying consumer that data is complete.
Dec 03, 2019 09:12:06.246 [0x7f7cc27fc700] DEBUG - Notifying consumer that data is complete.
Dec 03, 2019 09:12:06.246 [0x7f7cc27fc700] DEBUG - Notifying consumer that data is complete.
Dec 03, 2019 09:12:06.246 [0x7f7cc27fc700] DEBUG - Notifying consumer that data is complete.
Dec 03, 2019 09:12:06.307 [0x7f7d0bfff700] DEBUG - Transcoder: Cleaning old transcode directory: "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-1f07aa05-5bac-4d31-843b-7ebadd0022ee-1-22abd014-d3fc-49c1-a55b-3b5584d4a3d7"
Nope…only two users were active, very strange. As I am “working from home” today i’m updating some patches and rebooting the server. I’ll be playing something shortly and will pull updated logs if/when it happens.
@ChuckPa, fresh reboot and within minutes of watching a show it happened again. The file is HEVC and this type of file will produce the error almost everytime an HEVC file is played, however it also happes with other x264 files, just not as often. As in the past, the buffer is built and data sent to the client, while the client plays, the CPU continues transcoding until the buffer is full and the CPU utilization drops. This is all normal behavior, then at some point the buffer is instantly gone and the show stops playing and starts to buffer again. This shouldn’t happen as the server is 10 cores, plenty of bandwidth, and is used for nothing else.
update, this happens within the first 3-5 minutes of every HEVC file (if that helps in troubleshooting)
That doesn’t sound like the server at all.
It sounds like a) connection reliability between the two points or app itself.
Does it happen with every player? I see you are using Roku as the remote player
Is this server hosted somewhere? I don’t see local lan traffic
@ChuckPa, the server is a hosted VPS and has been for several years now. The storage is vis Gsuite and a mnt. While my client is a Roku 3 I do know that it is happening with other users. Do you see anything in the logs that would explain the behavior? Is it not able to find the source file and kills the session only to then find it and resume?
I do see a number of LPE (Local Path Evaluator) errors. Those imply missing files
a. subtitles it’s expecting
b. the main file itself (which would be visible – trash can on your media)
When is the last time you did a full
Scan, Empty Trash, Clean Bundles, and then Optimize Database on every section?
I scan often with new content incoming regularly, but ran through Scan, Empty Trash, Clean Bundles and Optimized. Testing now…thank you.
This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.
