[FFmpeg-devel] [PATCH] Add option to log timing

Bodecs Bela bodecsb at vivanet.hu
Wed Sep 4 22:12:52 EEST 2019


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 at ffmpeg.org
> https://ffmpeg.org/mailman/listinfo/ffmpeg-devel
>
> To unsubscribe, visit link above, or email
> f
bb
> fmpeg-devel-request at ffmpeg.org with subject "unsubscribe".


More information about the ffmpeg-devel mailing list