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

[Prakash <duggaraju@gmail.com>]

[-- 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".