Re: Log connection establishment timings

Hi,

On 2025-01-20 15:01:38 +0000, Bertrand Drouvot wrote:
> Regarding the TimestampTz vs instr_time choice, we have things like:
>
> + TimestampTz fork_time = ((BackendStartupData *) startup_data)->fork_time;
> + TimestampTz cur_time = GetCurrentTimestamp();
> +
> + conn_timing.fork_duration = TimestampDifferenceMicroseconds(fork_time,
> + cur_time);
>
> but looking at TimestampDifferenceMicroseconds():
>
> "
> /* If start_time is in the future or now, no time has elapsed */
> if (start_time >= stop_time)
> return 0;
> "
>
> I think that it can happen due to time changes.

It shouldn't during proper operation, the time should be accellerated or
slowed down, but not have backwards jumps.

> So with TimestampTz, we would:
>
> 1. return 0 if we moved the time backward
> 2. provide an inflated duration including the time jump (if the time move
> forward).
>
> But with instr_time (and on systems that support CLOCK_MONOTONIC) then
> pg_clock_gettime_ns() should not be affected by system time change IIUC.

It still does jump around a bit on some systems, even if it shouldn't. It's
not at all rare to see time distontinuities when getting scheduled on another
socket than before or when a VM got migrated. It shouldn't happen, but does.

> Though time changes are "rare", given the fact that those metrics could provide
> "inaccurate" measurements during that particular moment (time change) then it
> might be worth considering instr_time instead for this particular metric.

We calculate the times for log_min_duration_statement etc via
GetCurrentTimestamp(), I don't think it's worth worrying about that here.

I think it'd be better to use absolute times and store them as such in
ConnectionTimes or whatever. That way we have information about when a
connection was established for some future SQL functions and for debugging
problems.

Greetings,

Andres Freund