PMS on QNAP TVS951x - Buffering. all the time

memanole · October 8, 2019, 6:52am

Server Version#: 1.17.0.1841
Player Version#: Plex for Smart TVs > 3.13.21

Good morning guys,

I need a bit of help with an issue that is becoming more and more annoying. And that is the continous buffering I am getting, regardless of the movie quality/format or client device I am using.
I have checked and un-checked all the settings i found references about, but is pointless [most probably because i was quite chaotic in my tshooting due lack of time]

My setup:
I am running PMS on a QNAP TVS-951x which I purposely bought because it can do the hw transcoding
I am using as client 1x panasonic tv via wire and 1x samsung via wireless [none of them ]
network: I am using a Cisco 3750G [PO towards the qnap] and all other internal uplinks are on gig. For wireless i am using a cisco AP-2702

I can provide any log required

Any help would be really reall appreciated

Thank you
MM

memanole · October 9, 2019, 7:02am

Nobody?

nibbles · October 9, 2019, 9:36am

Without logs, just from looking at the NAS Compatibility List shows that your Celeron J385U is one of the not-a-corei3-or-better powered CPUs that Plex suggests. However, it’s fairly recent, being a 2017 model.

It should do a number of tasks well.

Let’s investigate your issue using a desktop or laptop computer if possible, at https://app.plex.tv/desktop

Tell us about the video you’re trying to play, h264? HEVC? The best thing you can do is zip and attach the XML Media Information for your file.

Stuttering can be caused by a variety of issues. You can cross off WiFi problems because you’ve tested the wired link to the TV and had the same issues. Can I assume you’ve had those problems from a wired desktop/laptop too?

memanole · October 9, 2019, 4:06pm

Hi Nibbles,

Many thanks for replying. I have attached the logs I exported a few days back, just after i had this issue for quite few times.Plex Media Server Logs_2019-10-05_20-38-54.zip (1021.1 KB)

Re TVS-951x > shouldn’t the dedicated transcoding hw do all the hardwork? that is the main reeason I bought this NAS

I usually have issues with hd movies in h264 format while playing on the TV’s || I have no problem playing any file/format on my laptops
I did check the dashboard while playing the file & it says that transcoding is taking place in HW [I checked the option in settings]
WHile digging trough logs via console I got the warning that database is busy, at the same time with video buffering // this correlates with no traffic from NAS to TV [based on graphic from dashboard]

Thank you
MM

ChuckPa · October 9, 2019, 4:09pm

Reviewing logs now. Please stand by

ChuckPa · October 9, 2019, 4:13pm

Thanks for those logs but they are unfortunately useless.

You turned DEBUG logging off. Having them on does not consume more disk space.
The default is DEBUG on, VERBOSE off. This is the optimal, desired, and default configuration.

Please:

Turn debug logging back on and leave it on, keeping verbose off.
Start Playback
Let play for 30 seconds
Stop Playback
Wait 30 seconds for logs to flush
Settings - Server - Troubleshooting - Download Logs
Attach the ZIP file here (drag & drop then wait for upload to complete)

nibbles · October 9, 2019, 6:11pm

Yes sir. It’s a modern Celeron, and will have a number of advanced HW acceleration capabilities including full support for h264 video tracks in HW.

Stuttering on TV when wired is okay => often because of subtitles, incompatible audio format, WiFi. database issues, media encoding abnormalities, number of total tracks (memory on TV runs low).

Looking forward to your logs and how you and ChuckPA get it sorted.

memanole · October 10, 2019, 3:22pm

Thanks mate for your reply. I am no expert in all this, and I hoped that if I buy the ‘proper’ thing it will auto-magically ust work

MM

memanole · October 10, 2019, 3:26pm

Hi ChuckPA,

Thank you for checking out my issue. really appreciated!
I have followed what you said and attached the logs. Please let me know if this time I captured in the proper wayPlex Media Server Logs_2019-10-10_16-20-15.zip (1.0 MB)

many thanks
MM

nibbles · October 10, 2019, 4:21pm

Pretty good job logging. When you played your film for 20min, the traffic looked normal.
Besides the database is locked errors, I spotted one thing:

Oct 08, 2019 16:11:13.244 [0x7fba5911f700] INFO - Library section 2 (Movies) will be updated because of a change in '"/share/CACHEDEV2_DATA/Movies"/@DownloadStationTempFiles'
Oct 08, 2019 16:11:16.231 [0x7fba5911f700] INFO - Library section 2 (Movies) will be updated because of a change in '"/share/CACHEDEV2_DATA/Movies/@DownloadStationTempFiles/admin/The.Secret.Life.of.Pets.2.2019.1080p.Bluray.DD5.1.x264-playHD.c1ef51951490fdb6d1ca6f229062157e50f4d2f0/The.Secret.Life.of.Pets.2.2019.1080p.Bluray.DD5.1.x264-playHD"/The.Secret.Life.of.Pets.2.2019.1080p.Bluray.DD5.1.x264-playHD.mkv.dsdownload'
Oct 08, 2019 16:11:36.309 [0x7fba5911f700] INFO - Library section 2 (Movies) will be updated because of a change in '"/share/CACHEDEV2_DATA/Movies/@DownloadStationTempFiles/admin/The.Secret.Life.of.Pets.2.2019.1080p.Bluray.DD5.1.x264-playHD.c1ef51951490fdb6d1ca6f229062157e50f4d2f0/The.Secret.Life.of.Pets.2.2019.1080p.Bluray.DD5.1.x264-playHD"/The.Secret.Life.of.Pets.2.2019.1080p.Bluray.DD5.1.x264-playHD.mkv.dsdownload'

Is plex scanning a directory used by QNAP Download Station?

ChuckPa · October 10, 2019, 4:24pm

It looks like the NAS is very backlogged. (busy database)

It’s difficult to see what caused it.

I’m not seeing where you enabled Debug logging then started the Playback version.

I would like to request this specific sequence:

Verify DEBUG is on
Restart PMS
Wait 60 seconds after restart for it
Play the movie again
Let it play for 30 seconds
Stop Playback
Wait 30 seconds for logs to settle
Setting -Server - Troubleshooting - Download Logs
Attach that ZIP file
Also include the Media Info (if there are subtitles) or XML (the <stream ......... /stream> lines near the top of the XML.

nibbles · October 10, 2019, 4:39pm

I was hoping you’d ask him to reboot the QNAP too in case it’s beneficial, but that might be a myth.

While we wait, I saw subtitleDecision="burn" in his “Plex Transcoder Statistics.log”
Thanks for helping.

ChuckPa · October 10, 2019, 4:52pm

If QTS and PMS are restarted together, and it fails, then I don’t know which it is.
Based on the logs, it does not look to be QTS related.

memanole · October 10, 2019, 8:53pm

Hi ChuckPA

ok, so I followed your steps and got the attached logs. I was thinking that I should have been more accurate about the bufferring: is not continously buffering and never playing, but that it stops, then play., then stops again…and so on and forth. I kept thinking that was because of my TV [not enough resources] untill I played an SD movie that I played before directly via a shared folder.

Plex Media Server Logs_2019-10-10_21-39-08.zip (995.3 KB)

xml_media_info.txt (3.3 KB)

Many thanks again for looking into this
MM

memanole · October 10, 2019, 8:55pm

Hi nibbles,

I think that has been a mistake on my end. I set up as temp down folder for incomplete files the same folder as final destination. I will change this.

Many thanks
M

ChuckPa · October 10, 2019, 9:06pm

Menanole,

Thanks for providing the XML. Now we know what PMS saw in the video.

<Part accessible="1" exists="1" id="50348" key="/library/parts/50348/1570067477/file.mkv" duration="3447808" file="/share/CACHEDEV2_DATA/TVprogrammes/The.Crown.S01.1080p.WEBRip.x264-DEFLATE/The.Crown.S01E04.1080p.WEBRip.X264-DEFLATE/The.Crown.S01E04.1080p.WEBRip.X264-DEFLATE.mkv" size="4430311278" container="mkv" videoProfile="high">
<Stream id="24005" streamType="1" default="1" codec="h264" index="0" bitrate="9896" language="English" languageCode="eng" bitDepth="8" chromaLocation="left" chromaSubsampling="4:2:0" frameRate="25.000" hasScalingMatrix="0" height="960" level="41" profile="high" refFrames="4" scanType="progressive" width="1920" displayTitle="1080p (H.264)"/>
<Stream id="24006" streamType="2" selected="1" default="1" codec="ac3" index="1" channels="6" bitrate="384" language="English" languageCode="eng" audioChannelLayout="5.1(side)" samplingRate="48000" displayTitle="English (AC3 5.1)"/>
<Stream id="24007" streamType="3" selected="1" codec="srt" index="2" language="English" languageCode="eng" title="English" displayTitle="English (SRT)"/>
<Stream id="24008" streamType="3" codec="srt" index="3" language="English" languageCode="eng" title="English (SDH)" displayTitle="English (SRT)"/>
<Stream id="24009" streamType="3" codec="srt" index="4" language="Français" languageCode="fre" title="French" displayTitle="Français (SRT)"/>
<Stream id="24010" streamType="3" codec="srt" index="5" language="Deutsch" languageCode="ger" title="German" displayTitle="Deutsch (SRT)"/>
<Stream id="24011" streamType="3" codec="srt" index="6" language="Italiano" languageCode="ita" title="Italian" displayTitle="Italiano (SRT)"/>
<Stream id="24012" streamType="3" codec="srt" index="7" language="Español" languageCode="spa" title="Spanish" displayTitle="Español (SRT)"/>
</Part>
</Media>

In the logs we see where the host itself got extremely busy when the transcoder was engaged.

Oct 05, 2019 20:37:17.138 [0x7fba5a88f700] DEBUG - Asked for segment 3199 from session.
Oct 05, 2019 20:37:17.138 [0x7fba5a88f700] DEBUG - Returning segment 3199 from session
Oct 05, 2019 20:37:17.138 [0x7fba5a88f700] DEBUG - Content-Length of /share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Library/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-cke6decm9k0ggb9mzrj919z9-fc757bad-e3e8-459d-84bd-785fd437f3db/media-03199.ts is 2218024 (of total: 2218024).
Oct 05, 2019 20:37:17.415 [0x7fba5a2b3700] DEBUG - Session cke6decm9k0ggb9mzrj919z9 (3) is unthrottling
Oct 05, 2019 20:37:17.416 [0x7fba4964d700] DEBUG - [Transcoder] Throttle - Getting back to work.
Oct 05, 2019 20:37:17.497 [0x7fba4bfff700] DEBUG - Transcoder segment range: 0 - 3260 (3260)
Oct 05, 2019 20:37:17.514 [0x7fba81d8c700] DEBUG - Transcoder segment range: 0 - 3261 (3260)
Oct 05, 2019 20:37:17.679 [0x7fba5a88f700] DEBUG - Transcoder segment range: 0 - 3261 (3261)
Oct 05, 2019 20:37:17.696 [0x7fba5a5a1700] DEBUG - Transcoder segment range: 0 - 3262 (3261)
Oct 05, 2019 20:37:17.829 [0x7fba4964d700] DEBUG - Session cke6decm9k0ggb9mzrj919z9 (3) is throttling
Oct 05, 2019 20:37:17.830 [0x7fba4bfff700] DEBUG - [Transcoder] Throttle - Going into sloth mode.
Oct 05, 2019 20:37:18.070 [0x7fba81d8c700] DEBUG - Transcoder segment range: 0 - 3262 (3262)
Oct 05, 2019 20:37:18.083 [0x7fba5a88f700] DEBUG - Transcoder segment range: 0 - 3263 (3262)
Oct 05, 2019 20:37:18.364 [0x7fba82656700] DEBUG - Completed: [172.16.0.55:63489] 200 GET /video/:/transcode/universal/session/cke6decm9k0ggb9mzrj919z9/base/03199.ts (12 live) 1225ms 2218024 bytes (pipelined: 2104)
Oct 05, 2019 20:37:18.364 [0x7fba82656700] DEBUG - Removed transcode data consumer, active count 1 => 0
Oct 05, 2019 20:37:18.412 [0x7fba5a2b3700] DEBUG - Request: [172.16.0.55:55057 (Allowed Network (Subnet))] GET /video/:/transcode/universal/session/cke6decm9k0ggb9mzrj919z9/base/index.m3u8 (12 live) Signed-in
Oct 05, 2019 20:37:18.413 [0x7fba5a2b3700] DEBUG - Found session GUID of cke6decm9k0ggb9mzrj919z9 in session start.
Oct 05, 2019 20:37:18.413 [0x7fba5a2b3700] DEBUG - HLS: Building an M3U8 for 10872 total seconds with 1 seconds/segment, target duration of 1.
Oct 05, 2019 20:37:18.438 [0x7fba82656700] DEBUG - Completed: [172.16.0.55:55057] 200 GET /video/:/transcode/universal/session/cke6decm9k0ggb9mzrj919z9/base/index.m3u8 (12 live) 25ms 293857 bytes (pipelined: 1)
Oct 05, 2019 20:37:18.473 [0x7fba4964d700] DEBUG - Request: [172.16.0.55:63489 (Allowed Network (Subnet))] GET /video/:/transcode/universal/session/cke6decm9k0ggb9mzrj919z9/base/03200.ts (12 live) Signed-in
Oct 05, 2019 20:37:18.473 [0x7fba4964d700] DEBUG - Asked for segment 3200 from session.
Oct 05, 2019 20:37:18.473 [0x7fba4964d700] DEBUG - Returning segment 3200 from session
Oct 05, 2019 20:37:18.473 [0x7fba4964d700] DEBUG - Content-Length of /share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Library/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-cke6decm9k0ggb9mzrj919z9-fc757bad-e3e8-459d-84bd-785fd437f3db/media-03200.ts is 2305444 (of total: 2305444).
Oct 05, 2019 20:37:18.967 [0x7fba82656700] DEBUG - Auth: authenticated user 1 as memanole
Oct 05, 2019 20:37:18.968 [0x7fba81d8c700] DEBUG - Request: [172.16.0.55:47262 (Allowed Network (Subnet))] GET /:/timeline?hasMDE=1&ratingKey=43146&key=%2Flibrary%2Fmetadata%2F43146&state=playing&playQueueItemID=9496&time=3197822&duration=10871392 (10 live) GZIP Signed-in Token (memanole)
Oct 05, 2019 20:37:29.919 [0x7fba4bfff700] WARN - Waited one whole second for a busy database.
Oct 05, 2019 20:38:49.961 [0x7fba5a2b3700] WARN - Waited one whole second for a busy database.
Oct 05, 2019 20:38:52.192 [0x7fba5a2b3700] WARN - Waited one whole second for a busy database.
Oct 05, 2019 20:38:54.377 [0x7fba82656700] WARN - Deleted file "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Library/tmp/logs.zip5110d4ee-c27a-4974-8354-2e701bccc3f9" after connection reset
Oct 05, 2019 20:59:21.031 [0x7fba4b735700] WARN - Waited one whole second for a busy database.
Oct 05, 2019 20:59:23.259 [0x7fba4b735700] WARN - Waited one whole second for a busy database.
Oct 05, 2019 20:59:25.489 [0x7fba4b735700] WARN - Waited one whole second for a busy database.
Oct 05, 2019 20:59:27.717 [0x7fba4b735700] WARN - Waited one whole second for a busy database.
Oct 05, 2019 20:59:29.944 [0x7fba4b735700] WARN - Waited one whole second for a busy database.
Oct 05, 2019 20:59:31.038 [0x7fba82368700] WARN - Waited one whole second for a busy database.
Oct 05, 2019 20:59:32.169 [0x7fba4b735700] WARN - Waited one whole second for a busy database.
Oct 05, 2019 20:59:33.267 [0x7fba82368700] WARN - Waited one whole second for a busy database.

The database locked warnings mean that there was not enough available CPU for the other parts of PMS to go in and do what it’s normally trying to do while the Transcoder is running.

Putting the pieces together:

Subtitles in the file
MDE decision = burn

<Stream burn="1" displayTitle="English (SRT)" id="24007" language="English" languageCode="eng" selected="1" streamType="3" decision="burn" location="segments-av" />

Regular CPU being unable to keep up with demand ( Subtitles are always done by the CPU and not the hardware )

This does confirm the buffering / stuttering / errors seen are from the subtitles.

Now, to find out where they are coming from is pretty easy:

Check the Player’s settings
See if they are set to “Always burn” - If so, set to Automatic.

If they are set to automatic, as a test, set to “Only Image Formats” . SRT subtitles are text.

Unless the subtitles are tagged as Forced in the video file, you should not have any stuttering. You won’t have any subtitles but it should not stutter either.

nibbles · October 10, 2019, 10:23pm

Another pretty good try

The logs you attached were not in debug mode when you did the test.
We can see that the only listings from Oct 10th are in regular mode.

Before I paste all of what just happened, I’m going to request that you enable
debug mode and save, then don’t turn it off. It’s perfectly okay to leave it on
for a few days while we work this out.

Here is your most recent experiment, all of it. It’s my opinion that you started
your test at about Oct 10 21.36:50 ish

The transcoder session timestamp in "Plex Transcoder Statistics.log"

<SessionReport version="2" startTime="0" startTimestamp="Oct 10, 2019 21:36:53.689" key="/library/metadata/43229" session="38v0751hivu6jemiaco56vzn" transcode="v1bwhd3lbqn0zfrj1zxy5ot9">
<User id="1" thumb="https://plex.tv/users/3afe1166b2aa28f6/avatar?c=1558031989" title="memanole" />
<Player address="172.16.0.55" device="" machineIdentifier="p8yaw8u6j3euerk9bzrubex6" model="" platform="Smart TV Alliance" platformVersion="3.0" product="Plex for Smart TVs" remotePublicAddress="" state="" title="" vendor="" version="3.13.21" local="1" relayed="0" secure="0" userID="1" />
<Variants>
<Variant id="a53bea1e-640f-4951-befd-3ab727f32749" targetBitrate="16393" context="streaming" sourceVideoCodec="h264" sourceAudioCodec="ac3" videoDecision="transcode" audioDecision="copy" subtitleDecision="burn" protocol="hls" container="mpegts" videoCodec="h264" audioCodec="ac3" audioChannels="6" transcodeHwRequested="1" transcodeHwDecoding="vaapi" transcodeHwEncoding="vaapi" transcodeHwDecodingTitle="Intel (VA API)" transcodeHwEncodingTitle="Intel (VA API)" transcodeHwFullPipeline="0">
<Media id="50338" videoProfile="high" audioChannels="6" audioCodec="ac3" bitrate="15228" container="mpegts" duration="3447808" height="960" protocol="hls" videoCodec="h264" videoFrameRate="PAL" videoResolution="1080p" width="1920" selected="1">
<Part id="50348" videoProfile="high" bitrate="15228" container="mpegts" duration="3447808" height="960" protocol="hls" width="1920" decision="transcode" selected="1">
<Stream bitrate="14844" chromaLocation="left" codec="h264" default="1" displayTitle="1080p (H.264)" frameRate="25" height="960" id="24005" language="English" languageCode="eng" streamType="1" width="1920" decision="transcode" location="segments-av" />
<Stream bitrate="384" bitrateMode="cbr" channels="6" codec="ac3" default="1" displayTitle="English (AC3 5.1)" id="24006" language="English" languageCode="eng" selected="1" streamType="2" decision="copy" location="segments-av" />
<Stream burn="1" displayTitle="English (SRT)" id="24007" language="English" languageCode="eng" selected="1" streamType="3" decision="burn" location="segments-av" />
</Part>

It showed in that test you were burning SRTs

The very end of "Plex Media Server.1.log" doesn't capture the test

Oct 10, 2019 20:59:03.058 [0x7fba58b43700] WARN - Waited one whole second for a busy database.
Oct 10, 2019 20:59:03.190 [0x7fba5ab7d700] WARN - Waited one whole second for a busy database.
Oct 10, 2019 21:35:43.584 [0x7fba82f20700] WARN - Timed out waiting for server to finish.
Oct 10, 2019 21:35:43.589 [0x7fba82f20700] WARN - JobManager: Could not find job for handle 24596
Oct 10, 2019 21:35:43.628 [0x7fba82f20700] WARN - JobManager: Could not find job for handle 24390

And in "Plex Media Server.log" you see the Transcoder error

Oct 10, 2019 21:36:11.449 [0x7f61de9ce700] INFO - Plex Media Server v1.17.0.1841-d42cfa161 - QNAP TVS-951X x86_64 - build: linux-x86_64 qnap - GMT 01:00
Oct 10, 2019 21:36:11.449 [0x7f61de9ce700] INFO - Linux version: QTS 4.3.6.1070, language: en-US
Oct 10, 2019 21:36:11.449 [0x7f61de9ce700] INFO - Processor Intel(R) Celeron(R) CPU 3865U @ 1.80GHz
Oct 10, 2019 21:36:11.449 [0x7f61de9ce700] INFO - ./Plex Media Server
Oct 10, 2019 21:36:11.581 [0x7f61e8419740] INFO - OCSP: Successfully retrieved response from cache.
Oct 10, 2019 21:36:15.199 [0x7f61c59e9700] WARN - [Preferences] No update channels loaded, so showing the previously-selected channel, labelled 'unknown' since we don't really know the name.
Oct 10, 2019 21:36:15.636 [0x7f61c540d700] WARN - Sync: local sync directory "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Library/Plex Media Server/Cache/Transcode/Sync+" does not exist
Oct 10, 2019 21:36:15.636 [0x7f61c7735700] INFO - Sync: downloaded 0 sync list(s) with 0 sync items(s): 0 new, 0 updated, 0 deleted
Oct 10, 2019 21:36:22.001 [0x7f61c7fff700] INFO - Refreshing paths watched by LibraryUpdateManager
Oct 10, 2019 21:36:53.223 [0x7f61c5fc5700] WARN - [FFMPEG] - No quality level set; using default (20).
Oct 10, 2019 21:37:03.361 [0x7f61c7a23700] ERROR - [Transcoder] [Parsed_inlineass_2 @ 0x1b6f380] fontselect: Using default font family: (Arial, 400, 0) -> /share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Fonts/DejaVuSans-Regular.ttf, 0, DejaVuSans
Oct 10, 2019 21:38:17.804 [0x7f61c540d700] WARN - Got a request to stop a transcode session without a session GUID (or with an invalid one).

So I guess run the test again, with debug mode on. If the CPU being bogged down is causing the transcoder to error about Parsed_inlineass_2 font problems, I can’t speak to that.

I never even saw any .ass subtitles, right? Crazy.
Okay I hope everyone is having a good day so far!

memanole · October 11, 2019, 2:39pm

Hi mate,

you were absolutely right! it was not enabled because…i was a dumbarse!

I will upload the logs in a few min

Many thanks for your help
MM

memanole · October 11, 2019, 2:45pm

Hi mate,

Re subtitle settings > it was set to Automatic so I changed it to ‘Only Image formats’
I restarted again the service & then run video for a few minutes and downloaded the attached logs. Hope this time will help.

Plex Media Server Logs_2019-10-11_15-42-33.zip (830.4 KB)

side note: I had this stuttering even though no subtitles were selected/played

Apologies for my late reply [damn work]

Thank you,
MM

nibbles · October 11, 2019, 4:23pm

Hey you did it
Really nice logs there, and plenty to go on.
Thanks for sticking with it.

Topic		Replies	Views
Lagging and buffering NAS & Devices server-qnap	30	1226	February 23, 2020
Continuous buffering and lag as of late NAS & Devices server-qnap , lg-webos	37	2072	January 19, 2020
Plex Buffering After Buying new QNAP NAS NAS & Devices server-qnap	22	1478	June 26, 2019
Buffering again! Desktops & Laptops server-linux	15	213	August 7, 2019
Severe Buffering since last update General Discussions	8	67	January 7, 2020

PMS on QNAP TVS951x - Buffering. all the time

Related topics