[FFmpeg-devel] [PATCH] libavutil/log: Support for logging timestamps in the log

[Tobias Rapp]

On 17/01/2023 22:52, Prakash wrote:

> libavutil/log: Support for logging timestamps in the log.
> Add 'time' flag to the -loglevel option to turn on timestamp logging.
> Useful for troubleshooting where time is spent from the log files.
>
> Signed-off-by: Prakash Duggaraju <duggaraju at gmail.com>
The commit message seems to be lacking a blank line between headline and 
body in the attached patch file.
> ---
>
>   doc/fftools-common-opts.texi |  4 ++++
>
>   fftools/opt_common.c         |  6 ++++++
>
>   libavutil/log.c              | 14 ++++++++++++++
>
>   libavutil/log.h              |  8 ++++++++
>
>   4 files changed, 32 insertions(+)
>
>
>
> diff --git a/doc/fftools-common-opts.texi b/doc/fftools-common-opts.texi
>
> index d9145704d6..a3cf9eb57d 100644
>
> --- a/doc/fftools-common-opts.texi
>
> +++ b/doc/fftools-common-opts.texi
>
> @@ -201,6 +201,10 @@ and the "Last message repeated n times" line will be
> omitted.
>
>   Indicates that log output should add a @code{[level]} prefix to each
> message
>
>   line. This can be used as an alternative to log coloring, e.g. when
> dumping the
>
>   log to file.
>
> + at item time
>
> +Indicates that log output should add a @code{[time]} prefix to each message
>
> +line. The time is the relative time in microseconds precision. This can be
>
> +useful for troubleshooting where time is spent from the logs.
Maybe you should mention here that adding the "time" flag practically 
disables any "repeated" flag if given.
>   @end table
>
>   Flags can also be used alone by adding a '+'/'-' prefix to set/reset a
> single
>
>   flag without affecting other @var{flags} or changing @var{loglevel}. When
>
> diff --git a/fftools/opt_common.c b/fftools/opt_common.c
>
> index 8a06df82df..a081ad6b08 100644
>
> --- a/fftools/opt_common.c
>
> +++ b/fftools/opt_common.c
>
> @@ -1269,6 +1269,12 @@ int opt_loglevel(void *optctx, const char *opt,
> const char *arg)
>
>               } else {
>
>                   flags |= AV_LOG_PRINT_LEVEL;
>
>               }
>
> +        } else if (av_strstart(token, "time", &arg)) {
>
> +            if (cmd == '-') {
>
> +                flags &= ~AV_LOG_PRINT_TIME;
>
> +            } else {
>
> +                flags |= AV_LOG_PRINT_TIME;
>
> +            }
>
>           } else {
>
>               break;
>
>           }
>
> diff --git a/libavutil/log.c b/libavutil/log.c
>
> index 5948e50467..cc16427178 100644
>
> --- a/libavutil/log.c
>
> +++ b/libavutil/log.c
>
> @@ -42,6 +42,7 @@
>
>   #include "internal.h"
>
>   #include "log.h"
>
>   #include "thread.h"
>
> +#include "time.h"
>
>
>
>   static AVMutex mutex = AV_MUTEX_INITIALIZER;
>
>
>
> @@ -319,6 +320,19 @@ static void format_line(void *avcl, int level, const
> char *fmt, va_list vl,
>
>       if (*print_prefix && (level > AV_LOG_QUIET) && (flags &
> AV_LOG_PRINT_LEVEL))
>
>           av_bprintf(part+2, "[%s] ", get_level_str(level));
>
>
>
> +    if (*print_prefix && (level > AV_LOG_QUIET) && (flags &
> AV_LOG_PRINT_TIME)) {
>
> +        int secs, mins;
>
> +        int64_t hours;
>
> +        int64_t time = av_gettime_relative();
>
> +        float millis = (time % 100000) / 1000.0f;

Should be modulo one million, instead one hundred thousand. But see 
comment regarding formatting below.

> +        time  /= 1000000;
>
> +        secs = time % 60;
>
> +        time /= 60;
>
> +        mins = time % 60;
>
> +        hours = time / 60;
>
> +        av_bprintf(part+2, "[%ldh:%02dm:%02ds:%07.03fms] ", hours, mins,
> secs, millis);
Adding it to part[2] will colorize time according to the log message 
level. Maybe add an own AVBPrint buffer for it?
> +    }
>
> +
>
>       av_vbprintf(part+3, fmt, vl);
>
>
>
>       if(*part[0].str || *part[1].str || *part[2].str || *part[3].str) {
>
> diff --git a/libavutil/log.h b/libavutil/log.h
>
> index ab7ceabe22..2e2d83f6d0 100644
>
> --- a/libavutil/log.h
>
> +++ b/libavutil/log.h
>
> @@ -377,6 +377,14 @@ int av_log_format_line2(void *ptr, int level, const
> char *fmt, va_list vl,
>
>    */
>
>   #define AV_LOG_PRINT_LEVEL 2
>
>
>
> +/**
>
> + * Include the system time with each log message.
>
> + * Useful for troubleshooting where the time was spent.
>
> + * Results in messages such as:
>
> + * [rawvideo @ 0xDEADBEEF] [01h:03m:05s:3.112ms] [error] encode did not
> produce valid pts

In my personal opinion I find formatting the timestamp with integer 
seconds and float milliseconds a bit weird. Using float seconds (like 
HH:MM:SS.mmm) would look more familiar to me.

And maybe add the timestamp at the very front of the formatted log 
message? That way it should be easier to scroll through the log file and 
spot time jumps.

> + */
>
> +#define AV_LOG_PRINT_TIME 4
>
> +
>
>   void av_log_set_flags(int arg);
>
>   int av_log_get_flags(void);

Regards, Tobias