Re: snapshot too old issues, first around wraparound and then more.

Hi,

On 2020-04-01 15:11:52 -0500, Kevin Grittner wrote:
> On Wed, Apr 1, 2020 at 2:43 PM Andres Freund <andres(at)anarazel(dot)de> wrote:
>
> > The thing that makes me really worried is that the contents of the time
> > mapping seem very wrong. I've reproduced query results in a REPEATABLE
> > READ transaction changing (pruned without triggering an error).
>
>
> That is a very big problem. On the sort-of bright side (ironic in light of
> the fact that I'm a big proponent of using serializable transactions), none
> of the uses that I have personally seen of this feature use anything other
> than the default READ COMMITTED isolation level. That might help explain
> the lack of complaints for those using the feature. But yeah, I REALLY
> want to see a solid fix for that!

I don't think it's dependent on RR - it's just a bit easier to verify
that the query results are wrong that way.

> > And I've
> > reproduced rows not getting removed for much longer than than they
> > should, according to old_snapshot_threshold.
> >
> > I suspect one reason for users not noticing either is that
> >
> > a) it's plausible that users of the feature would mostly have
> > long-running queries/transactions querying immutable or insert only
> > data. Those would not notice that, on other tables, rows are getting
> > removed, where access would not trigger the required error.
> >
> > b) I observe long-ish phases were no cleanup is happening (due to
> > oldSnapshotControl->head_timestamp getting updated more often than
> > correct). But if old_snapshot_threshold is small enough in relation to
> > the time the generated bloat becomes problematic, there will still be
> > occasions to actually perform cleanup.
> >
>
> Keep in mind that the real goal of this feature is not to eagerly _see_
> "snapshot too old" errors, but to prevent accidental debilitating bloat due
> to one misbehaving user connection.

I don't think it's an "intentional" inaccuracy issue leading to
this. The map contents are just wrong, in particular the head_timestamp
most of the time is so new that
TransactionIdLimitedForOldSnapshots(). When filling a new bucket,
MaintainOldSnapshotThreshold() unconditionally updates
oldSnapshotControl->head_timestamp to be the current minute, which means
it'll take old_snapshot_threshold minutes till
TransactionIdLimitedForOldSnapshots() even looks at the mapping again.

As far as I can tell, with a large old_snapshot_threshold, it can take a
very long time to get to a head_timestamp that's old enough for
TransactionIdLimitedForOldSnapshots() to do anything. Look at this
trace of a pgbench run with old_snapshot_threshold enabled, showing some of
the debugging output added in the patch upthread.

This is with a threshold of 10min, in a freshly started database:
> 2020-04-01 13:49:00.000 PDT [1268502][2/43571:2068881994] WARNING: head 0 min: filling 1 buckets starting at 0 for whenTaken 1 min, with xmin 2068881994
> 2020-04-01 13:49:00.000 PDT [1268502][2/43571:2068881994] WARNING: old snapshot mapping at "after update" with head ts: 1, current entries: 2 max entries: 20, offset: 0
> entry 0 (ring 0): min 1: xid 2068447214
> entry 1 (ring 1): min 2: xid 2068881994
>
> 2020-04-01 13:50:00.000 PDT [1268505][5/122542:0] WARNING: old snapshot mapping at "before update" with head ts: 1, current entries: 2 max entries: 20, offset: 0
> entry 0 (ring 0): min 1: xid 2068447214
> entry 1 (ring 1): min 2: xid 2068881994
>
> 2020-04-01 13:50:00.000 PDT [1268505][5/122542:0] WARNING: head 1 min: updating existing bucket 1 for whenTaken 2 min, with xmin 2069199511
> 2020-04-01 13:50:00.000 PDT [1268505][5/122542:0] WARNING: old snapshot mapping at "after update" with head ts: 1, current entries: 2 max entries: 20, offset: 0
> entry 0 (ring 0): min 1: xid 2068447214
> entry 1 (ring 1): min 2: xid 2069199511
>
> 2020-04-01 13:51:00.000 PDT [1268502][2/202674:2069516501] WARNING: old snapshot mapping at "before update" with head ts: 1, current entries: 2 max entries: 20, offset: 0
> entry 0 (ring 0): min 1: xid 2068447214
> entry 1 (ring 1): min 2: xid 2069199511
>
> 2020-04-01 13:51:00.000 PDT [1268502][2/202674:2069516501] WARNING: head 1 min: filling 2 buckets starting at 0 for whenTaken 3 min, with xmin 2069516499
> 2020-04-01 13:51:00.000 PDT [1268502][2/202674:2069516501] WARNING: old snapshot mapping at "after update" with head ts: 3, current entries: 4 max entries: 20, offset: 0
> entry 0 (ring 0): min 3: xid 2068447214
> entry 1 (ring 1): min 4: xid 2069199511
> entry 2 (ring 2): min 5: xid 2069516499
> entry 3 (ring 3): min 6: xid 2069516499
> ...
> 2020-04-01 14:03:00.000 PDT [1268504][4/1158832:2075918094] WARNING: old snapshot mapping at "before update" with head ts: 7, current entries: 8 max entries: 20, offset: 0
> entry 0 (ring 0): min 7: xid 2068447214
> entry 1 (ring 1): min 8: xid 2071112480
> entry 2 (ring 2): min 9: xid 2071434473
> entry 3 (ring 3): min 10: xid 2071755177
> entry 4 (ring 4): min 11: xid 2072075827
> entry 5 (ring 5): min 12: xid 2072395700
> entry 6 (ring 6): min 13: xid 2072715464
> entry 7 (ring 7): min 14: xid 2073035816

Before the mapping change the database had been running for 15
minutes. But the mapping starts only at 7 minutes from start. And then
is updated to

> 2020-04-01 14:03:00.000 PDT [1268504][4/1158832:2075918094] WARNING: head 7 min: filling 8 buckets starting at 0 for whenTaken 15 min, with xmin 2075918093
> 2020-04-01 14:03:00.000 PDT [1268504][4/1158832:2075918094] WARNING: old snapshot mapping at "after update" with head ts: 15, current entries: 16 max entries: 20, offset: 0
> entry 0 (ring 0): min 15: xid 2068447214
> entry 1 (ring 1): min 16: xid 2071112480
> entry 2 (ring 2): min 17: xid 2071434473
> entry 3 (ring 3): min 18: xid 2071755177
> entry 4 (ring 4): min 19: xid 2072075827
> entry 5 (ring 5): min 20: xid 2072395700
> entry 6 (ring 6): min 21: xid 2072715464
> entry 7 (ring 7): min 22: xid 2073035816
> entry 8 (ring 8): min 23: xid 2075918093
> entry 9 (ring 9): min 24: xid 2075918093
> entry 10 (ring 10): min 25: xid 2075918093
> entry 11 (ring 11): min 26: xid 2075918093
> entry 12 (ring 12): min 27: xid 2075918093
> entry 13 (ring 13): min 28: xid 2075918093
> entry 14 (ring 14): min 29: xid 2075918093
> entry 15 (ring 15): min 30: xid 2075918093

be considered having started in that moment. And we expand the size of
the mapping by 8 at the same time, filling the new buckets with the same
xid. Despite there being a continuous workload.

After a few more minutes we get:
> 2020-04-01 14:07:00.000 PDT [1268503][3/1473617:2077202085] WARNING: head 15 min: updating existing bucket 4 for whenTaken 19 min, with xmin 2077202085
> 2020-04-01 14:07:00.000 PDT [1268503][3/1473617:2077202085] WARNING: old snapshot mapping at "after update" with head ts: 15, current entries: 16 max entries: 20, offset: 0
> entry 0 (ring 0): min 15: xid 2068447214
> entry 1 (ring 1): min 16: xid 2076238895
> entry 2 (ring 2): min 17: xid 2076559154
> entry 3 (ring 3): min 18: xid 2076880731
> entry 4 (ring 4): min 19: xid 2077202085
> entry 5 (ring 5): min 20: xid 2072395700
> entry 6 (ring 6): min 21: xid 2072715464
> entry 7 (ring 7): min 22: xid 2073035816
> entry 8 (ring 8): min 23: xid 2075918093
> entry 9 (ring 9): min 24: xid 2075918093
> entry 10 (ring 10): min 25: xid 2075918093
> entry 11 (ring 11): min 26: xid 2075918093
> entry 12 (ring 12): min 27: xid 2075918093
> entry 13 (ring 13): min 28: xid 2075918093
> entry 14 (ring 14): min 29: xid 2075918093
> entry 15 (ring 15): min 30: xid 2075918093
>

Note how the xids are not monotonically ordered. And how IsLimited still
won't be able to make use of the mapping, as the head timestamp is only
4 minutes old (whenTaken == 19 min, head == 15min).

Greetings,

Andres Freund