From patchwork Fri Aug 14 17:34:41 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Stephen Hemminger X-Patchwork-Id: 75565 X-Patchwork-Delegate: thomas@monjalon.net Return-Path: X-Original-To: patchwork@inbox.dpdk.org Delivered-To: patchwork@inbox.dpdk.org Received: from dpdk.org (dpdk.org [92.243.14.124]) by inbox.dpdk.org (Postfix) with ESMTP id 457C8A04B0; Fri, 14 Aug 2020 19:34:54 +0200 (CEST) Received: from [92.243.14.124] (localhost [127.0.0.1]) by dpdk.org (Postfix) with ESMTP id 7CACF1C0CD; Fri, 14 Aug 2020 19:34:53 +0200 (CEST) Received: from mail-pg1-f196.google.com (mail-pg1-f196.google.com [209.85.215.196]) by dpdk.org (Postfix) with ESMTP id 5FD151C0C0 for ; Fri, 14 Aug 2020 19:34:52 +0200 (CEST) Received: by mail-pg1-f196.google.com with SMTP id 189so4217015pgg.13 for ; Fri, 14 Aug 2020 10:34:52 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=networkplumber-org.20150623.gappssmtp.com; s=20150623; h=from:to:cc:subject:date:message-id:mime-version :content-transfer-encoding; bh=75/RxtbuPmNwggjYKosjs3q1lkkYVRP7mTo6krEwNhw=; b=lxduagCHh2sIIcXXrQvWW6NMUEu2B5fwtISdHTzNs4WCP2W+WCBNF4pV+G+6x+Dk5w ZboSaMFA9aXik2QovCfx2a1Vb2BCQKdtRomrezXzJZhGeNEHILjwciQ1zv2spjD2LJcs c2rJWCHD9BZjQGaZViOTGFfTpWQZGTkB6FfUds2f0RH+dupVk50KRbgaosp/VW6exymd XQLsUMWkh6b2KQE8ofDJJC+Ksjhgh3NHdZUenVIYWD0evG8opCfiVcSWGG2fcJ4cPjAF lY1R7WlkkayoFeX0PQWqHv/nSsaGE6T9eqHpANqxa9Xlp3PFVams/i+CqvRWqg6nNam2 G1/w== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:mime-version :content-transfer-encoding; bh=75/RxtbuPmNwggjYKosjs3q1lkkYVRP7mTo6krEwNhw=; b=p7yXDopiHB6a2Qefi2Hif+DzglCJR5vBL+648Wp8uw82XllgghXlTMTtjRcPxcp6Ol qPyMG0M+QFZ3N9fDDzAs8cVlKe/Qnw2TyVsLJNF2VpM/pljzW/YcET72FTsBSDEBYkeI gaIh5tIvvbpLJtiEStlkawiLKnfFG3jClCE009kJXfiyCJ16vzicjMAkdJvQl/2DdVne sefq7R4rnBsSLkEtDm1UgWJuEba6PgLUWNgaOOQaa66hePrbO29KVTzr45s0ojtSIFQG s0+YbeoLEPgpTcZJq3dR+0cyeCGKjEOepO9bK7YF5RGpCFQufYlE3AMcHvq3iI8qhdsR M5CQ== X-Gm-Message-State: AOAM531uMzgTntp0DTLczpfz+CP00BBW2RGAJ1xOtlzZPVdf6vBfVxqh +tyF3s+E85qwe6SIzrbbYTACHeiRf/y85w== X-Google-Smtp-Source: ABdhPJyTlC3jYagI7AUTYADDMzn2ugAjnnvpg/80QvAK7UX89Z/4OW2i8TrH5+zYTbXS4BBZKNM2yA== X-Received: by 2002:a62:19d4:: with SMTP id 203mr2499880pfz.127.1597426490887; Fri, 14 Aug 2020 10:34:50 -0700 (PDT) Received: from hermes.lan (204-195-22-127.wavecable.com. [204.195.22.127]) by smtp.gmail.com with ESMTPSA id v2sm8949236pjd.18.2020.08.14.10.34.49 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Fri, 14 Aug 2020 10:34:50 -0700 (PDT) From: Stephen Hemminger To: dev@dpdk.org Cc: Stephen Hemminger Date: Fri, 14 Aug 2020 10:34:41 -0700 Message-Id: <20200814173441.23086-1-stephen@networkplumber.org> X-Mailer: git-send-email 2.27.0 MIME-Version: 1.0 Subject: [dpdk-dev] [PATCH] eal: add option to put timestamp on console output X-BeenThere: dev@dpdk.org X-Mailman-Version: 2.1.15 Precedence: list List-Id: DPDK patches and discussions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: dev-bounces@dpdk.org Sender: "dev" When debugging driver or startup issues, it is useful to have a timestamp on each message printed. The messages in syslog already have a timestamp, but often syslog is not available during testing. The timestamp format is chosen to look like the default Linux dmesg timestamp. Example: [ 0.000040] EAL: Probing VFIO support... Signed-off-by: Stephen Hemminger --- doc/guides/linux_gsg/linux_eal_parameters.rst | 5 +++ lib/librte_eal/common/eal_common_options.c | 5 +++ lib/librte_eal/common/eal_internal_cfg.h | 1 + lib/librte_eal/common/eal_options.h | 2 + lib/librte_eal/linux/eal_log.c | 41 +++++++++++++++++-- 5 files changed, 51 insertions(+), 3 deletions(-) diff --git a/doc/guides/linux_gsg/linux_eal_parameters.rst b/doc/guides/linux_gsg/linux_eal_parameters.rst index bd3977cb3d91..9336046c63a9 100644 --- a/doc/guides/linux_gsg/linux_eal_parameters.rst +++ b/doc/guides/linux_gsg/linux_eal_parameters.rst @@ -118,3 +118,8 @@ Other options local5 local6 local7 + +* ``--log-timestamp`` + + Add a timestamp of seconds and microseconds to each log message + written to standard output. diff --git a/lib/librte_eal/common/eal_common_options.c b/lib/librte_eal/common/eal_common_options.c index a5426e12346a..240610770ee1 100644 --- a/lib/librte_eal/common/eal_common_options.c +++ b/lib/librte_eal/common/eal_common_options.c @@ -76,6 +76,7 @@ eal_long_options[] = { {OPT_IOVA_MODE, 1, NULL, OPT_IOVA_MODE_NUM }, {OPT_LCORES, 1, NULL, OPT_LCORES_NUM }, {OPT_LOG_LEVEL, 1, NULL, OPT_LOG_LEVEL_NUM }, + {OPT_LOG_TIMESTAMP, 0, NULL, OPT_LOG_TIMESTAMP_NUM }, {OPT_TRACE, 1, NULL, OPT_TRACE_NUM }, {OPT_TRACE_DIR, 1, NULL, OPT_TRACE_DIR_NUM }, {OPT_TRACE_BUF_SIZE, 1, NULL, OPT_TRACE_BUF_SIZE_NUM }, @@ -1626,6 +1627,9 @@ eal_parse_common_option(int opt, const char *optarg, } break; } + case OPT_LOG_TIMESTAMP_NUM: + conf->log_timestamp = 1; + break; #ifndef RTE_EXEC_ENV_WINDOWS case OPT_TRACE_NUM: { @@ -1945,6 +1949,7 @@ eal_common_usage(void) " --"OPT_PROC_TYPE" Type of this process (primary|secondary|auto)\n" #ifndef RTE_EXEC_ENV_WINDOWS " --"OPT_SYSLOG" Set syslog facility\n" + " --"OPT_LOG_TIMESTAMP" Timestamp log output\n" #endif " --"OPT_LOG_LEVEL"= Set global log level\n" " --"OPT_LOG_LEVEL"=:\n" diff --git a/lib/librte_eal/common/eal_internal_cfg.h b/lib/librte_eal/common/eal_internal_cfg.h index 13f93388a781..75c476870c57 100644 --- a/lib/librte_eal/common/eal_internal_cfg.h +++ b/lib/librte_eal/common/eal_internal_cfg.h @@ -70,6 +70,7 @@ struct internal_config { * per-node) non-legacy mode only. */ volatile int syslog_facility; /**< facility passed to openlog() */ + volatile uint8_t log_timestamp; /**< add timestamp to console output */ /** default interrupt mode for VFIO */ volatile enum rte_intr_mode vfio_intr_mode; /** the shared VF token for VFIO-PCI bound PF and VFs devices */ diff --git a/lib/librte_eal/common/eal_options.h b/lib/librte_eal/common/eal_options.h index 89769d48b487..7c86f2e19109 100644 --- a/lib/librte_eal/common/eal_options.h +++ b/lib/librte_eal/common/eal_options.h @@ -35,6 +35,8 @@ enum { OPT_LCORES_NUM, #define OPT_LOG_LEVEL "log-level" OPT_LOG_LEVEL_NUM, +#define OPT_LOG_TIMESTAMP "log-timestamp" + OPT_LOG_TIMESTAMP_NUM, #define OPT_TRACE "trace" OPT_TRACE_NUM, #define OPT_TRACE_DIR "trace-dir" diff --git a/lib/librte_eal/linux/eal_log.c b/lib/librte_eal/linux/eal_log.c index 43c8460bfb07..cbd0924ec847 100644 --- a/lib/librte_eal/linux/eal_log.c +++ b/lib/librte_eal/linux/eal_log.c @@ -5,9 +5,12 @@ #include #include #include +#include +#include #include #include #include +#include #include #include @@ -18,6 +21,9 @@ #include #include "eal_private.h" +#include "eal_internal_cfg.h" + +static struct timespec log_start_time; /* * default log function @@ -25,11 +31,38 @@ static ssize_t console_log_write(__rte_unused void *c, const char *buf, size_t size) { + const struct internal_config *internal_conf + = eal_get_internal_configuration(); ssize_t ret; + char tbuf[64]; + struct iovec iov[2]; + + if (internal_conf->log_timestamp) { + struct timespec ts; + + /* format up monotonic timestamp */ + clock_gettime(CLOCK_MONOTONIC, &ts); + ts.tv_sec -= log_start_time.tv_sec; + ts.tv_nsec -= log_start_time.tv_nsec; + if (ts.tv_nsec < 0) { + --ts.tv_sec; + ts.tv_nsec += 1000000000ul; + } - /* write on stdout */ - ret = fwrite(buf, 1, size, stdout); - fflush(stdout); + iov[0].iov_base = tbuf; + iov[0].iov_len = snprintf(tbuf, sizeof(tbuf), "[%8lu.%06lu] ", + ts.tv_sec, ts.tv_nsec / 1000u); + + /* extra cast is workaround to remove const quallifier */ + iov[1].iov_base = (void *)(uintptr_t)buf; + iov[1].iov_len = size; + + fflush(stdout); + ret = writev(STDOUT_FILENO, iov, 2); + } else { + /* write on stdout */ + ret = fwrite(buf, 1, size, stdout); + } /* Syslog error levels are from 0 to 7, so subtract 1 to convert */ syslog(rte_log_cur_msg_loglevel() - 1, "%.*s", (int)size, buf); @@ -50,6 +83,8 @@ rte_eal_log_init(const char *id, int facility) { FILE *log_stream; + clock_gettime(CLOCK_MONOTONIC, &log_start_time); + log_stream = fopencookie(NULL, "w+", console_log_func); if (log_stream == NULL) return -1;