Message ID | MN2PR04MB59811973C35216A95226D47ABAF69@MN2PR04MB5981.namprd04.prod.outlook.com |
---|---|
State | Superseded, archived |
Headers | show |
Series | [FFmpeg-devel,v3,1/2] Add option to log timing | expand |
Context | Check | Description |
---|---|---|
andriy/x86_make | success | Make finished |
andriy/x86_make_fate | success | Make fate finished |
andriy/PPC64_make | success | Make finished |
andriy/PPC64_make_fate | success | Make fate finished |
Soft Works: > This commit adds two logging flags: 'timing' and 'datetiming'. > > Usage: > > ffmpeg -loglevel +timing > > or > > ffmpeg -loglevel +datetiming > > Signed-off-by: softworkz <softworkz@hotmail.com> > (cherry picked from commit 960c82cede25c21bcea478b26309691fdc7fcec7) > (cherry picked from commit 0851f36f5ecead61317a1ce631facdacae76d886) This refers to objects not in our repo, so it is useless. > --- > v2 was from 2019-09-17 > fftools/cmdutils.c | 14 ++++++++++++++ > fftools/ffmpeg.c | 6 +++++- > libavutil/log.c | 37 ++++++++++++++++++++++++++++++++----- > libavutil/log.h | 10 ++++++++++ > 4 files changed, 61 insertions(+), 6 deletions(-) > > diff --git a/fftools/cmdutils.c b/fftools/cmdutils.c > index f5e39f616f..238a607d03 100644 > --- a/fftools/cmdutils.c > +++ b/fftools/cmdutils.c > @@ -919,6 +919,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)) { Don't hardcode the length, use av_strstart. > + if (cmd == '-') { > + flags &= ~AV_LOG_PRINT_DATETIME; > + } else { > + flags |= AV_LOG_PRINT_DATETIME; > + } > + arg = token + 10; > } else { > break; > } > diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c > index b0ce7c7c32..b0b105be1c 100644 > --- a/fftools/ffmpeg.c > +++ b/fftools/ffmpeg.c > @@ -4983,7 +4983,7 @@ static void log_callback_null(void *ptr, int level, const char *fmt, va_list vl) > > int main(int argc, char **argv) > { > - int i, ret; > + int i, ret, log_flags; > BenchmarkTimeStamps ti; > > init_dynload(); > @@ -5049,6 +5049,10 @@ int main(int argc, char **argv) > if ((decode_error_stat[0] + decode_error_stat[1]) * max_error_rate < decode_error_stat[1]) > exit_program(69); > > + log_flags = av_log_get_flags(); > + if (log_flags & AV_LOG_PRINT_TIME || log_flags & AV_LOG_PRINT_DATETIME) > + av_log(NULL, AV_LOG_INFO, "\n"); /* end with line break to avoid mixing up with shell prompt */ > + > exit_program(received_nb_signals ? 255 : main_return_code); > return main_return_code; > } > diff --git a/libavutil/log.c b/libavutil/log.c > index 66defa9c42..ff4b6cc885 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; > > @@ -289,14 +291,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) { > @@ -314,6 +334,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)); > > @@ -334,12 +358,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; > } > > @@ -348,7 +372,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]; > @@ -383,6 +407,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); > @@ -397,7 +424,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); This is completely wrong: The AVBPrints that use AV_BPRINT_SIZE_AUTOMATIC don't need to be finalized, but the other one (namely part[3]) need it. The same goes for the change above. > ff_mutex_unlock(&mutex); > } > > diff --git a/libavutil/log.h b/libavutil/log.h > index 8727c38afc..27eb071884 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); > > You need to separate this into an libavutil patch and a subsequent patch to fftools. The documentation should be added to the commit introducing the things to be documented. The patch to libavutil needs an APIchanges entry and a minor version bump. - Andreas
> -----Original Message----- > From: ffmpeg-devel <ffmpeg-devel-bounces@ffmpeg.org> On Behalf Of > Andreas Rheinhardt > Sent: Monday, 9 August 2021 03:11 > To: ffmpeg-devel@ffmpeg.org > Subject: Re: [FFmpeg-devel] [PATCH v3 1/2] Add option to log timing > > Soft Works: > > This commit adds two logging flags: 'timing' and 'datetiming'. > > > > Usage: > > > > ffmpeg -loglevel +timing > > > > or > > > > ffmpeg -loglevel +datetiming > > > > Signed-off-by: softworkz <softworkz@hotmail.com> (cherry picked from > > commit 960c82cede25c21bcea478b26309691fdc7fcec7) > > (cherry picked from commit 0851f36f5ecead61317a1ce631facdacae76d886) > > This refers to objects not in our repo, so it is useless. Will remove. > > > --- > > v2 was from 2019-09-17 > > fftools/cmdutils.c | 14 ++++++++++++++ > > fftools/ffmpeg.c | 6 +++++- > > libavutil/log.c | 37 ++++++++++++++++++++++++++++++++----- > > libavutil/log.h | 10 ++++++++++ > > 4 files changed, 61 insertions(+), 6 deletions(-) > > > > diff --git a/fftools/cmdutils.c b/fftools/cmdutils.c index > > f5e39f616f..238a607d03 100644 > > --- a/fftools/cmdutils.c > > +++ b/fftools/cmdutils.c > > @@ -919,6 +919,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)) { > > Don't hardcode the length, use av_strstart. Well, I just followed the pattern of the existing code above. What shall I do? Change the existing code, change only my new code or leave it as is and add a patch later that changes only this bit but for all at once? > > > + if (cmd == '-') { > > + flags &= ~AV_LOG_PRINT_DATETIME; > > + } else { > > + flags |= AV_LOG_PRINT_DATETIME; > > + } > > + arg = token + 10; > > } else { > > break; > > } > > diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c index > > b0ce7c7c32..b0b105be1c 100644 > > --- a/fftools/ffmpeg.c > > +++ b/fftools/ffmpeg.c > > @@ -4983,7 +4983,7 @@ static void log_callback_null(void *ptr, int > > level, const char *fmt, va_list vl) > > > > int main(int argc, char **argv) > > { > > - int i, ret; > > + int i, ret, log_flags; > > BenchmarkTimeStamps ti; > > > > init_dynload(); > > @@ -5049,6 +5049,10 @@ int main(int argc, char **argv) > > if ((decode_error_stat[0] + decode_error_stat[1]) * max_error_rate < > decode_error_stat[1]) > > exit_program(69); > > > > + log_flags = av_log_get_flags(); > > + if (log_flags & AV_LOG_PRINT_TIME || log_flags & > AV_LOG_PRINT_DATETIME) > > + av_log(NULL, AV_LOG_INFO, "\n"); /* end with line break to > > + avoid mixing up with shell prompt */ > > + > > exit_program(received_nb_signals ? 255 : main_return_code); > > return main_return_code; > > } > > diff --git a/libavutil/log.c b/libavutil/log.c index > > 66defa9c42..ff4b6cc885 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; > > > > @@ -289,14 +291,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) { > > @@ -314,6 +334,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)); > > > > @@ -334,12 +358,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; > > } > > > > @@ -348,7 +372,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]; > > @@ -383,6 +407,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); > > @@ -397,7 +424,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); > > This is completely wrong: The AVBPrints that use > AV_BPRINT_SIZE_AUTOMATIC don't need to be finalized, but the other one > (namely part[3]) need it. The same goes for the change above. > > > ff_mutex_unlock(&mutex); > > } > > > > diff --git a/libavutil/log.h b/libavutil/log.h index > > 8727c38afc..27eb071884 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); > > > > > You need to separate this into an libavutil patch and a subsequent patch to > fftools. The documentation should be added to the commit introducing the > things to be documented. The patch to libavutil needs an APIchanges entry > and a minor version bump. The separate libavutil patch and the remaining patch - should they be separate as separate patches in a single patchset or also in separate patchsets? Thanks a lot for reviewing. sw
Soft Works: >> -----Original Message----- >> From: ffmpeg-devel <ffmpeg-devel-bounces@ffmpeg.org> On Behalf Of >> Andreas Rheinhardt >> Sent: Monday, 9 August 2021 03:11 >> To: ffmpeg-devel@ffmpeg.org >> Subject: Re: [FFmpeg-devel] [PATCH v3 1/2] Add option to log timing >> >> Soft Works: >>> This commit adds two logging flags: 'timing' and 'datetiming'. >>> >>> Usage: >>> >>> ffmpeg -loglevel +timing >>> >>> or >>> >>> ffmpeg -loglevel +datetiming >>> >>> Signed-off-by: softworkz <softworkz@hotmail.com> (cherry picked from >>> commit 960c82cede25c21bcea478b26309691fdc7fcec7) >>> (cherry picked from commit 0851f36f5ecead61317a1ce631facdacae76d886) >> >> This refers to objects not in our repo, so it is useless. > > Will remove. > >> >>> --- >>> v2 was from 2019-09-17 >>> fftools/cmdutils.c | 14 ++++++++++++++ >>> fftools/ffmpeg.c | 6 +++++- >>> libavutil/log.c | 37 ++++++++++++++++++++++++++++++++----- >>> libavutil/log.h | 10 ++++++++++ >>> 4 files changed, 61 insertions(+), 6 deletions(-) >>> >>> diff --git a/fftools/cmdutils.c b/fftools/cmdutils.c index >>> f5e39f616f..238a607d03 100644 >>> --- a/fftools/cmdutils.c >>> +++ b/fftools/cmdutils.c >>> @@ -919,6 +919,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)) { >> >> Don't hardcode the length, use av_strstart. > > Well, I just followed the pattern of the existing code above. > > What shall I do? Change the existing code, change only > my new code or leave it as is and add a patch later that > changes only this bit but for all at once? > If you add it with strncmp(), you'll just increase the ultimate diff. I don't care whether you send a (separate) patch changing the other code. >> >>> + if (cmd == '-') { >>> + flags &= ~AV_LOG_PRINT_DATETIME; >>> + } else { >>> + flags |= AV_LOG_PRINT_DATETIME; >>> + } >>> + arg = token + 10; >>> } else { >>> break; >>> } >>> diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c index >>> b0ce7c7c32..b0b105be1c 100644 >>> --- a/fftools/ffmpeg.c >>> +++ b/fftools/ffmpeg.c >>> @@ -4983,7 +4983,7 @@ static void log_callback_null(void *ptr, int >>> level, const char *fmt, va_list vl) >>> >>> int main(int argc, char **argv) >>> { >>> - int i, ret; >>> + int i, ret, log_flags; >>> BenchmarkTimeStamps ti; >>> >>> init_dynload(); >>> @@ -5049,6 +5049,10 @@ int main(int argc, char **argv) >>> if ((decode_error_stat[0] + decode_error_stat[1]) * max_error_rate < >> decode_error_stat[1]) >>> exit_program(69); >>> >>> + log_flags = av_log_get_flags(); >>> + if (log_flags & AV_LOG_PRINT_TIME || log_flags & >> AV_LOG_PRINT_DATETIME) >>> + av_log(NULL, AV_LOG_INFO, "\n"); /* end with line break to >>> + avoid mixing up with shell prompt */ >>> + >>> exit_program(received_nb_signals ? 255 : main_return_code); >>> return main_return_code; >>> } >>> diff --git a/libavutil/log.c b/libavutil/log.c index >>> 66defa9c42..ff4b6cc885 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; >>> >>> @@ -289,14 +291,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) { >>> @@ -314,6 +334,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)); >>> >>> @@ -334,12 +358,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; >>> } >>> >>> @@ -348,7 +372,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]; >>> @@ -383,6 +407,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); >>> @@ -397,7 +424,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); >> >> This is completely wrong: The AVBPrints that use >> AV_BPRINT_SIZE_AUTOMATIC don't need to be finalized, but the other one >> (namely part[3]) need it. The same goes for the change above. >> >>> ff_mutex_unlock(&mutex); >>> } >>> >>> diff --git a/libavutil/log.h b/libavutil/log.h index >>> 8727c38afc..27eb071884 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); >>> >>> >> You need to separate this into an libavutil patch and a subsequent patch to >> fftools. The documentation should be added to the commit introducing the >> things to be documented. The patch to libavutil needs an APIchanges entry >> and a minor version bump. > > The separate libavutil patch and the remaining patch - should they be separate > as separate patches in a single patchset or also in separate patchsets? > Single patchset.
diff --git a/fftools/cmdutils.c b/fftools/cmdutils.c index f5e39f616f..238a607d03 100644 --- a/fftools/cmdutils.c +++ b/fftools/cmdutils.c @@ -919,6 +919,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/fftools/ffmpeg.c b/fftools/ffmpeg.c index b0ce7c7c32..b0b105be1c 100644 --- a/fftools/ffmpeg.c +++ b/fftools/ffmpeg.c @@ -4983,7 +4983,7 @@ static void log_callback_null(void *ptr, int level, const char *fmt, va_list vl) int main(int argc, char **argv) { - int i, ret; + int i, ret, log_flags; BenchmarkTimeStamps ti; init_dynload(); @@ -5049,6 +5049,10 @@ int main(int argc, char **argv) if ((decode_error_stat[0] + decode_error_stat[1]) * max_error_rate < decode_error_stat[1]) exit_program(69); + log_flags = av_log_get_flags(); + if (log_flags & AV_LOG_PRINT_TIME || log_flags & AV_LOG_PRINT_DATETIME) + av_log(NULL, AV_LOG_INFO, "\n"); /* end with line break to avoid mixing up with shell prompt */ + exit_program(received_nb_signals ? 255 : main_return_code); return main_return_code; } diff --git a/libavutil/log.c b/libavutil/log.c index 66defa9c42..ff4b6cc885 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; @@ -289,14 +291,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) { @@ -314,6 +334,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)); @@ -334,12 +358,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; } @@ -348,7 +372,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]; @@ -383,6 +407,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); @@ -397,7 +424,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 8727c38afc..27eb071884 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);
This commit adds two logging flags: 'timing' and 'datetiming'. Usage: ffmpeg -loglevel +timing or ffmpeg -loglevel +datetiming Signed-off-by: softworkz <softworkz@hotmail.com> (cherry picked from commit 960c82cede25c21bcea478b26309691fdc7fcec7) (cherry picked from commit 0851f36f5ecead61317a1ce631facdacae76d886) --- v2 was from 2019-09-17 fftools/cmdutils.c | 14 ++++++++++++++ fftools/ffmpeg.c | 6 +++++- libavutil/log.c | 37 ++++++++++++++++++++++++++++++++----- libavutil/log.h | 10 ++++++++++ 4 files changed, 61 insertions(+), 6 deletions(-)