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 | 14 ++++++++++++++ libavutil/log.h | 8 ++++++++ 4 files changed, 32 insertions(+) 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..cc16427178 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; @@ -319,6 +320,19 @@ static void format_line(void *avcl, int level, const char *fmt, va_list vl, if (*print_prefix && (level > AV_LOG_QUIET) && (flags & AV_LOG_PRINT_LEVEL)) av_bprintf(part+2, "[%s] ", get_level_str(level)); + 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); + } + av_vbprintf(part+3, fmt, vl); if(*part[0].str || *part[1].str || *part[2].str || *part[3].str) { 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