Re: Protect syscache from bloating with negative cache entries

From: Kyotaro Horiguchi <horikyota(dot)ntt(at)gmail(dot)com>
To: andres(at)anarazel(dot)de
Cc: robertmhaas(at)gmail(dot)com, hlinnaka(at)iki(dot)fi, ideriha(dot)takeshi(at)jp(dot)fujitsu(dot)com, tomas(dot)vondra(at)2ndquadrant(dot)com, tgl(at)sss(dot)pgh(dot)pa(dot)us, tsunakawa(dot)takay(at)jp(dot)fujitsu(dot)com, alvherre(at)2ndquadrant(dot)com, bruce(at)momjian(dot)us, pgsql-hackers(at)lists(dot)postgresql(dot)org, michael(dot)paquier(at)gmail(dot)com, david(at)pgmasters(dot)net, craig(at)2ndquadrant(dot)com
Subject: Re: Protect syscache from bloating with negative cache entries
Date: 2020-11-20 07:29:35
Message-ID: 20201120.162935.479078194943245753.horikyota.ntt@gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: 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(dot)ntt(at)gmail(dot)com> wrote in
> At Thu, 19 Nov 2020 15:23:05 +0900 (JST), Kyotaro Horiguchi <horikyota(dot)ntt(at)gmail(dot)com> wrote in
> > At Wed, 18 Nov 2020 21:42:02 -0800, Andres Freund <andres(at)anarazel(dot)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

In response to

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Michael Paquier 2020-11-20 08:21:06 Re: Unnecessary delay in streaming replication due to replay lag
Previous Message Peter Eisentraut 2020-11-20 07:29:19 Re: Skip ExecCheckRTPerms in CTAS with no data