Video transcoding fails due to subtitle extraction issues

[Mikoyan 6]

Hello again.

After moving to Docker/Kube cluster setup on linux, no video will play unless its direct play or burned in subtitles, and I don't know why.

2024-03-18 10:02:43.059 Debug SubtitleEncoder: ProcessRun 'ffmpeg-subtitle_extract' Started.
2024-03-18 10:02:43.202 Info Server: http/1.1 Response 200 to ‌‍‍<CLIENT>‌. Time: 210ms. GET http://‌‍‍host‌/emby/videos/1206/hls1/main/4.ts?PlaySessionId=2b2072cd4ac8403e9e856c7b37cf41da
2024-03-18 10:02:43.210 Info SubtitleEncoder: ProcessRun 'ffmpeg-subtitle_extract' Process exited with code 1 - Failed
2024-03-18 10:02:43.210 Error SubtitleEncoder: ffmpeg subtitle extraction failed for file:/mnt/media/<MEDIA> to /embycache/cache/temp/de57d6811be6478db02699b539c68a8a.ass
2024-03-18 10:02:43.210 Error SubtitleEncoder: ProcessRun 'ffmpeg-subtitle_extract' Output:

2024-03-18 10:02:43.210 Error SubtitleEncoder: ProcessRun 'ffmpeg-subtitle_extract' Error Output:
        ffmpeg version 5.1-emby_2023_06_25 Copyright (c) 2000-2022 the FFmpeg developers and softworkz for Emby LLC
          built with gcc 10.3.0 (crosstool-NG 1.25.0)
          libavutil      57. 28.100 / 57. 28.100
          libavcodec     59. 37.100 / 59. 37.100
          libavformat    59. 27.100 / 59. 27.100
          libavdevice    59.  7.100 / 59.  7.100
          libavfilter     8. 44.100 /  8. 44.100
          libswscale      6.  7.100 /  6.  7.100
          libswresample   4.  7.100 /  4.  7.100
          libpostproc    56.  6.100 / 56.  6.100
        Execution Date: 2024-03-18 10:02:43
        Splitting the commandline.
        Reading option '-loglevel' ... matched as option 'loglevel' (set logging level) with argument 'trace'.
        Reading option '+timing' ... matched as output url.
        Reading option '-y' ... matched as option 'y' (overwrite output files) with argument '1'.
        Reading option '-i' ... matched as input url with argument 'file:/mnt/media/<MEDIA>'.
        Reading option '-map' ... matched as option 'map' (set input stream mapping) with argument '0:2'.
        Reading option '-vn' ... matched as option 'vn' (disable video) with argument '1'.
        Reading option '-an' ... matched as option 'an' (disable audio) with argument '1'.
        Reading option '-c:s:0' ... matched as option 'c' (codec name) with argument 'copy'.
        Reading option '/embycache/cache/temp/de57d6811be6478db02699b539c68a8a.ass' ... matched as output url.
        Finished splitting the commandline.
        Parsing a group of options: global .
        Applying option loglevel (set logging level) with argument trace.
        Applying option y (overwrite output files) with argument 1.
        Successfully parsed a group of options.
        Parsing a group of options: input url file:/mnt/media/<MEDIA>.
        Successfully parsed a group of options.
        Opening an input file: file:/mnt/media/<MEDIA>.
        [NULL @ 0x2266200] Opening 'file:/mnt/medi
2024-03-18 10:02:43.210 Error App: Error getting subtitles
        *** Error Report ***
        Version: 4.9.0.11
        Command line: /system/EmbyServer.dll -programdata /config -ffdetect /bin/ffdetect -ffmpeg /bin/ffmpeg -ffprobe /bin/ffprobe -restartexitcode 3
        Operating system: Linux version 5.15.0-100-generic (buildd@lcy02-amd64-116) (gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, GNU ld (GNU Binutils for Ubuntu) 2.38) #110-Ubun
        Framework: .NET 8.0.0
        OS/Process: x64/x64
        Runtime: system/System.Private.CoreLib.dll
        Processor count: 32
        Data path: /config
        Application path: /system
        System.Exception: System.Exception: ffmpeg subtitle extraction failed for file:/mnt/media/<MEDIA> to /embycache/cache/temp/de57d6811be6478db02699b539c68a8a.ass
           at Emby.Server.MediaEncoding.Subtitles.SubtitleEncoder.ExtractTextSubtitleInternal(String inputPath, Boolean isAudio, String inputSubtitleCodec, MediaStream subtitleStream, SubtitleMediaTypes outputCodec, String outputPath, Nullable`1 startTime, Nullable`1 endTime, Boolean preserveOriginalTimestamps, CancellationToken cancellationToken)
           at Emby.Server.MediaEncoding.Subtitles.SubtitleEncoder.ExtractTextSubtitle(ReadOnlyMemory`1 inputPath, Boolean isAudio, String inputSubtitleCodec, MediaProtocol protocol, MediaStream subtitleStream, SubtitleMediaTypes outputCodec, String outputPath, Nullable`1 startTime, Nullable`1 endTime, Boolean preserveOriginalTimestamps, CancellationToken cancellationToken)
           at Emby.Server.MediaEncoding.Subtitles.SubtitleEncoder.GetReadableFile(String mediaPath, MediaProtocol mediaSourceProtocol, Boolean isAudio, IDictionary`2 requestHeaders, MediaStream subtitleStream, String outputFormat, Int64 startTimeTicks, Int64 endTimeTicks, Boolean preserveOriginalTimestamps, EncodingContext encodingContext, CancellationToken cancellationToken)
           at Emby.Server.MediaEncoding.Subtitles.SubtitleEncoder.GetSubtitles(String inputPath, MediaProtocol inputProtocol, Boolean isAudio, IDictionary`2 requestHeaders, MediaStream subtitleStream, String outputFormat, Int64 startTimeTicks, Int64 endTimeTicks, Boolean preserveOriginalTimestamps, EncodingContext encodingContext, CancellationToken cancellationToken)
           at Emby.Api.Subtitles.SubtitleService.GetSubtitles(GetSubtitle request, CancellationToken cancellationToken)
           at Emby.Api.Subtitles.SubtitleService.Get(GetSubtitle request)
        Source: Emby.Server.MediaEncoding
        TargetSite: Void MoveNext()

2024-03-18 10:02:43.211 Info Server: http/1.1 Response 200 to ‌‍‍<CLIENT>‌. Time: 154ms. GET http://‌‍‍host‌/emby/Videos/1206/51a78c474307cff05183a331bb07a020/Subtitles/2/0/Stream.ass?api_key=‌token‌
2024-03-18 10:02:43.228 Info Server: http/1.1 GET http://‌‍‍host‌/emby/videos/1206/hls1/main/5.ts?PlaySessionId=2b2072cd4ac8403e9e856c7b37cf41da. Accept=*/*, Host=‌‍‍host‌, User-Agent=Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:123.0) Gecko/20100101 Firefox/123.0, Accept-Encoding=gzip, deflate, Accept-Language=en-US,en;q=0.5, Referer=‌‍‍http://host/emby/web/index.html‌, X-Request-ID=b23f7285980677e5c143f137d99de1f4, X-Real-IP=‌‍‍<CLIENT>‌, X-Forwarded-For=‌‍‍<CLIENT>‌, X-Forwarded-Host=‌‍‍host‌, X-Forwarded-Port=80, X-Forwarded-Proto=http, X-Forwarded-Scheme=http, X-Scheme=http, DNT=1, Sec-GPC=1
2024-03-18 10:02:43.229 Debug SqliteItemRepository: GetitemById Episode 1206 /mnt/media/<MEDIA>
2024-03-18 10:02:43.387 Debug EncodingManager: Deleting temp folder /config/transcoding-temp/53D8D7
2024-03-18 10:02:43.438 Info Server: http/1.1 Response 200 to ‌‍‍<CLIENT>‌. Time: 210ms. GET http://‌‍‍host‌/emby/videos/1206/hls1/main/5.ts?PlaySessionId=2b2072cd4ac8403e9e856c7b37cf41da
2024-03-18 10:02:43.460 Debug Server: http/1.1 GET http://‌‍‍host‌/emby/Items/1206/ThumbnailSet?Width=400&X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox Windows&X-Emby-Device-Id=a1134406-cac1-491e-b02d-ad046069484d&X-Emby-Client-Version=4.9.0.11&X-Emby-Token=‌token‌&X-Emby-Language=en-us. UserAgent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:123.0) Gecko/20100101 Firefox/123.0
2024-03-18 10:02:43.463 Debug SqliteItemRepository: GetitemById Episode 1206 /mnt/media/<MEDIA>
2024-03-18 10:02:43.465 Debug Server: http/1.1 Response 200 to ‌‍‍<CLIENT>‌. Time: 5ms. GET http://‌‍‍host‌/emby/Items/1206/ThumbnailSet?Width=400&X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox Windows&X-Emby-Device-Id=a1134406-cac1-491e-b02d-ad046069484d&X-Emby-Client-Version=4.9.0.11&X-Emby-Token=‌token‌&X-Emby-Language=en-us

 

Subtitle extraction fails. I have tried changing the cache directory, nothing happens.

 

2024-03-18 10:06:43.941 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Execute: /bin/ffmpeg -y -v quiet -dump_attachment:5 "/config/metadata/SubtitleFonts/Roboto-MediumItalic.378412.ttf" -i "/mnt/media/<MEDIA>"
2024-03-18 10:06:43.942 Debug SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Started.
2024-03-18 10:06:44.104 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Process exited with code 1 - Failed
2024-03-18 10:06:44.104 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Execute: /bin/ffmpeg -y -v quiet -dump_attachment:6 "/config/metadata/SubtitleFonts/arial.892680.ttf" -i "/mnt/media/<MEDIA>"
2024-03-18 10:06:44.105 Debug SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Started.
2024-03-18 10:06:44.155 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Process exited with code 1 - Failed
2024-03-18 10:06:44.155 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Execute: /bin/ffmpeg -y -v quiet -dump_attachment:7 "/config/metadata/SubtitleFonts/arialbd.854584.ttf" -i "/mnt/media/<MEDIA>"
2024-03-18 10:06:44.156 Debug SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Started.
2024-03-18 10:06:44.206 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Process exited with code 1 - Failed
2024-03-18 10:06:44.206 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Execute: /bin/ffmpeg -y -v quiet -dump_attachment:8 "/config/metadata/SubtitleFonts/comic.240588.ttf" -i "/mnt/media/<MEDIA>"
2024-03-18 10:06:44.207 Debug SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Started.
2024-03-18 10:06:44.259 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Process exited with code 1 - Failed
2024-03-18 10:06:44.259 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Execute: /bin/ffmpeg -y -v quiet -dump_attachment:9 "/config/metadata/SubtitleFonts/comicbd.224404.ttf" -i "/mnt/media/<MEDIA>"
2024-03-18 10:06:44.260 Debug SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Started.
2024-03-18 10:06:44.311 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Process exited with code 1 - Failed
2024-03-18 10:06:44.311 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Execute: /bin/ffmpeg -y -v quiet -dump_attachment:10 "/config/metadata/SubtitleFonts/times.975228.ttf" -i "/mnt/media/<MEDIA>"
2024-03-18 10:06:44.311 Debug SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Started.
2024-03-18 10:06:44.361 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Process exited with code 1 - Failed
2024-03-18 10:06:44.361 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Execute: /bin/ffmpeg -y -v quiet -dump_attachment:11 "/config/metadata/SubtitleFonts/timesbd.980120.ttf" -i "/mnt/media/<MEDIA>"
2024-03-18 10:06:44.362 Debug SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Started.
2024-03-18 10:06:44.412 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Process exited with code 1 - Failed
2024-03-18 10:06:44.412 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Execute: /bin/ffmpeg -y -v quiet -dump_attachment:12 "/config/metadata/SubtitleFonts/trebuc.218432.ttf" -i "/mnt/media/<MEDIA>"
2024-03-18 10:06:44.413 Debug SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Started.
2024-03-18 10:06:44.463 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Process exited with code 1 - Failed
2024-03-18 10:06:44.463 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Execute: /bin/ffmpeg -y -v quiet -dump_attachment:13 "/config/metadata/SubtitleFonts/trebucbd.206776.ttf" -i "/mnt/media/<MEDIA>"
2024-03-18 10:06:44.463 Debug SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Started.
2024-03-18 10:06:44.515 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Process exited with code 1 - Failed
2024-03-18 10:06:44.515 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Execute: /bin/ffmpeg -y -v quiet -dump_attachment:14 "/config/metadata/SubtitleFonts/verdana.240456.ttf" -i "/mnt/media/<MEDIA>"
2024-03-18 10:06:44.516 Debug SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Started.
2024-03-18 10:06:44.566 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Process exited with code 1 - Failed
2024-03-18 10:06:44.566 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Execute: /bin/ffmpeg -y -v quiet -dump_attachment:15 "/config/metadata/SubtitleFonts/verdanab.208456.ttf" -i "/mnt/media/<MEDIA>"
2024-03-18 10:06:44.567 Debug SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Started.
2024-03-18 10:06:44.612 Info SubtitleFontsManager: ProcessRun 'SubtitleFontsManager' Process exited with code 1 - Failed
2024-03-18 10:06:44.627 Info SubtitleFontsManager: Extracted 12 font attachments in 00:00:00.6905154

It says the process exits with a failed? But I see the fonts present in the SubtitleFonts folder. Something doesn't add up.

Forcing burn in also does not work.
This makes Emby unusable for any application that does not employ direct play capabilities. Please assist.

[Mikoyan 6]

Small correction, after a reboot the subtitle extraction process succeeds sometimes, but fails whenever I disable subtitle extraction on the fly, and try to play media on the web client. When it fails, usually the transcode fails with error 137 and then emby lets me know that no compatible streams are available.

[jaycedk 382]

Dev's will need th full logs, not just your snips.

 

[rbjtech 4270]

has /embycache/cache/temp got write permissions ?

[Mikoyan 6]

4 hours ago, rbjtech said:

has /embycache/cache/temp got write permissions ?

Hello rbjtech,

This directory is created as an empty directory and mounted as part of the container initialization process, so it should be always writable by emby. the user emby is started with owns the directory and has rwx. The contents of this directory are populated by Emby as of writing this post so it is my understanding it has no issues writing into this directory, and subdirectories of /embycache/cache/.

/embycache/cache # ls -l
total 40
drwxr-xr-x    3 1001     1003          4096 Mar 18 10:23 anidb
drwxr-xr-x   15 1001     1003          4096 Mar 18 10:23 anidb-people
drwxr-xr-x    3 1001     1003          4096 Mar 18 10:23 fanart-tv
drwxr-xr-x    2 1001     1003          4096 Mar 18 10:15 ffmpeg
drwxr-xr-x    2 1001     1003          4096 Mar 18 10:24 httpclient
drwxr-xr-x    3 1001     1003          4096 Mar 18 10:00 images
drwxr-xr-x   10 1001     1003          4096 Mar 18 20:34 subtitles
drwxr-xr-x    2 1001     1003          4096 Mar 18 21:59 temp
drwxr-xr-x    6 1001     1003          4096 Mar 18 10:24 tmdb-tv
drwxr-xr-x    6 1001     1003          4096 Mar 18 10:24 tvdb
/embycache/cache # cd temp
/embycache/cache/temp # ls
073eb78f06f94cd29b7036694c6062f5.ass  3ad9a2be65e6480ea8ccf339a970865d.ass  47545df842d7407f9b6dbb9865cfe61d.ass  49da8ddd55364672abadd3145586010f.ass  99d4ba52bbba4e26be5702a83adb9d19.png
1ba081d14b964a36a235cf50855b0103.ass  429440c84b43483b9d09422c4a51f43e.ass  47a2f8e45ffb48a3b6ad50acdf9e9327.ass  54715a6caf904a4e97c5223b7dba93dd.ass  ad7ab1a3ca1c4c9ba29fb7c826d5072e.ass

 

[Mikoyan 6]

5 hours ago, jaycedk said:

Dev's will need th full logs, not just your snips.

 

Hello jaycedk,

Thank you for your input - I will post full copy of logs if asked to. Since I was doing a lot of back and forth in my previous attempts with multiple types of video, I figured the log would be very messy and thus wanted to snip the parts that seemed relevant/explained the error, which would quickly explain what was happening (perhaps not the entire context, which can be done in controlled testing environment).

[Mikoyan 6]

Forcing burn-in shows ffmpeg trying about 3 times, then eventually giving up. Error code 137 for each transcode attempt so is the Emby core process killing it? Burn-in succeeds for some videos while others do not so maybe there is something tripping up ffmpeg that is causing burn-in to fail.

I've tried this for ASS style subtitles and PGSSUB. Both do not render as burn-in, but when I tick on "subtitle extraction on the fly" then it seems the subtitles are extracted and sent to devices that are capable. Occasionally, Emby cancels the task and simply does not display subtitles, but playing the same video again after exiting yields subtitles. Forcing burn-in on subtitle format compatible devices just results in video playing through with no subtitles to be seen. On web UI this does not work, and stream either crashes or says no compatible streams available.

This behavior is not visible for my previous instance of Emby running on Windows Server. For media with ASS subtitles, I was able to clearly see that transcoding was occurring and subtitles were being burnt in. However, for PGSSUB I noticed that stats shows subtitles were being converted directly into video, with no subtitles to be seen for some, while others were rendering properly.

One other thing, when this command runs with ffmpeg log level at trace, it fails. I was confused until I ran it myself because the trace is truncated in logs.

/bin/ffmpeg -loglevel trace +timing -y -i "file:/mnt/media/***" -map 0:2 -vn -an -c:s:0 copy "/config/cache/temp/e804fbf4a85e480bbe90be40e4958578.ass"
ffmpeg version 5.1-emby_2023_06_25 Copyright (c) 2000-2022 the FFmpeg developers and softworkz for Emby LLC
  built with gcc 10.3.0 (crosstool-NG 1.25.0)
  libavutil      57. 28.100 / 57. 28.100
  libavcodec     59. 37.100 / 59. 37.100
  libavformat    59. 27.100 / 59. 27.100
  libavdevice    59.  7.100 / 59.  7.100
  libavfilter     8. 44.100 /  8. 44.100
  libswscale      6.  7.100 /  6.  7.100
  libswresample   4.  7.100 /  4.  7.100
  libpostproc    56.  6.100 / 56.  6.100
Execution Date: 2024-03-19 09:21:22
Splitting the commandline.
Reading option '-loglevel' ... matched as option 'loglevel' (set logging level) with argument 'trace'.
Reading option '+timing' ... matched as output url.
Reading option '-y' ... matched as option 'y' (overwrite output files) with argument '1'.
Reading option '-i' ... matched as input url with argument 'file:/mnt/media/***'.
Reading option '-map' ... matched as option 'map' (set input stream mapping) with argument '0:2'.
Reading option '-vn' ... matched as option 'vn' (disable video) with argument '1'.
Reading option '-an' ... matched as option 'an' (disable audio) with argument '1'.
Reading option '-c:s:0' ... matched as option 'c' (codec name) with argument 'copy'.
Reading option '/config/cache/temp/e804fbf4a85e480bbe90be40e4958578.ass' ... matched as output url.
Finished splitting the commandline.
Parsing a group of options: global .
Applying option loglevel (set logging level) with argument trace.
Applying option y (overwrite output files) with argument 1.
Successfully parsed a group of options.
Parsing a group of options: input url file:/mnt/media/***.
Successfully parsed a group of options.
Opening an input file: file:/mnt/media/***.
[NULL @ 0x2343200] Opening 'file:/mnt/media/***' for reading
[file @ 0x2343bc0] Setting default whitelist 'file,crypto,data'
Probing matroska,webm score:100 size:2048
[matroska,webm @ 0x2343200] Format matroska,webm probed with size=2048 and score=100
[matroska,webm @ 0x2343200] Unknown entry 0x22B59D at pos. 4345
[matroska,webm @ 0x2343200] Unknown entry 0x22B59D at pos. 4415
[matroska,webm @ 0x2343200] Unknown entry 0x22B59D at pos. 7592
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064003
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064049
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064090
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064135
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064194
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064261
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064342
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064394
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064440
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064481
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064524
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064583
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064650
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064731
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064780
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064826
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064865
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064905
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397064964
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397065031
[matroska,webm @ 0x2343200] Unknown entry 0x447B at pos. 1397065112
st:0 removing common factor 1000000 from timebase
st:1 removing common factor 1000000 from timebase
st:2 removing common factor 1000000 from timebase
[matroska,webm @ 0x2343200] Before avformat_find_stream_info() pos: 6508613 bytes read:6542541 seeks:2 nb_streams:17
[h264 @ 0x2355940] nal_unit_type: 7(SPS), nal_ref_idc: 3
[h264 @ 0x2355940] nal_unit_type: 8(PPS), nal_ref_idc: 3
[h264 @ 0x2355940] nal_unit_type: 7(SPS), nal_ref_idc: 3
[h264 @ 0x2355940] nal_unit_type: 8(PPS), nal_ref_idc: 3
[h264 @ 0x2355940] nal_unit_type: 7(SPS), nal_ref_idc: 3
[h264 @ 0x2355940] nal_unit_type: 8(PPS), nal_ref_idc: 3
[h264 @ 0x2355940] nal_unit_type: 6(SEI), nal_ref_idc: 0
[h264 @ 0x2355940] nal_unit_type: 5(IDR), nal_ref_idc: 3
[h264 @ 0x2355940] Format yuv420p chosen by get_format().
[h264 @ 0x2355940] Reinit context to 1920x1088, pix_fmt: yuv420p
[h264 @ 0x2355940] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 2
    Last message repeated 5 times
[matroska,webm @ 0x2343200] All info found
[matroska,webm @ 0x2343200] stream 0: start_time: 0 duration: NOPTS
[matroska,webm @ 0x2343200] stream 1: start_time: 0 duration: NOPTS
[matroska,webm @ 0x2343200] stream 2: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] stream 3: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] stream 4: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] stream 5: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] stream 6: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] stream 7: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] stream 8: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] stream 9: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] stream 10: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] stream 11: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] stream 12: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] stream 13: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] stream 14: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] stream 15: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] stream 16: start_time: 0 duration: 1370.05
[matroska,webm @ 0x2343200] format: start_time: 0 duration: 1370.05 (estimate from stream) bitrate=8157 kb/s
[matroska,webm @ 0x2343200] After avformat_find_stream_info() pos: 6516424 bytes read:6575309 seeks:2 frames:24
Input #0, matroska,webm, from 'file:/mnt/media/***':
  Metadata:
    encoder         : no_variable_data
    creation_time   : 1970-01-01T00:00:00.000000Z
  Duration: 00:22:50.05, start: 0.000000, bitrate: 8157 kb/s
  Stream #0:0, 8, 1/1000: Video: h264 (High), 1 reference frame, yuv420p(tv, bt709, progressive, left), 1920x1080 (1920x1088) [SAR 1:1 DAR 16:9], 0/1, Level 40, 23.98 fps, 23.98 tbr, 1k tbn (default)
    Metadata:
      BPS-eng         : 7989512
      DURATION-eng    : 00:22:49.995000000
      NUMBER_OF_FRAMES-eng: 32847
      NUMBER_OF_BYTES-eng: 1368198971
  Stream #0:1(jpn), 16, 1/1000: Audio: aac (LC), 44100 Hz, stereo, fltp (default)
    Metadata:
      BPS-eng         : 128000
      DURATION-eng    : 00:22:50.047000000
      NUMBER_OF_FRAMES-eng: 59003
      NUMBER_OF_BYTES-eng: 21920752
  Stream #0:2(eng), 0, 1/1000: Subtitle: ass (default)
    Metadata:
      title           : English subs
      BPS-eng         : 108
      DURATION-eng    : 00:22:45.410000000
      NUMBER_OF_FRAMES-eng: 276
      NUMBER_OF_BYTES-eng: 18449
  Stream #0:3, 0, 1/90000: Attachment: ttf
    Metadata:
      filename        : Roboto-Medium.ttf
      mimetype        : application/x-truetype-font
  Stream #0:4, 0, 1/90000: Attachment: ttf
    Metadata:
      filename        : Roboto-MediumItalic.ttf
      mimetype        : application/x-truetype-font
  Stream #0:5, 0, 1/90000: Attachment: ttf
    Metadata:
      filename        : arial.ttf
      mimetype        : application/x-truetype-font
  Stream #0:6, 0, 1/90000: Attachment: ttf
    Metadata:
      filename        : arialbd.ttf
      mimetype        : application/x-truetype-font
  Stream #0:7, 0, 1/90000: Attachment: ttf
    Metadata:
      filename        : comic.ttf
      mimetype        : application/x-truetype-font
  Stream #0:8, 0, 1/90000: Attachment: ttf
    Metadata:
      filename        : comicbd.ttf
      mimetype        : application/x-truetype-font
  Stream #0:9, 0, 1/90000: Attachment: ttf
    Metadata:
      filename        : times.ttf
      mimetype        : application/x-truetype-font
  Stream #0:10, 0, 1/90000: Attachment: ttf
    Metadata:
      filename        : timesbd.ttf
      mimetype        : application/x-truetype-font
  Stream #0:11, 0, 1/90000: Attachment: ttf
    Metadata:
      filename        : trebuc.ttf
      mimetype        : application/x-truetype-font
  Stream #0:12, 0, 1/90000: Attachment: ttf
    Metadata:
      filename        : trebucbd.ttf
      mimetype        : application/x-truetype-font
  Stream #0:13, 0, 1/90000: Attachment: ttf
    Metadata:
      filename        : verdana.ttf
      mimetype        : application/x-truetype-font
  Stream #0:14, 0, 1/90000: Attachment: ttf
    Metadata:
      filename        : verdanab.ttf
      mimetype        : application/x-truetype-font
  Stream #0:15, 0, 1/90000: Attachment: ttf
    Metadata:
      filename        : CONSOLA.TTF
      mimetype        : application/x-truetype-font
  Stream #0:16, 0, 1/90000: Attachment: ttf
    Metadata:
      filename        : CONSOLAB.TTF
      mimetype        : application/x-truetype-font
Successfully opened the file.
Parsing a group of options: output url +timing.
Successfully parsed a group of options.
Opening an output file: +timing.
[NULL @ 0x2397bc0] Unable to find a suitable output format for '+timing'
+timing: Invalid argument
[AVIOContext @ 0x234c040] Statistics: 6575309 bytes read, 2 seeks

 

[Mikoyan 6]

Final investigation report.

Because there were inconsistencies between which file was able to play and which was not, I assumed that there was more that was occurring than was actually visible on a surface level. After ruling out possible issues with emby, taking a look at the system itself came next.

Apparently, there was something happening under the hood that is causing burn in failure. The burn-in process itself waits on ffmpeg transcode process to finish reading subtitles, but there are issues with how it is accessing and writing that data. It takes a HUGE amount of time to finish reading through the subtitles/video for ffmpeg and in that time, Emby cancels the process before it can finish, resulting in a failed transcode.

On my new system, Emby's cache sits on an SSD mirror (along with the container itself) but the actual videos are on a ZFS pool of spinners. This pool in particular was the issue. When I copy a problematic video to the SSDs, ffmpeg finishes extremely quickly, basically within about a second or two for a 1.3G file. That same file, run with the exact same parameters on the zpool, takes a mindboggling two minutes and change (over 50x) and hammers the pool with a huge amount of read operations while it finishes. That was very suspicious at first glance. Sure the disk may have been an SSD, but the spinners are enterprise platters on a SAS plane, so they are no slouches. And real world synchronous read writes were at least 5 to 600MB/s and therefore made no sense it took over two minutes to read 1GB.

Video on zpool:

  Total DISK READ:   10.02 G   ⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣷⣶⣶⣶⣶⣶⣶⣶⣤ |   Total DISK WRITE:  324.51 M   ⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿
Current DISK READ:   59.28 M/s ⣀⣀⣀⣀⣿⣆⣀⣀⣀⣀⣸⣿⣦⣀⣀⣀⣀⣀⣰⣿ | Current DISK WRITE:  410.37 K/s ⣀⣀⣀⣀⣇⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⡀⣇

It reads a crazy amount of data, however the actual writes are minimal. The actual operation never finishes.

Same video on SSD:

  Total DISK READ:   13.08 M   ⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿ |   Total DISK WRITE:  563.86 M   ⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿
Current DISK READ:    0.00 B/s ⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀    ⠀⠀⠀ | Current DISK WRITE:  642.28 K/s ⣀⣸⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀

Read finishes almost instantaneously, begins writing transcode.

This indicated that ZFS was performing a lot of operations against the disks themselves, pegging IO and causing ffmpeg to stall out and Emby to cancel the operation before it had a chance to finish. So going back through my configuration for this pool and dataset, I changed the cache settings and modified the zlog to prioritize latency, and that removed the issue with the ridiculous amount of reads. This problem was not initially evident because the usual read operations against the videos did not indicate any symptoms that would be considered problematic. Perhaps ffmpeg is not performing sequential read operations.

Current:

  Total DISK READ:  345.26 M   ⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿⣿ |   Total DISK WRITE:  112.89 M   ⣿⣿⣿⣶⣶⣶⣶⣶⣶⣶⣶⣶⣶⣶⣶⣶⣶⣶⣤⣤
Current DISK READ:    0.00 B/s ⠀⠀⢀⠀⠀⠀⠀⠀⠀⠀⠀⠀⢸⠀⠀⠀⠀⠀⠀⠀    | Current DISK WRITE:  200.18 K/s ⣀⣀⣸⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀⣀

Transcode performance for the same file now matches that of the SSD now. I do see increased memory usage due to more pressure against the primary cache, but this is not a concern as the system will receive more memory anyway.

TL;DR The burn-in capability works fine. Disk was the bottleneck, all other symptoms were red herrings or not related.

[Luke 37071]

Hi, thanks for following up !

[Lessaj 59]

Just curious what you were using to visualize the read/write speeds in that manner? Seems useful, I mostly use "zpool iostat 1" to monitor.

[Mikoyan 6]

10 hours ago, Lessaj said:

Just curious what you were using to visualize the read/write speeds in that manner? Seems useful, I mostly use "zpool iostat 1" to monitor.

Hi Lessaj, I use iotop-c on Ubuntu.

[Lessaj 59]

8 minutes ago, Mikoyan said:

Hi Lessaj, I use iotop-c on Ubuntu.

Neat, thanks! I also have iotop installed which looks similar but isn't quite the same, this looks nicer.