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

[Soft Works]

This commit adds two logging flags: 'timing' and 'datetiming'.

Usage:

ffmpeg -loglevel +timing

or

ffmpeg -loglevel +datetiming
---
 fftools/cmdutils.c | 14 ++++++++++++++
 libavutil/log.c    | 37 ++++++++++++++++++++++++++++++++-----
 libavutil/log.h    | 10 ++++++++++
 3 files changed, 56 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/libavutil/log.c b/libavutil/log.c
index 93a156b8e4..16a1d13d1d 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) {
@@ -268,6 +288,10 @@ static void format_line(void *avcl, int level, const char *fmt, va_list vl,
         if(type) type[1] = get_category(avcl);
     }
 
+    if (*print_prefix
+        && ((flags & AV_LOG_PRINT_TIME) || (flags & AV_LOG_PRINT_DATETIME)))
+        format_date_now(&part[4], flags & AV_LOG_PRINT_DATETIME);
+
     if (*print_prefix && (level > AV_LOG_QUIET) && (flags & AV_LOG_PRINT_LEVEL))
         av_bprintf(part+2, "[%s] ", get_level_str(level));
 
@@ -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..34ccded4bc 100644
--- a/libavutil/log.h
+++ b/libavutil/log.h
@@ -352,6 +352,16 @@ 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
+
 void av_log_set_flags(int arg);
 int av_log_get_flags(void);
 
-- 
2.17.1.windows.2