diff mbox

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

Message ID MN2PR13MB27524DB8A461B08F45729B87BA8F0@MN2PR13MB2752.namprd13.prod.outlook.com
State New
Headers show

Commit Message

Soft Works Sept. 17, 2019, 12:07 a.m. UTC
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(-)

Comments

Moritz Barsnick Sept. 17, 2019, 9:06 p.m. UTC | #1
On Tue, Sep 17, 2019 at 00:07:37 +0000, Soft Works wrote:
> This commit adds two logging flags: 'timing' and 'datetiming'.

I like the whole idea. I haven't tested yet, but I will in a moment.

> Usage:
> ffmpeg -loglevel +timing
> or
> ffmpeg -loglevel +datetiming

Have you considered what happens if you do
$ ffmpeg -loglevel +timing+datetiming
?

(It just seems a bit weird having one flag being a superset of another.
I don't mind otherwise.)

>  fftools/cmdutils.c | 14 ++++++++++++++
>  libavutil/log.c    | 37 ++++++++++++++++++++++++++++++++-----
>  libavutil/log.h    | 10 ++++++++++

You also need to add documentation for these options to
doc/fftools-common-opts.texi (section "@item -loglevel").

libavutil/log.h is part of the API, IIUC. So you should bump
libavutil's micro version, and even add an entry into doc/APIchanges.

> +        && ((flags & AV_LOG_PRINT_TIME) || (flags & AV_LOG_PRINT_DATETIME)))
> +        format_date_now(&part[4], flags & AV_LOG_PRINT_DATETIME);

According to the style of the other calls, you could express "&part[4]"
as "part+4".

>      if (*print_prefix && (level > AV_LOG_QUIET) && (flags & AV_LOG_PRINT_LEVEL))
>          av_bprintf(part+2, "[%s] ", get_level_str(level));

(As done here.)

Moritz
Soft Works Sept. 18, 2019, 12:38 a.m. UTC | #2
> -----Original Message-----

> From: ffmpeg-devel <ffmpeg-devel-bounces@ffmpeg.org> On Behalf Of

> Moritz Barsnick

> Sent: Tuesday, September 17, 2019 11:07 PM

> To: FFmpeg development discussions and patches <ffmpeg-

> devel@ffmpeg.org>

> Subject: Re: [FFmpeg-devel] [PATCH v2] Add option to log timing

> 

> On Tue, Sep 17, 2019 at 00:07:37 +0000, Soft Works wrote:

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

> 

> I like the whole idea. I haven't tested yet, but I will in a moment.

> 

> > Usage:

> > ffmpeg -loglevel +timing

> > or

> > ffmpeg -loglevel +datetiming

> 

> Have you considered what happens if you do $ ffmpeg -loglevel

> +timing+datetiming ?


It will print date + time.

> (It just seems a bit weird having one flag being a superset of another.

> I don't mind otherwise.)


You're correct, It's a superset. I found it more convenient to do it like this because:
- It would make little sense printing only the date for each line
- I wanted to avoid requiring a user to specify two separate flags to get both date and time

But I wouldn't mind changing this to independent flags

> You also need to add documentation for these options to doc/fftools-

> common-opts.texi (section "@item -loglevel").


Damn, this is going to get more work than expected ;-)

> libavutil/log.h is part of the API, IIUC. So you should bump libavutil's micro

> version, and even add an entry into doc/APIchanges.


OK.

> > +        && ((flags & AV_LOG_PRINT_TIME) || (flags &

> AV_LOG_PRINT_DATETIME)))

> > +        format_date_now(&part[4], flags & AV_LOG_PRINT_DATETIME);

> 

> According to the style of the other calls, you could express "&part[4]"

> as "part+4".


I won't argue - conformity wins of course.


Thanks for looking into this, I'll wait for other comments before updating the patch.

softworkz
Moritz Barsnick Sept. 18, 2019, 1:47 p.m. UTC | #3
On Wed, Sep 18, 2019 at 00:38:13 +0000, Soft Works wrote:
> You're correct, It's a superset. I found it more convenient to do it like this because:
> - It would make little sense printing only the date for each line
> - I wanted to avoid requiring a user to specify two separate flags to get both date and time
>
> But I wouldn't mind changing this to independent flags

It's okay by me, I was just pointing it out. Others may want to
comment.

> > You also need to add documentation for these options to doc/fftools-
> > common-opts.texi (section "@item -loglevel").
>
> Damn, this is going to get more work than expected ;-)

But it's easy just to add a few words. :-) (Be sure to rebuild the docs
as well, to ensure that your edits don't break the markup syntax.)

> Thanks for looking into this, I'll wait for other comments before updating the patch.

I always get a final date/time line without a terminating line break,
which is quite ugly:

barsnick@sunshine:/usr/new/tools/video/ffmpeg/ffmpeg-snapshot-2019-09-17 > ffmpeg -loglevel +datetiming -f lavfi -i testsrc2=g=x
2019-09-18 15:43:16.455 ffmpeg version N-94957-g65589ad Copyright (c) 2000-2019 the FFmpeg developers
2019-09-18 15:43:16.457   built with icc (ICC) 14.0.3 20140422
2019-09-18 15:43:16.457   configuration: --prefix=/usr/new/tools/video/install/ffmpeg/2019-09-17 --cc=icc --cxx=icpc --enable-gpl --enable-version3 --enable-nonfree --dis
able-shared --enable-gnutls --enable-libcdio --enable-libfreetype --enable-libx264 --enable-libvpx --enable-libmp3lame --enable-openal --enable-libopencore-amrnb --enable
-libopencore-amrwb --enable-libtwolame --enable-librtmp --enable-libass --enable-libv4l2 --enable-libvidstab --enable-libfdk-aac --enable-libsmbclient --enable-libzvbi --
enable-libtesseract --enable-libzmq --enable-libopus --enable-libcodec2 --enable-libxml2 --enable-libopencv
2019-09-18 15:43:16.458   libavutil      56. 35.100 / 56. 35.100
2019-09-18 15:43:16.459   libavcodec     58. 57.100 / 58. 57.100
2019-09-18 15:43:16.459   libavformat    58. 33.100 / 58. 33.100
2019-09-18 15:43:16.460   libavdevice    58.  9.100 / 58.  9.100
2019-09-18 15:43:16.461   libavfilter     7. 58.102 /  7. 58.102
2019-09-18 15:43:16.461   libswscale      5.  6.100 /  5.  6.100
2019-09-18 15:43:16.462   libswresample   3.  6.100 /  3.  6.100
2019-09-18 15:43:16.463   libpostproc    55.  6.100 / 55.  6.100
2019-09-18 15:43:16.465 [Parsed_testsrc2_0 @ 0xb24fa40] Option 'g' not found
2019-09-18 15:43:16.466 [lavfi @ 0xb24ea80] Error initializing filter 'testsrc2' with args 'g=x'
2019-09-18 15:43:16.468 testsrc2=g=x: Option not found
2019-09-18 15:43:16.469 barsnick@sunshine:/usr/new/tools/video/ffmpeg/ffmpeg-snapshot-2019-09-17 >

(See my new shell prompt appearing on the same line as the final
timestamp.)

Please try to find out why that is and whether it can be fixed without
a hack.

Moritz
diff mbox

Patch

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