Plex issue 30s delay

From miki
Jump to navigation Jump to search

This is the detailed analysis on the 30s startup delay on Plex.

30s startup delay

Relevant issues:

  • Nvidia 7-2-3 know bug: Not a SHIELD bug: Plex takes 30 seconds to start a video on SMB V3 NAS. Workaround for now is configure NAS to SMB V1. (Root cause is opportunistic locking in the NAS, fix is to turn of opportunistic locking to avoid issues with concurrent users/plex accessing the same files multiple times).
  • Some comments I posted [1].
  • [2], [3].

Fix:

  • Disable SMB opportunistic lock on NAS.

Symptoms:

  • Symptom: when launching media, 30s (32 in fact) of spinning wheel before media shows up. During that time, dashboard doesn't show any connection.
  • Seems to occur only when doing Direct Stream on the Plex App on Shieldh TV Pro.
  • When transcoding (can be forced by disabling HDMI passthrough on Plex App), delay is only 8s on Shield TV Pro.
  • Can't reproduce this anymore. Audio passthrough disabled doesn't trigger transcode when using AC3 anymore (saw a quick update message before playing the media).
  • On Web browser, delay is ~2s, direct or not.
  • On Kodi addon, delay is ~2s.

Summary:

  • The symptoms depend on:
  • Whether media is local or remote (SMB).
Local media means media on Shield TV Pro filesystem when using the Shield Plex serer, and media located on NAS filesystem when using the NAS Plex server.
  • Whether media container is MKV or MP4.
The type of MP4 (standard or web optimize) does not matter here (with respect to delay, direct play decision, or VOBSUB support).
  • Whether using the Plex App or Kodi add-on.
  • Without delay means ~2s.
  • In general remote or local, MP4 or MKV, with or without VOBSUB are always direct played without delay.
  • The exceptions are:
  • On Plex app, Remote MKV are direct play with 30s delay, and MP4 + VOBSUB are transcoded (with bad quality).
Transcode reason is Direct Play was attempted but failed, fallen back to transcoding.
  • On Kodi add-on, Remote MKV are direct play with 20s delay, or sometimes fail to play.
  • In conclusion, if we favor direct play anyway, our best bet is to use the Kodi add-on with the NAS Plex server.
  • But this means overloading the NAS with an additional process.
  • Kodi app is less remote friendly than the Plex app.

Some tests:

  • Select movie.
  • Select version
  • Play from start.
  • When Direct Play, try both Shield as server, and Wolverine.
  • Shield App:
  • Dec 26, 2020 17:33
  • 1080p, 1.9Mbps: Interstellar 1080p H264 AAC stereo .MP4: Direct Play AV, 3s (+SRT subtitles)
  • SD, 1.7Mbps: Interstellar 480p H264 AC3 5.1 .MKV: '
  • SD, 1.5Mbps: Interstellar 480p H264 AAC 5.1 .MKV: '
  • SD, 1.4Mbps: Interstellar 480p H265 AC3 5.1 .MKV: '
  • Dec 26, 2020 17:36:35
  • Shield Kodi:
  • Note: on Kodi, even when there is a delay, the play request shows up immediately on the dashboard. Looking in the log, we don't see the same 30s delay between the Content-Length requests.
  • Dec 26, 2020 17:37:51
  • 1080p, 1.9Mbps: Interstellar 1080p H264 AAC stereo .MP4: Direct Play AV, 3s (+SRT subtitles)
  • Note that in the logs, we see transcode messages, even though it direct plays.
    Dec 26, 2020 19:11:35.247 [4977] DEBUG - [Transcode] MDE: Interstellar (2014): no direct play video profile exists for http/mp4/h264
    Dec 26, 2020 19:11:35.247 [4977] DEBUG - [Transcode] MDE: Interstellar (2014): no direct play video profile exists for http/mp4/h264/aac
    Dec 26, 2020 19:11:35.247 [4977] DEBUG - [Transcode] MDE: Interstellar (2014): transcoding selected subtitle stream
    Dec 26, 2020 19:11:35.247 [4977] DEBUG - [Transcode] MDE: Interstellar (2014): selected media 0 / 183
  • SD, 1.7Mbps: Interstellar 480p H264 AC3 5.1 .MKV: Direct Play AV, 20s (+SRT subtitles!)
  • SD, 1.5Mbps: Interstellar 480p H264 AAC 5.1 .MKV: Direct Play AV, 20s (+SRT subtitles!)
  • SD, 1.4Mbps: Interstellar 480p H265 AC3 5.1 .MKV: '
  • Dec 26, 2020 17:40:24
  • Shield App with Shield Server:
  • Start — Dec 26, 2020 21:24:34
  • Delay One Brave-H264-AAC2ch.mkv: DP 30s (same with VOBSUB)
  • Delay Two Brave-H264-AAC2ch-mp4weboptim.m4v: DP 2s (no VOBSUB available :-( )
  • Delay Three Brave-H264-AAC5.1ch.mkv: DP 30s (same with VOBSUB)
  • Delay Four Brave-H264-AAC5.1ch-mp4weboptim.m4v: DP 2s (no VOBSUB available :-( )
  • Delay Five Brave-H264-AC32ch.mkv: DP 30s (same with VOBSUB)
  • Delay Six Brave-H264-AC32ch-mp4weboptim.m4v: DP 2s (no VOBSUB available :-( )
  • Delay Seven Brave-H264-AC35.1chpassthrough.mkv: DP 30s (same with VOBSUB)
  • Delay Eight Brave-H264-AC35.1chpassthrough-mp4weboptim.m4v: DP 2s (no VOBSUB available :-( )
  • Delay Nine Brave-H264-AC35.1chrecoded.mkv: DP 30s (same with VOBSUB)
  • Delay Ten Brave-H264-AC35.1chrecoded-mp4weboptim.m4v: DP 1s (no VOBSUB available :-( )
  • End — Dec 26, 2020 21:32:52
  • DelayTwo One - Bad Teacher-AAC2ch.mkv: DP 30s (same with VOBSUB)
  • DelayTwo Two - Bad Teacher-AAC2ch-mp4weboptim.m4v: DP 2s, but if playing VOBSUB, transcode V (and bad quality) (transcode reason: Direct Play was attempted but failed, fallen back to transcoding)
  • DelayTwo Three - Bad Teacher-AAC5.1ch-mp4weboptim.m4v: DP 2s, but if playing VOBSUB, transcode V (and bad quality) (transcode reason: Direct Play was attempted but failed, fallen back to transcoding)
  • DelayThree One - Brave - H264-AACstereo-MP4.m4v: DP 2s (Standard MP4) But if playing VOBSUB, transcode V (and bad quality) (transcode reason: Direct Play was attempted but failed, fallen back to transcoding)!
  • DelayThree Two - Brave - H264-AC3passthrough-MP4.m4v: DP 2s (Standard MP4). But if playing VOBSUB, transcode V (and bad quality) (transcode reason: Direct Play was attempted but failed, fallen back to transcoding)!
  • Shield App with Shield Server, with local library:
  • Bad Teacher H264 AC3 5.1.mkv: DP 2s (same with VOBSUB)
  • Shield Kodi with Shield Server:
  • Start — Dec 26, 2020 21:38:41
  • Delay One Brave-H264-AAC2ch.mkv: DP 20s, but DP 2s with local media.
  • Delay Two Brave-H264-AAC2ch-mp4weboptim.m4v: DP 2s
  • Delay Three Brave-H264-AAC5.1ch.mkv: DP 20s, but doesnt play (goes into Playing Next screen), but DP 2s with local media.
We get the following errors. But we get the same when it works, except the curl_easy_perform one.
   Dec 26, 2020 21:42:28.038 [10513] Error — Error issuing curl_easy_perform(handle): 28
   Dec 26, 2020 21:42:30.098 [10358] Error — [Transcode] ClientProfileExtra: missing protocol parameter
   Dec 26, 2020 21:42:30.098 [10358] Warning — [Transcode] ClientProfileExtra: ignoring directive: append-transcode-target-audio-codec(type=videoProfile&context=streaming&audioCodec=ac3)
   Dec 26, 2020 21:42:30.099 [10358] Warning — [Transcode] TranscodeUniversalRequest: at least one profile extra directive could not be read
   Dec 26, 2020 21:42:51.601 [10633] Error — Unknown metadata type: folder
   Dec 26, 2020 21:42:51.693 [10634] Warning — SLOW QUERY: It took 210.000000 ms to retrieve 51 items.
  • Delay Four Brave-H264-AAC5.1ch-mp4weboptim.m4v: DP 2s
  • Delay Five Brave-H264-AC32ch.mkv: DP 20s, but doesnt play.
  • Delay Six Brave-H264-AC32ch-mp4weboptim.m4v: DP 2s
  • Delay Seven Brave-H264-AC35.1chpassthrough.mkv: DP 20s, but doesnt play.
  • Delay Eight Brave-H264-AC35.1chpassthrough-mp4weboptim.m4v: DP 2s
  • Delay Nine Brave-H264-AC35.1chrecoded.mkv: DP 20s, but doesnt play.
  • Delay Ten Brave-H264-AC35.1chrecoded-mp4weboptim.m4v: DP 2s
  • End — Dec 26, 2020 21:54:33
  • DelayTwo One - Bad Teacher-AAC2ch.mkv: DP 20s
  • DelayTwo Two - Bad Teacher-AAC2ch-mp4weboptim.m4v: DP 2s
  • DelayTwo Three - Bad Teacher-AAC5.1ch-mp4weboptim.m4v: DP 2s
  • DelayThree One - Brave - H264-AACstereo-MP4.m4v: DP 2s (MP4 but not web optimized). If playing VOBSUB, DP 2s also!
  • DelayThree Two - Brave - H264-AC3passthrough-MP4.m4v: DP 2s (MP4 but not web optimized). If playing VOBSUB, DP 2s also!
  • Shield App with Shield Server, with HDMI passthrough disabled:
  • ... This was our trick to trigger anymore when using AC3, but this doesn't work anymore.
  • Shield App with Synology Server:
  • End — Dec 26, 2020 23:09:xx
  • Delay One to Ten: Direct Play 2s delay. Same with VOBSUB.
  • End — Dec 26, 2020 23:11:45
  • DelayThree One - Brave - H264-AACstereo-MP4.m4v: DP 2s (MP4 but not web optimized) But if playing VOBSUB, Cannot play media (because transcode disabled)!
  • DelayThree Two - Brave - H264-AC3passthrough-MP4.m4v: DP 2s (MP4 but not web optimized). But if playing VOBSUB, Cannot play media (because transcode disabled)!
  • Shield Kodi with Synology Server:
  • Start — Dec 26, 2020 23:15:21
  • Delay One to Ten: Direct Play 2s delay. Same with VOBSUB.
  • End — Dec 26, 2020 23:18:35
  • DelayTwo One - Bad Teacher-AAC2ch.mkv: DP 2s (same with VOBSUB)
  • DelayTwo Two - Bad Teacher-AAC2ch-mp4weboptim.m4v: DP 2s (same with VOBSUB)
  • DelayTwo Three - Bad Teacher-AAC5.1ch-mp4weboptim.m4v: DP 2s (same with VOBSUB)
  • DelayThree One - Brave - H264-AACstereo-MP4.m4v: DP 2s (MP4 but not web optimized). If playing VOBSUB, DP 2s also!
  • DelayThree Two - Brave - H264-AC3passthrough-MP4.m4v: DP 2s (MP4 but not web optimized). If playing VOBSUB, DP 2s also!

Relevant logs analysis:

  • We get a Failed to stream media, client probably disconnected after 5505024 bytes: 104 - Connection reset by peer. Initially thought it was linked to 30s delay, but we get it everytimes.
49122:Dec 26, 2020 16:53:12.388 [22929] DEBUG - Auth: authenticated user 1 as m.xelp@immie.org
49123:Dec 26, 2020 16:53:12.388 [32247] DEBUG - Request: [192.168.1.88:42344 (Subnet)] GET /library/parts/12486/1608848836/file.mkv?autoAdjustQuality=0&hasMDE=1&location=lan&mediaBufferSize=74944 (8 live) TLS Signed-in Token (m.xelp@immie.org) (range: bytes=0-) 
49124:Dec 26, 2020 16:53:12.404 [32247] DEBUG - Content-Length of /storage/WOLVERINE/family/movie/_tests/Interstellar (2014) - x265.mkv is 1746637281 (of total: 1746637281).
49125:Dec 26, 2020 16:53:12.620 [22929] DEBUG - Auth: authenticated user 1 as m.xelp@immie.org
49126:Dec 26, 2020 16:53:12.620 [31709] DEBUG - Request: [192.168.1.88:42346 (Subnet)] GET /library/parts/12486/1608848836/file.mkv?autoAdjustQuality=0&hasMDE=1&location=lan&mediaBufferSize=74944 (9 live) TLS Signed-in Token (m.xelp@immie.org) (range: bytes=1746378705-) 
49127:Dec 26, 2020 16:53:12.626 [31709] DEBUG - Content-Length of /storage/WOLVERINE/family/movie/_tests/Interstellar (2014) - x265.mkv is 258576 (of total: 1746637281).
49128:Dec 26, 2020 16:53:42.665 [22929] DEBUG - Failed to stream media, client probably disconnected after 5505024 bytes: 104 - Connection reset by peer
49129:Dec 26, 2020 16:53:42.665 [22929] DEBUG - Completed after connection close: [192.168.1.88:42344] 206 GET /library/parts/12486/1608848836/file.mkv?autoAdjustQuality=0&hasMDE=1&location=lan&mediaBufferSize=74944 (7 live) TLS 30276ms 5505024 bytes (range: bytes=0-) 
49130:Dec 26, 2020 16:53:42.680 [22929] DEBUG - Completed: [192.168.1.88:42346] 206 GET /library/parts/12486/1608848836/file.mkv?autoAdjustQuality=0&hasMDE=1&location=lan&mediaBufferSize=74944 (7 live) TLS 30059ms 258576 bytes (range: bytes=1746378705-) 
49131:Dec 26, 2020 16:53:42.780 [22929] DEBUG - Auth: authenticated user 1 as m.xelp@immie.org
49132:Dec 26, 2020 16:53:42.781 [31709] DEBUG - Request: [192.168.1.88:42350 (Subnet)] GET /library/parts/12486/1608848836/file.mkv?autoAdjustQuality=0&hasMDE=1&location=lan&mediaBufferSize=74944 (7 live) TLS Signed-in Token (m.xelp@immie.org) (range: bytes=5006-) 
49133:Dec 26, 2020 16:53:42.795 [31709] DEBUG - Content-Length of /storage/WOLVERINE/family/movie/_tests/Interstellar (2014) - x265.mkv is 1746632275 (of total: 1746637281).
49134:Dec 26, 2020 16:53:43.252 [22929] DEBUG - Auth: authenticated user 1 as m.xelp@immie.org
49135:Dec 26, 2020 16:53:43.252 [31709] DEBUG - Request: [192.168.1.88:42352 (Subnet)] POST /playQueues?includeChapters=1&continuous=0&includeLoudnessRamps=1&repeat=0&extrasPrefixCount=0&type=video&shuffle=0&uri=server%3A%2F%2F315dbe1ac5eab4b3b25956e1907bba687927fecf%2Fcom.plexapp.plugins.library%2Flibrary%2Fmetadata%2F183&key=%2Flibrary%2Fmetadata%2F183 (7 live) TLS GZIP Signed-in Token (m.xelp@immie.org)
  • When on Kodi Add-on, we get this msg every 5s, even when no movie playing:
   Dec 26, 2020 17:39:52.399 [22928] DEBUG - Auth: authenticated user 1 as m.xelp@immie.org
   Dec 26, 2020 17:39:52.399 [2609] DEBUG - Request: [192.168.1.61:59608 (Subnet)] GET /statistics/bandwidth?timespan=6 (17 live) GZIP Signed-in Token (m.xelp@immie.org)
   Dec 26, 2020 17:39:52.411 [22928] DEBUG - Completed: [192.168.1.61:59608] 200 GET /statistics/bandwidth?timespan=6 (17 live) GZIP 12ms 1514 bytes (pipelined: 19)
  • When streaming ends, we get:
   Dec 26, 2020 21:57:29.759 [11396] DEBUG — Streaming Resource: Terminated session 0x29fdd71598:440ac09a-635c-4e98-971b-720a0905387e with reason Client stopped playback.

Relevant client log: 

   12-28 18:29:37.154  i: [FFmpeg] [INFO] [Cache] Opening source from https://192-168-1-88.ab962241bee7454183355a238f9372ef.plex.direct:32400/library
   /parts/12474/1608832489/file.mkv?autoAdjustQuality=0&hasMDE=1&location=lan&mediaBufferSize=74944&X-Plex-Client-Identifier=46693b1320189a6d-com-ple
   xapp-android&X-Plex-Client-Platform=Android&X-Plex-Device=SHIELD%20Android%20TV&X-Plex-DRM=widevine%3Avideo&X-Plex-Platform=Android&X-Plex-Platfor
   m-Version=9&X-Plex-Product=Plex%20for%20Android%20(TV)&X-Plex-Token=...UX5q&X-Plex-Version=8.11.0.22186.
   12-28 18:29:37.358  i: [FFmpeg] [INFO] [Cache] Cache is enabled, connecting cache context.
   12-28 18:29:37.470  i: [FFmpeg] [INFO] [Cache] Worker thread has been enabled and will start processing data.
   12-28 18:29:37.479  i: [FFmpeg] [INFO] [Cache] Source seek requested to 1725850017 bytes with 0 whence.
   12-28 18:29:37.480  i: [FFmpeg] [INFO] [Cache] Seek found to 1725850017 bytes.
   12-28 18:29:40.459  i: [HttpServer] /192.168.1.61:38690 - GET /logging
   12-28 18:30:07.725  i: [FFmpeg] [INFO] [Cache] Seek complete to 1725850017 bytes.
   12-28 18:30:07.725  i: [FFmpeg] [INFO] [Cache] Seek has returned with a response of 1725850017.
   12-28 18:30:07.735  i: [FFmpeg] [INFO] [Cache] Source seek requested to 7059 bytes with 0 whence.
   12-28 18:30:07.737  i: [FFmpeg] [INFO] [Cache] Seek found to 7059 bytes.
   12-28 18:30:07.868  i: [FFmpeg] [INFO] [Cache] Seek complete to 7059 bytes.
   12-28 18:30:07.869  i: [FFmpeg] [INFO] [Cache] Seek has returned with a response of 7059.

Relevant analysis:

  • When using MP4 (web optimized) container, there is no thumbnail when movie is not identified, but there is one when using .MKV container.
  • AC3/AAC loudness difference:
  • With HDMI passthrough, loudness is bigger for AC3 than for AAC. When HDMI passthrough is disabled, AC3 and AAC have same loudness, which is same as AAC with HDMI passthrough.
  • This doesn't occur with Kodi add-on (probably because no HDMI passthrough).

Some script I used to analyze the log: 

#! /bin/bash

transform_time()
{
    # sed -r 's/^(([a-zA-Z]+) ([0-9]+)+, ([0-9]+) ([0-9]+):([0-9]+):([0-9]+)\.[0-9]+)/\4 #\2# \3 \5 \6 \7 \1/;s/#Jan#/01/; s/#Feb#/02/; s/#Mar#/03/; s/#Apr#/04/; s/#May#/05/; s/#Jun#/06/; s/#Jul#/07/; s/#Aug#/08/; s/#Sep#/09/; s/#Oct#/10/; s/#Nov#/11/; s/#Dec#/12/'
    sed -r 's/^(([a-zA-Z]+) ([0-9]+)+, ([0-9]+) ([0-9]+):([0-9]+):([0-9]+)\.[0-9]+)/\4-#\2#-\3-\5-\6-\7 \1/;s/#Jan#/01/; s/#Feb#/02/; s/#Mar#/03/; s/#Apr#/04/; s/#May#/05/; s/#Jun#/06/; s/#Jul#/07/; s/#Aug#/08/; s/#Sep#/09/; s/#Oct#/10/; s/#Nov#/11/; s/#Dec#/12/'
}

# F="Plex Media Server.5.log" "Plex Media Server.4.log" "Plex Media Server.3.log" "Plex Media Server.2.log" "Plex Media Server.1.log" "Plex Media Server.log"
for f in "Plex Media Server.5.log" "Plex Media Server.4.log" "Plex Media Server.3.log" "Plex Media Server.2.log" "Plex Media Server.1.log" "Plex Media Server.log"; do
    [ -e $f ] || touch $f
done

HUGEDELAY=15   # Delay in second

# cat "$F" | transform_time | tail
cat "Plex Media Server.5.log" "Plex Media Server.4.log" "Plex Media Server.3.log" "Plex Media Server.2.log" "Plex Media Server.1.log" "Plex Media Server.log" | transform_time | awk -v huge_delay=$HUGEDELAY '
    BEGIN {last=-1}
    {
        t=$1;
        gsub(/-/," ",t);
        t=mktime(t);
        if ((last>-1) && ((t - last) >= huge_delay ))
            printf "##### Huge delay: %d #################################################\n",(t - last);
        last = t;
        $1="";
        gsub(/^ +/,"",$0);
        print $0
    }
'
# | grep -C 5 "Huge delay"
# Huge delay
# DEBUG - Calculated media file path for path
# DEBUG - Content-Length of /storage/WOLVERINE/family
# ./analyze_plex_log.sh | egrep -i "Huge delay|interstellar|\[Now\]|DEBUG - Content-Length of /storage/WOLVERINE/family|DEBUG - Failed to stream media" | less
Retrieved from "https://miki.immie.org/mediawiki/index.php?title=Plex_issue_30s_delay&oldid=12687"