David G. Johnston wrote:
Bryn wrote:
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.)
transaction_timestamp() as txn_11,
statement_timestamp() as stm_11,
t_finish in timestamptz,
t_start in timestamptz,
expected_diff in double precision)
select expected_tstz_diff_error('txn_11 - stm_11 = 0', :s1_txn_11, :s1_stm_11, :zero);
txn_11 - stm_11 = 0 : error: -0.1 ms
err constant double precision not null :=
( (extract(epoch from t_finish) - extract(epoch from t_start)) - expected_diff )*dp_1000;
So, finish is the txn, start is the stm, and expected is 0 - thus if finish (txn) is earlier than start (stm) your error will be negative. Which it is, and since transaction should be earlier than statement this would seem to be correct. In short, you seem to have mis-interpreted the error sign’s meaning.
Thanks, David.
Damn... I'm so embarrassed. I'd been staring at my code for too long and was blind to my stupidity. Just goes to show how important it is to choose names sensibly. "Start" and "finish" were silly (a left-over from a previous use of that code). I changed the names to "t_expected_later" and "t_expected_sooner" — and twizzled my arguments where needed. All is clear now.
In summary, the first statement after the explicit "start transaction" is a bit later than the moment that the explicitly started txn starts—in line with intuition. And, of course, the round trip to invoke pg_sleep() takes time too.
I was talking nonsense when I wrote "commit is bound to take time and I'm not using an estimate for this". Doubtless "commit" does take some time. But it happens after my last recorded time measurement. That, too, was a left-over from a different test. Sigh...
Case closed.