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

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

[Prakash]

[-- Attachment #1: Type: text/plain, Size: 3656 bytes --]

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@gmail.com>

---

 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.

+@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.

 @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;

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

+    }

+

     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

+ */

+#define AV_LOG_PRINT_TIME 4

+

 void av_log_set_flags(int arg);

 int av_log_get_flags(void);



-- 

2.34.1

[-- Attachment #2: 0001-libavutil-log-Support-for-logging-timestamps-in-the-.patch --]
[-- Type: application/octet-stream, Size: 3690 bytes --]

[-- Attachment #3: Type: text/plain, Size: 251 bytes --]

_______________________________________________
ffmpeg-devel mailing list
ffmpeg-devel@ffmpeg.org
https://ffmpeg.org/mailman/listinfo/ffmpeg-devel

To unsubscribe, visit link above, or email
ffmpeg-devel-request@ffmpeg.org with subject "unsubscribe".

Re: [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@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.
>
> +@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@ffmpeg.org
https://ffmpeg.org/mailman/listinfo/ffmpeg-devel

To unsubscribe, visit link above, or email
ffmpeg-devel-request@ffmpeg.org with subject "unsubscribe".

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

To unsubscribe, visit link above, or email
ffmpeg-devel-request@ffmpeg.org with subject "unsubscribe".

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

[Tobias Rapp]

On 19/01/2023 00:20, Prakash wrote:

> The problem with int milliseconds is you lose the microseconds precision.
> Sometimes there are multiple log lines within the same millisecond.

If you want to do performance profiling like comparing between assembler 
and C versions of a routine in my opinion there are better ways to do 
that than using log timestamps. But I also have nothing against adding 
more positions after the decimal point, if you prefer that.

The usecase I see for log timestamps is more to find out whether a 
warning message appeared at the begin, middle, or end of the transcoding 
process.

>   I can
> definitely move the timestamp as the first field of the log line. Let me
> fix the patch file.
>
> -Prakash.
>
Regards, Tobias

_______________________________________________
ffmpeg-devel mailing list
ffmpeg-devel@ffmpeg.org
https://ffmpeg.org/mailman/listinfo/ffmpeg-devel

To unsubscribe, visit link above, or email
ffmpeg-devel-request@ffmpeg.org with subject "unsubscribe".

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

[Prakash]

[-- Attachment #1: Type: text/plain, Size: 8459 bytes --]

Moved the timestamp to the front (before loglevel but after the prefix if
present, so the timestamp has the same color as log line based on log
level).  Updated the patch and attached again.


From 04857a7bf0d4cf24a479e795a55a61ab2e2f618e Mon Sep 17 00:00:00 2001
From: Prakash Duggaraju <duggaraju@gmail.com>
Date: Thu, 16 Feb 2023 16:06:29 -0800
Subject: [PATCH] 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@gmail.com>
---
 doc/fftools-common-opts.texi |  4 ++++
 fftools/opt_common.c         |  6 ++++++
 libavutil/log.c              | 41 +++++++++++++++++++++++++-----------
 libavutil/log.h              |  8 +++++++
 4 files changed, 47 insertions(+), 12 deletions(-)

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.
+@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.
 @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..7b892ddd1e 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;

@@ -292,13 +293,14 @@ static const char *get_level_str(int level)
 }

 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+3, 0, AV_BPRINT_SIZE_AUTOMATIC);
+    av_bprint_init(part+4, 0, 65536);

     if(type) type[0] = type[1] = AV_CLASS_CATEGORY_NA + 16;
     if (*print_prefix && avc) {
@@ -316,13 +318,26 @@ static void format_line(void *avcl, int level, const
char *fmt, va_list vl,
         if(type) type[1] = get_category(avcl);
     }

+    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;
+        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);
+    }
+
     if (*print_prefix && (level > AV_LOG_QUIET) && (flags &
AV_LOG_PRINT_LEVEL))
-        av_bprintf(part+2, "[%s] ", get_level_str(level));
+        av_bprintf(part+3, "[%s] ", get_level_str(level));

-    av_vbprintf(part+3, fmt, vl);
+    av_vbprintf(part+4, fmt, vl);

-    if(*part[0].str || *part[1].str || *part[2].str || *part[3].str) {
-        char lastc = part[3].len && part[3].len <= part[3].size ?
part[3].str[part[3].len - 1] : 0;
+    if(*part[0].str || *part[1].str || *part[2].str || *part[3].str ||
*part[4].str) {
+        char lastc = part[4].len && part[4].len <= part[4].size ?
part[4].str[part[4].len - 1] : 0;
         *print_prefix = lastc == '\n' || lastc == '\r';
     }
 }
@@ -336,12 +351,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);
+    ret = snprintf(line, line_size, "%s%s%s%s%s", part[0].str,
part[1].str, part[2].str, part[3].str, part[4].str);
+    av_bprint_finalize(part+4, NULL);
     return ret;
 }

@@ -350,7 +365,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];
@@ -366,7 +381,7 @@ void av_log_default_callback(void* ptr, int level,
const char* fmt, va_list vl)
     ff_mutex_lock(&mutex);

     format_line(ptr, level, fmt, vl, part, &print_prefix, type);
-    snprintf(line, sizeof(line), "%s%s%s%s", part[0].str, part[1].str,
part[2].str, part[3].str);
+    snprintf(line, sizeof(line), "%s%s%s%s%s", part[0].str, part[1].str,
part[2].str, part[3].str, part[4].str);

 #if HAVE_ISATTY
     if (!is_atty)
@@ -393,13 +408,15 @@ void av_log_default_callback(void* ptr, int level,
const char* fmt, va_list vl)
     colored_fputs(av_clip(level >> 3, 0, NB_LEVELS - 1), tint >> 8,
part[2].str);
     sanitize(part[3].str);
     colored_fputs(av_clip(level >> 3, 0, NB_LEVELS - 1), tint >> 8,
part[3].str);
+    sanitize(part[4].str);
+    colored_fputs(av_clip(level >> 3, 0, NB_LEVELS - 1), tint >> 8,
part[4].str);

 #if CONFIG_VALGRIND_BACKTRACE
     if (level <= BACKTRACE_LOGLEVEL)
         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 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
+ */
+#define AV_LOG_PRINT_TIME 4
+
 void av_log_set_flags(int arg);
 int av_log_get_flags(void);

-- 
2.34.1


On Thu, Jan 19, 2023 at 12:24 AM Tobias Rapp <t.rapp@noa-archive.com> wrote:

> On 19/01/2023 00:20, Prakash wrote:
>
> > The problem with int milliseconds is you lose the microseconds precision.
> > Sometimes there are multiple log lines within the same millisecond.
>
> If you want to do performance profiling like comparing between assembler
> and C versions of a routine in my opinion there are better ways to do
> that than using log timestamps. But I also have nothing against adding
> more positions after the decimal point, if you prefer that.
>
> The usecase I see for log timestamps is more to find out whether a
> warning message appeared at the begin, middle, or end of the transcoding
> process.
>
> >   I can
> > definitely move the timestamp as the first field of the log line. Let me
> > fix the patch file.
> >
> > -Prakash.
> >
> Regards, Tobias
>
> _______________________________________________
> ffmpeg-devel mailing list
> ffmpeg-devel@ffmpeg.org
> https://ffmpeg.org/mailman/listinfo/ffmpeg-devel
>
> To unsubscribe, visit link above, or email
> ffmpeg-devel-request@ffmpeg.org with subject "unsubscribe".
>

[-- Attachment #2: 0001-libavutil-log-Support-for-logging-timestamps-in-the-lo.txt --]
[-- Type: text/plain, Size: 7148 bytes --]

From 04857a7bf0d4cf24a479e795a55a61ab2e2f618e Mon Sep 17 00:00:00 2001
From: Prakash Duggaraju <duggaraju@gmail.com>
Date: Thu, 16 Feb 2023 16:06:29 -0800
Subject: [PATCH] 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@gmail.com>
---
 doc/fftools-common-opts.texi |  4 ++++
 fftools/opt_common.c         |  6 ++++++
 libavutil/log.c              | 41 +++++++++++++++++++++++++-----------
 libavutil/log.h              |  8 +++++++
 4 files changed, 47 insertions(+), 12 deletions(-)

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.
+@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.
 @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..7b892ddd1e 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;
 
@@ -292,13 +293,14 @@ static const char *get_level_str(int level)
 }
 
 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+3, 0, AV_BPRINT_SIZE_AUTOMATIC);
+    av_bprint_init(part+4, 0, 65536);
 
     if(type) type[0] = type[1] = AV_CLASS_CATEGORY_NA + 16;
     if (*print_prefix && avc) {
@@ -316,13 +318,26 @@ static void format_line(void *avcl, int level, const char *fmt, va_list vl,
         if(type) type[1] = get_category(avcl);
     }
 
+    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;
+        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);
+    }
+
     if (*print_prefix && (level > AV_LOG_QUIET) && (flags & AV_LOG_PRINT_LEVEL))
-        av_bprintf(part+2, "[%s] ", get_level_str(level));
+        av_bprintf(part+3, "[%s] ", get_level_str(level));
 
-    av_vbprintf(part+3, fmt, vl);
+    av_vbprintf(part+4, fmt, vl);
 
-    if(*part[0].str || *part[1].str || *part[2].str || *part[3].str) {
-        char lastc = part[3].len && part[3].len <= part[3].size ? part[3].str[part[3].len - 1] : 0;
+    if(*part[0].str || *part[1].str || *part[2].str || *part[3].str || *part[4].str) {
+        char lastc = part[4].len && part[4].len <= part[4].size ? part[4].str[part[4].len - 1] : 0;
         *print_prefix = lastc == '\n' || lastc == '\r';
     }
 }
@@ -336,12 +351,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);
+    ret = snprintf(line, line_size, "%s%s%s%s%s", part[0].str, part[1].str, part[2].str, part[3].str, part[4].str);
+    av_bprint_finalize(part+4, NULL);
     return ret;
 }
 
@@ -350,7 +365,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];
@@ -366,7 +381,7 @@ void av_log_default_callback(void* ptr, int level, const char* fmt, va_list vl)
     ff_mutex_lock(&mutex);
 
     format_line(ptr, level, fmt, vl, part, &print_prefix, type);
-    snprintf(line, sizeof(line), "%s%s%s%s", part[0].str, part[1].str, part[2].str, part[3].str);
+    snprintf(line, sizeof(line), "%s%s%s%s%s", part[0].str, part[1].str, part[2].str, part[3].str, part[4].str);
 
 #if HAVE_ISATTY
     if (!is_atty)
@@ -393,13 +408,15 @@ void av_log_default_callback(void* ptr, int level, const char* fmt, va_list vl)
     colored_fputs(av_clip(level >> 3, 0, NB_LEVELS - 1), tint >> 8, part[2].str);
     sanitize(part[3].str);
     colored_fputs(av_clip(level >> 3, 0, NB_LEVELS - 1), tint >> 8, part[3].str);
+    sanitize(part[4].str);
+    colored_fputs(av_clip(level >> 3, 0, NB_LEVELS - 1), tint >> 8, part[4].str);
 
 #if CONFIG_VALGRIND_BACKTRACE
     if (level <= BACKTRACE_LOGLEVEL)
         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 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
+ */
+#define AV_LOG_PRINT_TIME 4
+
 void av_log_set_flags(int arg);
 int av_log_get_flags(void);
 
-- 
2.34.1


[-- Attachment #3: Type: text/plain, Size: 251 bytes --]

_______________________________________________
ffmpeg-devel mailing list
ffmpeg-devel@ffmpeg.org
https://ffmpeg.org/mailman/listinfo/ffmpeg-devel

To unsubscribe, visit link above, or email
ffmpeg-devel-request@ffmpeg.org with subject "unsubscribe".

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

[Anton Khirnov]

Quoting Prakash (2023-02-17 01:16:04)
> Moved the timestamp to the front (before loglevel but after the prefix if
> present, so the timestamp has the same color as log line based on log
> level).  Updated the patch and attached again.
> 
> 
> From 04857a7bf0d4cf24a479e795a55a61ab2e2f618e Mon Sep 17 00:00:00 2001
> From: Prakash Duggaraju <duggaraju@gmail.com>
> Date: Thu, 16 Feb 2023 16:06:29 -0800
> Subject: [PATCH] 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@gmail.com>
> ---
>  doc/fftools-common-opts.texi |  4 ++++
>  fftools/opt_common.c         |  6 ++++++
>  libavutil/log.c              | 41 +++++++++++++++++++++++++-----------
>  libavutil/log.h              |  8 +++++++
>  4 files changed, 47 insertions(+), 12 deletions(-)

I do not like this patch.

The default logging callback should be simple and straightforward, not a
kitchen sink of all possible functionality.

Callers who need this can and should implement this themselves.

-- 
Anton Khirnov
_______________________________________________
ffmpeg-devel mailing list
ffmpeg-devel@ffmpeg.org
https://ffmpeg.org/mailman/listinfo/ffmpeg-devel

To unsubscribe, visit link above, or email
ffmpeg-devel-request@ffmpeg.org with subject "unsubscribe".

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

[Lynne]

Feb 17, 2023, 12:08 by anton@khirnov.net:

> Quoting Prakash (2023-02-17 01:16:04)
>
>> Moved the timestamp to the front (before loglevel but after the prefix if
>> present, so the timestamp has the same color as log line based on log
>> level).  Updated the patch and attached again.
>>
>>
>> From 04857a7bf0d4cf24a479e795a55a61ab2e2f618e Mon Sep 17 00:00:00 2001
>> From: Prakash Duggaraju <duggaraju@gmail.com>
>> Date: Thu, 16 Feb 2023 16:06:29 -0800
>> Subject: [PATCH] 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@gmail.com>
>> ---
>>  doc/fftools-common-opts.texi |  4 ++++
>>  fftools/opt_common.c         |  6 ++++++
>>  libavutil/log.c              | 41 +++++++++++++++++++++++++-----------
>>  libavutil/log.h              |  8 +++++++
>>  4 files changed, 47 insertions(+), 12 deletions(-)
>>
>
> I do not like this patch.
>
> The default logging callback should be simple and straightforward, not a
> kitchen sink of all possible functionality.
>
> Callers who need this can and should implement this themselves.
>

Same, having the class pointer makes it already quite busy.

_______________________________________________
ffmpeg-devel mailing list
ffmpeg-devel@ffmpeg.org
https://ffmpeg.org/mailman/listinfo/ffmpeg-devel

To unsubscribe, visit link above, or email
ffmpeg-devel-request@ffmpeg.org with subject "unsubscribe".

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

[Prakash]

Logging timestamps is a basic functionality any logging
framework/infrastructure should support.
If I am using ffmpeg as a binary then I would need this functionality built
in.
Agree that the code in log.c can definitely be simplified but didn't want
to make any changes with potential for breaking the log output.

-Prakash

On Fri, Feb 17, 2023 at 3:50 AM Lynne <dev@lynne.ee> wrote:

> Feb 17, 2023, 12:08 by anton@khirnov.net:
>
> > Quoting Prakash (2023-02-17 01:16:04)
> >
> >> Moved the timestamp to the front (before loglevel but after the prefix
> if
> >> present, so the timestamp has the same color as log line based on log
> >> level).  Updated the patch and attached again.
> >>
> >>
> >> From 04857a7bf0d4cf24a479e795a55a61ab2e2f618e Mon Sep 17 00:00:00 2001
> >> From: Prakash Duggaraju <duggaraju@gmail.com>
> >> Date: Thu, 16 Feb 2023 16:06:29 -0800
> >> Subject: [PATCH] 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@gmail.com>
> >> ---
> >>  doc/fftools-common-opts.texi |  4 ++++
> >>  fftools/opt_common.c         |  6 ++++++
> >>  libavutil/log.c              | 41 +++++++++++++++++++++++++-----------
> >>  libavutil/log.h              |  8 +++++++
> >>  4 files changed, 47 insertions(+), 12 deletions(-)
> >>
> >
> > I do not like this patch.
> >
> > The default logging callback should be simple and straightforward, not a
> > kitchen sink of all possible functionality.
> >
> > Callers who need this can and should implement this themselves.
> >
>
> Same, having the class pointer makes it already quite busy.
>
> _______________________________________________
> ffmpeg-devel mailing list
> ffmpeg-devel@ffmpeg.org
> https://ffmpeg.org/mailman/listinfo/ffmpeg-devel
>
> To unsubscribe, visit link above, or email
> ffmpeg-devel-request@ffmpeg.org with subject "unsubscribe".
>
_______________________________________________
ffmpeg-devel mailing list
ffmpeg-devel@ffmpeg.org
https://ffmpeg.org/mailman/listinfo/ffmpeg-devel

To unsubscribe, visit link above, or email
ffmpeg-devel-request@ffmpeg.org with subject "unsubscribe".