From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [170.10.133.124]) by passt.top (Postfix) with ESMTP id E71525A004E for ; Mon, 29 Jul 2024 19:55:42 +0200 (CEST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1722275741; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding: in-reply-to:in-reply-to:references:references; bh=GdafMfU0pGp3EifcB2fvME53StfFr0un8FamR6y9VYE=; b=Glovg2oVjAKY9WSsU8ggHdGnRHTvciX5ew3s0XBkUSvpr0QcEWoFv6+l8G4ZOLqULdY2Ac Q75WjaKeNUzex7PpPiMk25n8rNemSI7sXE4ezeQoWuju30mAmW8DXvs+MS2zUXI9Dw7SuH 3ENapejsT0GEi+hihJdE8mDal/OZZDg= Received: from mail-qk1-f200.google.com (mail-qk1-f200.google.com [209.85.222.200]) by relay.mimecast.com with ESMTP with STARTTLS (version=TLSv1.3, cipher=TLS_AES_256_GCM_SHA384) id us-mta-568-lEYqivsTMMOL50D3QsUbxg-1; Mon, 29 Jul 2024 13:55:40 -0400 X-MC-Unique: lEYqivsTMMOL50D3QsUbxg-1 Received: by mail-qk1-f200.google.com with SMTP id af79cd13be357-7a1d06f8f03so379279585a.1 for ; Mon, 29 Jul 2024 10:55:40 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1722275739; x=1722880539; h=content-transfer-encoding:mime-version:organization:references :in-reply-to:message-id:subject:cc:to:from:date:x-gm-message-state :from:to:cc:subject:date:message-id:reply-to; bh=GdafMfU0pGp3EifcB2fvME53StfFr0un8FamR6y9VYE=; b=NIiZcceFV2tv/ast8UKhLi2SItdLll7N6dRakQ5sOgGmN+yQB8EiqP5EUbNepvk9ow 10DhOP1ntJ4ahSHanWj5UVhyrznHZ5MOb3R6HHEMaTRjVQum7tb/DXmUTAruMO+Ah0IY 2BwQq9jNQhEJcbwW39eySoVV9VLrLH0HIximFkGWlKTiV0LgxCwMA6gtr2OpWPBgXKNc nTIEy2GzmToM95wxg+WBYDDGX/Z+2Ti8iPitkb7iu8bMAi2qC/TjWP2r2fW08yDbkM7D df3xA5CPQwBsdVJniY/N9wH8jYcyAf021IFdP9lJitaKI5PLQGg3iAXF9D0LVuojH3r2 ateQ== X-Gm-Message-State: AOJu0YwFQvusmVtabXDfr3ye1x73ejZD1jJlkmG9uM+RGSp2hs4iRMT5 03VCHu4P9xmLNADq7fQGV570ZNvsqYM6ySsC2Jn63fpzowH8AXYQHJBkSuEaYvyLRHmCjzA1/J6 X4AePejvgDaOKpwqbFXPKr56uhV8s3yJQ1cIKXB0ue3QoNRzwBqcKSmk9jXvC X-Received: by 2002:a05:620a:240a:b0:79f:10e6:2ec with SMTP id af79cd13be357-7a1e526af12mr1085665685a.35.1722275739177; Mon, 29 Jul 2024 10:55:39 -0700 (PDT) X-Google-Smtp-Source: AGHT+IGVNLoo14bxP30arEYG+blNc7Cs683YR/6Co20Z+FGta2D/4CfQP0xDGRkn1yru+AjRATeFow== X-Received: by 2002:a05:620a:240a:b0:79f:10e6:2ec with SMTP id af79cd13be357-7a1e526af12mr1085663585a.35.1722275738716; Mon, 29 Jul 2024 10:55:38 -0700 (PDT) Received: from maya.cloud.tilaa.com (maya.cloud.tilaa.com. [164.138.29.33]) by smtp.gmail.com with ESMTPSA id af79cd13be357-7a1d73b1db1sm555434885a.29.2024.07.29.10.55.37 (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Mon, 29 Jul 2024 10:55:38 -0700 (PDT) Date: Mon, 29 Jul 2024 19:55:02 +0200 From: Stefano Brivio To: David Gibson Subject: Re: [PATCH 2/2] log: Avoid duplicate calls to clock_gettime() Message-ID: <20240729195502.01467e7c@elisabeth> In-Reply-To: <20240729042300.280684-3-david@gibson.dropbear.id.au> References: <20240729042300.280684-1-david@gibson.dropbear.id.au> <20240729042300.280684-3-david@gibson.dropbear.id.au> Organization: Red Hat X-Mailer: Claws Mail 4.2.0 (GTK 3.24.41; x86_64-pc-linux-gnu) MIME-Version: 1.0 X-Mimecast-Spam-Score: 0 X-Mimecast-Originator: redhat.com Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Message-ID-Hash: RERSZ5Z4SD4426URQPH7HX2FTOCLZIYZ X-Message-ID-Hash: RERSZ5Z4SD4426URQPH7HX2FTOCLZIYZ X-MailFrom: sbrivio@redhat.com X-Mailman-Rule-Misses: dmarc-mitigation; no-senders; approved; emergency; loop; banned-address; member-moderation; nonmember-moderation; administrivia; implicit-dest; max-recipients; max-size; news-moderation; no-subject; digests; suspicious-header CC: passt-dev@passt.top X-Mailman-Version: 3.3.8 Precedence: list List-Id: Development discussion and patches for passt Archived-At: Archived-At: List-Archive: List-Archive: List-Help: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: On Mon, 29 Jul 2024 14:23:00 +1000 David Gibson wrote: > We use clock_gettime() to get a timestamp for the log in two places: > - in vlogmsg(), which is used only for debug_print messages > - in logfile_write() which is only used messages to the log file > > These cases are mutually exclusive, so we don't ever print the same message > with different timestamps, but that's not particularly obvious to see. > > Refactor to have a single clock_gettime() call in vlogmsg() and use it for > all the places we need it. > > Signed-off-by: David Gibson > --- > log.c | 17 ++++++++--------- > 1 file changed, 8 insertions(+), 9 deletions(-) > > diff --git a/log.c b/log.c > index eb3a780a..418bdefd 100644 > --- a/log.c > +++ b/log.c > @@ -199,19 +199,17 @@ static int logfile_rotate(int fd, const struct timespec *now) > * logfile_write() - Write entry to log file, trigger rotation if full > * @newline: Append newline at the end of the message, if missing > * @pri: Facility and level map, same as priority for vsyslog() > + * @tp: Timestamp > * @format: Same as vsyslog() format > * @ap: Same as vsyslog() ap > */ > -static void logfile_write(bool newline, int pri, const char *format, va_list ap) > +static void logfile_write(bool newline, int pri, const struct timespec *tp, > + const char *format, va_list ap) > { > - struct timespec now; > char buf[BUFSIZ]; > int n; > > - if (clock_gettime(CLOCK_MONOTONIC, &now)) > - return; > - > - n = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now)); > + n = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(tp)); > n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]); > > n += vsnprintf(buf + n, BUFSIZ - n, format, ap); > @@ -219,7 +217,7 @@ static void logfile_write(bool newline, int pri, const char *format, va_list ap) > if (newline && format[strlen(format)] != '\n') > n += snprintf(buf + n, BUFSIZ - n, "\n"); > > - if ((log_written + n >= log_size) && logfile_rotate(log_file, &now)) > + if ((log_written + n >= log_size) && logfile_rotate(log_file, tp)) > return; > > if ((n = write(log_file, buf, n)) >= 0) > @@ -238,8 +236,9 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap) > bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1; > struct timespec tp; > > + clock_gettime(CLOCK_MONOTONIC, &tp); Maybe it's more readable now, but this has two disadvantages: 1. this way, we call clock_gettime() also when it's not needed (that's what I meant by "a bit of refactoring in vlogmsg()"). If we log to the system logger, which is the default, we'll fetch a timestamp for no reason, because the system logger adds it. It's not that bad as we're not verbose in that case, so I'm actually fine with this patch, but I wanted to point that out to you anyway, first. 2. POSIX.1-2024 has only one error defined for clock_gettime(): The clock_gettime() function shall fail if: [EOVERFLOW] The number of seconds will not fit in an object of type time_t. which should only happen on quite old systems (assuming their C library even knows about clock_gettime()) in 2038 (assuming CLOCK_REALTIME is used as initial CLOCK_MONOTONIC), but still, C libraries often decide to add errors on their own, and we would print stack contents if that happens. Before this patch, that could only happen with --debug. Perhaps we should simply initialise struct timespec to all zeroes (better to print with the wrong timestamp than not printing at all) or to log_start. > + > if (debug_print) { > - clock_gettime(CLOCK_MONOTONIC, &tp); > fprintf(stderr, logtime_fmt_and_arg(&tp)); > fprintf(stderr, ": "); > } > @@ -249,7 +248,7 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap) > > va_copy(ap2, ap); /* Don't clobber ap, we need it again */ > if (log_file != -1) > - logfile_write(newline, pri, format, ap2); > + logfile_write(newline, pri, &tp, format, ap2); > else if (!(log_mask & LOG_MASK(LOG_DEBUG))) > passt_vsyslog(newline, pri, format, ap2); > -- Stefano