Re: [PATCH 3/3] log: Fetch log times with CLOCK_MONOTONIC, not CLOCK_REALTIME

[Stefano Brivio <sbrivio@redhat.com>]

On Fri, 26 Jul 2024 09:15:59 +1000
David Gibson <david@gibson.dropbear.id.au> wrote:

> On Thu, Jul 25, 2024 at 06:26:34PM +0200, Stefano Brivio wrote:
> > We report relative timestamps in logs, so we want to avoid jumps in
> > the system time.
> > 
> > Suggested-by: David Gibson <david@gibson.dropbear.id.au>
> > Signed-off-by: Stefano Brivio <sbrivio@redhat.com>  
> 
> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
> 
> I noticed another pre-existing nit, though..
> 
> > ---
> >  log.c   | 4 ++--
> >  passt.c | 2 +-
> >  2 files changed, 3 insertions(+), 3 deletions(-)
> > 
> > diff --git a/log.c b/log.c
> > index 9474bad..0fb25b7 100644
> > --- a/log.c
> > +++ b/log.c
> > @@ -68,7 +68,7 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap)
> >  	struct timespec tp;
> >  
> >  	if (debug_print) {
> > -		clock_gettime(CLOCK_REALTIME, &tp);
> > +		clock_gettime(CLOCK_MONOTONIC, &tp);
> >  		fprintf(stderr, logtime_fmt_and_arg(&tp));
> >  		fprintf(stderr, ": ");
> >  	}
> > @@ -382,7 +382,7 @@ void logfile_write(bool newline, int pri, const char *format, va_list ap)
> >  	char buf[BUFSIZ];
> >  	int n;
> >  
> > -	if (clock_gettime(CLOCK_REALTIME, &now))
> > +	if (clock_gettime(CLOCK_MONOTONIC, &now))  
> 
> We have two separate calls to get the time for "this" message.  I
> think this means under the right circumstances we could have
> essentially the same message logged to different places with
> (slightly) different times.

This never happens because, in vlogmsg():

	bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1;

> That seems needlessly confusing.  It would be nice to have a single
> point at which we capture the time for a single message.

...but yes, it might be confusing. A single clock_gettime() call would
need a bit of refactoring in vlogmsg().

-- 
Stefano