Re: Re: [COMMITTERS] pgsql: Avoid extra locks in GetSnapshotData if old_snapshot_threshold < - Mailing list pgsql-hackers

On Thu, Apr 21, 2016 at 4:13 PM, Kevin Grittner <kgrittn@gmail.com> wrote:

> I have your test case running, and it is not immediately
> clear why old rows are not being vacuumed away.

I have not found the reason that the vacuuming is not as aggressive
as it should be with this old_snapshot_threshold, but I left your
test case running overnight and found that it eventually did kick
in.  So the question is why it was not nearly as aggressive as one
would expect.

From the server log:

kgrittn@Kevin-Desktop:~/pg/master$ grep -B2 -A3 'tuples: [1-9]'
Debug/data/pg_log/postgresql.log
[2016-04-21 16:21:29.658 CDT] LOG:  automatic vacuum of table
"kgrittn.public.high_throughput": index scans: 1       pages: 0 removed, 2759 remain, 0 skipped due to pins, 0 skipped
frozen      tuples: 94 removed, 159928 remain, 158935 are dead but not yet removable       buffer usage: 6005 hits, 0
misses,8 dirtied       avg read rate: 0.000 MB/s, avg write rate: 0.090 MB/s       system usage: CPU 0.00s/0.08u sec
elapsed0.69 sec
 
--
[2016-04-21 16:55:31.971 CDT] LOG:  automatic vacuum of table
"kgrittn.pg_catalog.pg_statistic": index scans: 1       pages: 0 removed, 23 remain, 0 skipped due to pins, 0 skipped
frozen      tuples: 2 removed, 515 remain, 128 are dead but not yet removable       buffer usage: 50 hits, 11 misses,
14dirtied       avg read rate: 4.048 MB/s, avg write rate: 5.152 MB/s       system usage: CPU 0.00s/0.00u sec elapsed
0.02sec
 
--
[2016-04-22 00:33:11.978 CDT] LOG:  automatic vacuum of table
"kgrittn.pg_catalog.pg_statistic": index scans: 1       pages: 0 removed, 68 remain, 0 skipped due to pins, 0 skipped
frozen      tuples: 1016 removed, 409 remain, 22 are dead but not yet removable       buffer usage: 89 hits, 127
misses,111 dirtied       avg read rate: 1.478 MB/s, avg write rate: 1.292 MB/s       system usage: CPU 0.00s/0.00u sec
elapsed0.67 sec
 
[2016-04-22 00:33:18.572 CDT] LOG:  automatic vacuum of table
"kgrittn.public.high_throughput": index scans: 1       pages: 0 removed, 20196 remain, 0 skipped due to pins, 0 skipped
frozen      tuples: 292030 removed, 3941 remain, 3553 are dead but not yet removable       buffer usage: 68541 hits,
14415misses, 20638 dirtied       avg read rate: 1.674 MB/s, avg write rate: 2.396 MB/s       system usage: CPU
0.23s/1.09usec elapsed 67.29 sec
 
--
[2016-04-22 00:52:13.013 CDT] LOG:  automatic vacuum of table
"kgrittn.public.high_throughput": index scans: 1       pages: 0 removed, 20233 remain, 0 skipped due to pins, 19575
skipped frozen       tuples: 8463 removed, 30533 remain, 28564 are dead but not yet removable       buffer usage: 8136
hits,4 misses, 158 dirtied       avg read rate: 0.027 MB/s, avg write rate: 1.065 MB/s       system usage: CPU
0.00s/0.03usec elapsed 1.15 sec
 
--
[2016-04-22 01:28:22.812 CDT] LOG:  automatic vacuum of table
"kgrittn.pg_catalog.pg_statistic": index scans: 1       pages: 0 removed, 68 remain, 0 skipped due to pins, 44 skipped
frozen      tuples: 26 removed, 760 remain, 108 are dead but not yet removable       buffer usage: 37 hits, 27 misses,
12dirtied       avg read rate: 4.963 MB/s, avg write rate: 2.206 MB/s       system usage: CPU 0.00s/0.00u sec elapsed
0.04sec
 
--
[2016-04-22 06:51:23.042 CDT] LOG:  automatic vacuum of table
"kgrittn.pg_catalog.pg_statistic": index scans: 1       pages: 0 removed, 68 remain, 0 skipped due to pins, 0 skipped
frozen      tuples: 692 removed, 403 remain, 16 are dead but not yet removable       buffer usage: 90 hits, 109 misses,
76dirtied       avg read rate: 1.646 MB/s, avg write rate: 1.148 MB/s       system usage: CPU 0.00s/0.00u sec elapsed
0.51sec
 
[2016-04-22 06:52:45.174 CDT] LOG:  automatic vacuum of table
"kgrittn.public.high_throughput": index scans: 1       pages: 0 removed, 28152 remain, 0 skipped due to pins, 0 skipped
frozen      tuples: 928116 removed, 14021 remain, 14021 are dead but not
 
yet removable       buffer usage: 88738 hits, 33068 misses, 45857 dirtied       avg read rate: 1.811 MB/s, avg write
rate:2.511 MB/s       system usage: CPU 0.43s/1.93u sec elapsed 142.68 sec
 
--
[2016-04-22 06:53:23.665 CDT] LOG:  automatic vacuum of table
"kgrittn.public.high_throughput": index scans: 1       pages: 0 removed, 28313 remain, 0 skipped due to pins, 27853
skipped frozen       tuples: 43 removed, 9002 remain, 8001 are dead but not yet removable       buffer usage: 9795
hits,22 misses, 28 dirtied       avg read rate: 0.159 MB/s, avg write rate: 0.202 MB/s       system usage: CPU
0.00s/0.03usec elapsed 1.08 sec
 
--
[2016-04-22 07:22:25.240 CDT] LOG:  automatic vacuum of table
"kgrittn.public.high_throughput": index scans: 1       pages: 0 removed, 28313 remain, 0 skipped due to pins, 25627
skipped frozen       tuples: 51 removed, 149639 remain, 147733 are dead but not yet removable       buffer usage: 14227
hits,18 misses, 15 dirtied       avg read rate: 0.089 MB/s, avg write rate: 0.074 MB/s       system usage: CPU
0.01s/0.10usec elapsed 1.58 sec
 

From the output stream of the python test script:

00:32:00]  Counted 1000 rows with max 1094 in high_throughput table
[00:32:05]  High throughput table size @ 31240s. Size 161624kB Last
vacuum 0:00:42.664285 ago
[00:32:10]  Interfering query got error snapshot too old

[00:32:10]  Waiting 3min to restart interfering query

[06:50:00]  Counted 1000 rows with max 1176984 in high_throughput table
[06:50:05]  High throughput table size @ 53920s. Size 225088kB Last
vacuum 0:00:23.685084 ago
[06:50:10]  Interfering query got error snapshot too old

[06:50:10]  Waiting 3min to restart interfering query

I don't see any evidence that it returned incorrect query results
at any point, and it did eventually limit bloat; what we have is
that it is not limiting it nearly as tightly as one would expect in
this particular test case.

I'm continuing to investigate.

-- 
Kevin Grittner
EDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company