[FFmpeg-devel] [PATCH v3 1/2] Add option to log timing
Andreas Rheinhardt
andreas.rheinhardt at outlook.com
Mon Aug 9 04:33:14 EEST 2021
Soft Works:
>> -----Original Message-----
>> From: ffmpeg-devel <ffmpeg-devel-bounces at ffmpeg.org> On Behalf Of
>> Andreas Rheinhardt
>> Sent: Monday, 9 August 2021 03:11
>> To: ffmpeg-devel at 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 at 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.
More information about the ffmpeg-devel
mailing list