Close video encoder pipes and wait for it to finalize the video before exiting #1503
Conversation
Codecov Report
@@ Coverage Diff @@
## master #1503 +/- ##
==========================================
+ Coverage 56.24% 56.32% +0.08%
==========================================
Files 54 54
Lines 6353 6386 +33
==========================================
+ Hits 3573 3597 +24
- Misses 2780 2789 +9
Continue to review full report at Codecov.
|
backend/baseclass.pm
Outdated
| no autodie qw(close waitpid); | ||
| close $video_encoders->{$_}->{pipe} for keys %$video_encoders; | ||
| bmwqemu::diag 'Waiting for video encoder to finalize the video'; | ||
| for (my $timeout = 30, my $interval = 1; $timeout > 0; sleep $interval, $timeout -= $interval) { |
There was a problem hiding this comment.
Does the sleep mean we wait needlessly at least one second in every case? The for loop with a sleep isn't convincing me yet :)
There was a problem hiding this comment.
No - it only sleeps when at least one video encoder process is still running. (Although it is not used often in Perl, this is a plain-old for loop and it behaves identical to the for loop in C/C++. The for loop has the advantage that all loop variables can be defined within the loop scope.)
By the way, I didn't simply make it two consecutive non-blocking waitpid calls because this way we couldn't implement a timeout. However, there's further cleanup code which is supposed to run so I'd refrain from blocking here forever.
There was a problem hiding this comment.
There are actually ways to enforce a timeout more efficiently: https://stackoverflow.com/questions/282176/waitpid-equivalent-with-timeout https://codechacha.com/en/fork-waitpid-and-timeout
However, I think it isn't worth the effort (at this point). (Using sigtimedwait would likely be the best solution but it isn't directly available in Perl so I would have to write that part in C++.)
There was a problem hiding this comment.
ok, I would prefer if you can show that the case of shutdown does not increase over what is actually necessary. Could you please provide some data from experiments to back this up?
There was a problem hiding this comment.
Yes. I've started a few tests which are very short and hence the video is also only ~2 minutes. Then the finalizing seems to be so fast that all the waiting code is basically a no-op, see the timestamps in the following logs:
�[0m�[37m[2020-08-11T13:55:40.423 CEST] [debug] isotovideo done
�[0m�[37m[2020-08-11T13:55:40.423 CEST] [debug] QEMU status is not 'shutdown', it is 'running'
�[0m�[37m[2020-08-11T13:55:40.423 CEST] [debug] BACKEND SHUTDOWN
�[0m�[33m[2020-08-11T13:55:40.424 CEST] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
�[0m�[37m[2020-08-11T13:55:42.468 CEST] [debug] flushing frames
�[0mframe= 248 fps=1.8 q=0.0 Lsize= 431kB time=00:00:10.29 bitrate= 343.4kbits/s speed=0.0734x
video:429kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 0.504507%
�[37m[2020-08-11T13:55:47.411 CEST] [debug] Waiting for video encoder to finalize the video
�[0m�[37m[2020-08-11T13:55:47.412 CEST] [debug] The external video encoder (pid 19794) terminated
�[0m�[37m[2020-08-11T13:55:47.412 CEST] [debug] The built-in video encoder (pid 19795) terminated
�[0m�[37m[2020-08-11T14:02:59.982 CEST] [debug] isotovideo done
�[0m�[37m[2020-08-11T14:02:59.983 CEST] [debug] QEMU status is not 'shutdown', it is 'running'
�[0m�[37m[2020-08-11T14:02:59.983 CEST] [debug] BACKEND SHUTDOWN
�[0m�[33m[2020-08-11T14:02:59.984 CEST] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
�[0m�[37m[2020-08-11T14:03:02.024 CEST] [debug] flushing frames
�[0mframe= 250 fps=1.8 q=0.0 Lsize= 531kB time=00:00:10.37 bitrate= 419.3kbits/s speed=0.0741x
video:529kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 0.413080%
�[37m[2020-08-11T14:03:05.479 CEST] [debug] Waiting for video encoder to finalize the video
�[0m�[37m[2020-08-11T14:03:05.479 CEST] [debug] The built-in video encoder (pid 21404) terminated
�[0m�[37m[2020-08-11T14:03:05.479 CEST] [debug] The external video encoder (pid 21403) terminated
There was a problem hiding this comment.
I see a shutdown time of 6-7s in the both cases you referenced which I consider bad. Do you know what caused it? I was now used to 1-2s after my last termination improvements. But the time between the later messages with just 1ms is negligible of course
There was a problem hiding this comment.
I had a look at the code again to find that out. It seems like my new code now duplicates the existing "flushing frames" handling for the internal video encoder. I somehow assumed we had no special handling for the old video encoder.
I better streamline the handling for the internal video encoder with the new code. I can also investigate why the "flushing frames" part takes so long.
There was a problem hiding this comment.
I now added the commit "Pass remaining frames to external video encoder as well". But it doesn't change the problem that it takes quite a while to send the remaining data to the internal video encoder.
Martchus
force-pushed
the
close-video-encoder-pipes
branch
2 times, most recently
from
2f4985e
to
077fbb1
Compare
This change unifies the existing code for "flushing frames" with the code to stop the video encoder. Now the remaining data is also passed to the external video encoder. The error handling has also been improved and there's a timeout of 30 seconds for the flushing.
Martchus
force-pushed
the
close-video-encoder-pipes
branch
from
077fbb1
to
ae542f1
Compare
See https://progress.opensuse.org/issues/68923#note-9
I've tested it manually. So far I haven't noticed any truncated videos anymore. (Not when the test exists normally and also not when stopped by the worker.)