strange 'vacuum verbose analyze' behaviour
Hi there,
we have a table with 500mln rows:
wsdb=# \d usno
Table "public.usno"
Column | Type | Modifiers
--------+--------+-----------
ra | real |
dec | real |
bmag | real |
rmag | real |
ipix | bigint |
Indexes:
"ipix_ind" btree (ipix)
"radec_idx1" btree (ra, "dec")
postgresql is a v8.0 release running on Linux 2.6.7
Day ago we run 'vacuum verbose analyze;' and now we're observing
strange output (see below). We see many repeated passes through the
table 'usno' and all indices (2). The only change is a string like:
INFO: index "radec_idx1" now contains 1024770075 row versions in 2946824 pages
^^^^^^^^^^
The loop is:
usno table ~ 20sec
index "radec_idx1" ~ 5100sec
index "ipix_ind" ~ 1000sec
and it repeated about 13 times ( 26hours/2hours )
Is this an expected behaviour or I miss something ?
===============================================
CPU 120.71s/459.94u sec elapsed 5135.44 sec.
INFO: index "ipix_ind" now contains 526280881 row versions in 1443010 pages
DETAIL: 0 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 66.65s/229.44u sec elapsed 1003.02 sec.
INFO: "usno": removed 2796013 row versions in 17809 pages
DETAIL: CPU 1.45s/1.79u sec elapsed 17.77 sec.
INFO: index "radec_idx1" now contains 1024770075 row versions in 2946824 pages
DETAIL: 2796013 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 147.80s/500.09u sec elapsed 5343.77 sec.
INFO: index "ipix_ind" now contains 526280881 row versions in 1443010 pages
DETAIL: 0 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 66.99s/228.63u sec elapsed 1005.83 sec.
INFO: "usno": removed 2796013 row versions in 17809 pages
DETAIL: CPU 1.41s/1.89u sec elapsed 19.37 sec.
INFO: index "radec_idx1" now contains 1021974062 row versions in 2946824 pages
DETAIL: 2796013 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 152.17s/507.50u sec elapsed 5307.60 sec.
INFO: index "ipix_ind" now contains 526280881 row versions in 1443010 pages
DETAIL: 0 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 67.38s/228.16u sec elapsed 1004.35 sec.
INFO: "usno": removed 2796013 row versions in 17809 pages
DETAIL: CPU 1.53s/1.75u sec elapsed 18.18 sec.
INFO: index "radec_idx1" now contains 1019178049 row versions in 2946824 pages
DETAIL: 2796013 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 131.59s/473.23u sec elapsed 5198.25 sec.
INFO: index "ipix_ind" now contains 526280881 row versions in 1443010 pages
DETAIL: 0 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 69.60s/231.15u sec elapsed 1004.39 sec.
INFO: "usno": removed 2796013 row versions in 17809 pages
DETAIL: CPU 1.50s/1.83u sec elapsed 19.18 sec.
INFO: index "radec_idx1" now contains 1016382036 row versions in 2946824 pages
DETAIL: 2796013 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 120.82s/457.42u sec elapsed 5137.68 sec.
INFO: index "ipix_ind" now contains 526280881 row versions in 1443010 pages
DETAIL: 0 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 67.00s/228.01u sec elapsed 1000.84 sec.
INFO: "usno": removed 2796013 row versions in 17809 pages
DETAIL: CPU 1.55s/1.73u sec elapsed 19.84 sec.
INFO: index "radec_idx1" now contains 1013586023 row versions in 2946824 pages
DETAIL: 2796013 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 114.79s/444.80u sec elapsed 5113.45 sec.
INFO: index "ipix_ind" now contains 526280881 row versions in 1443010 pages
DETAIL: 0 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 66.73s/228.66u sec elapsed 1006.17 sec.
INFO: "usno": removed 2796013 row versions in 17809 pages
DETAIL: CPU 1.49s/1.69u sec elapsed 20.00 sec.
INFO: index "radec_idx1" now contains 1010790010 row versions in 2946824 pages
DETAIL: 2796013 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 114.04s/442.33u sec elapsed 5080.93 sec.
INFO: index "ipix_ind" now contains 526280881 row versions in 1443010 pages
DETAIL: 0 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 67.12s/228.84u sec elapsed 1010.20 sec.
INFO: "usno": removed 2796013 row versions in 17809 pages
DETAIL: CPU 1.50s/1.82u sec elapsed 19.98 sec.
Regards,
Oleg
_____________________________________________________________
Oleg Bartunov, sci.researcher, hostmaster of AstroNet,
Sternberg Astronomical Institute, Moscow University (Russia)
Internet: oleg@sai.msu.su, http://www.sai.msu.su/~megera/
phone: +007(095)939-16-83, +007(095)939-23-83
Oleg Bartunov <oleg@sai.msu.su> writes:
Day ago we run 'vacuum verbose analyze;' and now we're observing
strange output (see below). We see many repeated passes through the
table 'usno' and all indices (2).
Nothing strange about it: that's how vacuum deals with large tables.
You can reduce the number of passes over the indexes by increasing
maintenance_work_mem (aka vacuum_mem). It looks like you have that
set to 16MB, which is enough to hold about 2.79M 6-byte CTIDs. When
that fills up, we have to go and clean out the corresponding index
entries before we resume scanning the heap.
It is a bit odd that nothing is getting deleted from "ipix_ind" ...
is that a partial index?
regards, tom lane
On Thu, 27 Jan 2005, Tom Lane wrote:
Oleg Bartunov <oleg@sai.msu.su> writes:
Day ago we run 'vacuum verbose analyze;' and now we're observing
strange output (see below). We see many repeated passes through the
table 'usno' and all indices (2).Nothing strange about it: that's how vacuum deals with large tables.
You can reduce the number of passes over the indexes by increasing
maintenance_work_mem (aka vacuum_mem). It looks like you have that
set to 16MB, which is enough to hold about 2.79M 6-byte CTIDs. When
that fills up, we have to go and clean out the corresponding index
entries before we resume scanning the heap.
thanks for info, just increased maintenance_work_mem and will see
It is a bit odd that nothing is getting deleted from "ipix_ind" ...
is that a partial index?
no.
wsdb=# \d ipix_ind
Index "public.ipix_ind"
Column | Type
--------+--------
ipix | bigint
btree, for table "public.usno"
regards, tom lane
Regards,
Oleg
_____________________________________________________________
Oleg Bartunov, sci.researcher, hostmaster of AstroNet,
Sternberg Astronomical Institute, Moscow University (Russia)
Internet: oleg@sai.msu.su, http://www.sai.msu.su/~megera/
phone: +007(095)939-16-83, +007(095)939-23-83
On Fri, 28 Jan 2005, Oleg Bartunov wrote:
On Thu, 27 Jan 2005, Tom Lane wrote:
Oleg Bartunov <oleg@sai.msu.su> writes:
Day ago we run 'vacuum verbose analyze;' and now we're observing
strange output (see below). We see many repeated passes through the
table 'usno' and all indices (2).Nothing strange about it: that's how vacuum deals with large tables.
You can reduce the number of passes over the indexes by increasing
maintenance_work_mem (aka vacuum_mem). It looks like you have that
set to 16MB, which is enough to hold about 2.79M 6-byte CTIDs. When
that fills up, we have to go and clean out the corresponding index
entries before we resume scanning the heap.I've increased maintenance_work_mem to 65536 (4x default value) and now I see
postmaster eats more than 1Gb memory !PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 20458
postgres 15 0 1350m 522m 204m D 8.0 51.6 1:08.26 postmasterIs this normal ? I've also increased checkpoint_segments to 12,
but it shouldn't affect to memory.
Memory growth stoped at 1.8Gb
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
20458 postgres 15 0 1902m 503m 204m D 5.9 49.7 13:59.61 postmaster
Regards,
Oleg
_____________________________________________________________
Oleg Bartunov, sci.researcher, hostmaster of AstroNet,
Sternberg Astronomical Institute, Moscow University (Russia)
Internet: oleg@sai.msu.su, http://www.sai.msu.su/~megera/
phone: +007(095)939-16-83, +007(095)939-23-83
Import Notes
Reply to msg id not found: Pine.GSO.4.62.0501281511160.6701@ra.sai.msu.su
Oleg Bartunov <oleg@sai.msu.su> writes:
Memory growth stoped at 1.8Gb
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
20458 postgres 15 0 1902m 503m 204m D 5.9 49.7 13:59.61 postmaster
Index-related memory leak maybe? What are the indexes on this table,
exactly?
regards, tom lane
On Fri, 28 Jan 2005, Tom Lane wrote:
Oleg Bartunov <oleg@sai.msu.su> writes:
Memory growth stoped at 1.8Gb
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
20458 postgres 15 0 1902m 503m 204m D 5.9 49.7 13:59.61 postmasterIndex-related memory leak maybe? What are the indexes on this table,
exactly?
nothing special :)
CREATE TABLE usno (
ra real,
dec real,
bmag real,
rmag real);
COPY usno FROM stdin with delimiter '|';
CREATE INDEX radec_idx1 ON usno (ra,dec) ;
ALTER TABLE usno ADD COLUMN ipix bigint;
UPDATE usno SET ipix = q3c_ang2pix(ra,dec);
CREATE INDEX ipix_ind ON usno (ipix);
regards, tom lane
---------------------------(end of broadcast)---------------------------
TIP 1: subscribe and unsubscribe commands go to majordomo@postgresql.org
Regards,
Oleg
_____________________________________________________________
Oleg Bartunov, sci.researcher, hostmaster of AstroNet,
Sternberg Astronomical Institute, Moscow University (Russia)
Internet: oleg@sai.msu.su, http://www.sai.msu.su/~megera/
phone: +007(095)939-16-83, +007(095)939-23-83
Tom,
After almost 20 hours running vacuum I see postmaster grew a little bit:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
20458 postgres 15 0 2136m 553m 204m D 33.2 54.7 198:18.36 postmaster
It's strange that I see no output since starting
vacuumdb -v -z -f wsdb > vacuum-wsdb.log 2>&1&
-rw-r--r-- 1 postgres postgres 48784 Jan 28 15:03 vacuum-wsdb.log
Is there something I could do ?
Oleg
On Fri, 28 Jan 2005, Oleg Bartunov wrote:
On Fri, 28 Jan 2005, Tom Lane wrote:
Oleg Bartunov <oleg@sai.msu.su> writes:
Memory growth stoped at 1.8Gb
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
20458 postgres 15 0 1902m 503m 204m D 5.9 49.7 13:59.61 postmasterIndex-related memory leak maybe? What are the indexes on this table,
exactly?nothing special :)
CREATE TABLE usno (
ra real,
dec real,
bmag real,
rmag real);COPY usno FROM stdin with delimiter '|';
CREATE INDEX radec_idx1 ON usno (ra,dec) ;
ALTER TABLE usno ADD COLUMN ipix bigint;
UPDATE usno SET ipix = q3c_ang2pix(ra,dec);
CREATE INDEX ipix_ind ON usno (ipix);
regards, tom lane
---------------------------(end of broadcast)---------------------------
TIP 1: subscribe and unsubscribe commands go to majordomo@postgresql.orgRegards,
Oleg
_____________________________________________________________
Oleg Bartunov, sci.researcher, hostmaster of AstroNet,
Sternberg Astronomical Institute, Moscow University (Russia)
Internet: oleg@sai.msu.su, http://www.sai.msu.su/~megera/
phone: +007(095)939-16-83, +007(095)939-23-83
Regards,
Oleg
_____________________________________________________________
Oleg Bartunov, sci.researcher, hostmaster of AstroNet,
Sternberg Astronomical Institute, Moscow University (Russia)
Internet: oleg@sai.msu.su, http://www.sai.msu.su/~megera/
phone: +007(095)939-16-83, +007(095)939-23-83