Surprising results from tests intended to show the difference in semantics between transaction_timestamp(), statement_timestamp(), and clock_timestamp()

Поиск
Список
Период
Сортировка
От Bryn Llewellyn
Тема Surprising results from tests intended to show the difference in semantics between transaction_timestamp(), statement_timestamp(), and clock_timestamp()
Дата
Msg-id 7A6BA954-F3F8-4E68-BDBA-4DB2869A0C50@icloud.com
обсуждение исходный текст
Список pgsql-general
I'm surprised by the results that I describe below. Please help me interpret them.

Briefly, why does transaction_timestamp() report a later value than statement_timestamp() when they're both invoked in the very first statement after "start transaction". (They report identical values in an implicitly started txn.)
— — — — — — — — — — — — — — — — — — — — — — — — —

*Introduction*

I'm presently documenting (in the YugabyteDB YSQL section) the various PG date-time functions that report the "current" moment. There are two degrees of freedom: the return data type; and the kind of moment. This would suggest that there's eighteen differently-named functions (considering also timetz—which the PG doc recommends against using). There are, in fact, far fewer. Never mind, timestamptz is almost always the best choice for the data type of the moment; and the three functions that I name in my "subject" return that data type.

I thought that this demo would be simple and convincing:

-- SINGLE STATEMENT TEST (IMPLICIT TXN)

select
  transaction_timestamp() as txn_11,
  statement_timestamp()   as stm_11,
  clock_timestamp()       as clk_11,
  pg_sleep(:slp_1)        as dummy,
  transaction_timestamp() as txn_12,
  statement_timestamp()   as stm_12,
  clock_timestamp()       as clk_12;

-- TWO STATEMENT TEST (EXPLICIT TXN)

start transaction;

select
  transaction_timestamp() as txn_11,
  statement_timestamp()   as stm_11,
  clock_timestamp()       as clk_11,
  pg_sleep(:slp_1)        as dummy,
  transaction_timestamp() as txn_12,
  statement_timestamp()   as stm_12,
  clock_timestamp()       as clk_12;

select pg_sleep(:slp_2);

select
  transaction_timestamp() as txn_2,
  statement_timestamp()   as stm_2,
  clock_timestamp()       as clk_2;

commit;

The output from this takes a huge mental effort to comprehend. So I wrote a naive reporting function:

function expected_tstz_diff_error(
  caption        in text,
  t_finish       in timestamptz,
  t_start        in timestamptz,
  expected_diff  in double precision)
  returns           text

I test what I get like this:

-- SINGLE STATEMENT TEST (IMPLICIT TXN)
select expected_tstz_diff_error('txn_12 - txn_11 = 0',            :s1_txn_12, :s1_txn_12, :zero);
select expected_tstz_diff_error('stm_12 - stm_11 = 0',            :s1_stm_12, :s1_stm_12, :zero);
select expected_tstz_diff_error('txn_11 - stm_11 = 0',            :s1_txn_11, :s1_stm_11, :zero);
select expected_tstz_diff_error('clk_12 - clk_11 = slp_1',        :s1_clk_12, :s1_clk_11, :slp_1);

and this:

-- TWO STATEMENT TEST (EXPLICIT TXN)

-- Within the first "select".
select expected_tstz_diff_error('txn_12 - txn_11 = 0',            :s1_txn_12, :s1_txn_12, :zero);
select expected_tstz_diff_error('stm_12 - stm_11 = 0',            :s1_stm_12, :s1_stm_12, :zero);
select expected_tstz_diff_error('txn_11 - stm_11 = 0',            :s1_txn_11, :s1_stm_11, :zero);
select expected_tstz_diff_error('clk_12 - clk_11 = slp_1',        :s1_clk_12, :s1_clk_11, :slp_1);

-- Within the trasaction but across the first and the second "select".
select expected_tstz_diff_error('txn_2 - txn_11 = 0',             :s2_txn_2,  :s1_txn_11, :zero);
select expected_tstz_diff_error('stm_2 - stm_11 = slp_1 + slp_2', :s2_stm_2,  :s1_stm_11, (:slp_1 + :slp_2));
select expected_tstz_diff_error('clk_2 - clk_11 = slp_1 + slp_2', :s2_clk_2,  :s1_clk_11, (:slp_1 + :slp_2));

The function reports either "exact" or the error in milliseconds.

The runnable code is copied at the very end, after my account of the problem. You can guess that there's a malarkey of quoting with \gset to populate all those psql "substitution variables". But it all works. The design concept is informed by these ideas:

— I can't use a PL/pgSQL encapsulation because, with this, it's all regarded as a single top-level statement and so I can't easily demonstrate the difference in semantics between transaction_timestamp() and statement_timestamp().

— I want to get my results back with the minimum of time-consuming fuss to get the most reliable timings. So I do the reporting after I have all the results to hand in psql "substitution variables".

*Results*

Here's what I get with my PG Version 13.4 installation on my MacBook. (I removed blank lines to improve the readability.)

SINGLE STATEMENT TEST (IMPLICIT TXN)

txn_12 - txn_11 = 0            : exact
stm_12 - stm_11 = 0            : exact
txn_11 - stm_11 = 0            : exact
clk_12 - clk_11 = slp_1        : error:  0.1 ms

TWO STATEMENT TEST (EXPLICIT TXN)

txn_12 - txn_11 = 0            : exact
stm_12 - stm_11 = 0            : exact
txn_11 - stm_11 = 0            : error: -0.1 ms
clk_12 - clk_11 = slp_1        : error:  0.6 ms

txn_2 - txn_11 = 0             : exact
stm_2 - stm_11 = slp_1 + slp_2 : error:  1.6 ms
clk_2 - clk_11 = slp_1 + slp_2 : error:  1.6 ms

*Discussion*

The stand-alone “select" that implicitly starts the txn gives the results that I'd expect.

I expected that, using the explicitly started txn, the values returned by transaction_timestamp() and statement_timestamp() in the first statement would be identical (just as they are with the implicitly started txn) because (as I believe) it's the first substantive SQL statement, and not "set transaction", that actually starts the txn. Else, if "set transaction" really does start the txn, then statement_timestamp() should return a later value than transaction_timestamp(). In fact, it's the other way round.

*Any thoughts on why?*

If I can explain why, with the explicitly started txn, the values from transaction_timestamp() and statement_timestamp() differ in the first "select", then, I suppose, there are no more mysteries in the results from the second "select" because "commit" is bound to take time and I'm not using an estimate for this in my value for "expected_diff".
— — — — — — — — — — — — — — — — — — — — — — — — —

create function expected_tstz_diff_error(
  caption        in text,
  t_finish       in timestamptz,
  t_start        in timestamptz,
  expected_diff  in double precision)
  returns           text
  language plpgsql
as $body$
declare
  dp_zero  constant double precision not null := 0;
  dp_1000  constant double precision not null := 1000;
  err      constant double precision not null :=
             ( (extract(epoch from t_finish) - extract(epoch from t_start)) - expected_diff )*dp_1000;
  x        constant text not null := rpad(caption, 30)||' : ';
  r                 text not null := x||'exact';
begin
  if err <> dp_zero then
    r := x||'error:'||to_char(err, '90.9')||' ms';
  end if;
  return r;
end;
$body$;

-- self-doc
\set AUTOCOMMIT 'on'

\set zero  0
\set slp_1 1
\set slp_2 2

\t on
\o pg-local.txt

-- ===================================================================
select 'SINGLE STATEMENT TEST (IMPLICIT TXN)';
----------------------------------------------------------------------

select
  ''''''''||transaction_timestamp() ::text||'''''''' as txn_11,
  ''''''''||statement_timestamp()   ::text||'''''''' as stm_11,
  ''''''''||clock_timestamp()       ::text||'''''''' as clk_11,
  ''''''''||pg_sleep(:slp_1)        ::text||'''''''' as dummy,
  ''''''''||transaction_timestamp() ::text||'''''''' as txn_12,
  ''''''''||statement_timestamp()   ::text||'''''''' as stm_12,
  ''''''''||clock_timestamp()       ::text||'''''''' as clk_12
\gset s1_

select expected_tstz_diff_error('txn_12 - txn_11 = 0',            :s1_txn_12, :s1_txn_12, :zero);
select expected_tstz_diff_error('stm_12 - stm_11 = 0',            :s1_stm_12, :s1_stm_12, :zero);
select expected_tstz_diff_error('txn_11 - stm_11 = 0',            :s1_txn_11, :s1_stm_11, :zero);
select expected_tstz_diff_error('clk_12 - clk_11 = slp_1',        :s1_clk_12, :s1_clk_11, :slp_1);

-- ===================================================================
select 'TWO STATEMENT TEST (EXPLICIT TXN)';
----------------------------------------------------------------------

start transaction;

select
  ''''''''||transaction_timestamp() ::text||'''''''' as txn_11,
  ''''''''||statement_timestamp()   ::text||'''''''' as stm_11,
  ''''''''||clock_timestamp()       ::text||'''''''' as clk_11,
  ''''''''||pg_sleep(:slp_1)        ::text||'''''''' as dummy,
  ''''''''||transaction_timestamp() ::text||'''''''' as txn_12,
  ''''''''||statement_timestamp()   ::text||'''''''' as stm_12,
  ''''''''||clock_timestamp()       ::text||'''''''' as clk_12
\gset s1_

select pg_sleep(:slp_2);

select
  ''''''''||transaction_timestamp() ::text||'''''''' as txn_2,
  ''''''''||statement_timestamp()   ::text||'''''''' as stm_2,
  ''''''''||clock_timestamp()       ::text||'''''''' as clk_2
\gset s2_

commit;

-- Within the first "select".
select expected_tstz_diff_error('txn_12 - txn_11 = 0',            :s1_txn_12, :s1_txn_12, :zero);
select expected_tstz_diff_error('stm_12 - stm_11 = 0',            :s1_stm_12, :s1_stm_12, :zero);
select expected_tstz_diff_error('txn_11 - stm_11 = 0',            :s1_txn_11, :s1_stm_11, :zero);
select expected_tstz_diff_error('clk_12 - clk_11 = slp_1',        :s1_clk_12, :s1_clk_11, :slp_1);

-- Within the trasaction but across the first and the second "select".
select expected_tstz_diff_error('txn_2 - txn_11 = 0',             :s2_txn_2,  :s1_txn_11, :zero);
select expected_tstz_diff_error('stm_2 - stm_11 = slp_1 + slp_2', :s2_stm_2,  :s1_stm_11, (:slp_1 + :slp_2));
select expected_tstz_diff_error('clk_2 - clk_11 = slp_1 + slp_2', :s2_clk_2,  :s1_clk_11, (:slp_1 + :slp_2));

\o
\t off


В списке pgsql-general по дате отправления:

Предыдущее
От: Steve Crawford
Дата:
Сообщение: Re: Timestamp with vs without time zone.
Следующее
От: Bryn Llewellyn
Дата:
Сообщение: Surprising results from tests intended to show the difference in semantics between transaction_timestamp(), statement_timestamp(), and clock_timestamp()