Обсуждение: strange 'vacuum verbose analyze' behaviour

Поиск
Список
Период
Сортировка

strange 'vacuum verbose analyze' behaviour

От
Oleg Bartunov
Дата:
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

Re: strange 'vacuum verbose analyze' behaviour

От
Tom Lane
Дата:
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

Re: strange 'vacuum verbose analyze' behaviour

От
Oleg Bartunov
Дата:
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

Re: strange 'vacuum verbose analyze' behaviour

От
Oleg Bartunov
Дата:
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

Re: strange 'vacuum verbose analyze' behaviour

От
Tom Lane
Дата:
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

Re: strange 'vacuum verbose analyze' behaviour

От
Oleg Bartunov
Дата:
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

Re: strange 'vacuum verbose analyze' behaviour

От
Oleg Bartunov
Дата:
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