Jump to content

Subtitle extraction is quick, but only begins ~2 minutes after playback start. Why?


elindred

Recommended Posts

elindred

HI all. New adopter of Emby here, and of home theatre software in general. I'm primarily using it to stream anime with English subtitles to my Chromecast gen 2. My Emby server is an old laptop for now while I'm still prototyping my setup.

 

My main media format is .mkv with included .ass subtitles. So far playback is smooth, but the subtitles don't display on screen until ~2 minutes after playback starts. My research tells me that subtitles are extracted on the fly and on slower machines the extraction can take a while, which explains the delay.

 

Looking into the logs, however, it seems that the actual subtitle extraction takes only a few seconds even with my laptop's low specs; the actual delay seems to be between when playback is first requested and when the extraction is first requested.

 

Here are some log lines trimmed from embyserver.txt. I've excluded all lines that don't contain either .mkv or .ass.

We can see that playback starts at 09:16:49.160, but the ffmpeg-subtitle_extract is only run at 09:19:03.115, ~2m14s later. Subtitle extraction is declared complete at 09:19:13.964, just over 10 seconds later and I could see subtitles on screen around that time.

2019-09-08 09:16:49.160 Info HttpServer: HTTP GET http://192.222.153.69:8096/emby/Videos/32/stream.mkv?Static=true&mediaSourceId=1d8a19831b8a46c97b5d1a7254abe754&deviceId=VmFsdGhhbmllbENhc3Q1. Host=192.222.153.69:8096, Connection=keep-alive, Origin=https://mediabrowser.github.io, Accept-Encoding=identity;q=1, *;q=0, User-Agent=Mozilla/5.0 (X11; Linux armv7l) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.100 Safari/537.36 CrKey/1.40.156414, Range=bytes=0-, chrome-proxy=frfr, Accept=*/*, Accept-Language=en-US,en;q=0.9, CAST-DEVICE-CAPABILITIES={"bluetooth_supported":true,"display_supported":true,"hi_res_audio_supported":false,"remote_control_input_supported":false,"touch_input_supported":false}
2019-09-08 09:16:49.494 Info HttpServer: HTTP GET http://192.222.153.69:8096/emby/Videos/32/stream.mkv?Static=true&mediaSourceId=1d8a19831b8a46c97b5d1a7254abe754&deviceId=VmFsdGhhbmllbENhc3Q1. Host=192.222.153.69:8096, Connection=keep-alive, Origin=https://mediabrowser.github.io, Accept-Encoding=identity;q=1, *;q=0, User-Agent=Mozilla/5.0 (X11; Linux armv7l) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.100 Safari/537.36 CrKey/1.40.156414, Range=bytes=401080320-, Accept=*/*, Accept-Language=en-US,en;q=0.9, CAST-DEVICE-CAPABILITIES={"bluetooth_supported":true,"display_supported":true,"hi_res_audio_supported":false,"remote_control_input_supported":false,"touch_input_supported":false}
2019-09-08 09:16:49.541 Info HttpServer: SocketException: http://192.222.153.69:8096/emby/Videos/32/stream.mkv?Static=true&mediaSourceId=1d8a19831b8a46c97b5d1a7254abe754&deviceId=VmFsdGhhbmllbENhc3Q1&api_key=da444c898e6542078ccd45706097d98f
2019-09-08 09:16:49.541 Info HttpServer: HTTP Response 206 to 192.168.50.1. Time: 381ms. http://192.222.153.69:8096/emby/Videos/32/stream.mkv?Static=true&mediaSourceId=1d8a19831b8a46c97b5d1a7254abe754&deviceId=VmFsdGhhbmllbENhc3Q1
2019-09-08 09:16:49.871 Info HttpServer: HTTP Response 206 to 192.168.50.1. Time: 376ms. http://192.222.153.69:8096/emby/Videos/32/stream.mkv?Static=true&mediaSourceId=1d8a19831b8a46c97b5d1a7254abe754&deviceId=VmFsdGhhbmllbENhc3Q1
2019-09-08 09:16:49.915 Info HttpServer: HTTP GET http://192.222.153.69:8096/emby/Videos/32/stream.mkv?Static=true&mediaSourceId=1d8a19831b8a46c97b5d1a7254abe754&deviceId=VmFsdGhhbmllbENhc3Q1. Host=192.222.153.69:8096, Connection=keep-alive, Origin=https://mediabrowser.github.io, Accept-Encoding=identity;q=1, *;q=0, User-Agent=Mozilla/5.0 (X11; Linux armv7l) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.100 Safari/537.36 CrKey/1.40.156414, Range=bytes=262144-, Accept=*/*, Accept-Language=en-US,en;q=0.9, CAST-DEVICE-CAPABILITIES={"bluetooth_supported":true,"display_supported":true,"hi_res_audio_supported":false,"remote_control_input_supported":false,"touch_input_supported":false}
2019-09-08 09:19:03.115 Info HttpServer: HTTP GET http://192.222.153.69:8096/emby/Videos/32/1d8a19831b8a46c97b5d1a7254abe754/Subtitles/2/0/Stream.ass. Host=192.222.153.69:8096, Connection=keep-alive, Origin=https://mediabrowser.github.io, User-Agent=Mozilla/5.0 (X11; Linux armv7l) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.100 Safari/537.36 CrKey/1.40.156414, Accept=*/*, Accept-Encoding=gzip, deflate, Accept-Language=en-US,en;q=0.9, CAST-DEVICE-CAPABILITIES={"bluetooth_supported":true,"display_supported":true,"hi_res_audio_supported":false,"remote_control_input_supported":false,"touch_input_supported":false}
2019-09-08 09:19:03.309 Info SubtitleEncoder: ProcessRun 'ffmpeg-subtitle_extract' Execute: /opt/emby-server/bin/ffmpeg -i file:"/videos/video.mkv" -map 0:2 -an -vn -c:s copy "/var/lib/emby/cache/subtitles/4/4793f25247aba87f1d646ef2e4b47c4e_637033947546526063_2_0_0_False.ass"
2019-09-08 09:19:13.964 Info SubtitleEncoder: ffmpeg subtitle extraction completed for file:"/videos/video.mkv" to /var/lib/emby/cache/subtitles/4/4793f25247aba87f1d646ef2e4b47c4e_637033947546526063_2_0_0_False.ass
2019-09-08 09:19:14.311 Info HttpServer: HTTP Response 200 to 192.168.50.1. Time: 11197ms. http://192.222.153.69:8096/emby/Videos/32/1d8a19831b8a46c97b5d1a7254abe754/Subtitles/2/0/Stream.ass
 

I can confirm that this extraction time is not exceptional; running the ffmpeg command manually (albeit using /usr/bin/ffmpeg rather than the emby-server version) yields similar results.

[root@[member="Localhost"] logs]# time /usr/bin/ffmpeg -i file:/videos/video.mkv -map 0:2 -an -vn -c:s copy /var/lib/emby/cache/subtitles/1/test.ass

[...]

real 0m8.209s
user 0m0.634s
sys 0m0.889s
[root@[member="Localhost"] logs]# 
 
 
My question is, is this 2m14s delay a bug which, if fixed, would let me start seeing subtitles with a delay of a few seconds rather than over 2 minutes?
If it's not a bug and some necessary work going on here is being impacted by poor performance, is it CPU related, I/O related or network related?
Edited by elindred
Link to comment
Share on other sites

elindred

Hi, thanks for the reply. The subtitle setting was already set to English (rather than 'none') prior to playback. So, while producing the output above I did not change any subtitle settings; my only interaction with the app interface was pressing the play button. After that the subtitles did appear on their own shortly after that last log line was logged.

 

Let me know if there's any more information I can provide.

Edited by elindred
Link to comment
Share on other sites

Hi again, checking in on this issue

 

If there's no answer to this question forthcoming, can someone at least indicate a workaround? Do I need a more powerful server? Or do I need to replace my Chromecast with something else? Hoping to have something to go on so I can work on this some more this weekend :)

Link to comment
Share on other sites

Hi, as a test, how does playing from your server machine directly compare? I mean playing locally in the web app without using Chromecast. Thanks.

Link to comment
Share on other sites

My server is too weak to act as its own client...

If I run a web client on a nearby computer the subtitles only take 20 seconds to load. Looking at the logs it seems it only waits 3 seconds to start subtitle extraction

 

Playback requested at 08:03:21

2019-09-13 08:03:21.748 Info App: ProcessRun 'StreamTranscode 81ea2d' Execute: /opt/emby-server/bin/ffmpeg -f matroska -noaccurate_seek -i file:"/videos/video.mkv" -threads 1 -map 0:0 -map 0:1 -sn -c:v:0 copy -bsf:v h264_mp4toannexb -copyts -vsync -1 -codec:a:0 copy -metadata:s:a:0 language=jpn -disposition:a:0 default -copypriorss:a:0 0 -f segment -max_delay 5000000 -avoid_negative_ts disabled -map_metadata -1 -map_chapters -1 -start_at_zero -segment_time 6  -individual_header_trailer 0 -break_non_keyframes 1 -segment_format mpegts -segment_write_temp 1 -segment_list_type m3u8 -segment_start_number 0 -segment_list "/var/lib/emby/transcoding-temp/30e98f31a8cbd253a940fb8ada9e2045.m3u8" -y "/var/lib/emby/transcoding-temp/30e98f31a8cbd253a940fb8ada9e2045%d.ts"
It seems to be looking for subtitles at 08:03:24.818? Extraction happens at 08:03:24.875, only 3 seconds after playback start. Video starts playing on screen.
2019-09-13 08:03:24.818 Info HttpServer: HTTP GET http://192.168.50.45:8096/emby/Videos/31/8c3481fc817eef0536091ac86430ccee/Subtitles/2/0/Stream.ass. Host=192.168.50.45:8096, Connection=keep-alive, User-Agent=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/75.0.3770.102 Safari/537.36 Vivaldi/2.6.1566.44, Accept=*/*, DNT=1, Referer=http://192.168.50.45:8096/web/bower_components/javascriptsubtitlesoctopus/dist/subtitles-octopus-worker.js, Accept-Encoding=gzip, deflate, Accept-Language=en-US,en;q=0.9, Cookie=ys-torrentGrid=o%3Acolumns%3Da%253Ao%25253Aid%25253Ds%2525253Aqueue%25255Ewidth%25253Dn%2525253A30%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Ds%2525253Aname%25255Ewidth%25253Dn%2525253A852%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A2%25255Ewidth%25253Dn%2525253A75%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A3%25255Ewidth%25253Dn%2525253A150%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A4%25255Ewidth%25253Dn%2525253A80%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A5%25255Ewidth%25253Dn%2525253A80%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A6%25255Ewidth%25253Dn%2525253A60%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A7%25255Ewidth%25253Dn%2525253A60%25255Ehidden%25253Db%2525253A1%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A8%25255Ewidth%25253Dn%2525253A60%25255Ehidden%25253Db%2525253A1%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A9%25255Ewidth%25253Dn%2525253A60%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A10%25255Ewidth%25253Dn%2525253A60%25255Ehidden%25253Db%2525253A1%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A11%25255Ewidth%25253Dn%2525253A80%25255Ehidden%25253Db%2525253A1%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A12%25255Ewidth%25253Dn%2525253A120%25255Ehidden%25253Db%2525253A1%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A13%25255Ewidth%25253Dn%2525253A120%25255Ehidden%25253Db%2525253A1%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A14%25255Ewidth%25253Dn%2525253A75%25255Ehidden%25253Db%2525253A1%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A15%25255Ewidth%25253Dn%2525253A75%25255Ehidden%25253Db%2525253A1%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A16%25255Ewidth%25253Dn%2525253A75%25255Ehidden%25253Db%2525253A1%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A17%25255Ewidth%25253Dn%2525253A75%25255Ehidden%25253Db%2525253A1%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A18%25255Ewidth%25253Dn%2525253A75%25255Ehidden%25253Db%2525253A1%25255Esortable%25253Db%2525253A1%255Eo%25253Aid%25253Dn%2525253A19%25255Ewidth%25253Dn%2525253A100; Jackett=CfDJ8NCtM11aVGZIiakVnKTOE1BgeNVXSEccvMT-hWwdiuQhbOFbLBGYUImkvxgbv4C6Jk5aAjG9x7OyDdZ3EDuWpN5eMF4ifZB__c7_52AjHBg_HolTw6tqs84WStBdRNKV-2hIG8S-xbNx7a7FXfPTnbaHzQhwFMfr_Ul1lAtB-J8EZVB8q0eq7gqAAkRu9ttNNJGDwpy2OMMRTqoFmSSUBEPAdM_lWmr4iBc6QOJEI0r-hrpgWY4yP3ryHGl77Y8Ba9gQjarXbJxMF8AFE0bZdHSjLz-ixdt0rwJrGrGqXV15ghXtBSivr6EPBvlfKR5fglaRCVXDJmAZzRQ-DK0m70Mf60
2019-09-13 08:03:24.875 Info SubtitleEncoder: ProcessRun 'ffmpeg-subtitle_extract' Execute: /opt/emby-server/bin/ffmpeg -i file:"/videos/video.mkv" -map 0:2 -an -vn -c:s copy "/var/lib/emby/cache/subtitles/c/c3345ce5146bb40142519b68024358a4_637033949638730664_2_0_0_False.ass" 
Extraction takes about 20 seconds. Subtitles appear at the 0:20 mark.
2019-09-13 08:03:44.067 Info SubtitleEncoder: ffmpeg subtitle extraction completed for file:"/videos/video.mkv" to /var/lib/emby/cache/subtitles/c/c3345ce5146bb40142519b68024358a4_637033949638730664_2_0_0_False.ass
2019-09-13 08:03:44.069 Info HttpServer: HTTP Response 200 to 192.168.50.71. Time: 19251ms. http://192.168.50.45:8096/emby/Videos/31/8c3481fc817eef0536091ac86430ccee/Subtitles/2/0/Stream.ass
I thought I attached the logs but looks like I forgot to press a button. Anyway, hope this helps. I'll upload them tonight if needed. Edited by elindred
Link to comment
Share on other sites

It takes about 50 seconds for ASS subtitles to start on my Chromecast Ultra, even if they're cached or external. They then flash by quickly until they're caught up with the video. Web playback on my phone doesn't exhibit this problem. I'm running server version 4.2.1.0 on Arch Linux.

Link to comment
Share on other sites

  • 2 weeks later...

Checking in on this. 

 

It takes about 50 seconds for ASS subtitles to start on my Chromecast Ultra, even if they're cached or external. They then flash by quickly until they're caught up with the video. Web playback on my phone doesn't exhibit this problem. I'm running server version 4.2.1.0 on Arch Linux.

Yes, I observe the exact same behaviour. It seems like the ASS + emby + chromecast setups is almost there, but not quite. It's kindof frustrating!

 

Is there really no useful information for this case? If someone can tell me that buying some other streaming device will fix my problems i'll buy it, of it my hardware needs to be upgraded or whatever.

Link to comment
Share on other sites

elindred

Hi Luke,

 

Yes, once the subtitles finish extracting, as chshrcat said the subtitles seem to 'fast forward' until it catches up with the current timestamp in the playback, and the subtitles play as normal.

Curiously, if you stop the video and play it again it seems to go through this whole process again, rather than using the previously extracted subtitles. The web player seems to be able to find previously extracted subtitles and display them without issue.

 

Thanks for your help.

Link to comment
Share on other sites

I actually don't think the problem is the extraction. The rendering library we use is quite large and also comes with a pretty large font file. It could just be taking a long time to load on Chromecast devices. I'll have to see what we can do there. Thanks.

Link to comment
Share on other sites

elindred

Thanks for looking into it. It seems from my logs, though, that the extraction only takes place long after playback is requested. Have I been mislead?

Link to comment
Share on other sites

Thanks for looking into it. It seems from my logs, though, that the extraction only takes place long after playback is requested. Have I been mislead?

 

Video starts playing first, then we load the subtitle rendering library, then that requests the subtitle url. I think the library is taking a while to load before it is able to actually download the subtitles.

Link to comment
Share on other sites

elindred

Video starts playing first, then we load the subtitle rendering library, then that requests the subtitle url. I think the library is taking a while to load before it is able to actually download the subtitles.

I believe you're heading down a different path...

In my case the ASS subtitles are embedded, and ffmpeg is being called to extract them. You can review my log snippets in the OP or the log files I attached a few posts later.

 

Hope this helps.

Link to comment
Share on other sites

raphaels880

Just for complement the information. I having the same problem with with animes episodes with the same behavior on chromecast playback, but my ASS subtitles are in external files to prevent ffmpeg extraction.

Link to comment
Share on other sites

I believe you're heading down a different path...

In my case the ASS subtitles are embedded, and ffmpeg is being called to extract them. You can review my log snippets in the OP or the log files I attached a few posts later.

 

Hope this helps.

 

No, we're on the same page. Thanks.

Link to comment
Share on other sites

  • 7 months later...
  • 4 weeks later...
elindred

I ended up buying a Roku. Subtitles render instantly, although it uses some pretty ugly open source fonts and poor customization options. I'd love to see this addressed for the chromecast as well.

Link to comment
Share on other sites

  • 2 weeks later...
  • 1 month later...
crippah

Got the same problem. Ended up using Synology Video Station which works flawlessly. Currently embedded ASS subtitles don't work for me. Tried setting up a server on my windows 10 PC with a Core i7-10700k, same problem. 

 

embyserver.txt

Edited by crippah
updated server logs
Link to comment
Share on other sites

  • 3 weeks later...
On 8/20/2020 at 11:35 AM, crippah said:

Got the same problem. Ended up using Synology Video Station which works flawlessly. Currently embedded ASS subtitles don't work for me. Tried setting up a server on my windows 10 PC with a Core i7-10700k, same problem. 

 

embyserver.txt 163.95 kB · 0 downloads

hi @crippah can you try with our online web app?

http://app.emby.media

How does that compare?

Link to comment
Share on other sites

On 9/9/2020 at 3:26 AM, Luke said:

hi @crippah can you try with our online web app?

http://app.emby.media

How does that compare?

Thank you for your response 😄,

When I play the video on http://app.emby.media in the browser, the subtitles start after about 5 - 10 seconds. I can't find the Chromecast when using the app.emby.media (It just shows Play On) but no chromecast to pick. When I start casting to the chromecast using my IP address or domain name from the NAS, subtitles are gone and it takes about 2 minutes and the video freezes or starts stuttering heavily during those 2 minutes. When I use DS video it works fine, seems DS video does something different with the subtitles to make it work.

Link to comment
Share on other sites

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now
×
×
  • Create New...