Re: snapshot too old issues, first around wraparound and then more. - Mailing list pgsql-hackers

Hi,

On 2020-04-01 14:11:11 -0700, Andres Freund wrote:
> 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:
> [...]

I took a lot longer till the queries started to be cancelled. The last
mapping update before that was:

> 2020-04-01 14:28:00.000 PDT [1268503][3/1894126:2078853871] WARNING:  old snapshot mapping at "before update" with
headts: 31, current entries: 20 max entries: 20, offset: 12
 
>       entry 0 (ring 12): min 31: xid 2078468128
>       entry 1 (ring 13): min 32: xid 2078642746
>       entry 2 (ring 14): min 33: xid 2078672303
>       entry 3 (ring 15): min 34: xid 2078700941
>       entry 4 (ring 16): min 35: xid 2078728729
>       entry 5 (ring 17): min 36: xid 2078755425
>       entry 6 (ring 18): min 37: xid 2078781089
>       entry 7 (ring 19): min 38: xid 2078805567
>       entry 8 (ring 0): min 39: xid 2078830065
>       entry 9 (ring 1): min 40: xid 2078611853
>       entry 10 (ring 2): min 41: xid 2078611853
>       entry 11 (ring 3): min 42: xid 2078611853
>       entry 12 (ring 4): min 43: xid 2078611853
>       entry 13 (ring 5): min 44: xid 2078611853
>       entry 14 (ring 6): min 45: xid 2078611853
>       entry 15 (ring 7): min 46: xid 2078611853
>       entry 16 (ring 8): min 47: xid 2078611853
>       entry 17 (ring 9): min 48: xid 2078611853
>       entry 18 (ring 10): min 49: xid 2078611853
>       entry 19 (ring 11): min 50: xid 2078611853
>
> 2020-04-01 14:28:00.000 PDT [1268503][3/1894126:2078853871] WARNING:  head 31 min: updating existing bucket 1 for
whenTaken40 min, with xmin 2078853870
 
> 2020-04-01 14:28:00.000 PDT [1268503][3/1894126:2078853871] WARNING:  old snapshot mapping at "after update" with
headts: 31, current entries: 20 max entries: 20, offset: 12
 
>       entry 0  (ring 12): min 31: xid 2078468128
>       entry 1  (ring 13): min 32: xid 2078642746
>       entry 2  (ring 14): min 33: xid 2078672303
>       entry 3  (ring 15): min 34: xid 2078700941
>       entry 4  (ring 16): min 35: xid 2078728729
>       entry 5  (ring 17): min 36: xid 2078755425
>       entry 6  (ring 18): min 37: xid 2078781089
>       entry 7  (ring 19): min 38: xid 2078805567
>       entry 8  (ring 0 ): min 39: xid 2078830065
>       entry 9  (ring 1 ): min 40: xid 2078853870
>       entry 10 (ring 2 ): min 41: xid 2078611853
>       entry 11 (ring 3 ): min 42: xid 2078611853
>       entry 12 (ring 4 ): min 43: xid 2078611853
>       entry 13 (ring 5 ): min 44: xid 2078611853
>       entry 14 (ring 6 ): min 45: xid 2078611853
>       entry 15 (ring 7 ): min 46: xid 2078611853
>       entry 16 (ring 8 ): min 47: xid 2078611853
>       entry 17 (ring 9 ): min 48: xid 2078611853
>       entry 18 (ring 10): min 49: xid 2078611853
>       entry 19 (ring 11): min 50: xid 2078611853


A query ran for fourty minutes during this, without getting cancelled.



A good while later this happens:
> 2020-04-01 15:30:00.000 PDT [1268503][3/2518699:2081262046] WARNING:  old snapshot mapping at "before update" with
headts: 82, current entries: 20 max entries: 20, offset: 12
 
>       entry 0 (ring 12): min 82: xid 2080333207
>       entry 1 (ring 13): min 83: xid 2080527298
>       entry 2 (ring 14): min 84: xid 2080566990
>       entry 3 (ring 15): min 85: xid 2080605960
>       entry 4 (ring 16): min 86: xid 2080644554
>       entry 5 (ring 17): min 87: xid 2080682957
>       entry 6 (ring 18): min 88: xid 2080721936
>       entry 7 (ring 19): min 89: xid 2080760947
>       entry 8 (ring 0): min 90: xid 2080799843
>       entry 9 (ring 1): min 91: xid 2080838696
>       entry 10 (ring 2): min 92: xid 2080877550
>       entry 11 (ring 3): min 93: xid 2080915870
>       entry 12 (ring 4): min 94: xid 2080954151
>       entry 13 (ring 5): min 95: xid 2080992556
>       entry 14 (ring 6): min 96: xid 2081030980
>       entry 15 (ring 7): min 97: xid 2081069403
>       entry 16 (ring 8): min 98: xid 2081107811
>       entry 17 (ring 9): min 99: xid 2081146322
>       entry 18 (ring 10): min 100: xid 2081185023
>       entry 19 (ring 11): min 101: xid 2081223632
>
> 2020-04-01 15:30:00.000 PDT [1268503][3/2518699:2081262046] WARNING:  head 82 min: filling 20 buckets starting at 12
forwhenTaken 102 min, with xmin 2081262046
 
> 2020-04-01 15:30:00.000 PDT [1268503][3/2518699:2081262046] WARNING:  old snapshot mapping at "after update" with
headts: 102, current entries: 1 max entries: 20, offset: 0
 
>       entry 0 (ring 0): min 102: xid 2081262046

The entire mapping reset, i.e. it'll take another fourty minutes for
cancellations to happen.

Greetings,

Andres Freund