[FFmpeg-devel] ffmpeg appears to be wasting CPU time

[Davy Durham]

Greetings,

   I'm seeing something curious when using ffmpeg and a readrate (using 
-re specifically). *The cumulative CPU usage when reading at a lower 
rate is significantly higher than when letting it run as fast as possible.*



      Evidence:

Using master HEAD, using the /time/ command, I am converting a 22.61s 
.wav file to .mp3.

Running at *full speed* the results are:

time ./ffmpeg -i input.wav output.mp3

    size=     355kB time=00:00:22.62 bitrate= 128.4kbits/s speed=52.1x
    video:0kB audio:354kB subtitle:0kB other streams:0kB global
    headers:0kB muxing overhead: 0.121834%

    real    0m0.464s
    *user    0m0.487s**
    **sys    0m0.036s*

Running at *realtime**speed* (adding -re) the results are:

time ./ffmpeg -i input.wav output.mp3

    real    0m22.664s
    *user    0m2.253s**
    **sys    0m0.156s*

This works out to the realtime speed run consuming *~10.6%* of the CPU 
(which about what I see on top as well) when it should only consume 
*~2.31%*, based on how much CPU was actually needed for the conversion 
in the fullspeed run.  (i.e. (0.487s+0.036s) * 100% / 22.61s == ~2.31%). 
    This means it consumes almost 5x the CPU when reading at the slower 
rate.


      Experiment:

I started digging and noticed that when readrates are enabled, the 
transcoding loop in ffmpeg sleeps arbitrarily for 10ms then wakes up and 
does more reading, however, the read function may decide it still isn't 
time to return anything (EAGAIN) and so things may go back to sleep for 
another trip through the loop.

I thought this might be the inefficiency, but it turns out not to be the 
case.

If I run it without the -re flag, but introduce an unconditional call to 
usleep(250ms) in the loop (simply to slow it down in a similar fashion, 
but avoiding the code paths that -re introduces), then one would expect 
it to consume about the same amount of cumulative CPU as the full sped 
run above, only it should just take more overall time while it mostly 
sleeps.

i.e. this simple change

    diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c
    index 438bee8fef..32a2087640 100644
    --- a/fftools/ffmpeg.c
    +++ b/fftools/ffmpeg.c
    @@ -3936,6 +3936,8 @@ static int transcode_step(void)
              av_log(NULL, AV_LOG_VERBOSE, "No more inputs to read from, finishing.\n");
              return AVERROR_EOF;
          }
    +
    +       av_usleep(250000/*250ms*/);
      
          if (ost->filter && !ost->filter->graph->graph) {
              if (ifilter_has_all_input_formats(ost->filter->graph)) {

This gives the same surprising result:

time ./ffmpeg -i input.wav output.mp3

    real	6m10.163s***user 0m2.304s****sys 0m0.174s*


And so again, that real time is expected, but the user+sys /should/ be 
about the same as it was in the first run (i.e. ~0.5s)..



      Conclusion?

*Can anyone guess as to why this may be happening?*  I'd like to get to 
the bottom of it and submit a patch.

I suspected something with the use of threads, and maybe threads aren't 
efficiently pausing but are spinning when queues start to fill or empty 
out?  But if I introduce a much longer sleep, I don't see anything 
register on top while the main thread is in that sleep state.

And BTW, the large discrepancy exists for much longer files too 
(involved in my actual use case).

I see the same behavior in v5.1.2 which I'm using in production.

If I perform the same experimental code change on v2.2.1, I do not get 
the unexpected difference.  I just picked some old version, and would be 
happy to figure out more precisely when it was introduced if that would 
help.

Any advice would be appreciated.  Thank You


P.S. You might wonder why I need to run ffmpeg in realtime, and it's 
because my actual use case involves HLS and requires converting at the 
realtime rate, but this simple mp3 conversion demonstrates the problem 
I'm seeing there.