Severe Buffering since last update

General Discussions
1

Hi

I have recently applied the PMS upgrade to by system which is running on an Intel based QNAP server, TS451 Pro. The problem is particularly troublesome when playing to either Chromecast or the Samsung Smart TV client.

AT THE MOMENT PMS IS BUFFERING SO MUCH IT IS NOT REALLY USABLE.

I have checked and replaced network cables, swapped out network switches. Other disgnostics on my LAN indicate that the LAN is operating properly.

This is all pointing to the PMS upgrade being the issue - all problems stem from then.

Please help, PMS is such a fantastic system, but right now it is broken.

Many thanks

2

I have done some further diagnostics. The culprit appears to be the Plex transcode process. This is sunning at between 40% and 90% on all four processor cores . Changing the settings on the Server for transcoder performance make little or do difference.

This is very different from when I first installed Plex Media Server on the same QNAP. Total processor utilisation then seldom topped 10%.

If any Plex Gurus can help I would appreciate this. My plex server is unusable in its present state.

3

@RickyCafe said:
I have done some further diagnostics. The culprit appears to be the Plex transcode process. This is sunning at between 40% and 90% on all four processor cores . Changing the settings on the Server for transcoder performance make little or do difference.

This is very different from when I first installed Plex Media Server on the same QNAP. Total processor utilisation then seldom topped 10%.

If any Plex Gurus can help I would appreciate this. My plex server is unusable in its present state.

Need logs.

4

@danjames92 said:

@RickyCafe said:
I have done some further diagnostics. The culprit appears to be the Plex transcode process. This is sunning at between 40% and 90% on all four processor cores . Changing the settings on the Server for transcoder performance make little or do difference.

This is very different from when I first installed Plex Media Server on the same QNAP. Total processor utilisation then seldom topped 10%.

If any Plex Gurus can help I would appreciate this. My plex server is unusable in its present state.

Need logs.

Dan, I have looked at the directory, there are a lot of log files in there as shown below. Which is the file that is needed here.

Many thanks

Mike

drwxr-xr-x 2 admin administ 12288 Aug 14 08:55 PMS Plugin Logs/
-rw-r–r-- 1 admin administ 0 May 18 2015 Plex DLNA Server Neptune.log
-rw-r–r-- 1 admin administ 0 May 18 2015 Plex DLNA Server Neptune.old.log
-rw-r–r-- 1 admin administ 15547 May 25 2015 Plex DLNA Server.log
-rw-r–r-- 1 admin administ 6079 May 18 2015 Plex DLNA Server.log.1
-rw-r–r-- 1 admin administ 72191 May 18 2015 Plex DLNA Server.log.2
-rw-r–r-- 1 admin administ 6081 Mar 9 2015 Plex DLNA Server.log.3
-rw-r–r-- 1 admin administ 6985 Mar 9 2015 Plex DLNA Server.log.4
-rw-r–r-- 1 admin administ 6948 Mar 8 2015 Plex DLNA Server.log.5
-rw-rw-rw- 1 admin administ 166611 Aug 14 04:03 Plex Media Scanner Analysis.1.log
-rw-rw-rw- 1 admin administ 131668 Aug 14 04:02 Plex Media Scanner Analysis.2.log
-rw-rw-rw- 1 admin administ 13898 Aug 13 04:46 Plex Media Scanner Analysis.3.log
-rw-rw-rw- 1 admin administ 17446 Aug 13 04:04 Plex Media Scanner Analysis.4.log
-rw-rw-rw- 1 admin administ 117241 Aug 13 04:03 Plex Media Scanner Analysis.5.log
-rw-rw-rw- 1 admin administ 102109 Aug 14 04:03 Plex Media Scanner Analysis.log
-rw-r–r-- 1 admin administ 9821 Apr 23 04:28 Plex Media Scanner Analysis.log.1
-rw-r–r-- 1 admin administ 9821 Apr 15 03:05 Plex Media Scanner Analysis.log.2
-rw-r–r-- 1 admin administ 9821 Apr 7 04:33 Plex Media Scanner Analysis.log.3
-rw-r–r-- 1 admin administ 9821 Mar 30 02:23 Plex Media Scanner Analysis.log.4
-rw-r–r-- 1 admin administ 9821 Mar 22 05:00 Plex Media Scanner Analysis.log.5
-rw-rw-rw- 1 admin administ 32857 Aug 14 04:28 Plex Media Scanner Chapter Thumbnails.1.log
-rw-rw-rw- 1 admin administ 4118 Aug 14 04:28 Plex Media Scanner Chapter Thumbnails.2.log
-rw-rw-rw- 1 admin administ 31935 Aug 14 04:28 Plex Media Scanner Chapter Thumbnails.3.log
-rw-rw-rw- 1 admin administ 4985 Aug 14 04:28 Plex Media Scanner Chapter Thumbnails.4.log
-rw-rw-rw- 1 admin administ 11956 Aug 14 04:28 Plex Media Scanner Chapter Thumbnails.5.log
-rw-rw-rw- 1 admin administ 7716 Aug 14 04:28 Plex Media Scanner Chapter Thumbnails.log
-rw-rw-rw- 1 admin administ 1745 Aug 14 04:04 Plex Media Scanner Deep Analysis.1.log
-rw-rw-rw- 1 admin administ 1423 Aug 14 04:04 Plex Media Scanner Deep Analysis.2.log
-rw-rw-rw- 1 admin administ 1507 Aug 14 04:04 Plex Media Scanner Deep Analysis.3.log
-rw-rw-rw- 1 admin administ 1723 Aug 14 04:04 Plex Media Scanner Deep Analysis.4.log
-rw-rw-rw- 1 admin administ 1480 Aug 14 04:04 Plex Media Scanner Deep Analysis.5.log
-rw-rw-rw- 1 admin administ 1780 Aug 14 04:04 Plex Media Scanner Deep Analysis.log
-rw-rw-rw- 1 admin administ 1375381 Aug 14 04:02 Plex Media Scanner.1.log
-rw-rw-rw- 1 admin administ 203094 Aug 14 04:02 Plex Media Scanner.2.log
-rw-rw-rw- 1 admin administ 243546 Aug 14 04:02 Plex Media Scanner.3.log
-rw-rw-rw- 1 admin administ 3118 Aug 14 04:02 Plex Media Scanner.4.log
-rw-rw-rw- 1 admin administ 4447 Aug 14 04:02 Plex Media Scanner.5.log
-rw-rw-rw- 1 admin administ 2610 Aug 14 04:02 Plex Media Scanner.log
-rw-rw-rw- 1 admin administ 2422 May 26 19:53 Plex Media Scanner.log.1
-rw-rw-rw- 1 admin administ 1226642 May 26 19:53 Plex Media Scanner.log.2
-rw-rw-rw- 1 admin administ 189621 May 26 19:53 Plex Media Scanner.log.3
-rw-rw-rw- 1 admin administ 214137 May 26 19:53 Plex Media Scanner.log.4
-rw-rw-rw- 1 admin administ 2920 May 26 19:53 Plex Media Scanner.log.5
-rw-rw-rw- 1 admin administ 5242890 Aug 14 15:54 Plex Media Server.1.log
-rw-rw-rw- 1 admin administ 5243006 Aug 14 15:20 Plex Media Server.2.log
-rw-r–r-- 1 admin administ 1138608 Aug 14 08:49 Plex Media Server.3.log
-rw-r–r-- 1 admin administ 5243077 Aug 14 08:39 Plex Media Server.4.log
-rw-rw-rw- 1 admin administ 3334239 Aug 14 07:59 Plex Media Server.5.log
-rw-rw-rw- 1 admin administ 317446 Aug 14 17:44 Plex Media Server.log
-rw-rw-rw- 1 admin administ 5242880 May 26 15:53 Plex Media Server.log.1
-rw-rw-rw- 1 admin administ 5243006 May 25 23:53 Plex Media Server.log.2
-rw-rw-rw- 1 admin administ 5242945 May 25 18:55 Plex Media Server.log.3
-rw-rw-rw- 1 admin administ 5243040 May 25 03:53 Plex Media Server.log.4
-rw-rw-rw- 1 admin administ 5243009 May 24 11:53 Plex Media Server.log.5

5

@RickyCafe said:

@danjames92 said:

@RickyCafe said:
I have done some further diagnostics. The culprit appears to be the Plex transcode process. This is sunning at between 40% and 90% on all four processor cores . Changing the settings on the Server for transcoder performance make little or do difference.

This is very different from when I first installed Plex Media Server on the same QNAP. Total processor utilisation then seldom topped 10%.

If any Plex Gurus can help I would appreciate this. My plex server is unusable in its present state.

Need logs.

Dan, I have looked at the directory, there are a lot of log files in there as shown below. Which is the file that is needed here.

Many thanks

Mike

drwxr-xr-x 2 admin administ 12288 Aug 14 08:55 PMS Plugin Logs/
-rw-r–r-- 1 admin administ 0 May 18 2015 Plex DLNA Server Neptune.log
-rw-r–r-- 1 admin administ 0 May 18 2015 Plex DLNA Server Neptune.old.log
-rw-r–r-- 1 admin administ 15547 May 25 2015 Plex DLNA Server.log
-rw-r–r-- 1 admin administ 6079 May 18 2015 Plex DLNA Server.log.1
-rw-r–r-- 1 admin administ 72191 May 18 2015 Plex DLNA Server.log.2
-rw-r–r-- 1 admin administ 6081 Mar 9 2015 Plex DLNA Server.log.3
-rw-r–r-- 1 admin administ 6985 Mar 9 2015 Plex DLNA Server.log.4
-rw-r–r-- 1 admin administ 6948 Mar 8 2015 Plex DLNA Server.log.5
-rw-rw-rw- 1 admin administ 166611 Aug 14 04:03 Plex Media Scanner Analysis.1.log
-rw-rw-rw- 1 admin administ 131668 Aug 14 04:02 Plex Media Scanner Analysis.2.log
-rw-rw-rw- 1 admin administ 13898 Aug 13 04:46 Plex Media Scanner Analysis.3.log
-rw-rw-rw- 1 admin administ 17446 Aug 13 04:04 Plex Media Scanner Analysis.4.log
-rw-rw-rw- 1 admin administ 117241 Aug 13 04:03 Plex Media Scanner Analysis.5.log
-rw-rw-rw- 1 admin administ 102109 Aug 14 04:03 Plex Media Scanner Analysis.log
-rw-r–r-- 1 admin administ 9821 Apr 23 04:28 Plex Media Scanner Analysis.log.1
-rw-r–r-- 1 admin administ 9821 Apr 15 03:05 Plex Media Scanner Analysis.log.2
-rw-r–r-- 1 admin administ 9821 Apr 7 04:33 Plex Media Scanner Analysis.log.3
-rw-r–r-- 1 admin administ 9821 Mar 30 02:23 Plex Media Scanner Analysis.log.4
-rw-r–r-- 1 admin administ 9821 Mar 22 05:00 Plex Media Scanner Analysis.log.5
-rw-rw-rw- 1 admin administ 32857 Aug 14 04:28 Plex Media Scanner Chapter Thumbnails.1.log
-rw-rw-rw- 1 admin administ 4118 Aug 14 04:28 Plex Media Scanner Chapter Thumbnails.2.log
-rw-rw-rw- 1 admin administ 31935 Aug 14 04:28 Plex Media Scanner Chapter Thumbnails.3.log
-rw-rw-rw- 1 admin administ 4985 Aug 14 04:28 Plex Media Scanner Chapter Thumbnails.4.log
-rw-rw-rw- 1 admin administ 11956 Aug 14 04:28 Plex Media Scanner Chapter Thumbnails.5.log
-rw-rw-rw- 1 admin administ 7716 Aug 14 04:28 Plex Media Scanner Chapter Thumbnails.log
-rw-rw-rw- 1 admin administ 1745 Aug 14 04:04 Plex Media Scanner Deep Analysis.1.log
-rw-rw-rw- 1 admin administ 1423 Aug 14 04:04 Plex Media Scanner Deep Analysis.2.log
-rw-rw-rw- 1 admin administ 1507 Aug 14 04:04 Plex Media Scanner Deep Analysis.3.log
-rw-rw-rw- 1 admin administ 1723 Aug 14 04:04 Plex Media Scanner Deep Analysis.4.log
-rw-rw-rw- 1 admin administ 1480 Aug 14 04:04 Plex Media Scanner Deep Analysis.5.log
-rw-rw-rw- 1 admin administ 1780 Aug 14 04:04 Plex Media Scanner Deep Analysis.log
-rw-rw-rw- 1 admin administ 1375381 Aug 14 04:02 Plex Media Scanner.1.log
-rw-rw-rw- 1 admin administ 203094 Aug 14 04:02 Plex Media Scanner.2.log
-rw-rw-rw- 1 admin administ 243546 Aug 14 04:02 Plex Media Scanner.3.log
-rw-rw-rw- 1 admin administ 3118 Aug 14 04:02 Plex Media Scanner.4.log
-rw-rw-rw- 1 admin administ 4447 Aug 14 04:02 Plex Media Scanner.5.log
-rw-rw-rw- 1 admin administ 2610 Aug 14 04:02 Plex Media Scanner.log
-rw-rw-rw- 1 admin administ 2422 May 26 19:53 Plex Media Scanner.log.1
-rw-rw-rw- 1 admin administ 1226642 May 26 19:53 Plex Media Scanner.log.2
-rw-rw-rw- 1 admin administ 189621 May 26 19:53 Plex Media Scanner.log.3
-rw-rw-rw- 1 admin administ 214137 May 26 19:53 Plex Media Scanner.log.4
-rw-rw-rw- 1 admin administ 2920 May 26 19:53 Plex Media Scanner.log.5
-rw-rw-rw- 1 admin administ 5242890 Aug 14 15:54 Plex Media Server.1.log
-rw-rw-rw- 1 admin administ 5243006 Aug 14 15:20 Plex Media Server.2.log
-rw-r–r-- 1 admin administ 1138608 Aug 14 08:49 Plex Media Server.3.log
-rw-r–r-- 1 admin administ 5243077 Aug 14 08:39 Plex Media Server.4.log
-rw-rw-rw- 1 admin administ 3334239 Aug 14 07:59 Plex Media Server.5.log
-rw-rw-rw- 1 admin administ 317446 Aug 14 17:44 Plex Media Server.log
-rw-rw-rw- 1 admin administ 5242880 May 26 15:53 Plex Media Server.log.1
-rw-rw-rw- 1 admin administ 5243006 May 25 23:53 Plex Media Server.log.2
-rw-rw-rw- 1 admin administ 5242945 May 25 18:55 Plex Media Server.log.3
-rw-rw-rw- 1 admin administ 5243040 May 25 03:53 Plex Media Server.log.4
-rw-rw-rw- 1 admin administ 5243009 May 24 11:53 Plex Media Server.log.5

Best to clear the logs out, quit the server, start the server, enable verbose logging, attempt to replicate the issue by playing some content, then providing the Plex Media Server log covering the time of playback. We’ll have to wait for a ninja to chime in as I am inexperienced with diagnosing logs.

6

I’ve had the same problem. CPU usage was peaking at about 90 - 95% when transcode settings were set to “Make My CPU Hurt” This wasn’t the case on previous builds and I suspect something major changed in the transcode section of the software. I have since changed the transcode setting to Auto and everything seems to work as required. That said, I would like to go back to my original setting for local playback without the constant buffering issue.

7

Okay, I have cleared the logs, set verbose and restarted the server.

The new log is huge already (11706 lines), is there a way to attach the file to this post - I don’t see any ‘Upload file’ feature on here. I could always cut and paste the text. The following seems fairly typical of the file content

Aug 16, 2016 08:50:44.267 [0xf1e23b90] DEBUG - Auth: authenticated user 1 as RickyCafe
Aug 16, 2016 08:50:44.267 [0xf1e23b90] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Aug 16, 2016 08:50:44.268 [0xf1e23b90] DEBUG - Client [5ofa86ia395dn29] reporting timeline state playing, progress of 231018/11258000ms for guid=, ratingKey=18150 url=, key=/library/metadata/18150, containerKey=, metadataId=18150
Aug 16, 2016 08:50:44.278 [0xe7511b90] DEBUG - Request: [127.0.0.1:60869] PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.1&size=88392628&speed=0.4&remaining=25164 (34 live)
Aug 16, 2016 08:50:44.279 [0xe7511b90] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 16, 2016 08:50:44.279 [0xe7511b90] DEBUG - Auth: Came in with the master token, authorization succeeded.
Aug 16, 2016 08:50:44.280 [0xe7511b90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:44.281 [0xf2111b90] DEBUG - Completed: [127.0.0.1:60869] 206 PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.1&size=88392628&speed=0.4&remaining=25164 (34 live) 3ms 289 bytes
Aug 16, 2016 08:50:44.358 [0xf1e23b90] DEBUG - Play progress on 18150 ‘London 2012 Opening Ceremony - CD1’ - got played 231018 ms by account 1!
Aug 16, 2016 08:50:44.358 [0xf1e23b90] DEBUG - [Now] User is RickyCafe (ID: 1)
Aug 16, 2016 08:50:44.358 [0xf1e23b90] DEBUG - [Now] Device is Chromecast (Chromecast).
Aug 16, 2016 08:50:44.358 [0xf1e23b90] DEBUG - [Now] Profile is Chromecast
Aug 16, 2016 08:50:44.358 [0xf1e23b90] DEBUG - [Now] Updated play state for /library/metadata/18150.
Aug 16, 2016 08:50:44.359 [0xf1e23b90] DEBUG - Statistics: (5ofa86ia395dn29) Reporting active playback in state 0 of type 1 (scrobble: 0) for account 1
Aug 16, 2016 08:50:44.359 [0xf1e23b90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:44.361 [0xf23ffb90] DEBUG - Completed: [192.168.0.61:38056] 200 GET /:/timeline?ratingKey=18150&key=%2Flibrary%2Fmetadata%2F18150&state=playing&playQueueItemID=27687&time=231018&duration=11258000 (33 live) TLS GZIP 96ms 433 bytes
Aug 16, 2016 08:50:44.798 [0xea511b90] DEBUG - Request: [127.0.0.1:60871] PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.1&size=88516972&speed=0.6&remaining=22033 (34 live)
Aug 16, 2016 08:50:44.800 [0xea511b90] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 16, 2016 08:50:44.800 [0xea511b90] DEBUG - Auth: Came in with the master token, authorization succeeded.
Aug 16, 2016 08:50:44.801 [0xea511b90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:44.801 [0xf23ffb90] DEBUG - Completed: [127.0.0.1:60871] 206 PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.1&size=88516972&speed=0.6&remaining=22033 (33 live) 3ms 289 bytes
Aug 16, 2016 08:50:45.367 [0xe9959b90] DEBUG - Request: [127.0.0.1:60872] PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.1&size=88550161&speed=0.6&remaining=17121 (33 live)
Aug 16, 2016 08:50:45.368 [0xe9959b90] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 16, 2016 08:50:45.368 [0xe9959b90] DEBUG - Auth: Came in with the master token, authorization succeeded.
Aug 16, 2016 08:50:45.370 [0xe9959b90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:45.370 [0xf23ffb90] DEBUG - Completed: [127.0.0.1:60872] 206 PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.1&size=88550161&speed=0.6&remaining=17121 (33 live) 3ms 289 bytes
Aug 16, 2016 08:50:45.943 [0xe77ffb90] DEBUG - Request: [127.0.0.1:60873] PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=88638850&speed=0.7&remaining=16426 (34 live)
Aug 16, 2016 08:50:45.944 [0xe77ffb90] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 16, 2016 08:50:45.944 [0xe77ffb90] DEBUG - Auth: Came in with the master token, authorization succeeded.
Aug 16, 2016 08:50:45.946 [0xe77ffb90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:45.946 [0xf23ffb90] DEBUG - Completed: [127.0.0.1:60873] 206 PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=88638850&speed=0.7&remaining=16426 (34 live) 3ms 289 bytes
Aug 16, 2016 08:50:46.481 [0xe9f35b90] DEBUG - Request: [127.0.0.1:60874] PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=88679756&speed=0.4&remaining=21482 (35 live)
Aug 16, 2016 08:50:46.482 [0xe9f35b90] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 16, 2016 08:50:46.482 [0xe9f35b90] DEBUG - Auth: Came in with the master token, authorization succeeded.
Aug 16, 2016 08:50:46.484 [0xe9f35b90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:46.484 [0xf23ffb90] DEBUG - Completed: [127.0.0.1:60874] 206 PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=88679756&speed=0.4&remaining=21482 (35 live) 3ms 289 bytes
Aug 16, 2016 08:50:47.018 [0xe7511b90] DEBUG - Request: [127.0.0.1:60875] PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=88714925&speed=0.5&remaining=25032 (36 live)
Aug 16, 2016 08:50:47.019 [0xe7511b90] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 16, 2016 08:50:47.019 [0xe7511b90] DEBUG - Auth: Came in with the master token, authorization succeeded.
Aug 16, 2016 08:50:47.020 [0xe7511b90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:47.021 [0xf23ffb90] DEBUG - Completed: [127.0.0.1:60875] 206 PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=88714925&speed=0.5&remaining=25032 (36 live) 3ms 289 bytes
Aug 16, 2016 08:50:47.502 [0xf1e23b90] DEBUG - Request: [127.0.0.1:60876] PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=88805298&speed=0.5&remaining=22322 (36 live)
Aug 16, 2016 08:50:47.503 [0xf1e23b90] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 16, 2016 08:50:47.503 [0xf1e23b90] DEBUG - Auth: Came in with the master token, authorization succeeded.
Aug 16, 2016 08:50:47.504 [0xf1e23b90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:47.504 [0xf2111b90] DEBUG - Completed: [127.0.0.1:60876] 206 PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=88805298&speed=0.5&remaining=22322 (36 live) 2ms 289 bytes
Aug 16, 2016 08:50:47.681 [0xef3ffb90] DEBUG - Request: [192.168.0.61:38056] OPTIONS /:/timeline?ratingKey=18150&key=%2Flibrary%2Fmetadata%2F18150&state=playing&playQueueItemID=27687&time=234871&duration=11258000 (36 live) TLS GZIP
Aug 16, 2016 08:50:47.683 [0xf2111b90] DEBUG - Completed: [192.168.0.61:38056] 200 OPTIONS /:/timeline?ratingKey=18150&key=%2Flibrary%2Fmetadata%2F18150&state=playing&playQueueItemID=27687&time=234871&duration=11258000 (35 live) TLS GZIP 2ms 516 bytes (pipelined: 2)
Aug 16, 2016 08:50:47.704 [0xe77ffb90] DEBUG - Request: [192.168.0.61:38058] GET /:/timeline?ratingKey=18150&key=%2Flibrary%2Fmetadata%2F18150&state=playing&playQueueItemID=27687&time=234871&duration=11258000 (35 live) TLS GZIP
Aug 16, 2016 08:50:47.705 [0xe77ffb90] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx42c-4aec-a491-b5e6ff83ba36), enabling token-based authentication.
Aug 16, 2016 08:50:47.705 [0xe77ffb90] DEBUG - Auth: authenticated user 1 as RickyCafe
Aug 16, 2016 08:50:47.706 [0xe77ffb90] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Aug 16, 2016 08:50:47.707 [0xe77ffb90] DEBUG - Client [5ofa86ia395dn29] reporting timeline state playing, progress of 234871/11258000ms for guid=, ratingKey=18150 url=, key=/library/metadata/18150, containerKey=, metadataId=18150
Aug 16, 2016 08:50:47.758 [0xe77ffb90] DEBUG - Play progress on 18150 ‘London 2012 Opening Ceremony - CD1’ - got played 234871 ms by account 1!
Aug 16, 2016 08:50:47.758 [0xe77ffb90] DEBUG - [Now] User is RickyCafe (ID: 1)
Aug 16, 2016 08:50:47.758 [0xe77ffb90] DEBUG - [Now] Device is Chromecast (Chromecast).
Aug 16, 2016 08:50:47.758 [0xe77ffb90] DEBUG - [Now] Profile is Chromecast
Aug 16, 2016 08:50:47.760 [0xe77ffb90] DEBUG - [Now] Updated play state for /library/metadata/18150.
Aug 16, 2016 08:50:47.760 [0xe77ffb90] DEBUG - Statistics: (5ofa86ia395dn29) Reporting active playback in state 0 of type 1 (scrobble: 0) for account 1
Aug 16, 2016 08:50:47.761 [0xe77ffb90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:47.763 [0xf23ffb90] DEBUG - Completed: [192.168.0.61:38058] 200 GET /:/timeline?ratingKey=18150&key=%2Flibrary%2Fmetadata%2F18150&state=playing&playQueueItemID=27687&time=234871&duration=11258000 (35 live) TLS GZIP 59ms 433 bytes
Aug 16, 2016 08:50:47.951 [0xe9f35b90] DEBUG - Request: [127.0.0.1:60877] PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=88896302&speed=0.5&remaining=22621 (34 live)
Aug 16, 2016 08:50:47.952 [0xe9f35b90] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 16, 2016 08:50:47.952 [0xe9f35b90] DEBUG - Auth: Came in with the master token, authorization succeeded.
Aug 16, 2016 08:50:47.953 [0xe9f35b90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:47.955 [0xf2111b90] DEBUG - Completed: [127.0.0.1:60877] 206 PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=88896302&speed=0.5&remaining=22621 (34 live) 4ms 289 bytes
Aug 16, 2016 08:50:48.558 [0xe7511b90] DEBUG - Request: [127.0.0.1:60878] PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=88933118&speed=0.5&remaining=23456 (34 live)
Aug 16, 2016 08:50:48.559 [0xe7511b90] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 16, 2016 08:50:48.559 [0xe7511b90] DEBUG - Auth: Came in with the master token, authorization succeeded.
Aug 16, 2016 08:50:48.560 [0xe7511b90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:48.561 [0xf23ffb90] DEBUG - Completed: [127.0.0.1:60878] 206 PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=88933118&speed=0.5&remaining=23456 (34 live) 3ms 289 bytes
Aug 16, 2016 08:50:49.051 [0xf1e23b90] DEBUG - Request: [127.0.0.1:60884] PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=88982873&speed=0.4&remaining=26033 (35 live)
Aug 16, 2016 08:50:49.052 [0xf1e23b90] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 16, 2016 08:50:49.053 [0xf1e23b90] DEBUG - Auth: Came in with the master token, authorization succeeded.
Aug 16, 2016 08:50:49.054 [0xf1e23b90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:49.054 [0xf23ffb90] DEBUG - Completed: [127.0.0.1:60884] 206 PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=88982873&speed=0.4&remaining=26033 (34 live) 3ms 289 bytes
Aug 16, 2016 08:50:49.134 [0xecd11b90] DEBUG - [CompanionProxy] player b7bdv45r74o was last refreshed 0 seconds ago
Aug 16, 2016 08:50:49.551 [0xef3ffb90] DEBUG - Request: [127.0.0.1:60886] PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=89068672&speed=0.4&remaining=29358 (34 live)
Aug 16, 2016 08:50:49.552 [0xef3ffb90] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 16, 2016 08:50:49.552 [0xef3ffb90] DEBUG - Auth: Came in with the master token, authorization succeeded.
Aug 16, 2016 08:50:49.553 [0xef3ffb90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:49.553 [0xf2111b90] DEBUG - Completed: [127.0.0.1:60886] 206 PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=89068672&speed=0.4&remaining=29358 (34 live) 3ms 289 bytes
Aug 16, 2016 08:50:50.102 [0xea511b90] DEBUG - Request: [127.0.0.1:60887] PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=89172642&speed=0.5&remaining=26294 (35 live)
Aug 16, 2016 08:50:50.103 [0xea511b90] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 16, 2016 08:50:50.104 [0xea511b90] DEBUG - Auth: Came in with the master token, authorization succeeded.
Aug 16, 2016 08:50:50.105 [0xea511b90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:50.105 [0xf23ffb90] DEBUG - Completed: [127.0.0.1:60887] 206 PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=89172642&speed=0.5&remaining=26294 (35 live) 3ms 289 bytes
Aug 16, 2016 08:50:50.645 [0xe9959b90] DEBUG - Request: [127.0.0.1:60890] PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=89280042&speed=0.5&remaining=22861 (36 live)
Aug 16, 2016 08:50:50.647 [0xe9959b90] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 16, 2016 08:50:50.647 [0xe9959b90] DEBUG - Auth: Came in with the master token, authorization succeeded.
Aug 16, 2016 08:50:50.648 [0xe9959b90] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Aug 16, 2016 08:50:50.648 [0xf23ffb90] DEBUG - Completed: [127.0.0.1:60890] 206 PUT /video/:/transcode/session/dasvg70qpgyoaznu7o9vu6jemi/progress?progress=2.2&size=89280042&speed=0.5&remaining=22861 (36 live) 3ms 289 bytes

8

Problem solved. The log files verifies that the transcode process was not running fast enough. I have re-ripped the offending movies and removed all extraneous soundtracks and subtitles. I have also ripped to m4v format rather than mkv which, although slower to rip produces files that the QNAP can take in its stride.