Re: recovery test failure on morepork with timestamp mystery

Hi,

On 2022-05-12 21:42:43 -0400, Melanie Plageman wrote:
> Andres drew my attention to this [1] build farm failure.
>
> Looks like a test I wrote resetting pg_stat_replication_slots is
> failing:
>
> # Failed test 'Check that reset timestamp is later after resetting
> stats for slot 'test_slot' again.'
> # at t/006_logical_decoding.pl line 261.
> # got: 'f'
> # expected: 't'
> # Looks like you failed 1 test of 20.
> [19:59:58] t/006_logical_decoding.pl ............
>
> This is the test code itself:
>
> is( $node_primary->safe_psql(
> 'postgres',
> qq(SELECT stats_reset > '$reset1'::timestamptz FROM
> pg_stat_replication_slots WHERE slot_name = '$stats_test_slot1')
> ),
> qq(t),
> qq(Check that reset timestamp is later after resetting stats for
> slot '$stats_test_slot1' again.)
> );
>
> This is the relevant SQL statement:
>
> SELECT stats_reset > '$reset1'::timestamptz FROM
> pg_stat_replication_slots WHERE slot_name = '$stats_test_slot1'
>
> When this statement is executed, reset1 is as shown:
>
> 2022-05-12 19:59:58.342 CEST [88829:3] 006_logical_decoding.pl LOG:
> statement: SELECT stats_reset > '2022-05-12
> 19:59:58.402808+02'::timestamptz FROM pg_stat_replication_slots WHERE
> slot_name = 'test_slot'
>
> Note the timestamp of this execution. The stats reset occurred in the
> past, and as such *must* have come before '2022-05-12
> 19:59:58.402808+02'::timestamptz.

The timestamp is computed during:

> 2022-05-12 19:59:58.317 CEST [18214:3] 006_logical_decoding.pl LOG:
> statement: SELECT pg_stat_reset_replication_slot(NULL)

One interesting tidbit is that the log timestamps are computed differently
(with elog.c:get_formatted_log_time()) than the reset timestamp (with
GetCurrentTimestamp()). Both use gettimeofday() internally.

I wonder if there's a chance that somehow openbsd ends up with more usecs than
"fit" in a second in the result of gettimeofday()? The elog.c case would
truncate everything above a second away afaics:
/* 'paste' milliseconds into place... */
sprintf(msbuf, ".%03d", (int) (saved_timeval.tv_usec / 1000));
memcpy(formatted_log_time + 19, msbuf, 4);

whereas GetCurrentTimestamp() would add them to the timestamp:
result = (TimestampTz) tp.tv_sec -
((POSTGRES_EPOCH_JDATE - UNIX_EPOCH_JDATE) * SECS_PER_DAY);
result = (result * USECS_PER_SEC) + tp.tv_usec;

Greetings,

Andres Freund