From aa1aef6727c742004681953481e26edea58ca413 Mon Sep 17 00:00:00 2001 From: Calvin Walton Date: Tue, 22 Nov 2022 13:12:07 -0500 Subject: [PATCH 1/3] Recording: Don't use stateful filters in ffmpeg video processing Because the input videos for BigBlueButton recording processing switch resolution and aspect ratio, the filter chain gets re-initialized, and any state in the filters is lost. This causes problems with the following filters: `color`: Timestamps restart from 0, rather than continuing at the point where they left off. `fps=start_time=12.345`: After reset, the fps filter thinks it's at the start of the file again, so the next frame it sees gets duplicated output for timestamps from the `start_time` until it catches back up. `setpts=PTS-STARTPTS`: The 'STARTPTS' is re-read as the first pts the filter sees after reinitialization, so timestamp of the next frame is reset to 0. (In practise, this didn't cause any problems because the duplicate frames created by the fps filter had the original start time.) The end result of all of these issues is that a lot of duplicate frames were created with invalid timestamps, which eventually get discarded by ffmpeg. But a lot of time is wasted, causing recordings to sometimes take hours to process when they should be ready in minutes. The fixes are as follows: * The `color` filters are used to generate the background and substitutes for missing videos. Move them out to separate filter chains by using the 'lavfi' input format, which lets you use a filter as if it was an input file. * Rather than use the `fps` filter's `start_time` feature, use the `trim` filter to remove early frames. * The actual start pts is already known by the script, so replace `setpts=PTS-STARTPTS` with `setpts=PTS-12.345/TB`, substituting in the absolute time. --- .../core/lib/recordandplayback/edl/video.rb | 44 ++++++++++++------- 1 file changed, 28 insertions(+), 16 deletions(-) diff --git a/record-and-playback/core/lib/recordandplayback/edl/video.rb b/record-and-playback/core/lib/recordandplayback/edl/video.rb index b0ba157246..1dac1b6eb7 100644 --- a/record-and-playback/core/lib/recordandplayback/edl/video.rb +++ b/record-and-playback/core/lib/recordandplayback/edl/video.rb @@ -379,8 +379,13 @@ module BigBlueButton duration = cut[:next_timestamp] - cut[:timestamp] BigBlueButton.logger.info " Cut start time #{cut[:timestamp]}, duration #{duration}" - ffmpeg_inputs = [] - ffmpeg_filter = "color=c=white:s=#{layout[:width]}x#{layout[:height]}:r=#{layout[:framerate]}" + ffmpeg_inputs = [ + { + format: 'lavfi', + filename: "color=c=white:s=#{layout[:width]}x#{layout[:height]}:r=#{layout[:framerate]}" + } + ] + ffmpeg_filter = '[0]null' layout[:areas].each do |layout_area| area = cut[:areas][layout_area[:name]] video_count = area.length @@ -478,9 +483,16 @@ module BigBlueButton tile_y += 1 end - # Only create the video input if the seekpoint is before the end of the file + input_index = ffmpeg_inputs.length + + # If the seekpoint is at or after the end of the file, the filter chain will + # have problems. Substitute in a blank video. if seek >= this_videoinfo[:duration] - ffmpeg_filter << "color=c=white:s=#{tile_width}x#{tile_height}:r=#{layout[:framerate]}[#{pad_name}];" + ffmpeg_inputs << { + format: 'lavfi', + filename: "color=c=white:s=#{tile_width}x#{tile_height}:r=#{layout[:framerate]}" + } + ffmpeg_filter << "[#{input_index}]null[#{pad_name}];" next end @@ -491,7 +503,6 @@ module BigBlueButton if seek > 0 seek = seek + seek_offset end - input_index = ffmpeg_inputs.length ffmpeg_inputs << { filename: video[:filename], seek: seek, @@ -501,16 +512,15 @@ module BigBlueButton if !scale.nil? ffmpeg_filter << "setpts=PTS*#{scale}," end - # Subtract away the offset from the timestamps, so the trimming - # in the fps filter is accurate - ffmpeg_filter << "setpts=PTS-#{ms_to_s(seek_offset)}/TB" - # fps filter fills in frames up to the desired start point, and - # cuts the video there - ffmpeg_filter << ",fps=#{layout[:framerate]}:start_time=#{ms_to_s(video[:timestamp])}" - # Reset the timestamps to start at 0 so that everything is synced - # for the video tiling, and scale to the desired size. - ffmpeg_filter << ",setpts=PTS-STARTPTS,scale=w=#{tile_width}:h=#{tile_height}:force_original_aspect_ratio=decrease,setsar=1" - # And finally, pad the video to the desired aspect ratio + # Subtract away the offset from the timestamps, so the trimming is accurate + ffmpeg_filter << "setpts=PTS-#{ms_to_s(video[:timestamp])}/TB" + # Clean up the video framerate + ffmpeg_filter << ",fps=#{layout[:framerate]}" + # Trim any frames from before the desired start point (seek offset strangeness) + ffmpeg_filter << ',trim=start=0' + # Scale to the desired size + ffmpeg_filter << ",scale=w=#{tile_width}:h=#{tile_height}:force_original_aspect_ratio=decrease,setsar=1" + # Pad the video to the desired aspect ratio ffmpeg_filter << ",pad=w=#{tile_width}:h=#{tile_height}:x=-1:y=-1:color=white" # Extend the video to the desired length ffmpeg_filter << ",tpad=stop=-1:stop_mode=add:color=white" @@ -549,7 +559,9 @@ module BigBlueButton ffmpeg_cmd = [*FFMPEG, '-copyts'] ffmpeg_inputs.each do |input| - ffmpeg_cmd += ['-ss', ms_to_s(input[:seek]), '-i', input[:filename]] + ffmpeg_cmd << '-ss' << ms_to_s(input[:seek]) if input.include?(:seek) + ffmpeg_cmd << '-f' << input[:format] if input.include?(:format) + ffmpeg_cmd << '-i' << input[:filename] end BigBlueButton.logger.debug(' ffmpeg filter_complex_script:') From 58c4ffd0686b4acb2a835a86e0ecf3ada2280d7c Mon Sep 17 00:00:00 2001 From: Calvin Walton Date: Mon, 5 Dec 2022 11:49:16 -0500 Subject: [PATCH 2/3] Recording: Pre-process video files using separate ffmpeg Even with the filter changes made, there's still some cases where filter chain hangs can result from filter reconfigurations. To solve the issue completely, I have split out pre-processing video files to separate ffmpeg processes, so that the filter chain for compositing will not ever be reconfigured. Each input video now has a separate ffmpeg process run for it which does the scaling, padding, and video extending steps. To avoid issues with disk space usage and extra cpu usage or quality loss, the output from these separate processes is sent to the compositing ffmpeg process as uncompressed video in a pipe. To simplify the setup, named pipes (special files) are used rather than setting up pipes in the ruby code programmatically. The extra ffmpeg processes are configured to log to files, and when complete their log output is copied to the recording processing log. Processes are joined to ensure zombie processes are not created, and the return codes of all the processes are checked so errors can be detected. Due to the overhead of transferring video through pipes, this might be a bit slower than the 2.4 recording processing - but on the other hand, some of the video decoding and scaling happens in parallel, so it might balance out. --- .../core/lib/recordandplayback/edl/video.rb | 90 ++++++++++++------- 1 file changed, 60 insertions(+), 30 deletions(-) diff --git a/record-and-playback/core/lib/recordandplayback/edl/video.rb b/record-and-playback/core/lib/recordandplayback/edl/video.rb index 1dac1b6eb7..2aa4340205 100644 --- a/record-and-playback/core/lib/recordandplayback/edl/video.rb +++ b/record-and-playback/core/lib/recordandplayback/edl/video.rb @@ -19,6 +19,7 @@ require 'json' require 'set' +require 'shellwords' module BigBlueButton module EDL @@ -379,6 +380,7 @@ module BigBlueButton duration = cut[:next_timestamp] - cut[:timestamp] BigBlueButton.logger.info " Cut start time #{cut[:timestamp]}, duration #{duration}" + aux_ffmpeg_processes = [] ffmpeg_inputs = [ { format: 'lavfi', @@ -442,25 +444,18 @@ module BigBlueButton scale_width, scale_height = aspect_scale(video_width, video_height, tile_width, tile_height) BigBlueButton.logger.debug " scaled size: #{scale_width}x#{scale_height}" + seek = video[:timestamp] BigBlueButton.logger.debug(" start timestamp: #{video[:timestamp]}") seek_offset = this_videoinfo[:start_time] BigBlueButton.logger.debug(" seek offset: #{seek_offset}") BigBlueButton.logger.debug(" codec: #{this_videoinfo[:video][:codec_name].inspect}") BigBlueButton.logger.debug(" duration: #{this_videoinfo[:duration]}, original duration: #{video[:original_duration]}") - if this_videoinfo[:video][:codec_name] == "flashsv2" - # Desktop sharing videos in flashsv2 do not have regular - # keyframes, so seeking in them doesn't really work. - # To make processing more reliable, always decode them from the - # start in each cut. (Slow!) - seek = 0 - else - # Webcam videos are variable, low fps; it might be that there's - # no frame until some time after the seek point. Start decoding - # 10s before the desired point to avoid this issue. - seek = video[:timestamp] - 10000 - seek = 0 if seek < 0 - end + # Desktop sharing videos in flashsv2 do not have regular + # keyframes, so seeking in them doesn't really work. + # To make processing more reliable, always decode them from the + # start in each cut. (Slow!) + seek = 0 if this_videoinfo[:video][:codec_name] == 'flashsv2' # Workaround early 1.1 deskshare timestamp bug # It resulted in video files that were too short. To workaround, we @@ -503,27 +498,48 @@ module BigBlueButton if seek > 0 seek = seek + seek_offset end + + # Launch the ffmpeg process to use for this input to pre-process the video to constant video resolution + # This has to be done in an external process, since if it's done in the same process, the entire filter + # chain gets re-initialized on every resolution change, resulting in losing state on all stateful filters. + ffmpeg_preprocess_output = "#{output}.#{pad_name}.nut" + ffmpeg_preprocess_log = "#{output}.#{pad_name}.log" + FileUtils.rm_f(ffmpeg_preprocess_output) + File.mkfifo(ffmpeg_preprocess_output) + + # Pre-filtering: scaling, padding, and extending. + ffmpeg_preprocess_filter = \ + "[0:v:0]scale=w=#{tile_width}:h=#{tile_height}:force_original_aspect_ratio=decrease,setsar=1,"\ + "pad=w=#{tile_width}:h=#{tile_height}:x=-1:y=-1:color=white,tpad=stop=-1:stop_mode=clone[out]" + + # Set up filters and inputs for video pre-processing ffmpeg command + ffmpeg_preprocess_command = [ + 'ffmpeg', '-y', '-v', 'info', '-nostats', '-nostdin', '-max_error_rate', '1.0', + # Ensure timebase conversion is not done, and frames prior to seek point run through filters. + '-vsync', 'passthrough', '-noaccurate_seek', + '-ss', ms_to_s(seek).to_s, '-itsoffset', ms_to_s(seek).to_s, '-i', video[:filename], + '-filter_complex', ffmpeg_preprocess_filter, '-map', '[out]', + # Trim to end point so process exits cleanly + '-to', ms_to_s(video[:timestamp] + duration).to_s, + '-c:v', 'rawvideo', "#{output}.#{pad_name}.nut" + ] + BigBlueButton.logger.debug("Executing: #{Shellwords.join(ffmpeg_preprocess_command)}") + ffmpeg_preprocess_pid = spawn(*ffmpeg_preprocess_command, err: [ffmpeg_preprocess_log, 'w']) + aux_ffmpeg_processes << { + pid: ffmpeg_preprocess_pid, + log: ffmpeg_preprocess_log + } + ffmpeg_inputs << { - filename: video[:filename], - seek: seek, + filename: ffmpeg_preprocess_output } ffmpeg_filter << "[#{input_index}]" # Scale the video length for the deskshare timestamp workaround - if !scale.nil? - ffmpeg_filter << "setpts=PTS*#{scale}," - end - # Subtract away the offset from the timestamps, so the trimming is accurate - ffmpeg_filter << "setpts=PTS-#{ms_to_s(video[:timestamp])}/TB" - # Clean up the video framerate - ffmpeg_filter << ",fps=#{layout[:framerate]}" - # Trim any frames from before the desired start point (seek offset strangeness) - ffmpeg_filter << ',trim=start=0' - # Scale to the desired size - ffmpeg_filter << ",scale=w=#{tile_width}:h=#{tile_height}:force_original_aspect_ratio=decrease,setsar=1" - # Pad the video to the desired aspect ratio - ffmpeg_filter << ",pad=w=#{tile_width}:h=#{tile_height}:x=-1:y=-1:color=white" - # Extend the video to the desired length - ffmpeg_filter << ",tpad=stop=-1:stop_mode=add:color=white" + ffmpeg_filter << "setpts=PTS*#{scale}," unless scale.nil? + # Clean up the video framerate and set exact start time + ffmpeg_filter << "fps=#{layout[:framerate]}:start_time=#{ms_to_s(video[:timestamp])}" + # Apply PTS offset so '0' time is aligned + ffmpeg_filter << ",setpts=PTS-#{ms_to_s(video[:timestamp])}/TB" ffmpeg_filter << "[#{pad_name}];" end @@ -575,6 +591,20 @@ module BigBlueButton ffmpeg_cmd += ['-an', *FFMPEG_WF_ARGS, '-r', layout[:framerate].to_s, output] exitstatus = BigBlueButton.exec_ret(*ffmpeg_cmd) + + aux_ffmpeg_exitstatuses = [] + aux_ffmpeg_processes.each do |process| + aux_exitstatus = Process.waitpid2(process[:pid]) + aux_ffmpeg_exitstatuses << aux_exitstatus[1] + BigBlueButton.logger.info("Command output: #{File.basename(process[:log])} #{aux_exitstatus[1]}") + File.open(process[:log], 'r') do |io| + io.each_line do |line| + BigBlueButton.logger.info(line.chomp) + end + end + end + raise 'At least one auxiliary ffmpeg process failed' unless aux_ffmpeg_exitstatuses.all?(&:success?) + raise "ffmpeg failed, exit code #{exitstatus}" if exitstatus != 0 return output From 5cb32ec088565ce1c6aaaa6200897de55da64ebd Mon Sep 17 00:00:00 2001 From: Calvin Walton Date: Tue, 6 Dec 2022 15:59:54 -0500 Subject: [PATCH 3/3] Recording: Move tpad filter to after fps filter The tpad filter is problematic on the variable-framerate webcam files, and the result can end up being hangs (or, at least, very slow processing) in the compositing. Move the tpad filter to the compositing process where it can run after the fps filter has converted the video to constant framerate. It still needs to run before the start trimming, so switch to using the trim filter rather than the fps filter's start_pts feature. --- .../core/lib/recordandplayback/edl/video.rb | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/record-and-playback/core/lib/recordandplayback/edl/video.rb b/record-and-playback/core/lib/recordandplayback/edl/video.rb index 2aa4340205..1e1746dec9 100644 --- a/record-and-playback/core/lib/recordandplayback/edl/video.rb +++ b/record-and-playback/core/lib/recordandplayback/edl/video.rb @@ -510,7 +510,7 @@ module BigBlueButton # Pre-filtering: scaling, padding, and extending. ffmpeg_preprocess_filter = \ "[0:v:0]scale=w=#{tile_width}:h=#{tile_height}:force_original_aspect_ratio=decrease,setsar=1,"\ - "pad=w=#{tile_width}:h=#{tile_height}:x=-1:y=-1:color=white,tpad=stop=-1:stop_mode=clone[out]" + "pad=w=#{tile_width}:h=#{tile_height}:x=-1:y=-1:color=white[out]" # Set up filters and inputs for video pre-processing ffmpeg command ffmpeg_preprocess_command = [ @@ -536,10 +536,10 @@ module BigBlueButton ffmpeg_filter << "[#{input_index}]" # Scale the video length for the deskshare timestamp workaround ffmpeg_filter << "setpts=PTS*#{scale}," unless scale.nil? - # Clean up the video framerate and set exact start time - ffmpeg_filter << "fps=#{layout[:framerate]}:start_time=#{ms_to_s(video[:timestamp])}" - # Apply PTS offset so '0' time is aligned - ffmpeg_filter << ",setpts=PTS-#{ms_to_s(video[:timestamp])}/TB" + # Clean up the video framerate and extend the video if needed + ffmpeg_filter << "fps=#{layout[:framerate]},tpad=stop=-1:stop_mode=clone" + # Apply PTS offset so '0' time is aligned, and trim frames before start point + ffmpeg_filter << ",setpts=PTS-#{ms_to_s(video[:timestamp])}/TB,trim=start=0" ffmpeg_filter << "[#{pad_name}];" end