33% in loading pause

[davepompea 0]

Just like the problem in 

both my Hisense TV and Roku stick do not work, anymore. Used to work, but we only use them when away from home, as we now are. Randomly, some recorded content does play, but only after a 2-3 minute wait (at 33%).

The content is OTA TV from all the major stations. They are recorded with SiliconDust HD Homerun with a Windows Media Center 7 computer. Emby is on a Windows 10 computer, thus the content is drive mapped into it.

 

Playing locally, on the Emby Server computer, using Emby in Chrome, does work 100%. Also, any non-OTA content starts/plays 100% fine remotely. It's only the OTA recordings that don't.

Emby 33pct logs.zip

[Gilgamesh_48 944]

By reaching 33% Emby is just saying it is in the first stages of loading. It really has no relationship to what is actually happening.
The other numbers you might see are also just pretty much random as well except the larger numbers to indicate "stages," sort of.
What is happening is that for some reason the requested content is not accessible. It could be that its relative location has changed or that the user running the server does not have rights to access the content.

[speechles 1920]

The 33% actually means that something in the "Format Detection" (remember those words) is failing. The "Format Detection" is actually a component of the Roku video player. It reads the header and determines whether the Roku can play it or not. If it cannot it should refuse to play and throw an error. But sometimes ffmpeg is slow or the Roku becomes confused. An error isn't thrown and instead you wind up in buffering hell.

You should become concerned if you ever see it hang at 33% that means it may never continue past that. There is a problem the Roku cannot understand. Something is causing the media to be presented in such a way that it is unplayable. Either the file itself has some kind of header the Roku cannot parse or ffmpeg is encountering some problem and the Roku is along for the ride.

Sometimes (as far as Roku is concerned) this is caused by embedded subtitles.

 

Extract from the ZIP of your logs the file ffmpeg-transcode-f0e2c5a0-1fd3-4e83-befb-2d4956dfff7b_1.txt and look inside.
In checking (open the spoiler below) it is indeed the subtitles that are causing your issue.

Spoiler

14:01:06.738 ffmpeg version 5.0.0-emby_2022_05_27-u1 Copyright (c) 2000-2022 the FFmpeg developers and softworkz for Emby LLC
14:01:06.739   built with gcc 10.3.0 (Rev5, Built by MSYS2 project)
14:01:06.739 Execution Date: 2022-11-28 14:01:06
14:01:06.780 [mpeg2video @ 000001e7ed951b40] Invalid frame dimensions 0x0.
    Last message repeated 13 times
14:01:06.796 Input #0, wtv, from '\\W7MCE-PC\E\Recorded TV\PBS NewsHour_WXXIDT_2022_11_25_19_00_05.wtv':
14:01:06.796   Metadata:
14:01:06.796     WM/MediaClassPrimaryID: db9830bd-3ab3-4fab-8a371a995f7ff74
14:01:06.796     WM/MediaClassSecondaryID: ba7f258a-62f7-47a9-b21f4651c42a000
14:01:06.796     Title           : PBS NewsHour
14:01:06.796     WM/SubTitle     : PBS NewsHour
14:01:06.797     WM/SubTitleDescription: Journalists report on the news of the day.
14:01:06.797     genre           : News;Uncategorized
14:01:06.797     WM/OriginalReleaseTime: 0
14:01:06.797     WM/MediaCredits : ;;Judy Woodruff;
14:01:06.797     service_provider: WXXIDT
14:01:06.797     service_name    : WXXIDT (WXXI-DT)
14:01:06.797     WM/MediaNetworkAffiliation: PBS
14:01:06.797     WM/MediaOriginalChannel: 21
14:01:06.797     WM/MediaOriginalChannelSubNumber: 1
14:01:06.797     WM/MediaOriginalBroadcastDateTime: 2022-11-25T05:00:00Z
14:01:06.797     WM/MediaOriginalRunTime: 37134711094
14:01:06.797     WM/MediaIsStereo: true
14:01:06.797     WM/MediaIsRepeat: false
14:01:06.797     WM/MediaIsLive  : false
14:01:06.797     WM/MediaIsTape  : false
14:01:06.797     WM/MediaIsDelay : false
14:01:06.797     WM/MediaIsSubtitled: false
14:01:06.797     WM/MediaIsMovie : false
14:01:06.797     WM/MediaIsPremiere: false
14:01:06.797     WM/MediaIsFinale: false
14:01:06.797     WM/MediaIsSAP   : false
14:01:06.797     WM/MediaIsSport : false
14:01:06.797     WM/Provider     : MediaCenterDefault
14:01:06.797     WM/VideoClosedCaptioning: true
14:01:06.797     WM/WMRVEncodeTime: 2022-11-26 00:00:06
14:01:06.797     WM/WMRVSeriesUID: !Series!01196307
14:01:06.797     WM/WMRVServiceID: !Service!EPG123_34355
14:01:06.797     WM/WMRVProgramID: !Program!EP01196307_3388
14:01:06.797     WM/WMRVRequestID: 0
14:01:06.797     WM/WMRVScheduleItemID: 0
14:01:06.797     WM/WMRVQuality  : 3
14:01:06.797     WM/WMRVOriginalSoftPrePadding: 420
14:01:06.797     WM/WMRVOriginalSoftPostPadding: 120
14:01:06.797     WM/WMRVHardPrePadding: 4294966996
14:01:06.797     WM/WMRVHardPostPadding: 0
14:01:06.797     WM/WMRVATSCContent: true
14:01:06.797     WM/WMRVDTVContent: true
14:01:06.797     WM/WMRVHDContent: true
14:01:06.797     Duration        : 37138271485
14:01:06.797     WM/WMRVEndTime  : 2022-11-26 01:02:00
14:01:06.797     WM/WMRVBitrate  : 7.908449
14:01:06.797     WM/WMRVKeepUntil: 4294967295
14:01:06.797     WM/WMRVActualSoftPrePadding: 293
14:01:06.797     WM/WMRVActualSoftPostPadding: 120
14:01:06.797     WM/WMRVContentProtected: false
14:01:06.797     WM/WMRVContentProtectedPercent: 0
14:01:06.797     WM/WMRVExpirationSpan: 9223372036854775807
14:01:06.797     WM/WMRVInBandRatingSystem: 255
14:01:06.797     WM/WMRVInBandRatingLevel: 255
14:01:06.797     WM/WMRVInBandRatingAttributes: 0
14:01:06.797     WM/WMRVWatched  : false
14:01:06.797     WM/MediaThumbWidth: 352
14:01:06.797     WM/MediaThumbHeight: 198
14:01:06.797     WM/MediaThumbStride: 1056
14:01:06.797     WM/MediaThumbRet: 0
14:01:06.797     WM/MediaThumbRatingSystem: 255
14:01:06.797     WM/MediaThumbRatingLevel: 255
14:01:06.797     WM/MediaThumbRatingAttributes: 0
14:01:06.797     WM/MediaThumbAspectRatioX: 16
14:01:06.798     WM/MediaThumbAspectRatioY: 9
14:01:06.798     WM/MediaThumbTimeStamp: 4645906563900967276
14:01:06.798   Duration: 01:01:52.74, start: 1.801129, bitrate: 7910 kb/s
14:01:06.798   Stream #0:0[0x314](eng): Audio: ac3, 48000 Hz, stereo, fltp, 384 kb/s, Start-Time 1.801s
14:01:06.798   Stream #0:1[0x315](spa): Audio: ac3, 48000 Hz, stereo, fltp, 192 kb/s, Start-Time 1.961s
14:01:06.798   Stream #0:2[0x316](fre): Audio: ac3, 48000 Hz, stereo, fltp, 128 kb/s, Start-Time 1.961s
14:01:06.798   Stream #0:3[0x317]: Video: mpeg2video (Main), yuv420p(tv, bt709, top first), 1920x1080 [SAR 1:1 DAR 16:9], Closed Captions, Level 4, 29.97 fps, 29.97 tbr, 10000k tbn, Start-Time 3.053s
14:01:06.798     Side data:
14:01:06.798       cpb: bitrate max/min/avg: 64000000/0/0 buffer size: 9781248 vbv_delay: N/A
14:01:06.798   Stream #0:4[0x318]: Subtitle: eia_608, Start-Time 2.920s
14:01:06.800 Output #1, segment, to 'C:\Users\dave\AppData\Roaming\Emby-Server\programdata\transcoding-temp\0791B2\0791B2_s100_%d.vtt':
14:01:06.800   Metadata:
14:01:06.800     encoder         : Lavf59.17.100
14:01:06.800   Stream #1:0: Subtitle: webvtt, 1920x1080
14:01:06.800     Metadata:
14:01:06.800       encoder         : Lavc59.21.100 webvtt
14:01:06.801   Stream #1:1: Video: mpeg2video (Main), yuv420p(tv, bt709, top first), 1920x1080 [SAR 1:1 DAR 16:9], q=2-31, Level 4, 29.97 fps, 29.97 tbr, 29.97 tbn
14:01:06.801     Side data:
14:01:06.801       cpb: bitrate max/min/avg: 64000000/0/0 buffer size: 9781248 vbv_delay: N/A
14:01:06.801 Output #2, segment, to 'C:\Users\dave\AppData\Roaming\Emby-Server\programdata\transcoding-temp\0791B2\0791B2_s4_%d.vtt':
14:01:06.801   Metadata:
14:01:06.801     encoder         : Lavf59.17.100
14:01:06.801   Stream #2:0: Subtitle: webvtt
14:01:06.801     Metadata:
14:01:06.801       encoder         : Lavc59.21.100 webvtt
14:01:06.801   Stream #2:1: Video: mpeg2video (Main), yuv420p(tv, bt709, top first), 1920x1080 [SAR 1:1 DAR 16:9], q=2-31, Level 4, 29.97 fps, 29.97 tbr, 29.97 tbn
14:01:06.801     Side data:
14:01:06.801       cpb: bitrate max/min/avg: 64000000/0/0 buffer size: 9781248 vbv_delay: N/A
14:01:06.801 Stream mapping:
14:01:06.801   Stream #0:3 (mpeg2video) -> splitcc:default
14:01:06.801   scale:default -> Stream #0:0 (libx264)
14:01:06.801   Stream #0:0 -> #0:1 (copy)
14:01:06.801   splitcc -> Stream #1:0 (webvtt)
14:01:06.801   Stream #0:3 -> #1:1 (copy)
14:01:06.802   Stream #0:4 -> #2:0 (eia_608 (cc_dec) -> webvtt (native))
14:01:06.802   Stream #0:3 -> #2:1 (copy)
14:01:06.802 Press [q] to stop, [?] for help

 

 

14:01:06.838 [libx264 @ 000001e7ed954bc0] using SAR=1/1
14:01:06.839 [libx264 @ 000001e7ed954bc0] using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2
14:01:06.842 [libx264 @ 000001e7ed954bc0] profile High, level 3.0, 4:2:0, 8-bit
14:01:06.842 [libx264 @ 000001e7ed954bc0] 264 - core 159 r2991 1771b55 - H.264/MPEG-4 AVC codec - Copyleft 2003-2019 - http://www.videolan.org/x264.html - options: cabac=1 ref=1 deblock=1:0:0 analyse=0x3:0 me=hex subme=0 psy=1 psy_rd=1.00:0.00 mixed_ref=0 me_range=4 chroma_me=1 trellis=0 8x8dct=1 cqm=0 deadzone=21,11 fast_pskip=1 chroma_qp_offset=0 threads=6 lookahead_threads=1 sliced_threads=0 nr=0 decimate=1 interlaced=0 bluray_compat=0 constrained_intra=0 bframes=3 b_pyramid=2 b_adapt=1 b_bias=0 direct=1 weightb=1 open_gop=0 weightp=1 keyint=90 keyint_min=46 scenecut=0 intra_refresh=0 rc_lookahead=10 rc=crf mbtree=1 crf=23.0 qcomp=0.60 qpmin=0 qpmax=69 qpstep=4 vbv_maxrate=575 vbv_bufsize=1151 crf_max=0.0 nal_hrd=none filler=0 ip_ratio=1.40 aq=1:1.00
14:01:06.842 Output #0, segment, to 'C:\Users\dave\AppData\Roaming\Emby-Server\programdata\transcoding-temp\0791B2\0791B2_%d.ts':
14:01:06.842   Metadata:
14:01:06.842     encoder         : Lavf59.17.100
14:01:06.842   Stream #0:0: Video: h264, yuv420p(tv, bt709, progressive), 640x360 [SAR 1:1 DAR 16:9], q=2-31, 29.97 fps, 90k tbn
14:01:06.842     Metadata:
14:01:06.842       encoder         : Lavc59.21.100 libx264
14:01:06.842     Side data:
14:01:06.842       cpb: bitrate max/min/avg: 575000/0/0 buffer size: 1151000 vbv_delay: N/A
14:01:06.842   Stream #0:1(eng): Audio: ac3, 48000 Hz, stereo, fltp, 384 kb/s (default)
14:01:06.843 elapsed=00:00:00.02 frame=    1 fps=0.0 q=0.0 q=-1.0 q=-1.0 size=N/A time=00:00:00.77 bitrate=N/A throttle=off speed=38.4x    
14:01:06.856 Ignoring repeated subtitle frame
    Last message repeated 144830 times
14:01:07.322 elapsed=00:00:00.52 frame=    2 fps=0.0 q=0.0 q=-1.0 q=-1.0 size=N/A time=00:00:00.80 bitrate=N/A throttle=off speed=1.55x    
14:01:07.322 Ignoring repeated subtitle frame
    Last message repeated 140676 times
14:01:07.822 elapsed=00:00:01.02 frame=    2 fps=2.0 q=0.0 q=-1.0 q=-1.0 size=N/A time=00:00:00.80 bitrate=N/A throttle=off speed=0.791x    
14:01:07.822 Ignoring repeated subtitle frame
    Last message repeated 144805 times
14:01:08.322 elapsed=00:00:01.52 frame=    3 fps=2.0 q=0.0 q=-1.0 q=-1.0 size=N/A time=00:00:00.84 bitrate=N/A throttle=off speed=0.553x    
14:01:08.322 Ignoring repeated subtitle frame
    Last message repeated 173271 times
14:01:08.822 elapsed=00:00:02.02 frame=    3 fps=1.5 q=0.0 q=-1.0 q=-1.0 size=N/A time=00:00:00.84 bitrate=N/A throttle=off speed=0.416x    
14:01:08.822 Ignoring repeated subtitle frame
    Last message repeated 150939 times
14:01:09.322 elapsed=00:00:02.52 frame=    4 fps=1.6 q=0.0 q=-1.0 q=-1.0 size=N/A time=00:00:00.87 bitrate=N/A throttle=off speed=0.347x    
14:01:09.322 Ignoring repeated subtitle frame
    Last message repeated 138088 times
14:01:09.822 elapsed=00:00:03.02 frame=    4 fps=1.3 q=0.0 q=-1.0 q=-1.0 size=N/A time=00:00:00.87 bitrate=N/A throttle=off speed=0.289x    
14:01:09.822 Ignoring repeated subtitle frame
    Last message repeated 192292 times
14:01:10.322 elapsed=00:00:03.52 frame=    5 fps=1.4 q=0.0 q=-1.0 q=-1.0 size=N/A time=00:00:00.90 bitrate=N/A throttle=off speed=0.258x    
14:01:10.322 Ignoring repeated subtitle frame
>> ThrottleBySegmentRequest: RequestPosition: 00:00:00 - TranscodingPosition: 00:00:00 - ThrottleBuffer: 1s (Treshold: 120s)
>> ThrottleBySegmentRequest: RequestPosition: 00:00:00 - TranscodingPosition: 00:00:00 - ThrottleBuffer: 1s (Treshold: 120s)
    Last message repeated 160379 times
14:01:10.822 elapsed=00:00:04.02 frame=    5 fps=1.2 q=0.0 q=-1.0 q=-1.0 size=N/A time=00:00:00.90 bitrate=N/A throttle=off speed=0.226x    
14:01:10.822 Ignoring repeated subtitle frame
    Last message repeated 136342 times
14:01:11.322 elapsed=00:00:04.52 frame=    6 fps=1.3 q=0.0 q=-1.0 q=-1.0 size=N/A time=00:00:00.94 bitrate=N/A throttle=off speed=0.208x    
14:01:11.322 Ignoring repeated subtitle frame
    Last message repeated 138601 times
14:01:11.822 elapsed=00:00:05.02 frame=    6 fps=1.2 q=0.0 q=-1.0 q=-1.0 size=N/A time=00:00:00.94 bitrate=N/A throttle=off speed=0.187x    
14:01:11.822 Ignoring repeated subtitle frame
    Last message repeated 153450 times
14:01:12.322 elapsed=00:00:05.52 frame=    7 fps=1.3 q=0.0 q=-1.0 q=-1.0 size=N/A time=00:00:00.97 bitrate=N/A throttle=off speed=0.176x    
14:01:12.322 Ignoring repeated subtitle frame

As you can see here (in the spoiler shown above) the header has some some weird attributes at the top of the file to identify some things about the source material. Those might choke the Roku and are part of the header. I also see that the subtitles are not able to be parsed correctly. Ffmpeg is assuming they are repeats (since it cannot be read properly) and something is lagging the process at you can see the FPS is barely 1 frame per second.

This isn't really a Roku issue as the problem is coming from FFMPEG.

@softworkz any ideas why this is so slow? is it doing too much having so much heavy lifting by ffmpeg on their machine and overwhelms it? Well obviously. But being the brains in that area hoping you can reply. Thanks.

Edited November 28, 2022 by speechles

[softworkz 3339]

@davepompea

There might be an issue with accessing the storage on \\W7MCE-PC\E\  - the logs show lots of ffprobe errors.

But please also try to playback without subtitles selected.

[davepompea 0]

Ahh, that (subtitles) seems to be it. Recorded TV content subtitle setting, when starting to play, showed "Und (Default EIA_608)" The app setting for Subtitle Mode was "Default". What is "Default" I wonder? I changed the app Subtitle Mode setting to "No subtitles" and cleared saved tracks selections.

How / why the subtitle selection got set On is a mystery. 

Now Roku /  Hisense TV takes about 6 seconds to start (after "Play" button is pressed) and show 33%, 14 seconds at 33% and about 6 seconds after that on the next "%" before playback actually starts.

I'll take a look at some logs as it seems to me it should be quicker to detect and build the filter graph as some content I play back (non-ota tv) gets actually playing in as few as 5 seconds.

Thanks!

[speechles 1920]

The Roku STB/Sticks do not support EIA-608/708 inside MPEG2 and the documentation above is made for them.

The Roku TV actually supports EIA-608/708 inside MPEG2 streams too. But only because the Roku TV must natively support those subtitles from over the air broadcasts. We may be able to get EIA-608/708 working directly on Roku TV units without having to extract/sidecar.

Edited November 29, 2022 by speechles

[softworkz 3339]

Yes, Emby server tries to convert them to VTT, but this feature shouldn't have been added to 4.7 as it wasn't fully tested.
It should work with 4.8, though.

[softworkz 3339]

@davepompea - WTV containers are a special case, though would you be able to provide a short recording for testing?

 

[davepompea 0]

1 hour ago, softworkz said:

@davepompea - WTV containers are a special case, though would you be able to provide a short recording for testing?

 

Sure. What size clip would you like?

[softworkz 3339]

3 minutes would suffice. Just make sure that

• There are actually some closed captions in the segment
• The problem reproduces with the clip

Thanks!

[davepompea 0]

The odd thing is that the App Settings for subtitle was Default. I switched it to No Subtitles(as I mentioned) and then back to Default. Then each content before playing, would  show Off. Previously and unnoticed it would show On , as mentioned. 

Now when I set the app the Default subtitle, the before playing selection is now Off/none. Perhaps the Default app setting was not initialized correctly?

Even odder, now some (many?) content will play with subtitles. But not all.

In any event, here is clip to look at. It should have subtitles in them, I think. I had another but the max upload size here is 195Meg.

Test1_WHECDT_2022_11_29_11_40_00.wtv

[ebr 14927]

12 hours ago, davepompea said:

App Settings for subtitle was Default

Hi.  Try selecting "Smart".