Обсуждение: Parsing VACUUM VERBOSE

Hi there,

I'd like to understand completely the report generated by VACUUM VERBOSE.
Please tell me where is it documented ?

TIA,
Sabin

Sabin,

On 6/14/07, Sabin Coanda <sabin.coanda@deuromedia.ro> wrote:
> I'd like to understand completely the report generated by VACUUM VERBOSE.
> Please tell me where is it documented ?

You can take a look to what I did for pgFouine:
http://pgfouine.projects.postgresql.org/vacuum.html

--
Guillaume

Le jeudi 14 juin 2007, Sabin Coanda a écrit :
> I'd like to understand completely the report generated by VACUUM VERBOSE.
> Please tell me where is it documented ?

Try the pgfouine reporting tool :
  http://pgfouine.projects.postgresql.org/
  http://pgfouine.projects.postgresql.org/reports/sample_vacuum.html

It's easier to understand the vacuum verbose output from the generated report.
--
dim

Hi Guillaume,

Very interesting !

Merci beaucoup,
Sabin

Can anyone share what value they have set log_min_duration_statement to?

--
Yudhvir Singh Sidhu
408 375 3134 cell

On 6/14/07, Y Sidhu <ysidhu@gmail.com> wrote:
> Can anyone share what value they have set log_min_duration_statement to?

It's OT but we use different values for different databases and needs.

On a very loaded database with a lot of complex queries (lots of join
on big tables, proximity queries, full text queries), we use 100 ms.
It logs ~ 300 000 queries. It allows us to detect big regressions or
new queries which are very slow.

On another database where I want to track transaction leaks, I'm
forced to put it to 0ms.

Basically, the answer is: set it to the lowest value you can afford
without impacting too much your performances (and if you use syslog,
use async I/O or send your log to the network).

--
Guillaume

I am trying to answer the question of how to tell if the cleanup of an index may be locked by a long transaction. And in the bigger context, why vacuums are taking long? What triggers them? I came across the following query which shows one table 'connect_tbl'  with high "heap hits" and "low heap buffer %" Now, 'heap' seems to be a memory construct. Any light shedding is appreciated.

mydb=# SELECT
mydb-# 'HEAP:'||relname AS table_name,
mydb-# (heap_blks_read+heap_blks_hit) AS heap_hits,
        ROUND(((heap_blks_hit)::NUMERIC/(heap_blks_read+heap_blks_hit)*100), 2)
mydb-# ROUND(((heap_blks_hit)::NUMERIC/(heap_blks_read+heap_blks_hit)*100), 2)
mydb-# AS heap_buffer_percentage
mydb-# FROM pg_statio_user_tables
mydb-# WHERE(heap_blks_read+heap_blks_hit)>0
mydb-# UNION
mydb-# SELECT
mydb-# 'TOAST:'||relname,
mydb-# (toast_blks_read+toast_blks_hit),
mydb-# ROUND(((toast_blks_hit)::NUMERIC/(toast_blks_read+toast_blks_hit)*100), 2)
mydb-# FROM pg_statio_user_tables
mydb-# WHERE(toast_blks_read+toast_blks_hit)>0
mydb-# UNION
mydb-# SELECT
mydb-# 'INDEX:'||relname,
mydb-# (idx_blks_read+idx_blks_hit),
mydb-# ROUND(((idx_blks_hit)::NUMERIC/(idx_blks_read+idx_blks_hit)*100), 2)
mydb-# FROM pg_statio_user_tables
mydb-# WHERE(idx_blks_read+idx_blks_hit)>0;
        table_name            | heap_hits | heap_buffer_percentage
------------------------------------+--------------+----------------------------------
 HEAP:connect_tbl         |    890878 |                  43.18
 HEAP:tblbound_tbl         |     43123 |                  13.80
 HEAP:tblcruel_tbl          |    225819 |                   6.98
 INDEX:connect_tbl         |    287224 |                  79.82
 INDEX:tblbound_tbl         |     81640 |                  90.28
 INDEX:tblcruel_tbl          |    253014 |                  50.73

--
Yudhvir Singh Sidhu
408 375 3134 cell

""Guillaume Smet"" <guillaume.smet@gmail.com> wrote in message
news:1d4e0c10706140752u30923a39v3f59a02408836ee4@mail.gmail.com...
> Sabin,
>
> On 6/14/07, Sabin Coanda <sabin.coanda@deuromedia.ro> wrote:
>> I'd like to understand completely the report generated by VACUUM VERBOSE.
>> Please tell me where is it documented ?
>
> You can take a look to what I did for pgFouine:
> http://pgfouine.projects.postgresql.org/vacuum.html
>

Hi Guillaume,

I tried pgFouine.php app on a sample log file but it reports me some errors.
Could you give me some startup support, please ?
I attach the log here to find what's wrong.

Regards,
Sabin


begin 666 postgresql-2007-06-18_160048.log
M,C P-RTP-BTQ." Q-CHP,#HT.2!%15-4(%LQ.3 W.5TZ(%LM,5T@3$]'.B @
M9&%T86)A<V4@<WES=&5M('=A<R!S:'5T(&1O=VX@870@,C P-RTP-BTQ." Q
M-CHP,#HT-R!%15-4"C(P,#<M,#8M,3@@,38Z,# Z-#D@14535"!;,3DP-SE=
M.B!;+3%=($Q/1SH@(&-H96-K<&]I;G0@<F5C;W)D(&ES(&%T(#,W+T$S-SDX
M-C8T"C(P,#<M,#8M,3@@,38Z,# Z-#D@14535"!;,3DP-SE=.B!;+3%=($Q/
M1SH@(')E9&\@<F5C;W)D(&ES(&%T(#,W+T$S-SDX-C8T.R!U;F1O(')E8V]R
M9"!I<R!A=" P+S [('-H=71D;W=N(%12544*,C P-RTP-BTQ." Q-CHP,#HT
M.2!%15-4(%LQ.3 W.5TZ(%LM,5T@3$]'.B @;F5X="!T<F%N<V%C=&EO;B!)
M1#H@,"\W.#@V,C$[(&YE>'0@3TE$.B V-C,W.#<*,C P-RTP-BTQ." Q-CHP
M,#HT.2!%15-4(%LQ.3 W.5TZ(%LM,5T@3$]'.B @;F5X="!-=6QT:5AA8W1)
M9#H@,S8[(&YE>'0@375L=&E886-T3V9F<V5T.B W,0HR,# W+3 V+3$X(#$V
M.C P.C0Y($5%4U0@6S$Y,#<Y73H@6RTQ72!,3T<Z("!D871A8F%S92!S>7-T
M96T@:7,@<F5A9'D*,C P-RTP-BTQ." Q-CHP,3HR-R!%15-4(%LQ.3 Y-UTZ
M(%LM,5T@3$]'.B @9'5R871I;VXZ(#@Q+C4P."!M<R @<W1A=&5M96YT.B!3
M150@1&%T95-T>6QE/4E33SM314Q%0U0@;VED+"!P9U]E;F-O9&EN9U]T;U]C
M:&%R*&5N8V]D:6YG*2!!4R!E;F-O9&EN9RP@9&%T;&%S='-Y<V]I9 H)("!&
M4D]-('!G7V1A=&%B87-E(%=(15)%(&]I9" ](#0V.30R,PHR,# W+3 V+3$X
M(#$V.C Q.C(W($5%4U0@6S$Y,#DW73H@6RTQ72!,3T<Z("!D=7)A=&EO;CH@
M,"XP.3$@;7,@('-T871E;65N=#H@<V5T(&-L:65N=%]E;F-O9&EN9R!T;R G
M54Y)0T]$12<*,C P-RTP-BTQ." Q-CHP,3HS-R!%15-4(%LQ.3 Y-UTZ(%LM
M,5T@3$]'.B @9'5R871I;VXZ(#DX+C8S-R!M<R @<W1A=&5M96YT.B!314Q%
M0U0@*B!&4D]-(")T8D-O;&QE8W1I;VYS(@HR,# W+3 V+3$X(#$V.C Q.C,W
M($5%4U0@6S$Y,#DW73H@6RTQ72!,3T<Z("!D=7)A=&EO;CH@-2XT.3(@;7,@
M('-T871E;65N=#H@4T5,14-4(&9O<FUA=%]T>7!E*&]I9"PM,2D@87,@='EP
M;F%M92!&4D]-('!G7W1Y<&4@5TA%4D4@;VED(#T@,C,*,C P-RTP-BTQ." Q
M-CHP,3HS-R!%15-4(%LQ.3 Y-UTZ(%LM,5T@3$]'.B @9'5R871I;VXZ(#0N
M,S<Q(&US("!S=&%T96UE;G0Z(%-%3$5#5"!#05-%(%=(14X@='EP8F%S971Y
M<&4],"!42$5.(&]I9"!E;'-E('1Y<&)A<V5T>7!E($5.1"!!4R!B87-E='EP
M90H)("!&4D]-('!G7W1Y<&4@5TA%4D4@;VED/3(S"C(P,#<M,#8M,3@@,38Z
M,#$Z,S<@14535"!;,3DP.3==.B!;+3%=($Q/1SH@(&1U<F%T:6]N.B P+C0S
M,B!M<R @<W1A=&5M96YT.B!314Q%0U0@9F]R;6%T7W1Y<&4H;VED+#$P-"D@
M87,@='EP;F%M92!&4D]-('!G7W1Y<&4@5TA%4D4@;VED(#T@,3 T,PHR,# W
M+3 V+3$X(#$V.C Q.C,W($5%4U0@6S$Y,#DW73H@6RTQ72!,3T<Z("!D=7)A
M=&EO;CH@,"XU,C,@;7,@('-T871E;65N=#H@4T5,14-4($-!4T4@5TA%3B!T
M>7!B87-E='EP93TP(%1(14X@;VED(&5L<V4@='EP8F%S971Y<&4@14Y$($%3
M(&)A<V5T>7!E"@D@($923TT@<&=?='EP92!72$5212!O:60],3 T,PHR,# W
M+3 V+3$X(#$V.C Q.C,W($5%4U0@6S$Y,#DW73H@6RTQ72!,3T<Z("!D=7)A
M=&EO;CH@,"XS-S$@;7,@('-T871E;65N=#H@4T5,14-4(&9O<FUA=%]T>7!E
M*&]I9"PM,2D@87,@='EP;F%M92!&4D]-('!G7W1Y<&4@5TA%4D4@;VED(#T@
M,C,*,C P-RTP-BTQ." Q-CHP,3HS-R!%15-4(%LQ.3 Y-UTZ(%LM,5T@3$]'
M.B @9'5R871I;VXZ(# N-3$T(&US("!S=&%T96UE;G0Z(%-%3$5#5"!#05-%
M(%=(14X@='EP8F%S971Y<&4],"!42$5.(&]I9"!E;'-E('1Y<&)A<V5T>7!E
M($5.1"!!4R!B87-E='EP90H)("!&4D]-('!G7W1Y<&4@5TA%4D4@;VED/3(S
M"C(P,#<M,#8M,3@@,38Z,#$Z,S<@14535"!;,3DP.3==.B!;+3%=($Q/1SH@
M(&1U<F%T:6]N.B P+C,W.2!M<R @<W1A=&5M96YT.B!314Q%0U0@9F]R;6%T
M7W1Y<&4H;VED+"TQ*2!A<R!T>7!N86UE($923TT@<&=?='EP92!72$5212!O
M:60@/2 R,PHR,# W+3 V+3$X(#$V.C Q.C,W($5%4U0@6S$Y,#DW73H@6RTQ
M72!,3T<Z("!D=7)A=&EO;CH@,"XU,3<@;7,@('-T871E;65N=#H@4T5,14-4
M($-!4T4@5TA%3B!T>7!B87-E='EP93TP(%1(14X@;VED(&5L<V4@='EP8F%S
M971Y<&4@14Y$($%3(&)A<V5T>7!E"@D@($923TT@<&=?='EP92!72$5212!O
M:60],C,*,C P-RTP-BTQ." Q-CHP,3HS-R!%15-4(%LQ.3 Y-UTZ(%LM,5T@
M3$]'.B @9'5R871I;VXZ(# N,S<Q(&US("!S=&%T96UE;G0Z(%-%3$5#5"!F
M;W)M871?='EP92AO:60L+3$I(&%S('1Y<&YA;64@1E)/32!P9U]T>7!E(%=(
M15)%(&]I9" ](#(S"C(P,#<M,#8M,3@@,38Z,#$Z,S<@14535"!;,3DP.3==
M.B!;+3%=($Q/1SH@(&1U<F%T:6]N.B P+C4Q,"!M<R @<W1A=&5M96YT.B!3
M14Q%0U0@0T%312!72$5.('1Y<&)A<V5T>7!E/3 @5$A%3B!O:60@96QS92!T
M>7!B87-E='EP92!%3D0@05,@8F%S971Y<&4*"2 @1E)/32!P9U]T>7!E(%=(
M15)%(&]I9#TR,PHR,# W+3 V+3$X(#$V.C Q.C,W($5%4U0@6S$Y,#DW73H@
M6RTQ72!,3T<Z("!D=7)A=&EO;CH@,"XS-S$@;7,@('-T871E;65N=#H@4T5,
M14-4(&9O<FUA=%]T>7!E*&]I9"PM,2D@87,@='EP;F%M92!&4D]-('!G7W1Y
M<&4@5TA%4D4@;VED(#T@,C,*,C P-RTP-BTQ." Q-CHP,3HS-R!%15-4(%LQ
M.3 Y-UTZ(%LM,5T@3$]'.B @9'5R871I;VXZ(# N-3$Y(&US("!S=&%T96UE
M;G0Z(%-%3$5#5"!#05-%(%=(14X@='EP8F%S971Y<&4],"!42$5.(&]I9"!E
M;'-E('1Y<&)A<V5T>7!E($5.1"!!4R!B87-E='EP90H)("!&4D]-('!G7W1Y
0<&4@5TA%4D4@;VED/3(S"@``
`
end

Guillaume and Sabin,

I am following this discussion with great interest. I have PG running on FreeBSD and am forced to run pgFouine on a separate Linux box. I am hoping I can create a log file. and then copy that over and have pgFouine analyze it on the Linux box.
a.  I created a log file out of vacuum verbose, is that right? It is not complete because I don't know how to dump it into a file in some sort of autmoated fashion. So, I have to take what is on the screen and copy it off.
b.  I can also set a variable "log_min_duration_statement" in pgsql.conf

I guess I am like Sabin,, and need some hand holding to get started.


--
Yudhvir Singh Sidhu
408 375 3134 cell

On 6/18/07, Sabin Coanda <sabin.coanda@deuromedia.ro> wrote:
> Hi Guillaume,
>
> I tried pgFouine.php app on a sample log file but it reports me some errors.
> Could you give me some startup support, please ?
> I attach the log here to find what's wrong.

Sorry for the delay. I answered to your private email this evening.

--
Guillaume

On 6/18/07, Y Sidhu <ysidhu@gmail.com> wrote:
>  I am following this discussion with great interest. I have PG running on
> FreeBSD and am forced to run pgFouine on a separate Linux box. I am hoping I
> can create a log file. and then copy that over and have pgFouine analyze it
> on the Linux box.
>  a.  I created a log file out of vacuum verbose, is that right? It is not
> complete because I don't know how to dump it into a file in some sort of
> autmoated fashion. So, I have to take what is on the screen and copy it off.

If you want to analyze a VACUUM log, just run vacuumdb with the option
you need (for example -a -z -v -f for a vacuum full analyze verbose).

# vacuumdb -a -z -v -f > your_log_file.log

Then analyze this log file as explained on the pgFouine website.

>  b.  I can also set a variable "log_min_duration_statement" in pgsql.conf
>
>  I guess I am like Sabin,, and need some hand holding to get started.

This is completely different and it's useful for query log analysis.
So you don't care if you just want to analyze your vacuum behaviour.

--
Guillaume