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 head ts: 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 whenTaken 40 min, with xmin 2078853870 > 2020-04-01 14:28:00.000 PDT [1268503][3/1894126:2078853871] WARNING: old > snapshot mapping at "after update" with head ts: 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 head ts: 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 for whenTaken 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 head ts: 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
