funkypenguin 0 Posted September 21, 2018 Share Posted September 21, 2018 Hey guys, I've been having occasional issues with my Emby install crashing my GPUs when attempting to transcode. My suspicion is that multiple stalled transcodes "on top of one another" eventually consume all my GPU's RAM. Today I "caught it in the act", and noted the following in the log: 2018-09-20 14:25:00.494 Error HttpServer: Error processing request *** Error Report *** Version: 3.5.2.0 Command line: /system/EmbyServer.dll -programdata /config -ffmpeg /bin/ffmpeg -ffprobe /bin/ffprobe -restartexitcode 3 Operating system: Unix 4.15.0.34 64-Bit OS: True 64-Bit Process: True User Interactive: True Processor count: 40 Program data path: /config Application directory: /system System.FormatException: Input string was not in a correct format. Does this indicate anything useful? Thanks! D Link to comment Share on other sites More sharing options...
Luke 37022 Posted September 21, 2018 Share Posted September 21, 2018 Hi there, can you please attach the complete emby server log? Thanks ! Link to comment Share on other sites More sharing options...
funkypenguin 0 Posted September 21, 2018 Author Share Posted September 21, 2018 Attached This is not the _complete_ log (it was over 100MB!), but it covers the time of the error. Thanks for the input, and let me know if I can provide anything else! embylogs-crash.txt Link to comment Share on other sites More sharing options...
Luke 37022 Posted September 22, 2018 Share Posted September 22, 2018 Unfortunately this is still only a snippet that is missing the server startup sequences. Link to comment Share on other sites More sharing options...
funkypenguin 0 Posted September 22, 2018 Author Share Posted September 22, 2018 Aah, we need the startup sequence? That was somewhere else in the 100MB, I'll dig around... Link to comment Share on other sites More sharing options...
Luke 37022 Posted September 22, 2018 Share Posted September 22, 2018 It helps me understand the full picture of what is going on. Thanks. Link to comment Share on other sites More sharing options...
funkypenguin 0 Posted September 22, 2018 Author Share Posted September 22, 2018 I found this: 2018-09-20 00:00:00.032 Info App: Application version: 3.5.2.0 2018-09-20 00:00:00.076 Info App: Emby Command line: /system/EmbyServer.dll -programdata /config -ffmpeg /bin/ffmpeg -ffprobe /bin/ffprobe -restartexitcode 3 Operating system: Unix 4.15.0.34 64-Bit OS: True 64-Bit Process: True User Interactive: True Processor count: 40 Program data path: /config Application directory: /system 2018-09-20 00:00:00.076 Info App: Plugins: Open Subtitles 1.0.2.0 IMVDb 1.0.1.0 Kodi companion 2.0.3.0 Server Configuration Backup 1.2.3.0 Cinema Mode 1.0.2.0 2018-09-20 00:00:00.076 Info TaskManager: Rotate log file Completed after 0 minute(s) and 0 seconds 2018-09-20 00:00:00.094 Info TaskManager: ExecuteQueuedTasks I can upload the full 100MB log somewhere, if that's less trouble than snipping out bits? D Link to comment Share on other sites More sharing options...
Luke 37022 Posted September 22, 2018 Share Posted September 22, 2018 Is your system locale setting set to something other than English? Link to comment Share on other sites More sharing options...
funkypenguin 0 Posted September 23, 2018 Author Share Posted September 23, 2018 I don't think so - I'm running the official docker container under Ubuntu LTS 1604: root@docker:~# cat /etc/default/locale # File generated by update-locale LANG="en_US.UTF-8" root@docker:~# Link to comment Share on other sites More sharing options...
Luke 37022 Posted September 23, 2018 Share Posted September 23, 2018 What Emby app is this happening with? Link to comment Share on other sites More sharing options...
funkypenguin 0 Posted September 23, 2018 Author Share Posted September 23, 2018 (edited) Sorry, pasted too fast Edited September 23, 2018 by funkypenguin Link to comment Share on other sites More sharing options...
Luke 37022 Posted September 23, 2018 Share Posted September 23, 2018 What is that? Link to comment Share on other sites More sharing options...
funkypenguin 0 Posted September 23, 2018 Author Share Posted September 23, 2018 What Emby app is this happening with? It's hard to tell, now that I look, because the problem seems to start hours earlier, now that I look more closely. Seems like available GPU RAM slowly decreases, and by the time I notice, I've got a bunch of deadlocked ffmpeg processes, and nvidia-smi has stopped responding: Here's an example, that seemed to snowball over time... you think if I tracked down the emby app which generated the first defunct process, that might be a clue? bin 5961 22191 1 Sep21 ? 00:09:41 [ffmpeg] <defunct> bin 8094 22191 1 Sep21 ? 00:09:31 [ffmpeg] <defunct> bin 9571 22191 1 Sep21 ? 00:09:25 [ffmpeg] <defunct> bin 18551 22191 1 Sep21 ? 00:09:39 [ffmpeg] <defunct> bin 22819 18748 50 08:07 ? 00:02:40 [ffmpeg] <defunct> bin 23004 18748 99 08:07 ? 00:17:17 [ffmpeg] <defunct> bin 24015 18566 1 07:47 ? 00:00:19 [ffmpeg] <defunct> bin 25750 18566 1 07:48 ? 00:00:18 [ffmpeg] <defunct> bin 29490 22191 1 Sep21 ? 00:12:45 [ffmpeg] <defunct> bin 31798 22191 1 Sep21 ? 00:09:22 [ffmpeg] <defunct> bin 33296 18748 0 08:10 ? 00:00:00 /bin/ffmpeg -i file:/media/downloads/Movies/Apollo.13.1995/Apollo.13.1995.HDTV-1080p.mkv -threads 0 -map 0:0 -map 0:1 -map -0:s -codec:v:0 h264_nvenc -vf scale=trunc(min(max(iw\,ih*dar)\,720)/2)*2:trunc(ow/dar/2)*2 -pix_fmt yuv420p -preset fast -b:v 1950801 -maxrate 1950801 -bufsize 3901602 -profile:v high -forced-idr 1 -force_key_frames expr:if(isnan(prev_forced_t),eq(t,t),gte(t,prev_forced_t+3)) -copyts -vsync -1 -codec:a:0 ac3 -ac 6 -ab 384000 -f segment -max_delay 5000000 -avoid_negative_ts disabled -map_metadata -1 -map_chapters -1 -start_at_zero -segment_time 3 -individual_header_trailer 0 -segment_format mpegts -segment_list_type m3u8 -segment_start_number 0 -segment_list /config/transcoding-temp/transcoding-temp/70bd62d141ef71701901944d85b88356.m3u8 -y /config/transcoding-temp/transcoding-temp/70bd62d141ef71701901944d85b88356%d.ts bin 35599 18748 0 08:11 ? 00:00:00 /bin/ffmpeg -i file:/media/downloads/Movies/Apollo.13.1995/Apollo.13.1995.HDTV-1080p.mkv -threads 0 -map 0:0 -map 0:1 -map -0:s -codec:v:0 h264_nvenc -vf scale=trunc(min(max(iw\,ih*dar)\,720)/2)*2:trunc(ow/dar/2)*2 -pix_fmt yuv420p -preset fast -b:v 1950801 -maxrate 1950801 -bufsize 3901602 -profile:v high -forced-idr 1 -force_key_frames expr:if(isnan(prev_forced_t),eq(t,t),gte(t,prev_forced_t+3)) -copyts -vsync -1 -codec:a:0 ac3 -ac 6 -ab 384000 -f segment -max_delay 5000000 -avoid_negative_ts disabled -map_metadata -1 -map_chapters -1 -start_at_zero -segment_time 3 -individual_header_trailer 0 -segment_format mpegts -segment_list_type m3u8 -segment_start_number 0 -segment_list /config/transcoding-temp/transcoding-temp/11b8df864abd8a2f5ae4e88997eac579.m3u8 -y /config/transcoding-temp/transcoding-temp/11b8df864abd8a2f5ae4e88997eac579%d.ts bin 36901 22191 1 Sep21 ? 00:09:12 [ffmpeg] <defunct> bin 36943 22191 1 Sep21 ? 00:09:40 [ffmpeg] <defunct> root 40547 26163 0 08:12 ? 00:00:00 grep ffmpeg Link to comment Share on other sites More sharing options...
Luke 37022 Posted September 23, 2018 Share Posted September 23, 2018 it looks like a bad url created by whatever app you're using, and based on the user agent doesn't look like one of our apps. Link to comment Share on other sites More sharing options...
funkypenguin 0 Posted September 23, 2018 Author Share Posted September 23, 2018 Thank you, I'll try to correlate user agent with the defunct processes Link to comment Share on other sites More sharing options...
funkypenguin 0 Posted September 26, 2018 Author Share Posted September 26, 2018 I caught it in the act! I found these 5-hour-old ffmpeg processes, each consuming GPU ram: bin 26643 9540 1 Sep23 ? 00:54:30 /bin/ffmpeg -c:v hevc_cuvid -resize 1920x1080 -i file:/media/downloads/4K Movies/Avengers.Infinity.War.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR/Avengers.Infinity.War.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv -threads 0 -map 0:0 -map 0:1 -codec:v:0 h264_nvenc -filter_complex [0:4]scale=3840:2160:force_original_aspect_ratio=decrease[sub];[0:0][sub]overlay -pix_fmt yuv420p -preset fast -b:v 18588332 -maxrate 18588332 -bufsize 37176664 -profile:v high -forced-idr 1 -force_key_frames expr:if(isnan(prev_forced_t),eq(t,t),gte(t,prev_forced_t+3)) -copyts -vsync -1 -codec:a:0 ac3 -ac 6 -ab 384000 -f segment -max_delay 5000000 -avoid_negative_ts disabled -map_metadata -1 -map_chapters -1 -start_at_zero -segment_time 3 -individual_header_trailer 0 -segment_format mpegts -segment_list_type m3u8 -segment_start_number 0 -segment_list /config/transcoding-temp/transcoding-temp/56ddc27823520022cb75f949034c5155.m3u8 -y /config/transcoding-temp/transcoding-temp/56ddc27823520022cb75f949034c5155%d.ts bin 34591 28655 1 Sep25 ? 00:18:43 /bin/ffmpeg -c:v hevc_cuvid -resize 1920x1080 -i file:/media/downloads/4K Movies/Avengers.Infinity.War.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR/Avengers.Infinity.War.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv -threads 0 -map 0:0 -map 0:1 -codec:v:0 h264_nvenc -filter_complex [0:4]scale=3840:2160:force_original_aspect_ratio=decrease[sub];[0:0][sub]overlay -pix_fmt yuv420p -preset fast -b:v 23556150 -maxrate 23556150 -bufsize 47112300 -profile:v high -forced-idr 1 -force_key_frames expr:if(isnan(prev_forced_t),eq(t,t),gte(t,prev_forced_t+3)) -copyts -vsync -1 -codec:a:0 aac -strict experimental -ac 6 -ab 384000 -f segment -max_delay 5000000 -avoid_negative_ts disabled -map_metadata -1 -map_chapters -1 -start_at_zero -segment_time 3 -individual_header_trailer 0 -segment_format mpegts -segment_list_type m3u8 -segment_start_number 0 -segment_list /config/transcoding-temp/transcoding-temp/d68ebc0e83df34850fafd911d160811b.m3u8 -y /config/transcoding-temp/transcoding-temp/d68ebc0e83df34850fafd911d160811b%d.ts bin 36708 28655 1 Sep25 ? 00:18:55 /bin/ffmpeg -ss 02:02:00.000 -c:v hevc_cuvid -resize 1920x1080 -i file:/media/downloads/4K Movies/Avengers.Infinity.War.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR/Avengers.Infinity.War.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv -threads 0 -map 0:0 -map 0:1 -codec:v:0 h264_nvenc -filter_complex [0:4]scale=3840:2160:force_original_aspect_ratio=decrease[sub];[0:0][sub]overlay -pix_fmt yuv420p -preset fast -b:v 23556150 -maxrate 23556150 -bufsize 47112300 -profile:v high -forced-idr 1 -force_key_frames expr:if(isnan(prev_forced_t),eq(t,t),gte(t,prev_forced_t+3)) -copyts -vsync -1 -codec:a:0 aac -strict experimental -ac 6 -ab 384000 -f segment -max_delay 5000000 -avoid_negative_ts disabled -map_metadata -1 -map_chapters -1 -start_at_zero -segment_time 3 -segment_time_delta -7320 -individual_header_trailer 0 -segment_format mpegts -segment_list_type m3u8 -segment_start_number 2440 -segment_list /config/transcoding-temp/transcoding-temp/28896cb5d061411bac16b942d783de0d.m3u8 -y /config/transcoding-temp/transcoding-temp/28896cb5d061411bac16b942d783de0d%d.ts bin 38125 28655 2 Sep25 ? 00:19:20 /bin/ffmpeg -ss 02:02:00.000 -c:v hevc_cuvid -resize 1920x1080 -i file:/media/downloads/4K Movies/Avengers.Infinity.War.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR/Avengers.Infinity.War.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv -threads 0 -map 0:0 -map 0:1 -codec:v:0 h264_nvenc -filter_complex [0:4]scale=3840:2160:force_original_aspect_ratio=decrease[sub];[0:0][sub]overlay -pix_fmt yuv420p -preset fast -b:v 23556150 -maxrate 23556150 -bufsize 47112300 -profile:v high -forced-idr 1 -force_key_frames expr:if(isnan(prev_forced_t),eq(t,t),gte(t,prev_forced_t+3)) -copyts -vsync -1 -codec:a:0 aac -strict experimental -ac 6 -ab 384000 -f segment -max_delay 5000000 -avoid_negative_ts disabled -map_metadata -1 -map_chapters -1 -start_at_zero -segment_time 3 -segment_time_delta -7320 -individual_header_trailer 0 -segment_format mpegts -segment_list_type m3u8 -segment_start_number 2440 -segment_list /config/transcoding-temp/transcoding-temp/aad7371d13a862725e88c6ec87082ba0.m3u8 -y /config/transcoding-temp/transcoding-temp/aad7371d13a862725e88c6ec87082ba0%d.ts bin 39060 28655 2 Sep25 ? 00:19:46 /bin/ffmpeg -c:v hevc_cuvid -resize 1920x1080 -i file:/media/downloads/4K Movies/Avengers.Infinity.War.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR/Avengers.Infinity.War.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv -threads 0 -map 0:0 -map 0:1 -codec:v:0 h264_nvenc -filter_complex [0:4]scale=3840:2160:force_original_aspect_ratio=decrease[sub];[0:0][sub]overlay -pix_fmt yuv420p -preset fast -b:v 23556150 -maxrate 23556150 -bufsize 47112300 -profile:v high -forced-idr 1 -force_key_frames expr:if(isnan(prev_forced_t),eq(t,t),gte(t,prev_forced_t+3)) -copyts -vsync -1 -codec:a:0 aac -strict experimental -ac 6 -ab 384000 -f segment -max_delay 5000000 -avoid_negative_ts disabled -map_metadata -1 -map_chapters -1 -start_at_zero -segment_time 3 -individual_header_trailer 0 -segment_format mpegts -segment_list_type m3u8 -segment_start_number 0 -segment_list /config/transcoding-temp/transcoding-temp/97edb41789d077595bdf2da975ef2d22.m3u8 -y /config/transcoding-temp/transcoding-temp/97edb41789d077595bdf2da975ef2d22%d.ts And (there were one or two normal transcodes going on when I captured this) +-----------------------------------------------------------------------------+ | NVIDIA-SMI 396.54 Driver Version: 396.54 | |-------------------------------+----------------------+----------------------+ | GPU Name Persistence-M| Bus-Id Disp.A | Volatile Uncorr. ECC | | Fan Temp Perf Pwr:Usage/Cap| Memory-Usage | GPU-Util Compute M. | |===============================+======================+======================| | 0 Quadro P4000 Off | 00000000:03:00.0 Off | N/A | | 46% 33C P8 9W / 105W | 6218MiB / 8119MiB | 0% Default | +-------------------------------+----------------------+----------------------+ +-----------------------------------------------------------------------------+ | Processes: GPU Memory | | GPU PID Type Process name Usage | |=============================================================================| | 0 4308 C /bin/ffmpeg 83MiB | | 0 4479 C /bin/ffmpeg 83MiB | | 0 26619 C /bin/ffmpeg 877MiB | | 0 26643 C /bin/ffmpeg 877MiB | | 0 34591 C /bin/ffmpeg 877MiB | | 0 36708 C /bin/ffmpeg 877MiB | | 0 38125 C /bin/ffmpeg 877MiB | | 0 39060 C /bin/ffmpeg 877MiB | | 0 39438 C /bin/ffmpeg 769MiB | +-----------------------------------------------------------------------------+ I confirmed that the video listed in the ffmpeg processes was _not_ currently being streamed. So I killed the ffmpeg processes, and the GPU RAM was released. Then, curious as to whether I could reproduce the problem, I started playing the video again on my phone, waiting for the transcoding session to start, and then killed the emby app on my phone (iOS). The process remained, consuming 1000% CPU. But after ~3min, the ffmpeg process disappeared and the memory/cpu was released. My theory is (as you suggest above) an app which starts the ffmpeg trancode, fails, re-attempts, etc, and because the Emby process dies (see the error log in the attached debugs), Emby is never able to kill the ffmpeg process. I've attached (compressed) debug logs this time, 220MB uncompressed. Right now, I've just setup a cron job to kill any transcoding processes older than 3h, but that's a very big hammer for a very subtle problem - any suggestions / advice would be appreciated D transcoding_debug.tar.gz Link to comment Share on other sites More sharing options...
Luke 37022 Posted September 26, 2018 Share Posted September 26, 2018 Thanks for the investigation but please avoid x-ing out the versions as this makes it harder to assess what is happening. thanks. Link to comment Share on other sites More sharing options...
funkypenguin 0 Posted September 26, 2018 Author Share Posted September 26, 2018 Sorry, that was unintentional I only intended to x-out my IP addresses. I didn’t keep the original, but can supply any version details necessary? Link to comment Share on other sites More sharing options...
Luke 37022 Posted October 3, 2018 Share Posted October 3, 2018 If the server crashes then yes it's possible that some ffmpeg processes may be left running. 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