| Message ID | MN2PR13MB27524DB8A461B08F45729B87BA8F0@MN2PR13MB2752.namprd13.prod.outlook.com |
|---|---|
| State | Superseded, archived |
| Headers | show |
On Tue, Sep 17, 2019 at 00:07:37 +0000, Soft Works wrote: > This commit adds two logging flags: 'timing' and 'datetiming'. I like the whole idea. I haven't tested yet, but I will in a moment. > Usage: > ffmpeg -loglevel +timing > or > ffmpeg -loglevel +datetiming Have you considered what happens if you do $ ffmpeg -loglevel +timing+datetiming ? (It just seems a bit weird having one flag being a superset of another. I don't mind otherwise.) > fftools/cmdutils.c | 14 ++++++++++++++ > libavutil/log.c | 37 ++++++++++++++++++++++++++++++++----- > libavutil/log.h | 10 ++++++++++ You also need to add documentation for these options to doc/fftools-common-opts.texi (section "@item -loglevel"). libavutil/log.h is part of the API, IIUC. So you should bump libavutil's micro version, and even add an entry into doc/APIchanges. > + && ((flags & AV_LOG_PRINT_TIME) || (flags & AV_LOG_PRINT_DATETIME))) > + format_date_now(&part[4], flags & AV_LOG_PRINT_DATETIME); According to the style of the other calls, you could express "&part[4]" as "part+4". > if (*print_prefix && (level > AV_LOG_QUIET) && (flags & AV_LOG_PRINT_LEVEL)) > av_bprintf(part+2, "[%s] ", get_level_str(level)); (As done here.) Moritz
> -----Original Message----- > From: ffmpeg-devel <ffmpeg-devel-bounces@ffmpeg.org> On Behalf Of > Moritz Barsnick > Sent: Tuesday, September 17, 2019 11:07 PM > To: FFmpeg development discussions and patches <ffmpeg- > devel@ffmpeg.org> > Subject: Re: [FFmpeg-devel] [PATCH v2] Add option to log timing > > On Tue, Sep 17, 2019 at 00:07:37 +0000, Soft Works wrote: > > This commit adds two logging flags: 'timing' and 'datetiming'. > > I like the whole idea. I haven't tested yet, but I will in a moment. > > > Usage: > > ffmpeg -loglevel +timing > > or > > ffmpeg -loglevel +datetiming > > Have you considered what happens if you do $ ffmpeg -loglevel > +timing+datetiming ? It will print date + time. > (It just seems a bit weird having one flag being a superset of another. > I don't mind otherwise.) You're correct, It's a superset. I found it more convenient to do it like this because: - It would make little sense printing only the date for each line - I wanted to avoid requiring a user to specify two separate flags to get both date and time But I wouldn't mind changing this to independent flags > You also need to add documentation for these options to doc/fftools- > common-opts.texi (section "@item -loglevel"). Damn, this is going to get more work than expected ;-) > libavutil/log.h is part of the API, IIUC. So you should bump libavutil's micro > version, and even add an entry into doc/APIchanges. OK. > > + && ((flags & AV_LOG_PRINT_TIME) || (flags & > AV_LOG_PRINT_DATETIME))) > > + format_date_now(&part[4], flags & AV_LOG_PRINT_DATETIME); > > According to the style of the other calls, you could express "&part[4]" > as "part+4". I won't argue - conformity wins of course. Thanks for looking into this, I'll wait for other comments before updating the patch. softworkz
On Wed, Sep 18, 2019 at 00:38:13 +0000, Soft Works wrote: > You're correct, It's a superset. I found it more convenient to do it like this because: > - It would make little sense printing only the date for each line > - I wanted to avoid requiring a user to specify two separate flags to get both date and time > > But I wouldn't mind changing this to independent flags It's okay by me, I was just pointing it out. Others may want to comment. > > You also need to add documentation for these options to doc/fftools- > > common-opts.texi (section "@item -loglevel"). > > Damn, this is going to get more work than expected ;-) But it's easy just to add a few words. :-) (Be sure to rebuild the docs as well, to ensure that your edits don't break the markup syntax.) > Thanks for looking into this, I'll wait for other comments before updating the patch. I always get a final date/time line without a terminating line break, which is quite ugly: barsnick@sunshine:/usr/new/tools/video/ffmpeg/ffmpeg-snapshot-2019-09-17 > ffmpeg -loglevel +datetiming -f lavfi -i testsrc2=g=x 2019-09-18 15:43:16.455 ffmpeg version N-94957-g65589ad Copyright (c) 2000-2019 the FFmpeg developers 2019-09-18 15:43:16.457 built with icc (ICC) 14.0.3 20140422 2019-09-18 15:43:16.457 configuration: --prefix=/usr/new/tools/video/install/ffmpeg/2019-09-17 --cc=icc --cxx=icpc --enable-gpl --enable-version3 --enable-nonfree --dis able-shared --enable-gnutls --enable-libcdio --enable-libfreetype --enable-libx264 --enable-libvpx --enable-libmp3lame --enable-openal --enable-libopencore-amrnb --enable -libopencore-amrwb --enable-libtwolame --enable-librtmp --enable-libass --enable-libv4l2 --enable-libvidstab --enable-libfdk-aac --enable-libsmbclient --enable-libzvbi -- enable-libtesseract --enable-libzmq --enable-libopus --enable-libcodec2 --enable-libxml2 --enable-libopencv 2019-09-18 15:43:16.458 libavutil 56. 35.100 / 56. 35.100 2019-09-18 15:43:16.459 libavcodec 58. 57.100 / 58. 57.100 2019-09-18 15:43:16.459 libavformat 58. 33.100 / 58. 33.100 2019-09-18 15:43:16.460 libavdevice 58. 9.100 / 58. 9.100 2019-09-18 15:43:16.461 libavfilter 7. 58.102 / 7. 58.102 2019-09-18 15:43:16.461 libswscale 5. 6.100 / 5. 6.100 2019-09-18 15:43:16.462 libswresample 3. 6.100 / 3. 6.100 2019-09-18 15:43:16.463 libpostproc 55. 6.100 / 55. 6.100 2019-09-18 15:43:16.465 [Parsed_testsrc2_0 @ 0xb24fa40] Option 'g' not found 2019-09-18 15:43:16.466 [lavfi @ 0xb24ea80] Error initializing filter 'testsrc2' with args 'g=x' 2019-09-18 15:43:16.468 testsrc2=g=x: Option not found 2019-09-18 15:43:16.469 barsnick@sunshine:/usr/new/tools/video/ffmpeg/ffmpeg-snapshot-2019-09-17 > (See my new shell prompt appearing on the same line as the final timestamp.) Please try to find out why that is and whether it can be fixed without a hack. Moritz
diff --git a/fftools/cmdutils.c b/fftools/cmdutils.c index fdcd376b76..7805058f8b 100644 --- a/fftools/cmdutils.c +++ b/fftools/cmdutils.c @@ -912,6 +912,20 @@ int opt_loglevel(void *optctx, const char *opt, const char *arg) flags |= AV_LOG_PRINT_LEVEL; } arg = token + 5; + } else if (!strncmp(token, "timing", 6)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_TIME; + } else { + flags |= AV_LOG_PRINT_TIME; + } + arg = token + 6; + } else if (!strncmp(token, "datetiming", 10)) { + if (cmd == '-') { + flags &= ~AV_LOG_PRINT_DATETIME; + } else { + flags |= AV_LOG_PRINT_DATETIME; + } + arg = token + 10; } else { break; } diff --git a/libavutil/log.c b/libavutil/log.c index 93a156b8e4..16a1d13d1d 100644 --- a/libavutil/log.c +++ b/libavutil/log.c @@ -40,6 +40,8 @@ #include "internal.h" #include "log.h" #include "thread.h" +#include "time.h" +#include "time_internal.h" static AVMutex mutex = AV_MUTEX_INITIALIZER; @@ -243,14 +245,32 @@ static const char *get_level_str(int level) } } +static void format_date_now(AVBPrint* timeBuf, int include_date) +{ + struct tm *ptm, tmbuf; + int64_t time_us = av_gettime(); + int64_t time_ms = time_us / 1000; + const time_t time_s = time_ms / 1000; + int millisec = time_ms - (time_s * 1000); + ptm = localtime_r(&time_s, &tmbuf); + if (ptm) { + if (include_date) + av_bprint_strftime(timeBuf, "%Y-%m-%d ", ptm); + + av_bprint_strftime(timeBuf, "%H:%M:%S", ptm); + av_bprintf(timeBuf, ".%03d ", millisec); + } +} + static void format_line(void *avcl, int level, const char *fmt, va_list vl, - AVBPrint part[4], int *print_prefix, int type[2]) + AVBPrint part[5], int *print_prefix, int type[2]) { AVClass* avc = avcl ? *(AVClass **) avcl : NULL; av_bprint_init(part+0, 0, AV_BPRINT_SIZE_AUTOMATIC); av_bprint_init(part+1, 0, AV_BPRINT_SIZE_AUTOMATIC); av_bprint_init(part+2, 0, AV_BPRINT_SIZE_AUTOMATIC); av_bprint_init(part+3, 0, 65536); + av_bprint_init(part+4, 0, AV_BPRINT_SIZE_AUTOMATIC); if(type) type[0] = type[1] = AV_CLASS_CATEGORY_NA + 16; if (*print_prefix && avc) { @@ -268,6 +288,10 @@ static void format_line(void *avcl, int level, const char *fmt, va_list vl, if(type) type[1] = get_category(avcl); } + if (*print_prefix + && ((flags & AV_LOG_PRINT_TIME) || (flags & AV_LOG_PRINT_DATETIME))) + format_date_now(&part[4], flags & AV_LOG_PRINT_DATETIME); + if (*print_prefix && (level > AV_LOG_QUIET) && (flags & AV_LOG_PRINT_LEVEL)) av_bprintf(part+2, "[%s] ", get_level_str(level)); @@ -288,12 +312,12 @@ void av_log_format_line(void *ptr, int level, const char *fmt, va_list vl, int av_log_format_line2(void *ptr, int level, const char *fmt, va_list vl, char *line, int line_size, int *print_prefix) { - AVBPrint part[4]; + AVBPrint part[5]; int ret; format_line(ptr, level, fmt, vl, part, print_prefix, NULL); ret = snprintf(line, line_size, "%s%s%s%s", part[0].str, part[1].str, part[2].str, part[3].str); - av_bprint_finalize(part+3, NULL); + av_bprint_finalize(part+4, NULL); return ret; } @@ -302,7 +326,7 @@ void av_log_default_callback(void* ptr, int level, const char* fmt, va_list vl) static int print_prefix = 1; static int count; static char prev[LINE_SZ]; - AVBPrint part[4]; + AVBPrint part[5]; char line[LINE_SZ]; static int is_atty; int type[2]; @@ -337,6 +361,9 @@ void av_log_default_callback(void* ptr, int level, const char* fmt, va_list vl) count = 0; } strcpy(prev, line); + + sanitize(part[4].str); + colored_fputs(7, 0, part[4].str); sanitize(part[0].str); colored_fputs(type[0], 0, part[0].str); sanitize(part[1].str); @@ -351,7 +378,7 @@ void av_log_default_callback(void* ptr, int level, const char* fmt, va_list vl) VALGRIND_PRINTF_BACKTRACE("%s", ""); #endif end: - av_bprint_finalize(part+3, NULL); + av_bprint_finalize(part+4, NULL); ff_mutex_unlock(&mutex); } diff --git a/libavutil/log.h b/libavutil/log.h index d9554e609d..34ccded4bc 100644 --- a/libavutil/log.h +++ b/libavutil/log.h @@ -352,6 +352,16 @@ int av_log_format_line2(void *ptr, int level, const char *fmt, va_list vl, */ #define AV_LOG_PRINT_LEVEL 2 +/** + * Include system time in log output. + */ +#define AV_LOG_PRINT_TIME 4 + +/** + * Include system date and time in log output. + */ +#define AV_LOG_PRINT_DATETIME 8 + void av_log_set_flags(int arg); int av_log_get_flags(void);