[PATCH 0/3] Add option to log timing
This pathcset adds two logging flags: 'timing' and 'datetiming'. Usage: ffmpeg -loglevel +timing or ffmpeg -loglevel +datetiming softworkz (3): avutil/log: support logging of date and timing information fftools/opt_common: add timing and datetiming log flags doc/fftools-common-opts: document log timing flags doc/APIchanges | 3 +++ doc/fftools-common-opts.texi | 4 ++++ fftools/opt_common.c | 12 ++++++++++++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 4 ++-- 6 files changed, 60 insertions(+), 5 deletions(-) base-commit: 48cb2c7a8a2deca40dd2f143848dd5addc25465c Published-As: https://github.com/ffstaging/FFmpeg/releases/tag/pr-ffstaging-37%2Fsoftworkz... Fetch-It-Via: git fetch https://github.com/ffstaging/FFmpeg pr-ffstaging-37/softworkz/submit_logtiming-v1 Pull-Request: https://github.com/ffstaging/FFmpeg/pull/37 -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> Signed-off-by: softworkz <softworkz@hotmail.com> --- doc/APIchanges | 3 +++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 4 ++-- 4 files changed, 44 insertions(+), 5 deletions(-) diff --git a/doc/APIchanges b/doc/APIchanges index 4c0c9db628..eae5ba0525 100644 --- a/doc/APIchanges +++ b/doc/APIchanges @@ -14,6 +14,9 @@ libavutil: 2021-04-27 API changes, most recent first: +2022-08-xx - xxxxxxxxxx - lavu 57.34.100 - log.h + Add flags AV_LOG_PRINT_TIME and AV_LOG_PRINT_DATETIME. + 2022-08-xx - xxxxxxxxxx - lavf 59 - avformat.h Deprecate av_stream_get_end_pts() without replacement. diff --git a/libavutil/log.c b/libavutil/log.c index 5948e50467..15a43c1631 100644 --- a/libavutil/log.c +++ b/libavutil/log.c @@ -42,6 +42,8 @@ #include "internal.h" #include "log.h" #include "thread.h" +#include "time.h" +#include "time_internal.h" static AVMutex mutex = AV_MUTEX_INITIALIZER; @@ -291,14 +293,32 @@ static const char *get_level_str(int level) } } +static void format_date_now(AVBPrint* timeBuf, int include_date) +{ + struct tm *ptm, tmbuf; + const int64_t time_us = av_gettime(); + const int64_t time_ms = time_us / 1000; + const time_t time_s = time_ms / 1000; + const 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) { @@ -316,6 +336,9 @@ 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 | 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)); @@ -336,7 +359,7 @@ 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); @@ -350,7 +373,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]; @@ -385,6 +408,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); diff --git a/libavutil/log.h b/libavutil/log.h index ab7ceabe22..8336f65b16 100644 --- a/libavutil/log.h +++ b/libavutil/log.h @@ -377,6 +377,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); diff --git a/libavutil/version.h b/libavutil/version.h index 05661922b3..5d0df781cc 100644 --- a/libavutil/version.h +++ b/libavutil/version.h @@ -79,8 +79,8 @@ */ #define LIBAVUTIL_VERSION_MAJOR 57 -#define LIBAVUTIL_VERSION_MINOR 33 -#define LIBAVUTIL_VERSION_MICRO 101 +#define LIBAVUTIL_VERSION_MINOR 34 +#define LIBAVUTIL_VERSION_MICRO 100 #define LIBAVUTIL_VERSION_INT AV_VERSION_INT(LIBAVUTIL_VERSION_MAJOR, \ LIBAVUTIL_VERSION_MINOR, \ -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> This commit adds two logging flags: 'timing' and 'datetiming'. Usage: ffmpeg -loglevel +timing or ffmpeg -loglevel +datetiming Signed-off-by: softworkz <softworkz@hotmail.com> --- fftools/opt_common.c | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/fftools/opt_common.c b/fftools/opt_common.c index ae5e28a5af..bd8430751c 100644 --- a/fftools/opt_common.c +++ b/fftools/opt_common.c @@ -1268,6 +1268,18 @@ int opt_loglevel(void *optctx, const char *opt, const char *arg) } else { flags |= AV_LOG_PRINT_LEVEL; } + } else if (av_strstart(token, "timing", &arg)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_TIME; + } else { + flags |= AV_LOG_PRINT_TIME; + } + } else if (av_strstart(token, "datetiming", &arg)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_DATETIME; + } else { + flags |= AV_LOG_PRINT_DATETIME; + } } else { break; } -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> Signed-off-by: softworkz <softworkz@hotmail.com> --- doc/fftools-common-opts.texi | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/doc/fftools-common-opts.texi b/doc/fftools-common-opts.texi index d9145704d6..eee3b6ead0 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 timing +Indicates that log lines should be prefixed with timing information. +@item datetiming +Indicates that log lines should be prefixed with date and timing information. @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 -- ffmpeg-codebot
Ping again Thanks
-----Original Message----- From: ffmpegagent <ffmpegagent@gmail.com> Sent: Wednesday, August 24, 2022 9:38 PM To: ffmpeg-devel@ffmpeg.org Cc: softworkz <softworkz@hotmail.com> Subject: [PATCH 0/3] Add option to log timing
This pathcset adds two logging flags: 'timing' and 'datetiming'.
Usage:
ffmpeg -loglevel +timing
or
ffmpeg -loglevel +datetiming
softworkz (3): avutil/log: support logging of date and timing information fftools/opt_common: add timing and datetiming log flags doc/fftools-common-opts: document log timing flags
doc/APIchanges | 3 +++ doc/fftools-common-opts.texi | 4 ++++ fftools/opt_common.c | 12 ++++++++++++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 4 ++-- 6 files changed, 60 insertions(+), 5 deletions(-)
base-commit: 48cb2c7a8a2deca40dd2f143848dd5addc25465c Published-As: https://github.com/ffstaging/FFmpeg/releases/tag/pr- ffstaging-37%2Fsoftworkz%2Fsubmit_logtiming-v1 Fetch-It-Via: git fetch https://github.com/ffstaging/FFmpeg pr- ffstaging-37/softworkz/submit_logtiming-v1 Pull-Request: https://github.com/ffstaging/FFmpeg/pull/37 -- ffmpeg-codebot
This pathcset adds two logging flags: 'timing' and 'datetiming'. Usage: ffmpeg -loglevel +timing or ffmpeg -loglevel +datetiming Update V2 * Fix merge conflicts Update V3 * Rebased softworkz (3): avutil/log: support logging of date and timing information fftools/opt_common: add timing and datetiming log flags doc/fftools-common-opts: document log timing flags doc/APIchanges | 3 +++ doc/fftools-common-opts.texi | 4 ++++ fftools/opt_common.c | 12 ++++++++++++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 2 +- 6 files changed, 59 insertions(+), 4 deletions(-) base-commit: 4ba9ae7742a6f8a29d6486e25ff5709a075edb5b Published-As: https://github.com/ffstaging/FFmpeg/releases/tag/pr-ffstaging-37%2Fsoftworkz... Fetch-It-Via: git fetch https://github.com/ffstaging/FFmpeg pr-ffstaging-37/softworkz/submit_logtiming-v2 Pull-Request: https://github.com/ffstaging/FFmpeg/pull/37 Range-diff vs v1: 1: 5dc718cfd5 ! 1: 13a7dc164b avutil/log: support logging of date and timing information @@ Commit message Signed-off-by: softworkz <softworkz@hotmail.com> ## doc/APIchanges ## -@@ doc/APIchanges: libavutil: 2021-04-27 +@@ doc/APIchanges: The last version increases of all libraries were on 2024-03-07 API changes, most recent first: -+2022-08-xx - xxxxxxxxxx - lavu 57.34.100 - log.h ++2025-01-xx - xxxxxxxxxx - lavu 59.57.100 - log.h + Add flags AV_LOG_PRINT_TIME and AV_LOG_PRINT_DATETIME. + - 2022-08-xx - xxxxxxxxxx - lavf 59 - avformat.h - Deprecate av_stream_get_end_pts() without replacement. + 2025-01-25 - xxxxxxxxxx - lavu 59.56.100 - frame.h + Add AV_SIDE_DATA_PROP_CHANNEL_DEPENDENT. ## libavutil/log.c ## @@ libavutil/log.c static AVMutex mutex = AV_MUTEX_INITIALIZER; -@@ libavutil/log.c: static const char *get_level_str(int level) - } +@@ libavutil/log.c: static const char *item_name(void *obj, const AVClass *cls) + return (cls->item_name ? cls->item_name : av_default_item_name)(obj); } +static void format_date_now(AVBPrint* timeBuf, int include_date) @@ libavutil/version.h @@ */ - #define LIBAVUTIL_VERSION_MAJOR 57 --#define LIBAVUTIL_VERSION_MINOR 33 --#define LIBAVUTIL_VERSION_MICRO 101 -+#define LIBAVUTIL_VERSION_MINOR 34 -+#define LIBAVUTIL_VERSION_MICRO 100 + #define LIBAVUTIL_VERSION_MAJOR 59 +-#define LIBAVUTIL_VERSION_MINOR 56 ++#define LIBAVUTIL_VERSION_MINOR 57 + #define LIBAVUTIL_VERSION_MICRO 100 #define LIBAVUTIL_VERSION_INT AV_VERSION_INT(LIBAVUTIL_VERSION_MAJOR, \ - LIBAVUTIL_VERSION_MINOR, \ 2: 23f6cad25e = 2: 9eb9a6cf48 fftools/opt_common: add timing and datetiming log flags 3: 595d03037f = 3: 20e049c4c7 doc/fftools-common-opts: document log timing flags -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> Signed-off-by: softworkz <softworkz@hotmail.com> --- doc/APIchanges | 3 +++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 2 +- 4 files changed, 43 insertions(+), 4 deletions(-) diff --git a/doc/APIchanges b/doc/APIchanges index 0f2b640601..83d57ae314 100644 --- a/doc/APIchanges +++ b/doc/APIchanges @@ -2,6 +2,9 @@ The last version increases of all libraries were on 2024-03-07 API changes, most recent first: +2025-01-xx - xxxxxxxxxx - lavu 59.57.100 - log.h + Add flags AV_LOG_PRINT_TIME and AV_LOG_PRINT_DATETIME. + 2025-01-25 - xxxxxxxxxx - lavu 59.56.100 - frame.h Add AV_SIDE_DATA_PROP_CHANNEL_DEPENDENT. diff --git a/libavutil/log.c b/libavutil/log.c index 46662f3db0..3ea6cb671e 100644 --- a/libavutil/log.c +++ b/libavutil/log.c @@ -42,6 +42,8 @@ #include "internal.h" #include "log.h" #include "thread.h" +#include "time.h" +#include "time_internal.h" static AVMutex mutex = AV_MUTEX_INITIALIZER; @@ -296,14 +298,32 @@ static const char *item_name(void *obj, const AVClass *cls) return (cls->item_name ? cls->item_name : av_default_item_name)(obj); } +static void format_date_now(AVBPrint* timeBuf, int include_date) +{ + struct tm *ptm, tmbuf; + const int64_t time_us = av_gettime(); + const int64_t time_ms = time_us / 1000; + const time_t time_s = time_ms / 1000; + const 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) { @@ -321,6 +341,9 @@ 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 | 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)); @@ -341,7 +364,7 @@ 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); @@ -355,7 +378,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]; @@ -390,6 +413,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); diff --git a/libavutil/log.h b/libavutil/log.h index 4c8c92266f..dd094307ce 100644 --- a/libavutil/log.h +++ b/libavutil/log.h @@ -406,6 +406,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); diff --git a/libavutil/version.h b/libavutil/version.h index 83b7822125..ee4a36cb17 100644 --- a/libavutil/version.h +++ b/libavutil/version.h @@ -79,7 +79,7 @@ */ #define LIBAVUTIL_VERSION_MAJOR 59 -#define LIBAVUTIL_VERSION_MINOR 56 +#define LIBAVUTIL_VERSION_MINOR 57 #define LIBAVUTIL_VERSION_MICRO 100 #define LIBAVUTIL_VERSION_INT AV_VERSION_INT(LIBAVUTIL_VERSION_MAJOR, \ -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> This commit adds two logging flags: 'timing' and 'datetiming'. Usage: ffmpeg -loglevel +timing or ffmpeg -loglevel +datetiming Signed-off-by: softworkz <softworkz@hotmail.com> --- fftools/opt_common.c | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/fftools/opt_common.c b/fftools/opt_common.c index 34da2cee7d..94e9dae8b6 100644 --- a/fftools/opt_common.c +++ b/fftools/opt_common.c @@ -1292,6 +1292,18 @@ int opt_loglevel(void *optctx, const char *opt, const char *arg) } else { flags |= AV_LOG_PRINT_LEVEL; } + } else if (av_strstart(token, "timing", &arg)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_TIME; + } else { + flags |= AV_LOG_PRINT_TIME; + } + } else if (av_strstart(token, "datetiming", &arg)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_DATETIME; + } else { + flags |= AV_LOG_PRINT_DATETIME; + } } else { break; } -- ffmpeg-codebot
Hi softworkz On Thu, Jan 30, 2025 at 03:53:25AM +0000, softworkz wrote:
From: softworkz <softworkz@hotmail.com>
This commit adds two logging flags: 'timing' and 'datetiming'.
Usage:
ffmpeg -loglevel +timing
or
ffmpeg -loglevel +datetiming
./ffmpeg -loglevel +timing ... 02:04:00.926 Use -h to get full help or, even better, run 'man ffmpeg' 02:04:00.926 michael@box:~/ffmpeg/$ It seems the shell command prompt is after the last time is this intended ? thx [...] -- Michael GnuPG fingerprint: 9FF2128B147EF6730BADF133611EC787040B0FAB Take away the freedom of one citizen and you will be jailed, take away the freedom of all citizens and you will be congratulated by your peers in Parliament.
Hi Michael, thanks a lot for looking at this.
-----Original Message----- From: ffmpeg-devel <ffmpeg-devel-bounces@ffmpeg.org> On Behalf Of Michael Niedermayer Sent: Sunday, February 2, 2025 2:14 AM To: FFmpeg development discussions and patches <ffmpeg- devel@ffmpeg.org> Subject: Re: [FFmpeg-devel] [PATCH v2 2/3] fftools/opt_common: add timing and datetiming log flags
Hi softworkz
On Thu, Jan 30, 2025 at 03:53:25AM +0000, softworkz wrote:
From: softworkz <softworkz@hotmail.com>
This commit adds two logging flags: 'timing' and 'datetiming'.
Usage:
ffmpeg -loglevel +timing
or
ffmpeg -loglevel +datetiming
./ffmpeg -loglevel +timing ... 02:04:00.926 Use -h to get full help or, even better, run 'man ffmpeg' 02:04:00.926 michael@box:~/ffmpeg/$
It seems the shell command prompt is after the last time is this intended ?
Of course not 😊 Where it's in use, I had also added printing of the word "EXIT" before exiting (to easily recognize crashed or killed vs regular terminations), that's probably why I've never seen this. Will submit an update, thank you very much, sw
From: softworkz <softworkz@hotmail.com> Signed-off-by: softworkz <softworkz@hotmail.com> --- doc/fftools-common-opts.texi | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/doc/fftools-common-opts.texi b/doc/fftools-common-opts.texi index 8b0931a86d..37bed92864 100644 --- a/doc/fftools-common-opts.texi +++ b/doc/fftools-common-opts.texi @@ -226,6 +226,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 timing +Indicates that log lines should be prefixed with timing information. +@item datetiming +Indicates that log lines should be prefixed with date and timing information. @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 -- ffmpeg-codebot
This pathcset adds two logging flags: 'timing' and 'datetiming'. Usage: ffmpeg -loglevel +timing or ffmpeg -loglevel +datetiming Update V1 * Fix merge conflicts Update V2 * Rebased Update V3 * Fix print timing on exit (as reported by Michael Niedermayer) softworkz (3): avutil/log: support logging of date and timing information fftools/opt_common: add timing and datetiming log flags doc/fftools-common-opts: document log timing flags doc/APIchanges | 3 +++ doc/fftools-common-opts.texi | 4 ++++ fftools/ffmpeg.c | 1 + fftools/opt_common.c | 12 ++++++++++++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 2 +- 7 files changed, 60 insertions(+), 4 deletions(-) base-commit: 4ba9ae7742a6f8a29d6486e25ff5709a075edb5b Published-As: https://github.com/ffstaging/FFmpeg/releases/tag/pr-ffstaging-37%2Fsoftworkz... Fetch-It-Via: git fetch https://github.com/ffstaging/FFmpeg pr-ffstaging-37/softworkz/submit_logtiming-v3 Pull-Request: https://github.com/ffstaging/FFmpeg/pull/37 Range-diff vs v2: 1: 13a7dc164b = 1: 13a7dc164b avutil/log: support logging of date and timing information 2: 9eb9a6cf48 ! 2: 6c435fc02d fftools/opt_common: add timing and datetiming log flags @@ Commit message ffmpeg -loglevel +datetiming + Setting av_log_set_flags(0) in term_exit in ffmpeg.c prevents + timing to be printed when exiting. + Signed-off-by: softworkz <softworkz@hotmail.com> + ## fftools/ffmpeg.c ## +@@ fftools/ffmpeg.c: static void term_exit_sigsafe(void) + + void term_exit(void) + { ++ av_log_set_flags(0); + av_log(NULL, AV_LOG_QUIET, "%s", ""); + term_exit_sigsafe(); + } + ## fftools/opt_common.c ## @@ fftools/opt_common.c: int opt_loglevel(void *optctx, const char *opt, const char *arg) } else { 3: 20e049c4c7 = 3: f0aa91d5c1 doc/fftools-common-opts: document log timing flags -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> Signed-off-by: softworkz <softworkz@hotmail.com> --- doc/APIchanges | 3 +++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 2 +- 4 files changed, 43 insertions(+), 4 deletions(-) diff --git a/doc/APIchanges b/doc/APIchanges index 0f2b640601..83d57ae314 100644 --- a/doc/APIchanges +++ b/doc/APIchanges @@ -2,6 +2,9 @@ The last version increases of all libraries were on 2024-03-07 API changes, most recent first: +2025-01-xx - xxxxxxxxxx - lavu 59.57.100 - log.h + Add flags AV_LOG_PRINT_TIME and AV_LOG_PRINT_DATETIME. + 2025-01-25 - xxxxxxxxxx - lavu 59.56.100 - frame.h Add AV_SIDE_DATA_PROP_CHANNEL_DEPENDENT. diff --git a/libavutil/log.c b/libavutil/log.c index 46662f3db0..3ea6cb671e 100644 --- a/libavutil/log.c +++ b/libavutil/log.c @@ -42,6 +42,8 @@ #include "internal.h" #include "log.h" #include "thread.h" +#include "time.h" +#include "time_internal.h" static AVMutex mutex = AV_MUTEX_INITIALIZER; @@ -296,14 +298,32 @@ static const char *item_name(void *obj, const AVClass *cls) return (cls->item_name ? cls->item_name : av_default_item_name)(obj); } +static void format_date_now(AVBPrint* timeBuf, int include_date) +{ + struct tm *ptm, tmbuf; + const int64_t time_us = av_gettime(); + const int64_t time_ms = time_us / 1000; + const time_t time_s = time_ms / 1000; + const 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) { @@ -321,6 +341,9 @@ 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 | 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)); @@ -341,7 +364,7 @@ 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); @@ -355,7 +378,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]; @@ -390,6 +413,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); diff --git a/libavutil/log.h b/libavutil/log.h index 4c8c92266f..dd094307ce 100644 --- a/libavutil/log.h +++ b/libavutil/log.h @@ -406,6 +406,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); diff --git a/libavutil/version.h b/libavutil/version.h index 83b7822125..ee4a36cb17 100644 --- a/libavutil/version.h +++ b/libavutil/version.h @@ -79,7 +79,7 @@ */ #define LIBAVUTIL_VERSION_MAJOR 59 -#define LIBAVUTIL_VERSION_MINOR 56 +#define LIBAVUTIL_VERSION_MINOR 57 #define LIBAVUTIL_VERSION_MICRO 100 #define LIBAVUTIL_VERSION_INT AV_VERSION_INT(LIBAVUTIL_VERSION_MAJOR, \ -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> This commit adds two logging flags: 'timing' and 'datetiming'. Usage: ffmpeg -loglevel +timing or ffmpeg -loglevel +datetiming Setting av_log_set_flags(0) in term_exit in ffmpeg.c prevents timing to be printed when exiting. Signed-off-by: softworkz <softworkz@hotmail.com> --- fftools/ffmpeg.c | 1 + fftools/opt_common.c | 12 ++++++++++++ 2 files changed, 13 insertions(+) diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c index dc321fb4a2..f4c717afaa 100644 --- a/fftools/ffmpeg.c +++ b/fftools/ffmpeg.c @@ -130,6 +130,7 @@ static void term_exit_sigsafe(void) void term_exit(void) { + av_log_set_flags(0); av_log(NULL, AV_LOG_QUIET, "%s", ""); term_exit_sigsafe(); } diff --git a/fftools/opt_common.c b/fftools/opt_common.c index 34da2cee7d..94e9dae8b6 100644 --- a/fftools/opt_common.c +++ b/fftools/opt_common.c @@ -1292,6 +1292,18 @@ int opt_loglevel(void *optctx, const char *opt, const char *arg) } else { flags |= AV_LOG_PRINT_LEVEL; } + } else if (av_strstart(token, "timing", &arg)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_TIME; + } else { + flags |= AV_LOG_PRINT_TIME; + } + } else if (av_strstart(token, "datetiming", &arg)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_DATETIME; + } else { + flags |= AV_LOG_PRINT_DATETIME; + } } else { break; } -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> Signed-off-by: softworkz <softworkz@hotmail.com> --- doc/fftools-common-opts.texi | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/doc/fftools-common-opts.texi b/doc/fftools-common-opts.texi index 8b0931a86d..37bed92864 100644 --- a/doc/fftools-common-opts.texi +++ b/doc/fftools-common-opts.texi @@ -226,6 +226,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 timing +Indicates that log lines should be prefixed with timing information. +@item datetiming +Indicates that log lines should be prefixed with date and timing information. @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 -- ffmpeg-codebot
It works good. First pass thoughts: 1- Rename `timeBuf` -> `bp_time`, in this way it follows snake case convention and conveys clearly that the parameter is an `AVBPrint` 2- Option switch: +datetime and +time feels lighter/easier (vs. -ing) 3- Term color: the space after the time keeps the background of the time, which looks odd IMO with terminal emulator color schemes that show the background. Not sure if this is intentional. Let me know if you need a screenshot. 4- (Optional): how would you feel about RFC3339 representation? If machine parsing is a goal for this.
-----Original Message----- From: Marth64 <marth64@proxyid.net> Sent: Friday, February 7, 2025 4:58 AM To: FFmpeg development discussions and patches <ffmpeg- devel@ffmpeg.org> Cc: Michael Niedermayer <michael@niedermayer.cc>; softworkz <softworkz@hotmail.com>; Soft Works <softworkz-at- hotmail.com@ffmpeg.org> Subject: Re: [FFmpeg-devel] [PATCH v3 0/3] Add option to log timing
It works good.
Millions of log lines were written with it already :-)
First pass thoughts: 1- Rename `timeBuf` -> `bp_time`, in this way it follows snake case convention and conveys clearly that the parameter is an `AVBPrint`
Oops, missed that.
2- Option switch: +datetime and +time feels lighter/easier (vs. -ing)
Sure, I don't remember how I even came to the 'ing'.
3- Term color: the space after the time keeps the background of the time, which looks odd IMO with terminal emulator color schemes that show the background. Not sure if this is intentional. Let me know if you need a screenshot.
Here are two screenshots: https://gist.github.com/softworkz/f78a6a4973f804b9381fe37d5f75f9ea I suppose the lower one is what you are referring to, but in the upper one you can see that there are many lines with black background where it would probably also be odd when there's a single white space in-between. That being said, I don't really care about coloring so I'll gladly change it to whichever way is desired.
4- (Optional): how would you feel about RFC3339 representation? If machine parsing is a goal for this.
What I feel is that the T and Z letters make it just much harder to read. Why wouldn't it be machine-parsable without those letters? Thanks sw
it would probably also be odd when there's a single white space in-between. Yes, it would look worse on white background. OK as is, then.
Why wouldn't it be machine-parsable without those letters? It is more about having timezone, etc. I actually think it is better for readability as is, but was checking if preservation for machine parsing* (phrasing what I meant better) was a goal, then it should be compliant. But I don't see much value in that.
Thanks
The example I was thinking of was if I wanted to look at the logs 2 years later, it would have time zone in case of DST or whatever. But it's a total obscure stretch case IMO. I'm not advocating for it, just sharing what I meant with my logic. (And if someone really needs it later they can make a +rfc3339 switch or whatever)
-----Original Message----- From: Marth64 <marth64@proxyid.net> Sent: Friday, February 7, 2025 5:47 AM To: Soft Works <softworkz@hotmail.com> Cc: FFmpeg development discussions and patches <ffmpeg- devel@ffmpeg.org>; Michael Niedermayer <michael@niedermayer.cc>; Soft Works <softworkz-at-hotmail.com@ffmpeg.org> Subject: Re: [FFmpeg-devel] [PATCH v3 0/3] Add option to log timing
it would probably also be odd when there's a single white space in- between.
Yes, it would look worse on white background. OK as is, then.
Fine. If someone has a specific wish or idea, feel free to comment.
Why wouldn't it be machine-parsable without those letters?
It is more about having timezone, etc. I actually think it is better for readability as is, but was checking if preservation for machine parsing* (phrasing what I meant better) was a goal, then it should be compliant. But I don't see much value in that.
We actually parse this output in some analysis tool, but only the time.
The example I was thinking of was if I wanted to look at the logs 2 years later, it would have time zone in case of DST or whatever. But it's a total obscure stretch case IMO. I'm not advocating for it, just sharing what I meant with my logic. (And if someone really needs it later they can make a +rfc3339 switch or whatever)
I don’t find that case "obscure" at all. In fact, the time zone can get really important when correlating information from multiple log files (e.g. ffmpeg + application). For this, we are printing the full date with time zone just once at the top of the logs and let ffmpeg print the time only. The date occupies a lot of horizontal screen estate which is inconvenient for manual review and largely redundant anyway. The only corner case would be a long-running process where ffmpeg doesn't print a single log line for a whole day - in that case, the time-only output would become ambiguous.. Thanks sw
I meant obscure in the context of running ffmpeg CLI in a short lived (<1 day) session for the average user. Nonetheless I am good. Thanks!
This pathcset adds two logging flags: 'timing' and 'datetiming'. Usage: ffmpeg -loglevel +timing or ffmpeg -loglevel +datetiming Update V1 * Fix merge conflicts Update V2 * Rebased Update V3 * Fix print timing on exit (as reported by Michael Niedermayer) softworkz (3): avutil/log: support logging of date and timing information fftools/opt_common: add timing and datetiming log flags doc/fftools-common-opts: document log timing flags doc/APIchanges | 3 +++ doc/fftools-common-opts.texi | 4 ++++ fftools/ffmpeg.c | 1 + fftools/opt_common.c | 12 ++++++++++++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 2 +- 7 files changed, 60 insertions(+), 4 deletions(-) base-commit: 4ba9ae7742a6f8a29d6486e25ff5709a075edb5b Published-As: https://github.com/ffstaging/FFmpeg/releases/tag/pr-ffstaging-37%2Fsoftworkz... Fetch-It-Via: git fetch https://github.com/ffstaging/FFmpeg pr-ffstaging-37/softworkz/submit_logtiming-v4 Pull-Request: https://github.com/ffstaging/FFmpeg/pull/37 Range-diff vs v3: 1: 13a7dc164b ! 1: 2871595d3b avutil/log: support logging of date and timing information @@ libavutil/log.c: static const char *item_name(void *obj, const AVClass *cls) return (cls->item_name ? cls->item_name : av_default_item_name)(obj); } -+static void format_date_now(AVBPrint* timeBuf, int include_date) ++static void format_date_now(AVBPrint* bp_time, int include_date) +{ + struct tm *ptm, tmbuf; + const int64_t time_us = av_gettime(); @@ libavutil/log.c: static const char *item_name(void *obj, const AVClass *cls) + ptm = localtime_r(&time_s, &tmbuf); + if (ptm) { + if (include_date) -+ av_bprint_strftime(timeBuf, "%Y-%m-%d ", ptm); ++ av_bprint_strftime(bp_time, "%Y-%m-%d ", ptm); + -+ av_bprint_strftime(timeBuf, "%H:%M:%S", ptm); -+ av_bprintf(timeBuf, ".%03d ", millisec); ++ av_bprint_strftime(bp_time, "%H:%M:%S", ptm); ++ av_bprintf(bp_time, ".%03d ", millisec); + } +} + 2: 6c435fc02d ! 2: aed251e1f5 fftools/opt_common: add timing and datetiming log flags @@ fftools/opt_common.c: int opt_loglevel(void *optctx, const char *opt, const char } else { flags |= AV_LOG_PRINT_LEVEL; } -+ } else if (av_strstart(token, "timing", &arg)) { ++ } else if (av_strstart(token, "time", &arg)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_TIME; + } else { + flags |= AV_LOG_PRINT_TIME; + } -+ } else if (av_strstart(token, "datetiming", &arg)) { ++ } else if (av_strstart(token, "datetime", &arg)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_DATETIME; + } else { 3: f0aa91d5c1 ! 3: 600020f36e doc/fftools-common-opts: document log timing flags @@ doc/fftools-common-opts.texi: and the "Last message repeated n times" line will 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 timing -+Indicates that log lines should be prefixed with timing information. -+@item datetiming -+Indicates that log lines should be prefixed with date and timing information. ++@item time ++Indicates that log lines should be prefixed with time information. ++@item datetime ++Indicates that log lines should be prefixed with date and time information. @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 -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> Signed-off-by: softworkz <softworkz@hotmail.com> --- doc/APIchanges | 3 +++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 2 +- 4 files changed, 43 insertions(+), 4 deletions(-) diff --git a/doc/APIchanges b/doc/APIchanges index 0f2b640601..83d57ae314 100644 --- a/doc/APIchanges +++ b/doc/APIchanges @@ -2,6 +2,9 @@ The last version increases of all libraries were on 2024-03-07 API changes, most recent first: +2025-01-xx - xxxxxxxxxx - lavu 59.57.100 - log.h + Add flags AV_LOG_PRINT_TIME and AV_LOG_PRINT_DATETIME. + 2025-01-25 - xxxxxxxxxx - lavu 59.56.100 - frame.h Add AV_SIDE_DATA_PROP_CHANNEL_DEPENDENT. diff --git a/libavutil/log.c b/libavutil/log.c index 46662f3db0..2fe21d4900 100644 --- a/libavutil/log.c +++ b/libavutil/log.c @@ -42,6 +42,8 @@ #include "internal.h" #include "log.h" #include "thread.h" +#include "time.h" +#include "time_internal.h" static AVMutex mutex = AV_MUTEX_INITIALIZER; @@ -296,14 +298,32 @@ static const char *item_name(void *obj, const AVClass *cls) return (cls->item_name ? cls->item_name : av_default_item_name)(obj); } +static void format_date_now(AVBPrint* bp_time, int include_date) +{ + struct tm *ptm, tmbuf; + const int64_t time_us = av_gettime(); + const int64_t time_ms = time_us / 1000; + const time_t time_s = time_ms / 1000; + const int millisec = time_ms - (time_s * 1000); + ptm = localtime_r(&time_s, &tmbuf); + if (ptm) { + if (include_date) + av_bprint_strftime(bp_time, "%Y-%m-%d ", ptm); + + av_bprint_strftime(bp_time, "%H:%M:%S", ptm); + av_bprintf(bp_time, ".%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) { @@ -321,6 +341,9 @@ 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 | 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)); @@ -341,7 +364,7 @@ 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); @@ -355,7 +378,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]; @@ -390,6 +413,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); diff --git a/libavutil/log.h b/libavutil/log.h index 4c8c92266f..dd094307ce 100644 --- a/libavutil/log.h +++ b/libavutil/log.h @@ -406,6 +406,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); diff --git a/libavutil/version.h b/libavutil/version.h index 83b7822125..ee4a36cb17 100644 --- a/libavutil/version.h +++ b/libavutil/version.h @@ -79,7 +79,7 @@ */ #define LIBAVUTIL_VERSION_MAJOR 59 -#define LIBAVUTIL_VERSION_MINOR 56 +#define LIBAVUTIL_VERSION_MINOR 57 #define LIBAVUTIL_VERSION_MICRO 100 #define LIBAVUTIL_VERSION_INT AV_VERSION_INT(LIBAVUTIL_VERSION_MAJOR, \ -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> This commit adds two logging flags: 'timing' and 'datetiming'. Usage: ffmpeg -loglevel +timing or ffmpeg -loglevel +datetiming Setting av_log_set_flags(0) in term_exit in ffmpeg.c prevents timing to be printed when exiting. Signed-off-by: softworkz <softworkz@hotmail.com> --- fftools/ffmpeg.c | 1 + fftools/opt_common.c | 12 ++++++++++++ 2 files changed, 13 insertions(+) diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c index dc321fb4a2..f4c717afaa 100644 --- a/fftools/ffmpeg.c +++ b/fftools/ffmpeg.c @@ -130,6 +130,7 @@ static void term_exit_sigsafe(void) void term_exit(void) { + av_log_set_flags(0); av_log(NULL, AV_LOG_QUIET, "%s", ""); term_exit_sigsafe(); } diff --git a/fftools/opt_common.c b/fftools/opt_common.c index 34da2cee7d..317e8458c1 100644 --- a/fftools/opt_common.c +++ b/fftools/opt_common.c @@ -1292,6 +1292,18 @@ 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 if (av_strstart(token, "datetime", &arg)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_DATETIME; + } else { + flags |= AV_LOG_PRINT_DATETIME; + } } else { break; } -- ffmpeg-codebot
On 7 Feb 2025, at 7:27, softworkz wrote:
From: softworkz <softworkz@hotmail.com>
This commit adds two logging flags: 'timing' and 'datetiming'.
Usage:
ffmpeg -loglevel +timing
or
ffmpeg -loglevel +datetiming
This commit message seems out of date regarding the actual commit contents given the flags are time and datetime now?
Setting av_log_set_flags(0) in term_exit in ffmpeg.c prevents timing to be printed when exiting.
Signed-off-by: softworkz <softworkz@hotmail.com> --- fftools/ffmpeg.c | 1 + fftools/opt_common.c | 12 ++++++++++++ 2 files changed, 13 insertions(+)
diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c index dc321fb4a2..f4c717afaa 100644 --- a/fftools/ffmpeg.c +++ b/fftools/ffmpeg.c @@ -130,6 +130,7 @@ static void term_exit_sigsafe(void)
void term_exit(void) { + av_log_set_flags(0); av_log(NULL, AV_LOG_QUIET, "%s", ""); term_exit_sigsafe(); } diff --git a/fftools/opt_common.c b/fftools/opt_common.c index 34da2cee7d..317e8458c1 100644 --- a/fftools/opt_common.c +++ b/fftools/opt_common.c @@ -1292,6 +1292,18 @@ 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 if (av_strstart(token, "datetime", &arg)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_DATETIME; + } else { + flags |= AV_LOG_PRINT_DATETIME; + } } else { break; } -- ffmpeg-codebot
_______________________________________________ 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".
-----Original Message----- From: ffmpeg-devel <ffmpeg-devel-bounces@ffmpeg.org> On Behalf Of epirat07@gmail.com Sent: Friday, February 7, 2025 7:46 AM To: FFmpeg development discussions and patches <ffmpeg- devel@ffmpeg.org> Subject: Re: [FFmpeg-devel] [PATCH v4 2/3] fftools/opt_common: add timing and datetiming log flags
On 7 Feb 2025, at 7:27, softworkz wrote:
From: softworkz <softworkz@hotmail.com>
This commit adds two logging flags: 'timing' and 'datetiming'.
Usage:
ffmpeg -loglevel +timing
or
ffmpeg -loglevel +datetiming
This commit message seems out of date regarding the actual commit contents given the flags are time and datetime now?
Yes of course. Thanks! sw
From: softworkz <softworkz@hotmail.com> Signed-off-by: softworkz <softworkz@hotmail.com> --- doc/fftools-common-opts.texi | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/doc/fftools-common-opts.texi b/doc/fftools-common-opts.texi index 8b0931a86d..f6d452c40e 100644 --- a/doc/fftools-common-opts.texi +++ b/doc/fftools-common-opts.texi @@ -226,6 +226,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 lines should be prefixed with time information. +@item datetime +Indicates that log lines should be prefixed with date and time information. @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 -- ffmpeg-codebot
This commit adds two logging flags: 'time' and 'datetime'. Usage: ffmpeg -loglevel +time or ffmpeg -loglevel +datetime Update V1 * Fix merge conflicts Update V2 * Rebased Update V3 * Fix print timing on exit (as reported by Michael Niedermayer) Update V4 * Rename variable * Rename flags to time and datetime (as suggested by Marth64) Update V5 * Fix commit message (as noted by epirat07) softworkz (3): avutil/log: support logging of date and time information fftools/opt_common: add time and datetime log flags doc/fftools-common-opts: document log timing flags doc/APIchanges | 3 +++ doc/fftools-common-opts.texi | 4 ++++ fftools/ffmpeg.c | 1 + fftools/opt_common.c | 12 ++++++++++++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 2 +- 7 files changed, 60 insertions(+), 4 deletions(-) base-commit: 4ba9ae7742a6f8a29d6486e25ff5709a075edb5b Published-As: https://github.com/ffstaging/FFmpeg/releases/tag/pr-ffstaging-37%2Fsoftworkz... Fetch-It-Via: git fetch https://github.com/ffstaging/FFmpeg pr-ffstaging-37/softworkz/submit_logtiming-v5 Pull-Request: https://github.com/ffstaging/FFmpeg/pull/37 Range-diff vs v4: 1: 2871595d3b ! 1: dae6bd3210 avutil/log: support logging of date and timing information @@ Metadata Author: softworkz <softworkz@hotmail.com> ## Commit message ## - avutil/log: support logging of date and timing information + avutil/log: support logging of date and time information Signed-off-by: softworkz <softworkz@hotmail.com> 2: aed251e1f5 ! 2: 63ab3a9411 fftools/opt_common: add timing and datetiming log flags @@ Metadata Author: softworkz <softworkz@hotmail.com> ## Commit message ## - fftools/opt_common: add timing and datetiming log flags + fftools/opt_common: add time and datetime log flags - This commit adds two logging flags: 'timing' and 'datetiming'. + This commit adds two logging flags: 'time' and 'datetime'. Usage: - ffmpeg -loglevel +timing + ffmpeg -loglevel +time or - ffmpeg -loglevel +datetiming + ffmpeg -loglevel +datetime Setting av_log_set_flags(0) in term_exit in ffmpeg.c prevents timing to be printed when exiting. 3: 600020f36e = 3: 038cbf45ed doc/fftools-common-opts: document log timing flags -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> Signed-off-by: softworkz <softworkz@hotmail.com> --- doc/APIchanges | 3 +++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 2 +- 4 files changed, 43 insertions(+), 4 deletions(-) diff --git a/doc/APIchanges b/doc/APIchanges index 0f2b640601..83d57ae314 100644 --- a/doc/APIchanges +++ b/doc/APIchanges @@ -2,6 +2,9 @@ The last version increases of all libraries were on 2024-03-07 API changes, most recent first: +2025-01-xx - xxxxxxxxxx - lavu 59.57.100 - log.h + Add flags AV_LOG_PRINT_TIME and AV_LOG_PRINT_DATETIME. + 2025-01-25 - xxxxxxxxxx - lavu 59.56.100 - frame.h Add AV_SIDE_DATA_PROP_CHANNEL_DEPENDENT. diff --git a/libavutil/log.c b/libavutil/log.c index 46662f3db0..2fe21d4900 100644 --- a/libavutil/log.c +++ b/libavutil/log.c @@ -42,6 +42,8 @@ #include "internal.h" #include "log.h" #include "thread.h" +#include "time.h" +#include "time_internal.h" static AVMutex mutex = AV_MUTEX_INITIALIZER; @@ -296,14 +298,32 @@ static const char *item_name(void *obj, const AVClass *cls) return (cls->item_name ? cls->item_name : av_default_item_name)(obj); } +static void format_date_now(AVBPrint* bp_time, int include_date) +{ + struct tm *ptm, tmbuf; + const int64_t time_us = av_gettime(); + const int64_t time_ms = time_us / 1000; + const time_t time_s = time_ms / 1000; + const int millisec = time_ms - (time_s * 1000); + ptm = localtime_r(&time_s, &tmbuf); + if (ptm) { + if (include_date) + av_bprint_strftime(bp_time, "%Y-%m-%d ", ptm); + + av_bprint_strftime(bp_time, "%H:%M:%S", ptm); + av_bprintf(bp_time, ".%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) { @@ -321,6 +341,9 @@ 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 | 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)); @@ -341,7 +364,7 @@ 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); @@ -355,7 +378,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]; @@ -390,6 +413,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); diff --git a/libavutil/log.h b/libavutil/log.h index 4c8c92266f..dd094307ce 100644 --- a/libavutil/log.h +++ b/libavutil/log.h @@ -406,6 +406,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); diff --git a/libavutil/version.h b/libavutil/version.h index 83b7822125..ee4a36cb17 100644 --- a/libavutil/version.h +++ b/libavutil/version.h @@ -79,7 +79,7 @@ */ #define LIBAVUTIL_VERSION_MAJOR 59 -#define LIBAVUTIL_VERSION_MINOR 56 +#define LIBAVUTIL_VERSION_MINOR 57 #define LIBAVUTIL_VERSION_MICRO 100 #define LIBAVUTIL_VERSION_INT AV_VERSION_INT(LIBAVUTIL_VERSION_MAJOR, \ -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> This commit adds two logging flags: 'time' and 'datetime'. Usage: ffmpeg -loglevel +time or ffmpeg -loglevel +datetime Setting av_log_set_flags(0) in term_exit in ffmpeg.c prevents timing to be printed when exiting. Signed-off-by: softworkz <softworkz@hotmail.com> --- fftools/ffmpeg.c | 1 + fftools/opt_common.c | 12 ++++++++++++ 2 files changed, 13 insertions(+) diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c index dc321fb4a2..f4c717afaa 100644 --- a/fftools/ffmpeg.c +++ b/fftools/ffmpeg.c @@ -130,6 +130,7 @@ static void term_exit_sigsafe(void) void term_exit(void) { + av_log_set_flags(0); av_log(NULL, AV_LOG_QUIET, "%s", ""); term_exit_sigsafe(); } diff --git a/fftools/opt_common.c b/fftools/opt_common.c index 34da2cee7d..317e8458c1 100644 --- a/fftools/opt_common.c +++ b/fftools/opt_common.c @@ -1292,6 +1292,18 @@ 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 if (av_strstart(token, "datetime", &arg)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_DATETIME; + } else { + flags |= AV_LOG_PRINT_DATETIME; + } } else { break; } -- ffmpeg-codebot
On 07/02/2025 08:57, softworkz wrote:
From: softworkz <softworkz@hotmail.com>
This commit adds two logging flags: 'time' and 'datetime'.
Usage:
ffmpeg -loglevel +time
or
ffmpeg -loglevel +datetime
Setting av_log_set_flags(0) in term_exit in ffmpeg.c prevents timing to be printed when exiting.
Signed-off-by: softworkz <softworkz@hotmail.com> --- fftools/ffmpeg.c | 1 + fftools/opt_common.c | 12 ++++++++++++ 2 files changed, 13 insertions(+)
diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c index dc321fb4a2..f4c717afaa 100644 --- a/fftools/ffmpeg.c +++ b/fftools/ffmpeg.c @@ -130,6 +130,7 @@ static void term_exit_sigsafe(void)
void term_exit(void) { + av_log_set_flags(0); av_log(NULL, AV_LOG_QUIET, "%s", ""); term_exit_sigsafe(); }
If I understand the purpose of AV_LOG_QUIET correctly the correct way would be to skip writing time/datetime information in the log writer itself (part of patch #1 in this patch-set) if level is <= AV_LOG_QUIET, rather than clearing the flags here. Regards, Tobias
-----Original Message----- From: ffmpeg-devel <ffmpeg-devel-bounces@ffmpeg.org> On Behalf Of Tobias Rapp Sent: Friday, February 7, 2025 11:42 AM To: ffmpeg-devel@ffmpeg.org Subject: Re: [FFmpeg-devel] [PATCH v5 2/3] fftools/opt_common: add time and datetime log flags
On 07/02/2025 08:57, softworkz wrote:
From: softworkz <softworkz@hotmail.com>
This commit adds two logging flags: 'time' and 'datetime'.
Usage:
ffmpeg -loglevel +time
or
ffmpeg -loglevel +datetime
Setting av_log_set_flags(0) in term_exit in ffmpeg.c prevents timing to be printed when exiting.
Signed-off-by: softworkz <softworkz@hotmail.com> --- fftools/ffmpeg.c | 1 + fftools/opt_common.c | 12 ++++++++++++ 2 files changed, 13 insertions(+)
diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c index dc321fb4a2..f4c717afaa 100644 --- a/fftools/ffmpeg.c +++ b/fftools/ffmpeg.c @@ -130,6 +130,7 @@ static void term_exit_sigsafe(void)
void term_exit(void) { + av_log_set_flags(0); av_log(NULL, AV_LOG_QUIET, "%s", ""); term_exit_sigsafe(); }
If I understand the purpose of AV_LOG_QUIET correctly the correct way would be to skip writing time/datetime information in the log writer itself (part of patch #1 in this patch-set) if level is <= AV_LOG_QUIET, rather than clearing the flags here.
Regards, Tobias
Hi Tobias, my understanding of AV_LOG_QUIET would be that when program code logs a message with that level, it will be printed even when the user has "-loglevel quiet". I would wonder why such log messages shouldn't be prefixed with the time (normally). To me it appears that the special case is rather the log invocation on exit which prints - well: nothing. I'd rather question why it is not printing the log level for quiet. Is it really intended or was it only done to make it possible to print this empty message on exit? Do I see it wrong? Then I'll change it of course. Thanks a lot for reviewing! sw
-----Original Message----- From: ffmpeg-devel <ffmpeg-devel-bounces@ffmpeg.org> On Behalf Of Soft Works Sent: Friday, February 7, 2025 12:27 PM To: FFmpeg development discussions and patches <ffmpeg- devel@ffmpeg.org> Subject: Re: [FFmpeg-devel] [PATCH v5 2/3] fftools/opt_common: add time and datetime log flags
-----Original Message----- From: ffmpeg-devel <ffmpeg-devel-bounces@ffmpeg.org> On Behalf Of Tobias Rapp Sent: Friday, February 7, 2025 11:42 AM To: ffmpeg-devel@ffmpeg.org Subject: Re: [FFmpeg-devel] [PATCH v5 2/3] fftools/opt_common: add time and datetime log flags
On 07/02/2025 08:57, softworkz wrote:
From: softworkz <softworkz@hotmail.com>
This commit adds two logging flags: 'time' and 'datetime'.
Usage:
ffmpeg -loglevel +time
or
ffmpeg -loglevel +datetime
Setting av_log_set_flags(0) in term_exit in ffmpeg.c prevents timing to be printed when exiting.
Signed-off-by: softworkz <softworkz@hotmail.com> --- fftools/ffmpeg.c | 1 + fftools/opt_common.c | 12 ++++++++++++ 2 files changed, 13 insertions(+)
diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c index dc321fb4a2..f4c717afaa 100644 --- a/fftools/ffmpeg.c +++ b/fftools/ffmpeg.c @@ -130,6 +130,7 @@ static void term_exit_sigsafe(void)
void term_exit(void) { + av_log_set_flags(0); av_log(NULL, AV_LOG_QUIET, "%s", ""); term_exit_sigsafe(); }
If I understand the purpose of AV_LOG_QUIET correctly the correct way would be to skip writing time/datetime information in the log writer itself (part of patch #1 in this patch-set) if level is <= AV_LOG_QUIET, rather than clearing the flags here.
Regards, Tobias
Hi Tobias,
my understanding of AV_LOG_QUIET would be that when program code logs a message with that level, it will be printed even when the user has "-loglevel quiet". I would wonder why such log messages shouldn't be prefixed with the time (normally). To me it appears that the special case is rather the log invocation on exit which prints - well: nothing.
I'd rather question why it is not printing the log level for quiet. Is it really intended or was it only done to make it possible to print this empty message on exit?
Do I see it wrong? Then I'll change it of course.
Thanks a lot for reviewing!
sw
Hi Tobias, what do you think about this? if (*print_prefix && (flags & (AV_LOG_PRINT_TIME | AV_LOG_PRINT_DATETIME))) format_date_now(&part[4], flags & AV_LOG_PRINT_DATETIME); if (*print_prefix && (flags & AV_LOG_PRINT_LEVEL)) av_bprintf(part+2, "[%s] ", get_level_str(level)); av_vbprintf(part+3, fmt, vl); if ((level == AV_LOG_QUIET) && part[3].len == 0) { *print_prefix = 0; } else 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; *print_prefix = lastc == '\n' || lastc == '\r'; } (plus removal of the flags clearance ofc) sw
On 07/02/2025 12:27, Soft Works wrote:
-----Original Message----- From: ffmpeg-devel<ffmpeg-devel-bounces@ffmpeg.org> On Behalf Of Tobias Rapp Sent: Friday, February 7, 2025 11:42 AM To:ffmpeg-devel@ffmpeg.org Subject: Re: [FFmpeg-devel] [PATCH v5 2/3] fftools/opt_common: add time and datetime log flags
On 07/02/2025 08:57, softworkz wrote:
From: softworkz<softworkz@hotmail.com>
This commit adds two logging flags: 'time' and 'datetime'.
Usage:
ffmpeg -loglevel +time
or
ffmpeg -loglevel +datetime
Setting av_log_set_flags(0) in term_exit in ffmpeg.c prevents timing to be printed when exiting.
Signed-off-by: softworkz<softworkz@hotmail.com> --- fftools/ffmpeg.c | 1 + fftools/opt_common.c | 12 ++++++++++++ 2 files changed, 13 insertions(+)
diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c index dc321fb4a2..f4c717afaa 100644 --- a/fftools/ffmpeg.c +++ b/fftools/ffmpeg.c @@ -130,6 +130,7 @@ static void term_exit_sigsafe(void)
void term_exit(void) { + av_log_set_flags(0); av_log(NULL, AV_LOG_QUIET, "%s", ""); term_exit_sigsafe(); } If I understand the purpose of AV_LOG_QUIET correctly the correct way would be to skip writing time/datetime information in the log writer itself (part of patch #1 in this patch-set) if level is <= AV_LOG_QUIET, rather than clearing the flags here.
Regards, Tobias
Hi Tobias,
my understanding of AV_LOG_QUIET would be that when program code logs a message with that level, it will be printed even when the user has "-loglevel quiet". I would wonder why such log messages shouldn't be prefixed with the time (normally). To me it appears that the special case is rather the log invocation on exit which prints - well: nothing.
I'd rather question why it is not printing the log level for quiet. Is it really intended or was it only done to make it possible to print this empty message on exit?
Do I see it wrong? Then I'll change it of course.
Thanks a lot for reviewing!
sw
The documentation for AV_LOG_QUIET in log.h says "Print no output" and from grepping through code it seems the implementation matches that definition. The purpose of av_log(NULL, AV_LOG_QUIET, "%s", "") is described with the AV_LOG_SKIP_REPEATED flag, see https://ffmpeg.org/doxygen/trunk/group__lavu__log.html#ga6cdf5cd331b17e80e83... . So I suggest to just add a "(level > AV_LOG_QUIET)" clause to the added lines in forma_line(), similar to how it is done with the loglevel prefix in that function some lines below: if (*print_prefix && (level > AV_LOG_QUIET) && (flags & (AV_LOG_PRINT_TIME | AV_LOG_PRINT_DATETIME))) format_date_now(&part[4], flags & AV_LOG_PRINT_DATETIME); Regards, Tobias
-----Original Message----- From: ffmpeg-devel <ffmpeg-devel-bounces@ffmpeg.org> On Behalf Of Tobias Rapp Sent: Friday, February 7, 2025 2:22 PM To: ffmpeg-devel@ffmpeg.org Subject: Re: [FFmpeg-devel] [PATCH v5 2/3] fftools/opt_common: add time and datetime log flags
On 07/02/2025 12:27, Soft Works wrote:
-----Original Message----- From: ffmpeg-devel<ffmpeg-devel-bounces@ffmpeg.org> On Behalf Of Tobias Rapp Sent: Friday, February 7, 2025 11:42 AM To:ffmpeg-devel@ffmpeg.org Subject: Re: [FFmpeg-devel] [PATCH v5 2/3] fftools/opt_common: add time and datetime log flags
On 07/02/2025 08:57, softworkz wrote:
From: softworkz<softworkz@hotmail.com>
This commit adds two logging flags: 'time' and 'datetime'.
Usage:
ffmpeg -loglevel +time
or
ffmpeg -loglevel +datetime
Setting av_log_set_flags(0) in term_exit in ffmpeg.c prevents timing to be printed when exiting.
Signed-off-by: softworkz<softworkz@hotmail.com> --- fftools/ffmpeg.c | 1 + fftools/opt_common.c | 12 ++++++++++++ 2 files changed, 13 insertions(+)
diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c index dc321fb4a2..f4c717afaa 100644 --- a/fftools/ffmpeg.c +++ b/fftools/ffmpeg.c @@ -130,6 +130,7 @@ static void term_exit_sigsafe(void)
void term_exit(void) { + av_log_set_flags(0); av_log(NULL, AV_LOG_QUIET, "%s", ""); term_exit_sigsafe(); } If I understand the purpose of AV_LOG_QUIET correctly the correct
would be to skip writing time/datetime information in the log writer itself (part of patch #1 in this patch-set) if level is <= AV_LOG_QUIET, rather than clearing the flags here.
Regards, Tobias
Hi Tobias,
my understanding of AV_LOG_QUIET would be that when program code logs a message with that level, it will be printed even when the user has "-loglevel quiet". I would wonder why such log messages shouldn't be prefixed with the time (normally). To me it appears that the special case is rather the log invocation on exit which prints - well: nothing.
I'd rather question why it is not printing the log level for quiet. Is it really intended or was it only done to make it possible to
way print this empty message on exit?
Do I see it wrong? Then I'll change it of course.
Thanks a lot for reviewing!
sw
The documentation for AV_LOG_QUIET in log.h says "Print no output"
This is the user-facing definition. When a user configures quiet, it means that ffmpeg prints no output. But on the side of the code, specifying AV_LOG_QUIET doesn't mean "print no output" but the opposite ("print it, no matter what!").
from grepping through code it seems the implementation matches that definition. The purpose of av_log(NULL, AV_LOG_QUIET, "%s", "") is described with the AV_LOG_SKIP_REPEATED flag, see https://ffmpeg.org/doxygen/trunk/group__lavu__log.html#ga6cdf5cd331b1 7e80e8308124f05a6db8
Hm, not sure whether this has been the original purpose of AV_LOG_QUIET. And one could argue that consumers of avutil might use this log level for printing non-empty messages. That's what the snippet above would have preserved working. But the quirky part has already happened (not introducing av_log_flush() or something), so - as a whole - it can't be easily remedied anyway.
So I suggest to just add a "(level > AV_LOG_QUIET)" clause to the added lines in forma_line(), similar to how it is done with the loglevel prefix in that function some lines below:
if (*print_prefix && (level > AV_LOG_QUIET) && (flags & (AV_LOG_PRINT_TIME | AV_LOG_PRINT_DATETIME))) format_date_now(&part[4], flags & AV_LOG_PRINT_DATETIME);
Fine. Done for the next version, thank you very much! sw
From: softworkz <softworkz@hotmail.com> Signed-off-by: softworkz <softworkz@hotmail.com> --- doc/fftools-common-opts.texi | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/doc/fftools-common-opts.texi b/doc/fftools-common-opts.texi index 8b0931a86d..f6d452c40e 100644 --- a/doc/fftools-common-opts.texi +++ b/doc/fftools-common-opts.texi @@ -226,6 +226,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 lines should be prefixed with time information. +@item datetime +Indicates that log lines should be prefixed with date and time information. @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 -- ffmpeg-codebot
This commit adds two logging flags: 'time' and 'datetime'. Usage: ffmpeg -loglevel +time or ffmpeg -loglevel +datetime Update V1 * Fix merge conflicts Update V2 * Rebased Update V3 * Fix print timing on exit (as reported by Michael Niedermayer) Update V4 * Rename variable * Rename flags to time and datetime (as suggested by Marth64) Update V5 * Fix commit message (as noted by epirat07) Update V6 * Handle empty quiet messages in log.c rather than clearing log flags in ffmpeg.c (as suggested by Tobias Rapp) softworkz (3): avutil/log: support logging of date and time information fftools/opt_common: add time and datetime log flags doc/fftools-common-opts: document log timing flags doc/APIchanges | 3 +++ doc/fftools-common-opts.texi | 4 ++++ fftools/opt_common.c | 12 ++++++++++++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 2 +- 6 files changed, 59 insertions(+), 4 deletions(-) base-commit: 4ba9ae7742a6f8a29d6486e25ff5709a075edb5b Published-As: https://github.com/ffstaging/FFmpeg/releases/tag/pr-ffstaging-37%2Fsoftworkz... Fetch-It-Via: git fetch https://github.com/ffstaging/FFmpeg pr-ffstaging-37/softworkz/submit_logtiming-v6 Pull-Request: https://github.com/ffstaging/FFmpeg/pull/37 Range-diff vs v5: 1: dae6bd3210 ! 1: 4c5bf1c03b avutil/log: support logging of date and time information @@ libavutil/log.c: static void format_line(void *avcl, int level, const char *fmt, if(type) type[1] = get_category(avcl); } -+ if (*print_prefix && (flags & (AV_LOG_PRINT_TIME | AV_LOG_PRINT_DATETIME))) ++ if (*print_prefix && (level > AV_LOG_QUIET) && (flags & (AV_LOG_PRINT_TIME | 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)) 2: 63ab3a9411 ! 2: 81d9e24908 fftools/opt_common: add time and datetime log flags @@ Commit message ffmpeg -loglevel +datetime - Setting av_log_set_flags(0) in term_exit in ffmpeg.c prevents - timing to be printed when exiting. - Signed-off-by: softworkz <softworkz@hotmail.com> - ## fftools/ffmpeg.c ## -@@ fftools/ffmpeg.c: static void term_exit_sigsafe(void) - - void term_exit(void) - { -+ av_log_set_flags(0); - av_log(NULL, AV_LOG_QUIET, "%s", ""); - term_exit_sigsafe(); - } - ## fftools/opt_common.c ## @@ fftools/opt_common.c: int opt_loglevel(void *optctx, const char *opt, const char *arg) } else { 3: 038cbf45ed = 3: a3522a2116 doc/fftools-common-opts: document log timing flags -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> Signed-off-by: softworkz <softworkz@hotmail.com> --- doc/APIchanges | 3 +++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 2 +- 4 files changed, 43 insertions(+), 4 deletions(-) diff --git a/doc/APIchanges b/doc/APIchanges index 0f2b640601..83d57ae314 100644 --- a/doc/APIchanges +++ b/doc/APIchanges @@ -2,6 +2,9 @@ The last version increases of all libraries were on 2024-03-07 API changes, most recent first: +2025-01-xx - xxxxxxxxxx - lavu 59.57.100 - log.h + Add flags AV_LOG_PRINT_TIME and AV_LOG_PRINT_DATETIME. + 2025-01-25 - xxxxxxxxxx - lavu 59.56.100 - frame.h Add AV_SIDE_DATA_PROP_CHANNEL_DEPENDENT. diff --git a/libavutil/log.c b/libavutil/log.c index 46662f3db0..c5ee876a88 100644 --- a/libavutil/log.c +++ b/libavutil/log.c @@ -42,6 +42,8 @@ #include "internal.h" #include "log.h" #include "thread.h" +#include "time.h" +#include "time_internal.h" static AVMutex mutex = AV_MUTEX_INITIALIZER; @@ -296,14 +298,32 @@ static const char *item_name(void *obj, const AVClass *cls) return (cls->item_name ? cls->item_name : av_default_item_name)(obj); } +static void format_date_now(AVBPrint* bp_time, int include_date) +{ + struct tm *ptm, tmbuf; + const int64_t time_us = av_gettime(); + const int64_t time_ms = time_us / 1000; + const time_t time_s = time_ms / 1000; + const int millisec = time_ms - (time_s * 1000); + ptm = localtime_r(&time_s, &tmbuf); + if (ptm) { + if (include_date) + av_bprint_strftime(bp_time, "%Y-%m-%d ", ptm); + + av_bprint_strftime(bp_time, "%H:%M:%S", ptm); + av_bprintf(bp_time, ".%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) { @@ -321,6 +341,9 @@ 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 | 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)); @@ -341,7 +364,7 @@ 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); @@ -355,7 +378,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]; @@ -390,6 +413,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); diff --git a/libavutil/log.h b/libavutil/log.h index 4c8c92266f..dd094307ce 100644 --- a/libavutil/log.h +++ b/libavutil/log.h @@ -406,6 +406,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); diff --git a/libavutil/version.h b/libavutil/version.h index 83b7822125..ee4a36cb17 100644 --- a/libavutil/version.h +++ b/libavutil/version.h @@ -79,7 +79,7 @@ */ #define LIBAVUTIL_VERSION_MAJOR 59 -#define LIBAVUTIL_VERSION_MINOR 56 +#define LIBAVUTIL_VERSION_MINOR 57 #define LIBAVUTIL_VERSION_MICRO 100 #define LIBAVUTIL_VERSION_INT AV_VERSION_INT(LIBAVUTIL_VERSION_MAJOR, \ -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> This commit adds two logging flags: 'time' and 'datetime'. Usage: ffmpeg -loglevel +time or ffmpeg -loglevel +datetime Signed-off-by: softworkz <softworkz@hotmail.com> --- fftools/opt_common.c | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/fftools/opt_common.c b/fftools/opt_common.c index 34da2cee7d..317e8458c1 100644 --- a/fftools/opt_common.c +++ b/fftools/opt_common.c @@ -1292,6 +1292,18 @@ 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 if (av_strstart(token, "datetime", &arg)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_DATETIME; + } else { + flags |= AV_LOG_PRINT_DATETIME; + } } else { break; } -- ffmpeg-codebot
From: softworkz <softworkz@hotmail.com> Signed-off-by: softworkz <softworkz@hotmail.com> --- doc/fftools-common-opts.texi | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/doc/fftools-common-opts.texi b/doc/fftools-common-opts.texi index 8b0931a86d..f6d452c40e 100644 --- a/doc/fftools-common-opts.texi +++ b/doc/fftools-common-opts.texi @@ -226,6 +226,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 lines should be prefixed with time information. +@item datetime +Indicates that log lines should be prefixed with date and time information. @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 -- ffmpeg-codebot
On 07/02/2025 15:34, ffmpegagent wrote:
This commit adds two logging flags: 'time' and 'datetime'.
Usage:
ffmpeg -loglevel +time
or
ffmpeg -loglevel +datetime
Update V1
* Fix merge conflicts
Update V2
* Rebased
Update V3
* Fix print timing on exit (as reported by Michael Niedermayer)
Update V4
* Rename variable * Rename flags to time and datetime (as suggested by Marth64)
Update V5
* Fix commit message (as noted by epirat07)
Update V6
* Handle empty quiet messages in log.c rather than clearing log flags in ffmpeg.c (as suggested by Tobias Rapp)
softworkz (3): avutil/log: support logging of date and time information fftools/opt_common: add time and datetime log flags doc/fftools-common-opts: document log timing flags
doc/APIchanges | 3 +++ doc/fftools-common-opts.texi | 4 ++++ fftools/opt_common.c | 12 ++++++++++++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 2 +- 6 files changed, 59 insertions(+), 4 deletions(-)
[...]
Looks fine from my side regarding the handling of AV_LOG_QUIET. Thanks, Tobias
On Fri, Feb 07, 2025 at 04:57:55PM +0100, Tobias Rapp wrote:
On 07/02/2025 15:34, ffmpegagent wrote:
This commit adds two logging flags: 'time' and 'datetime'.
Usage:
ffmpeg -loglevel +time
or
ffmpeg -loglevel +datetime
Update V1
* Fix merge conflicts
Update V2
* Rebased
Update V3
* Fix print timing on exit (as reported by Michael Niedermayer)
Update V4
* Rename variable * Rename flags to time and datetime (as suggested by Marth64)
Update V5
* Fix commit message (as noted by epirat07)
Update V6
* Handle empty quiet messages in log.c rather than clearing log flags in ffmpeg.c (as suggested by Tobias Rapp)
softworkz (3): avutil/log: support logging of date and time information fftools/opt_common: add time and datetime log flags doc/fftools-common-opts: document log timing flags
doc/APIchanges | 3 +++ doc/fftools-common-opts.texi | 4 ++++ fftools/opt_common.c | 12 ++++++++++++ libavutil/log.c | 32 +++++++++++++++++++++++++++++--- libavutil/log.h | 10 ++++++++++ libavutil/version.h | 2 +- 6 files changed, 59 insertions(+), 4 deletions(-)
[...]
Looks fine from my side regarding the handling of AV_LOG_QUIET.
will apply patchset thx [...] -- Michael GnuPG fingerprint: 9FF2128B147EF6730BADF133611EC787040B0FAB Awnsering whenever a program halts or runs forever is On a turing machine, in general impossible (turings halting problem). On any real computer, always possible as a real computer has a finite number of states N, and will either halt in less than N cycles or never halt.
participants (7)
-
epirat07ï¼ gmail.com -
ffmpegagent -
Marth64 -
Michael Niedermayer -
Soft Works -
softworkz
-
Tobias Rapp