diff mbox

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

Message ID 20180420202113.131836-1-wachsler@google.com
State New
Headers show

Commit Message

Mark Wachsler April 20, 2018, 8:21 p.m. UTC 
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(-)

Comments

Mark Wachsler April 23, 2018, 9:29 p.m. UTC | #1 
Ping.

On Fri, Apr 20, 2018 at 4:21 PM, Mark Wachsler <wachsler@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
>
>
Mark Wachsler April 26, 2018, 7:19 p.m. UTC | #2 
Friendly ping. Could someone please take a look? Thanks!

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

> Ping.
>
> On Fri, Apr 20, 2018 at 4:21 PM, Mark Wachsler <wachsler@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
>>
>>
>
wm4 April 26, 2018, 7:28 p.m. UTC | #3 
On Fri, 20 Apr 2018 16:21:13 -0400
Mark Wachsler <wachsler-at-google.com@ffmpeg.org> 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]);

Is there any reason you you can't just use /usr/bin/time?
Mark Wachsler April 26, 2018, 7:32 p.m. UTC | #4 
-benchmark_all separately measures time spent encoding video, decoding
video, encoding audio, and decoding audio. You can't do that with
/usr/bin/time.

It is true that -benchmark could be replaced with /usr/bin/time, but that's
always been true. It seemed to make sense to -benchmark and -benchmark_all
continue to measure the same things.

Regards,
Mark

On Thu, Apr 26, 2018 at 12:28 PM, wm4 <nfxjfg@googlemail.com> wrote:

> On Fri, 20 Apr 2018 16:21:13 -0400
> Mark Wachsler <wachsler-at-google.com@ffmpeg.org> 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]);
>
> Is there any reason you you can't just use /usr/bin/time?
> _______________________________________________
> ffmpeg-devel mailing list
> ffmpeg-devel@ffmpeg.org
> http://ffmpeg.org/mailman/listinfo/ffmpeg-devel
>
Michael Niedermayer April 27, 2018, 4:31 p.m. UTC | #5 
On Fri, Apr 20, 2018 at 04:21:13PM -0400, Mark Wachsler 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;

indention mismatches the rest of the file

also please use some other name, time stamps exist in many areas
of multimedia. This is benchmarking specific. "Benchmark" should be
part of the name to seperate it from other time uses


> +
>  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();

again, indention mismatches, also the { placement mismatches other functions
(i dont mind really much personally, but some people are sensitive about this)

thx

[...]
diff mbox

Patch

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]);