[FFmpeg-devel] [PATCH] Add system and real time to benchmarking.

[Mark Wachsler]

Friendly ping. Could someone please take a look? Thanks!

On Mon, Apr 23, 2018 at 2:29 PM, Mark Wachsler <wachsler at google.com> wrote:

> Ping.
>
> On Fri, Apr 20, 2018 at 4:21 PM, Mark Wachsler <wachsler at google.com>
> wrote:
>
>> The -benchmark and -benchmark_all options now show user, system, and real
>> time,
>> instead of just user time.
>> ---
>>  fftools/ffmpeg.c | 50 ++++++++++++++++++++++++++++++++++--------------
>>  1 file changed, 36 insertions(+), 14 deletions(-)
>>
>> diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c
>> index 4dbe72186d..d37171d567 100644
>> --- a/fftools/ffmpeg.c
>> +++ b/fftools/ffmpeg.c
>> @@ -120,8 +120,14 @@ const char *const forced_keyframes_const_names[] = {
>>      NULL
>>  };
>>
>> +typedef struct TimeStamps {
>> +  int64_t real_usec;
>> +  int64_t user_usec;
>> +  int64_t sys_usec;
>> +} TimeStamps;
>> +
>>  static void do_video_stats(OutputStream *ost, int frame_size);
>> -static int64_t getutime(void);
>> +static TimeStamps get_time_stamps(void);
>>  static int64_t getmaxrss(void);
>>  static int ifilter_has_all_input_formats(FilterGraph *fg);
>>
>> @@ -133,7 +139,7 @@ static int64_t decode_error_stat[2];
>>
>>  static int want_sdp = 1;
>>
>> -static int current_time;
>> +static TimeStamps current_time;
>>  AVIOContext *progress_avio = NULL;
>>
>>  static uint8_t *subtitle_out;
>> @@ -653,7 +659,7 @@ static void abort_codec_experimental(AVCodec *c, int
>> encoder)
>>  static void update_benchmark(const char *fmt, ...)
>>  {
>>      if (do_benchmark_all) {
>> -        int64_t t = getutime();
>> +        TimeStamps t = get_time_stamps();
>>          va_list va;
>>          char buf[1024];
>>
>> @@ -661,7 +667,11 @@ static void update_benchmark(const char *fmt, ...)
>>              va_start(va, fmt);
>>              vsnprintf(buf, sizeof(buf), fmt, va);
>>              va_end(va);
>> -            av_log(NULL, AV_LOG_INFO, "bench: %8"PRIu64" %s \n", t -
>> current_time, buf);
>> +            av_log(NULL, AV_LOG_INFO,
>> +                   "bench: %8" PRIu64 " user %8" PRIu64 " sys %8" PRIu64
>> " real %s \n",
>> +                   t.user_usec - current_time.user_usec,
>> +                   t.sys_usec - current_time.sys_usec,
>> +                   t.real_usec - current_time.real_usec, buf);
>>          }
>>          current_time = t;
>>      }
>> @@ -4715,23 +4725,30 @@ static int transcode(void)
>>      return ret;
>>  }
>>
>> -
>> -static int64_t getutime(void)
>> -{
>> +static TimeStamps get_time_stamps(void) {
>> +  TimeStamps time_stamps;
>> +  time_stamps.real_usec = av_gettime_relative();
>>  #if HAVE_GETRUSAGE
>>      struct rusage rusage;
>>
>>      getrusage(RUSAGE_SELF, &rusage);
>> -    return (rusage.ru_utime.tv_sec * 1000000LL) +
>> rusage.ru_utime.tv_usec;
>> +    time_stamps.user_usec =
>> +        (rusage.ru_utime.tv_sec * 1000000LL) + rusage.ru_utime.tv_usec;
>> +    time_stamps.sys_usec =
>> +        (rusage.ru_stime.tv_sec * 1000000LL) + rusage.ru_stime.tv_usec;
>>  #elif HAVE_GETPROCESSTIMES
>>      HANDLE proc;
>>      FILETIME c, e, k, u;
>>      proc = GetCurrentProcess();
>>      GetProcessTimes(proc, &c, &e, &k, &u);
>> -    return ((int64_t) u.dwHighDateTime << 32 | u.dwLowDateTime) / 10;
>> +    time_stamps.user_usec =
>> +        ((int64_t)u.dwHighDateTime << 32 | u.dwLowDateTime) / 10;
>> +    time_stamps.sys_usec =
>> +        ((int64_t)k.dwHighDateTime << 32 | k.dwLowDateTime) / 10;
>>  #else
>> -    return av_gettime_relative();
>> +    time_stamps.user_usec = time_stamps.sys_usec = 0;
>>  #endif
>> +    return time_stamps;
>>  }
>>
>>  static int64_t getmaxrss(void)
>> @@ -4759,7 +4776,7 @@ static void log_callback_null(void *ptr, int level,
>> const char *fmt, va_list vl)
>>  int main(int argc, char **argv)
>>  {
>>      int i, ret;
>> -    int64_t ti;
>> +    TimeStamps ti;
>>
>>      init_dynload();
>>
>> @@ -4811,12 +4828,17 @@ int main(int argc, char **argv)
>>              want_sdp = 0;
>>      }
>>
>> -    current_time = ti = getutime();
>> +    current_time = ti = get_time_stamps();
>>      if (transcode() < 0)
>>          exit_program(1);
>> -    ti = getutime() - ti;
>>      if (do_benchmark) {
>> -        av_log(NULL, AV_LOG_INFO, "bench: utime=%0.3fs\n", ti /
>> 1000000.0);
>> +      current_time = get_time_stamps();
>> +      int64_t utime = current_time.user_usec - ti.user_usec;
>> +      int64_t stime = current_time.sys_usec - ti.sys_usec;
>> +      int64_t rtime = current_time.real_usec - ti.real_usec;
>> +      av_log(NULL, AV_LOG_INFO,
>> +             "bench: utime=%0.3fs stime=%0.3fs rtime=%0.3fs\n",
>> +             utime / 1000000.0, stime / 1000000.0, rtime / 1000000.0);
>>      }
>>      av_log(NULL, AV_LOG_DEBUG, "%"PRIu64" frames successfully decoded,
>> %"PRIu64" decoding errors\n",
>>             decode_error_stat[0], decode_error_stat[1]);
>> --
>> 2.17.0.484.g0c8726318c-goog
>>
>>
>