From: Guillaume Cottenceau <gc@mnc.ch>
To: pgsql-performance@postgresql.org
Subject: 9.2.1 & index-only scans : abnormal heap fetches after VACUUM FULL 
Date: Thu, 29 Nov 2012 12:33:50 +0100
Message-ID: <m3mwy0myn5.fsf@mnc.ch>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/23.3 (gnu/linux)
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="=-=-="
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org


--=-=-=

Hello,

I am toying around with 9.2.1, trying to measure/determine how
index-only scans can improve our performance.

A small script which is attached to this mail, shows that as long
as the table has been VACUUM FULL'd, there is a unusual high
amount of heap fetches. It is strange that the visibilitymap_test
predicate fails in these situations, is the visibility map
somehow trashed in this situation? It should not, or at least the
documentation[1] should state it (my understanding is that vacuum
full does *more* than vacuum, but nothing less) (note to usual
anti vacuum full trollers: I know you hate vacuum full).

Using pg 9.2.1 compiled from sources, almost standard
configuration except shared_buffers at 512M, effective_cache_size
at 1536M, random_page_cost at 2, and vacuum delays increased.

Please find complete logs attached, and selected logs below:

After table creation + analyze:

 Index Only Scan using i on ta  (cost=0.00..156991.10 rows=2018667 width=4) (actual time=0.034..336.443 rows=2000000 loops=1)
   Index Cond: (ca = 1)
   Heap Fetches: 2000000

After vacuum:

 Index Only Scan using i on ta  (cost=0.00..50882.62 rows=2018667 width=4) (actual time=0.014..193.120 rows=2000000 loops=1)
   Index Cond: (ca = 1)
   Heap Fetches: 0

After vacuum analyze:

 Index Only Scan using i on ta  (cost=0.00..50167.13 rows=1990353 width=4) (actual time=0.015..193.035 rows=2000000 loops=1)
   Index Cond: (ca = 1)
   Heap Fetches: 0

After vacuum full:

 Index Only Scan using i on ta  (cost=0.00..155991.44 rows=1990333 width=4) (actual time=0.042..364.412 rows=2000000 loops=1)
   Index Cond: (ca = 1)
   Heap Fetches: 2000000
                 ^^^^^^^ uh uh, looking bad

After vacuum full analyze:

 Index Only Scan using i on ta  (cost=0.00..157011.85 rows=2030984 width=4) (actual time=0.025..365.657 rows=2000000 loops=1)
   Index Cond: (ca = 1)
   Heap Fetches: 2000000

After vacuum:

 Index Only Scan using i on ta  (cost=0.00..51192.45 rows=2031000 width=4) (actual time=0.015..192.520 rows=2000000 loops=1)
   Index Cond: (ca = 1)
   Heap Fetches: 0

Thanks for any comments/hints,

Ref: 
[1] http://www.postgresql.org/docs/9.1/static/sql-vacuum.html


--=-=-=
Content-Type: application/octet-stream
Content-Disposition: attachment; filename=vacfull.sql
Content-Transfer-Encoding: base64

U0VUIHZhY3V1bV9jb3N0X2RlbGF5ID0gMDsKXHRpbWluZyBmYWxzZQpEUk9Q
IFRBQkxFIHRhOwoKQ1JFQVRFIFRBQkxFIHRhIChjYSBpbnQsIGNiIGludCwg
Y2MgaW50KTsKSU5TRVJUIElOVE8gdGEgVkFMVUVTIChnZW5lcmF0ZV9zZXJp
ZXMoMSwgNSksIGdlbmVyYXRlX3NlcmllcygxLCAxMDAwMDAwMCksIGdlbmVy
YXRlX3NlcmllcygxLCAxMDAwMDAwMCkpOwpBTkFMWVpFIHRhOwpDUkVBVEUg
SU5ERVggaSBPTiB0YSAoY2EsIGNiLCBjYyk7CgpFWFBMQUlOIEFOQUxZWkUg
U0VMRUNUIGNiIEZST00gdGEgV0hFUkUgY2EgPSAxIE9SREVSIEJZIGNiOwoK
VkFDVVVNIHRhOwpFWFBMQUlOIEFOQUxZWkUgU0VMRUNUIGNiIEZST00gdGEg
V0hFUkUgY2EgPSAxIE9SREVSIEJZIGNiOwoKVkFDVVVNIEFOQUxZWkUgdGE7
CkVYUExBSU4gQU5BTFlaRSBTRUxFQ1QgY2IgRlJPTSB0YSBXSEVSRSBjYSA9
IDEgT1JERVIgQlkgY2I7CgpWQUNVVU0gRlVMTCB0YTsKRVhQTEFJTiBBTkFM
WVpFIFNFTEVDVCBjYiBGUk9NIHRhIFdIRVJFIGNhID0gMSBPUkRFUiBCWSBj
YjsKClZBQ1VVTSBGVUxMIEFOQUxZWkUgdGE7CkVYUExBSU4gQU5BTFlaRSBT
RUxFQ1QgY2IgRlJPTSB0YSBXSEVSRSBjYSA9IDEgT1JERVIgQlkgY2I7CgpW
QUNVVU0gdGE7CkVYUExBSU4gQU5BTFlaRSBTRUxFQ1QgY2IgRlJPTSB0YSBX
SEVSRSBjYSA9IDEgT1JERVIgQlkgY2I7CgpEUk9QIFRBQkxFIHRhOw==

--=-=-=
Content-Disposition: inline; filename=fulloutput.log

DROP TABLE ta;
psql:/tmp/vacfull.sql:3: ERROR:  table "ta" does not exist
CREATE TABLE ta (ca int, cb int, cc int);
CREATE TABLE
INSERT INTO ta VALUES (generate_series(1, 5), generate_series(1, 10000000), generate_series(1, 10000000));
INSERT 0 10000000
ANALYZE ta;
ANALYZE
CREATE INDEX i ON ta (ca, cb, cc);
CREATE INDEX
EXPLAIN ANALYZE SELECT cb FROM ta WHERE ca = 1 ORDER BY cb;
                                                          QUERY PLAN                                                          
------------------------------------------------------------------------------------------------------------------------------
 Index Only Scan using i on ta  (cost=0.00..156991.10 rows=2018667 width=4) (actual time=0.034..336.443 rows=2000000 loops=1)
   Index Cond: (ca = 1)
   Heap Fetches: 2000000
 Total runtime: 385.023 ms
(4 rows)

VACUUM ta;
VACUUM
EXPLAIN ANALYZE SELECT cb FROM ta WHERE ca = 1 ORDER BY cb;
                                                         QUERY PLAN                                                          
-----------------------------------------------------------------------------------------------------------------------------
 Index Only Scan using i on ta  (cost=0.00..50882.62 rows=2018667 width=4) (actual time=0.014..193.120 rows=2000000 loops=1)
   Index Cond: (ca = 1)
   Heap Fetches: 0
 Total runtime: 241.079 ms
(4 rows)

VACUUM ANALYZE ta;
VACUUM
EXPLAIN ANALYZE SELECT cb FROM ta WHERE ca = 1 ORDER BY cb;
                                                         QUERY PLAN                                                          
-----------------------------------------------------------------------------------------------------------------------------
 Index Only Scan using i on ta  (cost=0.00..50167.13 rows=1990353 width=4) (actual time=0.015..193.035 rows=2000000 loops=1)
   Index Cond: (ca = 1)
   Heap Fetches: 0
 Total runtime: 241.101 ms
(4 rows)

VACUUM FULL ta;
VACUUM
EXPLAIN ANALYZE SELECT cb FROM ta WHERE ca = 1 ORDER BY cb;
                                                          QUERY PLAN                                                          
------------------------------------------------------------------------------------------------------------------------------
 Index Only Scan using i on ta  (cost=0.00..155991.44 rows=1990333 width=4) (actual time=0.042..364.412 rows=2000000 loops=1)
   Index Cond: (ca = 1)
   Heap Fetches: 2000000
 Total runtime: 412.715 ms
(4 rows)

VACUUM FULL ANALYZE ta;
VACUUM
EXPLAIN ANALYZE SELECT cb FROM ta WHERE ca = 1 ORDER BY cb;
                                                          QUERY PLAN                                                          
------------------------------------------------------------------------------------------------------------------------------
 Index Only Scan using i on ta  (cost=0.00..157011.85 rows=2030984 width=4) (actual time=0.025..365.657 rows=2000000 loops=1)
   Index Cond: (ca = 1)
   Heap Fetches: 2000000
 Total runtime: 414.223 ms
(4 rows)

VACUUM ta;
VACUUM
EXPLAIN ANALYZE SELECT cb FROM ta WHERE ca = 1 ORDER BY cb;
                                                         QUERY PLAN                                                          
-----------------------------------------------------------------------------------------------------------------------------
 Index Only Scan using i on ta  (cost=0.00..51192.45 rows=2031000 width=4) (actual time=0.015..192.520 rows=2000000 loops=1)
   Index Cond: (ca = 1)
   Heap Fetches: 0
 Total runtime: 240.918 ms
(4 rows)

DROP TABLE ta;
DROP TABLE

--=-=-=


-- 
Guillaume Cottenceau

--=-=-=
Content-Type: text/plain
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
MIME-Version: 1.0


-- 
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

--=-=-=--