[FFmpeg-devel] Add option to log timing

This commit adds two logging flags: 'timing' and 'datetiming'.

Usage: ffmpeg -logleve +timing

Timing information will only be added to log lines once transcoding has started.
---
fftools/cmdutils.c | 14 ++++++++++++++
fftools/ffmpeg.c   |  3 +++
libavutil/log.c    | 37 ++++++++++++++++++++++++++++++++-----
libavutil/log.h    | 17 +++++++++++++++++
4 files changed, 66 insertions(+), 5 deletions(-)

Hi,

2019.09.04. 20:53 keltezéssel, Soft Works írta:
> This commit adds two logging flags: 'timing' and 'datetiming'.
>
> Usage: ffmpeg -logleve +timing
>
> Timing information will only be added to log lines once transcoding has started.

Why this restriction? I think all log lines should be start with 
time/date if corresponding flag is present. This makes the log to be 
easy to parse by scripts.

> ---
> fftools/cmdutils.c | 14 ++++++++++++++
> fftools/ffmpeg.c   |  3 +++
> libavutil/log.c    | 37 ++++++++++++++++++++++++++++++++-----
> libavutil/log.h    | 17 +++++++++++++++++
> 4 files changed, 66 insertions(+), 5 deletions(-)
>
> diff --git a/fftools/cmdutils.c b/fftools/cmdutils.c
> index fdcd376b76..7805058f8b 100644
> --- a/fftools/cmdutils.c
> +++ b/fftools/cmdutils.c
> @@ -912,6 +912,20 @@ int opt_loglevel(void *optctx, const char *opt, const char *arg)
>                   flags |= AV_LOG_PRINT_LEVEL;
>               }
>               arg = token + 5;
> +        } else if (!strncmp(token, "timing", 6)) {
> +            if (cmd == '-') {
> +                flags &= ~AV_LOG_PRINT_TIME;
> +            } else {
> +                flags |= AV_LOG_PRINT_TIME;
> +            }
> +            arg = token + 6;
> +        } else if (!strncmp(token, "datetiming", 10)) {
> +            if (cmd == '-') {
> +                flags &= ~AV_LOG_PRINT_DATETIME;
> +            } else {
> +                flags |= AV_LOG_PRINT_DATETIME;
> +            }
> +            arg = token + 10;
>           } else {
>               break;
>           }
> diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c
> index 01f04103cf..ed1c6ab6fc 100644
> --- a/fftools/ffmpeg.c
> +++ b/fftools/ffmpeg.c
> @@ -4668,6 +4668,9 @@ static int transcode(void)
>           av_log(NULL, AV_LOG_INFO, "Press [q] to stop, [?] for help\n");
>       }
> +    /* Enable log timestamps if configured */
> +    av_log_set_flags(av_log_get_flags() | AV_LOG_PRINT_STARTUPCOMPLETE);
> +
>       timer_start = av_gettime_relative();
>   #if HAVE_THREADS
> diff --git a/libavutil/log.c b/libavutil/log.c
> index 93a156b8e4..a374a68c4e 100644
> --- a/libavutil/log.c
> +++ b/libavutil/log.c
> @@ -40,6 +40,8 @@
> #include "internal.h"
> #include "log.h"
> #include "thread.h"
> +#include "time.h"
> +#include "time_internal.h"
>   static AVMutex mutex = AV_MUTEX_INITIALIZER;
> @@ -243,14 +245,32 @@ static const char *get_level_str(int level)
>       }
> }
> +static void format_date_now(AVBPrint* timeBuf, int include_date)
> +{
> +    struct tm *ptm, tmbuf;
> +    int64_t time_us = av_gettime();
> +    int64_t time_ms = time_us / 1000;
> +    const time_t time_s = time_ms / 1000;
> +    int millisec = time_ms - (time_s * 1000);
> +    ptm = localtime_r(&time_s, &tmbuf);
> +    if (ptm) {
> +        if (include_date)
> +            av_bprint_strftime(timeBuf, "%Y-%m-%d ", ptm);
> +
> +        av_bprint_strftime(timeBuf, "%H:%M:%S", ptm);
> +        av_bprintf(timeBuf, ".%03d ", millisec);
> +    }
> +}
> +
> static void format_line(void *avcl, int level, const char *fmt, va_list vl,
> -                        AVBPrint part[4], int *print_prefix, int type[2])
> +                        AVBPrint part[5], int *print_prefix, int type[2])
> {
>       AVClass* avc = avcl ? *(AVClass **) avcl : NULL;
>       av_bprint_init(part+0, 0, AV_BPRINT_SIZE_AUTOMATIC);
>       av_bprint_init(part+1, 0, AV_BPRINT_SIZE_AUTOMATIC);
>       av_bprint_init(part+2, 0, AV_BPRINT_SIZE_AUTOMATIC);
>       av_bprint_init(part+3, 0, 65536);
> +    av_bprint_init(part+4, 0, AV_BPRINT_SIZE_AUTOMATIC);
>       if(type) type[0] = type[1] = AV_CLASS_CATEGORY_NA + 16;
>       if (*print_prefix && avc) {
> @@ -277,6 +297,10 @@ static void format_line(void *avcl, int level, const char *fmt, va_list vl,
>           char lastc = part[3].len && part[3].len <= part[3].size ? part[3].str[part[3].len - 1] : 0;
>           *print_prefix = lastc == '\n' || lastc == '\r';
>       }
> +
> +    if (*print_prefix && part[3].len > 1 && (flags & AV_LOG_PRINT_STARTUPCOMPLETE)
> +        && ((flags & AV_LOG_PRINT_TIME) || (flags & AV_LOG_PRINT_DATETIME)))
> +        format_date_now(&part[4], flags & AV_LOG_PRINT_DATETIME);
> }
>   void av_log_format_line(void *ptr, int level, const char *fmt, va_list vl,
> @@ -288,12 +312,12 @@ void av_log_format_line(void *ptr, int level, const char *fmt, va_list vl,
> int av_log_format_line2(void *ptr, int level, const char *fmt, va_list vl,
>                           char *line, int line_size, int *print_prefix)
> {
> -    AVBPrint part[4];
> +    AVBPrint part[5];
>       int ret;
>       format_line(ptr, level, fmt, vl, part, print_prefix, NULL);
>       ret = snprintf(line, line_size, "%s%s%s%s", part[0].str, part[1].str, part[2].str, part[3].str);
> -    av_bprint_finalize(part+3, NULL);
> +    av_bprint_finalize(part+4, NULL);
>       return ret;
> }
> @@ -302,7 +326,7 @@ void av_log_default_callback(void* ptr, int level, const char* fmt, va_list vl)
>       static int print_prefix = 1;
>       static int count;
>       static char prev[LINE_SZ];
> -    AVBPrint part[4];
> +    AVBPrint part[5];
>       char line[LINE_SZ];
>       static int is_atty;
>       int type[2];
> @@ -337,6 +361,9 @@ void av_log_default_callback(void* ptr, int level, const char* fmt, va_list vl)
>           count = 0;
>       }
>       strcpy(prev, line);
> +
> +    sanitize(part[4].str);
> +    colored_fputs(7, 0, part[4].str);
>       sanitize(part[0].str);
>       colored_fputs(type[0], 0, part[0].str);
>       sanitize(part[1].str);
> @@ -351,7 +378,7 @@ void av_log_default_callback(void* ptr, int level, const char* fmt, va_list vl)
>           VALGRIND_PRINTF_BACKTRACE("%s", "");
> #endif
> end:
> -    av_bprint_finalize(part+3, NULL);
> +    av_bprint_finalize(part+4, NULL);
>       ff_mutex_unlock(&mutex);
> }
> diff --git a/libavutil/log.h b/libavutil/log.h
> index d9554e609d..a4a750de74 100644
> --- a/libavutil/log.h
> +++ b/libavutil/log.h
> @@ -352,6 +352,23 @@ int av_log_format_line2(void *ptr, int level, const char *fmt, va_list vl,
>    */
> #define AV_LOG_PRINT_LEVEL 2
> +/**
> + * Include system time in log output.
> + */
> +#define AV_LOG_PRINT_TIME 4
> +
> +/**
> + * Include system date and time in log output.
> + */
> +#define AV_LOG_PRINT_DATETIME 8
> +
> +/**
> + * Internal flag indicating that transcoding has started
> + * and subsequent log output should include timing when
> + * AV_LOG_PRINT_TIME or AV_LOG_PRINT_DATETIME is set.
> + */
> +#define AV_LOG_PRINT_STARTUPCOMPLETE 65536
> +
> void av_log_set_flags(int arg);
> int av_log_get_flags(void);
> --
> 2.17.1.windows.2
>
> _______________________________________________
> ffmpeg-devel mailing list
> ffmpeg-devel@ffmpeg.org
> https://ffmpeg.org/mailman/listinfo/ffmpeg-devel
>
> To unsubscribe, visit link above, or email
> f
bb
> fmpeg-devel-request@ffmpeg.org with subject "unsubscribe".

> Why this restriction? I think all log lines should be start with
> time/date if corresponding flag is present. This makes the log to be
> easy to parse by scripts.

Initially I didn’t have this restriction, but it doesn’t work well together with some multi-line logging.
See below for an example.

To get this nice, it would require a larger amount of changes, and probably result in something that nobody wants to merge in.

Anyway, there’s a flag controlling this behavior and if you really want, you can set it.
Then you’ll see something like this:


18:59:04.449 Input #0, mov,mp4,m4a,3gp,3g2,mj2, from 'file:xxxxxxx.mp4':
18:59:04.449   Metadata:
    major_brand     : isom18:59:04.449
    minor_version   : 51218:59:04.449
    compatible_brands: isomiso2avc1mp4118:59:04.449
    encoder         : Lavf58.12.10018:59:04.449
  Duration: 00:20:52.72, start: 0.000000, bitrate: 1386 kb/s18:59:04.449
    Stream #0:0(und): Video: h264 (High) (avc1 / 0x31637661), yuv420p, 640x360 [SAR 1:1 DAR 16:9], 612 kb/s, Level 30, 25 fps, 25 tbr, 12800 tbn, 50 tbc (default)18:59:04.449
18:59:04.449     Metadata:
      handler_name    : VideoHandler18:59:04.449
    Stream #0:1(ger): Audio: aac (LC) (mp4a / 0x6134706D), 48000 Hz, 5.1, fltp, 381 kb/s (default)18:59:04.449
18:59:04.449     Metadata:
      handler_name    : SoundHandler18:59:04.449
    Stream #0:2(eng): Audio: aac (LC) (mp4a / 0x6134706D), 48000 Hz, 5.1, fltp, 382 kb/s18:59:04.449
18:59:04.449     Metadata:
      handler_name    : SoundHandler18:59:04.449
18:59:04.737 Stream mapping:
  Stream #0:0 (h264_cuvid) -> scale_cuda (graph 0)18:59:04.737
  scale_cuda (graph 0)18:59:04.737  -> Stream #0:0 (h264_nvenc)
  Stream #0:1 -> #0:1 (aac (native) -> mp3 (libmp3lame))18:59:04.737

On Wed, Sep 04, 2019 at 06:53:28PM +0000, Soft Works wrote:
> This commit adds two logging flags: 'timing' and 'datetiming'.
> 
> Usage: ffmpeg -logleve +timing
> 
> Timing information will only be added to log lines once transcoding has started.
> ---
> fftools/cmdutils.c | 14 ++++++++++++++
> fftools/ffmpeg.c   |  3 +++
> libavutil/log.c    | 37 ++++++++++++++++++++++++++++++++-----
> libavutil/log.h    | 17 +++++++++++++++++
> 4 files changed, 66 insertions(+), 5 deletions(-)

Applying: Add option to log timing
error: corrupt patch at line 45
...

[...]

On Wed, Sep 04, 2019 at 07:35:11PM +0000, Soft Works wrote:
> 
> > Why this restriction? I think all log lines should be start with
> > time/date if corresponding flag is present. This makes the log to be
> > easy to parse by scripts.
> 
> Initially I didn’t have this restriction, but it doesn’t work well together with some multi-line logging.
> See below for an example.
> 
> To get this nice, it would require a larger amount of changes, and probably result in something that nobody wants to merge in.
> 
> Anyway, there’s a flag controlling this behavior and if you really want, you can set it.
> Then you’ll see something like this:

how hard would it be to fix this ?

because nothing stops a codec from doing whatever the code outside transcode
did here causing this ...

[...]

> Michael Niedermayer wrote:
> >
> > > Why this restriction? I think all log lines should be start with
> > > time/date if corresponding flag is present. This makes the log to be
> > > easy to parse by scripts.
> >
> > Initially I didn’t have this restriction, but it doesn’t work well together with some multi-line logging.
> > See below for an example.
> >
> > To get this nice, it would require a larger amount of changes, and probably result in something that nobody wants to merge in.
> >
> > Anyway, there’s a flag controlling this behavior and if you really want, you can set it.
> > Then you’ll see something like this:
>
> how hard would it be to fix this ?
>
> because nothing stops a codec from doing whatever the code outside transcode
> did here causing this ...

Hi Michael,

it follows the same logic as the class prefixes do (those in square braces),
that's why the codec outputs are normally not doing those things that happen during startup.

If there is a normal line break in a codec output, that's ok and won't lead to the
nasty outputs I've shown. It will just don't have a timing in the second line, which is
just right imo, because then it's not a new log event but just continued output of
the previous line. A parser needs to check for this and will add the line content to the
previous log entry instead of parsing it as a new one.

softworkz