Mikoyan 6 Posted March 18 Share Posted March 18 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. Link to comment Share on other sites More sharing options...
Mikoyan 6 Posted March 18 Author Share Posted March 18 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. Link to comment Share on other sites More sharing options...
jaycedk 392 Posted March 18 Share Posted March 18 Dev's will need th full logs, not just your snips. Link to comment Share on other sites More sharing options...
rbjtech 4314 Posted March 18 Share Posted March 18 has /embycache/cache/temp got write permissions ? Link to comment Share on other sites More sharing options...
Mikoyan 6 Posted March 18 Author Share Posted March 18 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 1 Link to comment Share on other sites More sharing options...
Mikoyan 6 Posted March 18 Author Share Posted March 18 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). Link to comment Share on other sites More sharing options...
Mikoyan 6 Posted March 19 Author Share Posted March 19 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 Link to comment Share on other sites More sharing options...
Solution Mikoyan 6 Posted March 20 Author Solution Share Posted March 20 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. 2 1 Link to comment Share on other sites More sharing options...
Luke 37191 Posted March 20 Share Posted March 20 Hi, thanks for following up ! 1 Link to comment Share on other sites More sharing options...
Lessaj 80 Posted March 20 Share Posted March 20 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. Link to comment Share on other sites More sharing options...
Mikoyan 6 Posted March 21 Author Share Posted March 21 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. Link to comment Share on other sites More sharing options...
Lessaj 80 Posted March 21 Share Posted March 21 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. Link to comment Share on other sites More sharing options...
Recommended Posts
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 accountSign in
Already have an account? Sign in here.
Sign In Now