From patchwork Wed Sep 4 18:53:28 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Soft Works X-Patchwork-Id: 14906 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 C07CB4483BF for ; Wed, 4 Sep 2019 21:53:42 +0300 (EEST) Received: from [127.0.1.1] (localhost [127.0.0.1]) by ffbox0-bg.mplayerhq.hu (Postfix) with ESMTP id 94F1F68045D; Wed, 4 Sep 2019 21:53:42 +0300 (EEST) X-Original-To: ffmpeg-devel@ffmpeg.org Delivered-To: ffmpeg-devel@ffmpeg.org Received: from NAM01-SN1-obe.outbound.protection.outlook.com (mail-oln040092002071.outbound.protection.outlook.com [40.92.2.71]) by ffbox0-bg.mplayerhq.hu (Postfix) with ESMTPS id A691D680092 for ; Wed, 4 Sep 2019 21:53:35 +0300 (EEST) ARC-Seal: i=1; a=rsa-sha256; s=arcselector9901; d=microsoft.com; cv=none; b=KwkVY9BWsOz7ircvQkK+UjBtkOVXMY6Ifwlhca+CrjDq4FcYK1LC48C6RS+KuWhrIDkm14Ol8djGGlyjeN63j1VBTu9J0DGOdE8KpKJ/4xuVxUx8OOJWHQs5G0AdBfs3dEFetBupn3vYWb61fmZJFunYUtymu6dIfkufD+hX6Ia6+WIAaykORtz9GWk5vxWZ5eFH2JFgUCiS/8TlRkdRb+D51k276JnDx0VZUcPZcTDewBadDtBVPKf9+YwXkBx2b/eDRLCy2E89iTvUFWUr5pT3lwdzQCMi5yPdsfaJxVywHPAYE5tQceaQdBz2GEwnJNcDe3B5b4JX87whPIiy6g== 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=ApG/405hIV9n8ddvSmnoJjjCojhQgayeqm2G786w6Uo=; b=fLkBC5f33hdd3TWpBKhYplxfe3f/EDALkUwvlvcAmYMJ0QmwU2GV0WgiiOQXqIwLJL46kdsU/gENPjEgQnr8ZaHqibAmN2DOPVxP7kK5vwnHUnahs1Y7wG6GPnsZub9hutHtoOkvbgJq+Sb2/KjJ1m1g1yDgpDF5KHuOLYODBCaHkg+lgmrKqGZE+k1korqM6A+OjnGkY8exJEsW0dUEr4QYmAKR+YzqXG+AJqJiTPGsRTVqkwSZc56ZS2Llq6+QLKGiyhmxun0qkbvRZbb3GuZeVGWU8JJwXvAG64GABUFjTuQ4CyPfCJ8ubv9y7rcNlArAWAtG+z9FAzmsEvCzyw== 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=ApG/405hIV9n8ddvSmnoJjjCojhQgayeqm2G786w6Uo=; b=L59uMAeTlJRXhx+v5+JTa130XpcQ8q3XspyBOfMaP1tXdPcYpahzQaFqaiMPC/k+7+aJzf9geMgeB4Y9RstbqTd3Z6b1ZVNYWfLOl73VjK0Z5abCMsKGWcfstlEfUBF2bHgQ2AsICVQbkJrmNz91MznjgGaJ8QUSA5Eli6FxeQgTeteBvoghkKLSkX//Zh+ssRue+wzXhKlq185EccZ39ha9X3/pBnhdfTZRLyL+K8H+UMw0xqm1JWxeSsXpIOTEGHjBJvmmgOFrf5Gen8BxfEcbANjNUiHhDl416aQ6oxCIifeIaSDx5ryyiivkySffqtDS4yDpIXK+G7YxdSQPcQ== Received: from BN3NAM01FT010.eop-nam01.prod.protection.outlook.com (10.152.66.56) by BN3NAM01HT102.eop-nam01.prod.protection.outlook.com (10.152.66.251) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384) id 15.20.2199.13; Wed, 4 Sep 2019 18:53:29 +0000 Received: from MN2PR13MB2752.namprd13.prod.outlook.com (10.152.66.58) by BN3NAM01FT010.mail.protection.outlook.com (10.152.66.245) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.20.2199.13 via Frontend Transport; Wed, 4 Sep 2019 18:53:29 +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.2241.014; Wed, 4 Sep 2019 18:53:28 +0000 From: Soft Works To: "ffmpeg-devel@ffmpeg.org" Thread-Topic: [PATCH] Add option to log timing Thread-Index: AQHVY1GmUc0krsOC4kKUhxrP00z+6A== Date: Wed, 4 Sep 2019 18:53:28 +0000 Message-ID: Accept-Language: en-US Content-Language: de-DE X-MS-Has-Attach: yes X-MS-TNEF-Correlator: x-incomingtopheadermarker: OriginalChecksum:81C43648F16CC5FEA52DCD77DB0631283B8B7D26D9D2ACD02A0750BE747A28F5; UpperCasedChecksum:EAD863AA2778235693A0A0F4D4FC2622FF7526C4AB9C759D642BFB1286386A20; SizeAsReceived:6497; Count:40 x-tmn: [Pk9bHJxt92e12GLO/K8u1xBmk2hpTm68] 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:BN3NAM01HT102; x-ms-traffictypediagnostic: BN3NAM01HT102: x-microsoft-antispam-message-info: AcyrJcUSeyWU8UqHVdaONerRnDMqbVMUHqMzsabZBg2xfKQxLUtW+K2QC7J/SjaqcYaSRQKHrXLkDCzVw5JZplIKfFIJM9XjbPTSkP03bjJWrKeIgUdCwYtujV3I1k9Fx8RbCx8A3KVOrfwzjN3qH6Rp8rU1E8g7fF3yILulCeCOE5JaRbgf/zF7jcbcKUVg 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: 2971d0bd-1c5f-483f-cabc-08d731692cc8 X-MS-Exchange-CrossTenant-rms-persistedconsumerorg: 00000000-0000-0000-0000-000000000000 X-MS-Exchange-CrossTenant-originalarrivaltime: 04 Sep 2019 18:53:28.8008 (UTC) X-MS-Exchange-CrossTenant-fromentityheader: Internet X-MS-Exchange-CrossTenant-id: 84df9e7f-e9f6-40af-b435-aaaaaaaaaaaa X-MS-Exchange-Transport-CrossTenantHeadersStamped: BN3NAM01HT102 X-Content-Filtered-By: Mailman/MimeDel 2.1.20 Subject: [FFmpeg-devel] [PATCH] 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 -logleve +timing Timing information will only be added to log lines once transcoding has started. --- fftools/cmdutils.c | 14 ++++++++++++++ fftools/ffmpeg.c | 3 +++ libavutil/log.c | 37 ++++++++++++++++++++++++++++++++----- libavutil/log.h | 17 +++++++++++++++++ 4 files changed, 66 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/fftools/ffmpeg.c b/fftools/ffmpeg.c index 01f04103cf..ed1c6ab6fc 100644 --- a/fftools/ffmpeg.c +++ b/fftools/ffmpeg.c @@ -4668,6 +4668,9 @@ static int transcode(void) av_log(NULL, AV_LOG_INFO, "Press [q] to stop, [?] for help\n"); } + /* Enable log timestamps if configured */ + av_log_set_flags(av_log_get_flags() | AV_LOG_PRINT_STARTUPCOMPLETE); + timer_start = av_gettime_relative(); #if HAVE_THREADS diff --git a/libavutil/log.c b/libavutil/log.c index 93a156b8e4..a374a68c4e 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) { @@ -277,6 +297,10 @@ static void format_line(void *avcl, int level, const char *fmt, va_list vl, char lastc = part[3].len && part[3].len <= part[3].size ? part[3].str[part[3].len - 1] : 0; *print_prefix = lastc == '\n' || lastc == '\r'; } + + if (*print_prefix && part[3].len > 1 && (flags & AV_LOG_PRINT_STARTUPCOMPLETE) + && ((flags & AV_LOG_PRINT_TIME) || (flags & AV_LOG_PRINT_DATETIME))) + format_date_now(&part[4], flags & AV_LOG_PRINT_DATETIME); } void av_log_format_line(void *ptr, int level, const char *fmt, va_list vl, @@ -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..a4a750de74 100644 --- a/libavutil/log.h +++ b/libavutil/log.h @@ -352,6 +352,23 @@ 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 + +/** + * Internal flag indicating that transcoding has started + * and subsequent log output should include timing when + * AV_LOG_PRINT_TIME or AV_LOG_PRINT_DATETIME is set. + */ +#define AV_LOG_PRINT_STARTUPCOMPLETE 65536 + void av_log_set_flags(int arg); int av_log_get_flags(void); -- 2.17.1.windows.2