On Wed, Feb 2, 2022 at 2:14 PM Andres Freund <andres@anarazel.de> wrote:
> On 2022-02-02 13:59:56 +1300, Thomas Munro wrote:
> > 2022-02-01 04:47:59.294 EST [3670:15] 027_stream_regress.pl LOG:
> > statement: SET TRANSACTION ISOLATION LEVEL REPEATABLE READ, READ ONLY
> > ...
> > 2022-02-01 04:49:09.881 EST [3683:2585] 027_stream_regress.pl ERROR:
> > canceling statement due to conflict with recovery
>
> That, uh, seems slow. Is it perhaps waiting for a lock? Seems
> Cluster.pm::init() should add at least log_lock_waits...
I quoted the wrong lines, let me try that again this time for the same
session, the one with pid 3683:
2022-02-01 04:48:38.352 EST [3683:15] 027_stream_regress.pl LOG:
statement: SET TRANSACTION ISOLATION LEVEL REPEATABLE READ, READ ONLY
...
2022-02-01 04:49:09.881 EST [3683:2585] 027_stream_regress.pl ERROR:
canceling statement due to conflict with recovery
It looks like it's processing statements fairly consistently slowly
through the whole period. Each non-trivial statement takes a bit
under ~10ms, so it would make sense if by the time we've processed
~2.5k lines we've clocked up 30 seconds and a VACUUM replay whacks us.