strange 'vacuum verbose analyze' behaviour

Started by Oleg Bartunovabout 21 years ago7 messageshackers
Jump to latest
#1Oleg Bartunov
oleg@sai.msu.su

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

#2Tom Lane
tgl@sss.pgh.pa.us
In reply to: Oleg Bartunov (#1)
Re: strange 'vacuum verbose analyze' behaviour

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

#3Oleg Bartunov
oleg@sai.msu.su
In reply to: Tom Lane (#2)
Re: strange 'vacuum verbose analyze' behaviour

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

#4Oleg Bartunov
oleg@sai.msu.su
In reply to: Oleg Bartunov (#1)
Re: strange 'vacuum verbose analyze' behaviour

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 postmaster

Is 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

#5Tom Lane
tgl@sss.pgh.pa.us
In reply to: Oleg Bartunov (#4)
Re: strange 'vacuum verbose analyze' behaviour

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

#6Oleg Bartunov
oleg@sai.msu.su
In reply to: Tom Lane (#5)
Re: strange 'vacuum verbose analyze' behaviour

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 postmaster

Index-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

#7Oleg Bartunov
oleg@sai.msu.su
In reply to: Oleg Bartunov (#6)
Re: strange 'vacuum verbose analyze' behaviour

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 postmaster

Index-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

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