From 04857a7bf0d4cf24a479e795a55a61ab2e2f618e Mon Sep 17 00:00:00 2001 From: Prakash Duggaraju Date: Thu, 16 Feb 2023 16:06:29 -0800 Subject: [PATCH] libavutil/log: Support for logging timestamps in the log. Add 'time' flag to the -loglevel option to turn on timestamp logging. Useful for troubleshooting where time is spent from the log files. Signed-off-by: Prakash Duggaraju --- doc/fftools-common-opts.texi | 4 ++++ fftools/opt_common.c | 6 ++++++ libavutil/log.c | 41 +++++++++++++++++++++++++----------- libavutil/log.h | 8 +++++++ 4 files changed, 47 insertions(+), 12 deletions(-) diff --git a/doc/fftools-common-opts.texi b/doc/fftools-common-opts.texi index d9145704d6..a3cf9eb57d 100644 --- a/doc/fftools-common-opts.texi +++ b/doc/fftools-common-opts.texi @@ -201,6 +201,10 @@ and the "Last message repeated n times" line will be omitted. Indicates that log output should add a @code{[level]} prefix to each message line. This can be used as an alternative to log coloring, e.g. when dumping the log to file. +@item time +Indicates that log output should add a @code{[time]} prefix to each message +line. The time is the relative time in microseconds precision. This can be +useful for troubleshooting where time is spent from the logs. @end table Flags can also be used alone by adding a '+'/'-' prefix to set/reset a single flag without affecting other @var{flags} or changing @var{loglevel}. When diff --git a/fftools/opt_common.c b/fftools/opt_common.c index 8a06df82df..a081ad6b08 100644 --- a/fftools/opt_common.c +++ b/fftools/opt_common.c @@ -1269,6 +1269,12 @@ int opt_loglevel(void *optctx, const char *opt, const char *arg) } else { flags |= AV_LOG_PRINT_LEVEL; } + } else if (av_strstart(token, "time", &arg)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_TIME; + } else { + flags |= AV_LOG_PRINT_TIME; + } } else { break; } diff --git a/libavutil/log.c b/libavutil/log.c index 5948e50467..7b892ddd1e 100644 --- a/libavutil/log.c +++ b/libavutil/log.c @@ -42,6 +42,7 @@ #include "internal.h" #include "log.h" #include "thread.h" +#include "time.h" static AVMutex mutex = AV_MUTEX_INITIALIZER; @@ -292,13 +293,14 @@ static const char *get_level_str(int level) } static void format_line(void *avcl, int level, const char *fmt, va_list vl, - AVBPrint part[4], int *print_prefix, int type[2]) + AVBPrint part[5], int *print_prefix, int type[2]) { AVClass* avc = avcl ? *(AVClass **) avcl : NULL; av_bprint_init(part+0, 0, AV_BPRINT_SIZE_AUTOMATIC); av_bprint_init(part+1, 0, AV_BPRINT_SIZE_AUTOMATIC); av_bprint_init(part+2, 0, AV_BPRINT_SIZE_AUTOMATIC); - av_bprint_init(part+3, 0, 65536); + av_bprint_init(part+3, 0, AV_BPRINT_SIZE_AUTOMATIC); + av_bprint_init(part+4, 0, 65536); if(type) type[0] = type[1] = AV_CLASS_CATEGORY_NA + 16; if (*print_prefix && avc) { @@ -316,13 +318,26 @@ static void format_line(void *avcl, int level, const char *fmt, va_list vl, if(type) type[1] = get_category(avcl); } + if (*print_prefix && (level > AV_LOG_QUIET) && (flags & AV_LOG_PRINT_TIME)) { + int secs, mins; + int64_t hours; + int64_t time = av_gettime_relative(); + float millis = (time % 100000) / 1000.0f; + time /= 1000000; + secs = time % 60; + time /= 60; + mins = time % 60; + hours = time / 60; + av_bprintf(part+2, "[%ldh:%02dm:%02ds:%07.03fms] ", hours, mins, secs, millis); + } + if (*print_prefix && (level > AV_LOG_QUIET) && (flags & AV_LOG_PRINT_LEVEL)) - av_bprintf(part+2, "[%s] ", get_level_str(level)); + av_bprintf(part+3, "[%s] ", get_level_str(level)); - av_vbprintf(part+3, fmt, vl); + av_vbprintf(part+4, fmt, vl); - if(*part[0].str || *part[1].str || *part[2].str || *part[3].str) { - char lastc = part[3].len && part[3].len <= part[3].size ? part[3].str[part[3].len - 1] : 0; + if(*part[0].str || *part[1].str || *part[2].str || *part[3].str || *part[4].str) { + char lastc = part[4].len && part[4].len <= part[4].size ? part[4].str[part[4].len - 1] : 0; *print_prefix = lastc == '\n' || lastc == '\r'; } } @@ -336,12 +351,12 @@ void av_log_format_line(void *ptr, int level, const char *fmt, va_list vl, int av_log_format_line2(void *ptr, int level, const char *fmt, va_list vl, char *line, int line_size, int *print_prefix) { - AVBPrint part[4]; + AVBPrint part[5]; int ret; format_line(ptr, level, fmt, vl, part, print_prefix, NULL); - ret = snprintf(line, line_size, "%s%s%s%s", part[0].str, part[1].str, part[2].str, part[3].str); - av_bprint_finalize(part+3, NULL); + ret = snprintf(line, line_size, "%s%s%s%s%s", part[0].str, part[1].str, part[2].str, part[3].str, part[4].str); + av_bprint_finalize(part+4, NULL); return ret; } @@ -350,7 +365,7 @@ void av_log_default_callback(void* ptr, int level, const char* fmt, va_list vl) static int print_prefix = 1; static int count; static char prev[LINE_SZ]; - AVBPrint part[4]; + AVBPrint part[5]; char line[LINE_SZ]; static int is_atty; int type[2]; @@ -366,7 +381,7 @@ void av_log_default_callback(void* ptr, int level, const char* fmt, va_list vl) ff_mutex_lock(&mutex); format_line(ptr, level, fmt, vl, part, &print_prefix, type); - snprintf(line, sizeof(line), "%s%s%s%s", part[0].str, part[1].str, part[2].str, part[3].str); + snprintf(line, sizeof(line), "%s%s%s%s%s", part[0].str, part[1].str, part[2].str, part[3].str, part[4].str); #if HAVE_ISATTY if (!is_atty) @@ -393,13 +408,15 @@ void av_log_default_callback(void* ptr, int level, const char* fmt, va_list vl) colored_fputs(av_clip(level >> 3, 0, NB_LEVELS - 1), tint >> 8, part[2].str); sanitize(part[3].str); colored_fputs(av_clip(level >> 3, 0, NB_LEVELS - 1), tint >> 8, part[3].str); + sanitize(part[4].str); + colored_fputs(av_clip(level >> 3, 0, NB_LEVELS - 1), tint >> 8, part[4].str); #if CONFIG_VALGRIND_BACKTRACE if (level <= BACKTRACE_LOGLEVEL) VALGRIND_PRINTF_BACKTRACE("%s", ""); #endif end: - av_bprint_finalize(part+3, NULL); + av_bprint_finalize(part+4, NULL); ff_mutex_unlock(&mutex); } diff --git a/libavutil/log.h b/libavutil/log.h index ab7ceabe22..2e2d83f6d0 100644 --- a/libavutil/log.h +++ b/libavutil/log.h @@ -377,6 +377,14 @@ int av_log_format_line2(void *ptr, int level, const char *fmt, va_list vl, */ #define AV_LOG_PRINT_LEVEL 2 +/** + * Include the system time with each log message. + * Useful for troubleshooting where the time was spent. + * Results in messages such as: + * [rawvideo @ 0xDEADBEEF] [01h:03m:05s:3.112ms] [error] encode did not produce valid pts + */ +#define AV_LOG_PRINT_TIME 4 + void av_log_set_flags(int arg); int av_log_get_flags(void); -- 2.34.1