Re: Protect syscache from bloating with negative cache entries - Mailing list pgsql-hackers

Ah. It was obvious from the first.

Sorry for the sloppy diagnosis.

At Fri, 20 Nov 2020 16:08:40 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> At Thu, 19 Nov 2020 15:23:05 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> > At Wed, 18 Nov 2020 21:42:02 -0800, Andres Freund <andres@anarazel.de> wrote in 
> > > Hi,
> > > 
> > > On 2020-11-19 14:25:36 +0900, Kyotaro Horiguchi wrote:
> > > > # Creation, searching and expiration
> > > > master     :  6393.23    (100.0)
> > > > patched-off:  6527.94    (102.1)
> > > > patched-on : 15880.01    (248.4)
> > > 
> > > What's the deal with this massive increase here?

catalog_cache_min_prune_age was set to 0 at the time, so almost all
catcache entries are dropped at rehashing time. Most of the difference
should be the time to search on the system catalog.


2020-11-20 16:25:25.988  LOG:  database system is ready to accept connections
2020-11-20 16:26:48.504  LOG:  Catcache reset
2020-11-20 16:26:48.504  LOG:  pruning catalog cache id=58 for pg_statistic: removed 0 / 257: 0.001500 ms
2020-11-20 16:26:48.504  LOG:  rehashed catalog cache id 58 for pg_statistic; 257 tups, 256 buckets, 0.020748 ms
2020-11-20 16:26:48.505  LOG:  pruning catalog cache id=58 for pg_statistic: removed 0 / 513: 0.003221 ms
2020-11-20 16:26:48.505  LOG:  rehashed catalog cache id 58 for pg_statistic; 513 tups, 512 buckets, 0.006962 ms
2020-11-20 16:26:48.505  LOG:  pruning catalog cache id=58 for pg_statistic: removed 0 / 1025: 0.006744 ms
2020-11-20 16:26:48.505  LOG:  rehashed catalog cache id 58 for pg_statistic; 1025 tups, 1024 buckets, 0.009580 ms
2020-11-20 16:26:48.507  LOG:  pruning catalog cache id=58 for pg_statistic: removed 0 / 2049: 0.015683 ms
2020-11-20 16:26:48.507  LOG:  rehashed catalog cache id 58 for pg_statistic; 2049 tups, 2048 buckets, 0.041008 ms
2020-11-20 16:26:48.509  LOG:  pruning catalog cache id=58 for pg_statistic: removed 0 / 4097: 0.042438 ms
2020-11-20 16:26:48.509  LOG:  rehashed catalog cache id 58 for pg_statistic; 4097 tups, 4096 buckets, 0.077379 ms
2020-11-20 16:26:48.515  LOG:  pruning catalog cache id=58 for pg_statistic: removed 0 / 8193: 0.123798 ms
2020-11-20 16:26:48.515  LOG:  rehashed catalog cache id 58 for pg_statistic; 8193 tups, 8192 buckets, 0.198505 ms
2020-11-20 16:26:48.525  LOG:  pruning catalog cache id=58 for pg_statistic: removed 0 / 16385: 0.180831 ms
2020-11-20 16:26:48.526  LOG:  rehashed catalog cache id 58 for pg_statistic; 16385 tups, 16384 buckets, 0.361109 ms
2020-11-20 16:26:48.546  LOG:  pruning catalog cache id=58 for pg_statistic: removed 0 / 32769: 0.717899 ms
2020-11-20 16:26:48.547  LOG:  rehashed catalog cache id 58 for pg_statistic; 32769 tups, 32768 buckets, 1.443587 ms
2020-11-20 16:26:48.588  LOG:  pruning catalog cache id=58 for pg_statistic: removed 0 / 65537: 1.204804 ms
2020-11-20 16:26:48.591  LOG:  rehashed catalog cache id 58 for pg_statistic; 65537 tups, 65536 buckets, 3.069916 ms
2020-11-20 16:26:48.674  LOG:  pruning catalog cache id=58 for pg_statistic: removed 0 / 131073: 2.707709 ms
2020-11-20 16:26:48.681  LOG:  rehashed catalog cache id 58 for pg_statistic; 131073 tups, 131072 buckets, 7.127622 ms
2020-11-20 16:26:48.848  LOG:  pruning catalog cache id=58 for pg_statistic: removed 0 / 262145: 5.895630 ms
2020-11-20 16:26:48.862  LOG:  rehashed catalog cache id 58 for pg_statistic; 262145 tups, 262144 buckets, 13.433610
ms
2020-11-20 16:26:49.195  LOG:  pruning catalog cache id=58 for pg_statistic: removed 0 / 524289: 12.302632 ms
2020-11-20 16:26:49.223  LOG:  rehashed catalog cache id 58 for pg_statistic; 524289 tups, 524288 buckets, 27.710900
ms
2020-11-20 16:26:49.937  LOG:  pruning catalog cache id=58 for pg_statistic: removed 1001000 / 1048577: 66.062629 ms
2020-11-20 16:26:51.195  LOG:  pruning catalog cache id=58 for pg_statistic: removed 1002001 / 1048577: 65.533468 ms
2020-11-20 16:26:52.413  LOG:  pruning catalog cache id=58 for pg_statistic: removed 0 / 1048577: 25.623740 ms
2020-11-20 16:26:52.468  LOG:  rehashed catalog cache id 58 for pg_statistic; 1048577 tups, 1048576 buckets, 54.314825
ms
2020-11-20 16:26:53.898  LOG:  pruning catalog cache id=58 for pg_statistic: removed 2000999 / 2097153: 134.530582 ms
2020-11-20 16:26:56.404  LOG:  pruning catalog cache id=58 for pg_statistic: removed 1002001 / 2097153: 111.634597 ms
2020-11-20 16:26:57.779  LOG:  pruning catalog cache id=58 for pg_statistic: removed 2000999 / 2097153: 134.628430 ms
2020-11-20 16:27:00.389  LOG:  pruning catalog cache id=58 for pg_statistic: removed 1002001 / 2097153: 147.221688 ms
2020-11-20 16:27:01.851  LOG:  pruning catalog cache id=58 for pg_statistic: removed 2000999 / 2097153: 177.610820 ms

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center