From patchwork Tue Sep 17 00:07:37 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Soft Works X-Patchwork-Id: 15106 Return-Path: X-Original-To: patchwork@ffaux-bg.ffmpeg.org Delivered-To: patchwork@ffaux-bg.ffmpeg.org Received: from ffbox0-bg.mplayerhq.hu (ffbox0-bg.ffmpeg.org [79.124.17.100]) by ffaux.localdomain (Postfix) with ESMTP id 95BA3447E07 for ; Tue, 17 Sep 2019 03:07:46 +0300 (EEST) Received: from [127.0.1.1] (localhost [127.0.0.1]) by ffbox0-bg.mplayerhq.hu (Postfix) with ESMTP id 6E07B687F43; Tue, 17 Sep 2019 03:07:46 +0300 (EEST) X-Original-To: ffmpeg-devel@ffmpeg.org Delivered-To: ffmpeg-devel@ffmpeg.org Received: from NAM04-BN3-obe.outbound.protection.outlook.com (mail-oln040092009010.outbound.protection.outlook.com [40.92.9.10]) by ffbox0-bg.mplayerhq.hu (Postfix) with ESMTPS id 135C2681850 for ; Tue, 17 Sep 2019 03:07:40 +0300 (EEST) ARC-Seal: i=1; a=rsa-sha256; s=arcselector9901; d=microsoft.com; cv=none; b=YIsAI5T40KNk1amTLSCLu8NKIgsJMYZk4vjJpiZk4axq8HNYNcki1alik/6CKArQwyHZDOjgYkfkq30Xb14j3mmpD5bSYVvc4ZL778XrbkWm0sd6SWKoZtMH7Vijy5P/56unrAHcFatsuDeIhtG9NAWhdascIY+aTt2798PZ35QcwykAA1e/lJqQltq+DA/DIeflzc3dmE8CrKwEU2HusL5A06cn5BgXDZ9Y9FmtjTeKyDSN3OlkZ/sMBgK9zVXpZXmfdyseSsMvTM6voL6liKaIB+1lrMXL4/UV8anlEgDNWh7NlCvQhLVpTpfD8OZro0N9KBdsMCLFb1itMMrx9A== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=microsoft.com; s=arcselector9901; h=From:Date:Subject:Message-ID:Content-Type:MIME-Version:X-MS-Exchange-SenderADCheck; bh=BXZM31O+jd1xqsrM8T9FyJlIgQcOHHrbwmfYKBfQdkg=; b=nw9iaO2imOjXHo3z2OC2Jie83Wh3/8+Wl2ORelk1BaCBFjHHB4wwJ6HsBXXAHnRH70HnEphYwEZ4AcQiB/akq5+lB3irEZV6VcfcpHPU1PGQdflHdFZKW0g5itV8SZPOGLC8qrcCr7hOXAVrKXmMYAuqaEGKXHzB1TyLUMJAFAKhqvM+lcZZfQTSmzy22KRpgZG06JcDr/YzGTaS8qo57vgD6fgOHXuv4RbHIbj00XlIDdAoHHJ7Gmw8bIfeD5Y/520SvdLMq6RpN8d5wio50xHcqyzMqzVMMGxm4PdMnXsrZOMmeZF2g5I/Y6K9+c1NOv8AYrguJE8gQoCV0PWNpQ== ARC-Authentication-Results: i=1; mx.microsoft.com 1; spf=none; dmarc=none; dkim=none; arc=none DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=hotmail.com; s=selector1; h=From:Date:Subject:Message-ID:Content-Type:MIME-Version:X-MS-Exchange-SenderADCheck; bh=BXZM31O+jd1xqsrM8T9FyJlIgQcOHHrbwmfYKBfQdkg=; b=qVrBFlkvZAZmM4r0vrmFaY5EiJyJik5hKOZp1k6XPmf3J8r76/RuM4Z0KvZGVVPNxcHq59MvRUDK6DSTlspdVP7hu2fYHISwPBWLqoV3ZPTugXnwL5pzIB+mdprGmYU4qmefQPTwgyrIycw5nHJbNlW9jUQD08dR9eSjX6iNuXz+Hyf0gLHPuw0i+kVTX4oclpLlNxwkGjdI+IXrcgL/KnCkO4JpXI3kSUMO0eaoHbstZDlmX6f2VOtLeHM0vZWer8hlRXkLX0BdAyuKzbML4gqU27ABkiBdIkPMq09d0CDAyfCD7fYGcx1U0nuro8k5wF/sbg7hD9cShUTtokWQOQ== Received: from BN3NAM04FT027.eop-NAM04.prod.protection.outlook.com (10.152.92.59) by BN3NAM04HT070.eop-NAM04.prod.protection.outlook.com (10.152.93.187) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384) id 15.20.2263.14; Tue, 17 Sep 2019 00:07:37 +0000 Received: from MN2PR13MB2752.namprd13.prod.outlook.com (10.152.92.58) by BN3NAM04FT027.mail.protection.outlook.com (10.152.92.171) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384) id 15.20.2263.14 via Frontend Transport; Tue, 17 Sep 2019 00:07:37 +0000 Received: from MN2PR13MB2752.namprd13.prod.outlook.com ([fe80::9c2c:8444:38e1:5d6]) by MN2PR13MB2752.namprd13.prod.outlook.com ([fe80::9c2c:8444:38e1:5d6%7]) with mapi id 15.20.2284.009; Tue, 17 Sep 2019 00:07:37 +0000 From: Soft Works To: FFmpeg development discussions and patches Thread-Topic: [PATCH v2] Add option to log timing Thread-Index: AdVs69RrjNKfx94AQdqXraJ0R/il6w== Date: Tue, 17 Sep 2019 00:07:37 +0000 Message-ID: Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: x-incomingtopheadermarker: OriginalChecksum:19D3C7F4667AA1C6B3BA28C15ADD07754B471A1C09A2CF134E4B6D4AF636BE46; UpperCasedChecksum:8E0362BAAD773BF0167400B997B979A63B41F636C71292115C0F9776A92A2549; SizeAsReceived:6559; Count:40 x-tmn: [X03jelm5GnSg6jqBEvhL/eeQIjboSR1t] x-ms-publictraffictype: Email x-incomingheadercount: 40 x-eopattributedmessage: 0 x-microsoft-antispam: BCL:0; PCL:0; RULEID:(2390118)(5050001)(7020095)(20181119110)(201702061078)(5061506573)(5061507331)(1603103135)(2017031320274)(2017031322404)(2017031323274)(2017031324274)(1601125500)(1603101475)(1701031045); SRVR:BN3NAM04HT070; x-ms-traffictypediagnostic: BN3NAM04HT070: x-microsoft-antispam-message-info: Mmo6oMahyJRTxuLjDyYa8jNpr7Z4EoUP+SXehzzYnBpmG8HUUvyk5NMVGJVwfmetBHSIsse0S8MBnuebK+F4MYFYlscvaHgdY3uyJfnoFL+NR6OKqO/tanq60a4lfxCNMyVfSXQVL/0PEZfm/nga5sKrQyGYgJ4Ek02OyetNCV6SCYTguvmZvHPM5qBWZpZ5 x-ms-exchange-transport-forked: True MIME-Version: 1.0 X-OriginatorOrg: hotmail.com X-MS-Exchange-CrossTenant-RMS-PersistedConsumerOrg: 00000000-0000-0000-0000-000000000000 X-MS-Exchange-CrossTenant-Network-Message-Id: b9ba111c-5f32-4b6e-49be-08d73b030c68 X-MS-Exchange-CrossTenant-rms-persistedconsumerorg: 00000000-0000-0000-0000-000000000000 X-MS-Exchange-CrossTenant-originalarrivaltime: 17 Sep 2019 00:07:37.3977 (UTC) X-MS-Exchange-CrossTenant-fromentityheader: Internet X-MS-Exchange-CrossTenant-id: 84df9e7f-e9f6-40af-b435-aaaaaaaaaaaa X-MS-Exchange-Transport-CrossTenantHeadersStamped: BN3NAM04HT070 Subject: [FFmpeg-devel] [PATCH v2] Add option to log timing X-BeenThere: ffmpeg-devel@ffmpeg.org X-Mailman-Version: 2.1.20 Precedence: list List-Id: FFmpeg development discussions and patches List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Reply-To: FFmpeg development discussions and patches Errors-To: ffmpeg-devel-bounces@ffmpeg.org Sender: "ffmpeg-devel" This commit adds two logging flags: 'timing' and 'datetiming'. Usage: ffmpeg -loglevel +timing or ffmpeg -loglevel +datetiming --- fftools/cmdutils.c | 14 ++++++++++++++ libavutil/log.c | 37 ++++++++++++++++++++++++++++++++----- libavutil/log.h | 10 ++++++++++ 3 files changed, 56 insertions(+), 5 deletions(-) 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);