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

[Prakash]

The problem with int milliseconds is you lose the microseconds precision.
Sometimes there are multiple log lines within the same millisecond.  I can
definitely move the timestamp as the first field of the log line. Let me
fix the patch file.

-Prakash.

On Wed, Jan 18, 2023 at 12:51 AM Tobias Rapp <t.rapp at noa-archive.com> wrote:

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