CLUSTER VERBOSE (9.1.3)

On Mon, Mar 5, 2012 at 4:40 PM, Larry Rosenman <ler@lerctr.org> wrote:

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Is there any way to get more info out of CLUSTER VERBOSE so it says
what index it's working on AFTER the table re-write?

INFO:  clustering "public.values" using sequential scan and sort
INFO:  "values": found 0 removable, 260953511 nonremovable row
versions in 4224437 pages
DETAIL:  0 dead row versions cannot be removed yet.
CPU 168.02s/4324.68u sec elapsed 8379.12 sec.

And at this point it's doing something(tm), I assume re-doing the indexes.

It would be nice(tm) to get more info.

Ideas?

Try setting client_min_messages=DEBUG1. At least on current sources
that gives some additional, relevant output; I think that's probably
there in 9.1.x as well.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 3/6/2012 8:32 AM, Robert Haas wrote:

On Mon, Mar 5, 2012 at 4:40 PM, Larry Rosenman <ler@lerctr.org>
wrote:

-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1

Is there any way to get more info out of CLUSTER VERBOSE so it
says what index it's working on AFTER the table re-write?

INFO: clustering "public.values" using sequential scan and sort
INFO: "values": found 0 removable, 260953511 nonremovable row
versions in 4224437 pages DETAIL: 0 dead row versions cannot be
removed yet. CPU 168.02s/4324.68u sec elapsed 8379.12 sec.

And at this point it's doing something(tm), I assume re-doing the
indexes.

It would be nice(tm) to get more info.

Ideas?

Try setting client_min_messages=DEBUG1. At least on current
sources that gives some additional, relevant output; I think that's
probably there in 9.1.x as well.

Thanks. That helps some, but I'd like to see:
1) these moved up to INFO when CLUSTER VERBOSE
2) time/statistics on each index build

INFO: clustering "public.values" using sequential scan and sort
INFO: "values": found 0 removable, 260953511 nonremovable row
versions in 4224437 pages
DETAIL: 0 dead row versions cannot be removed yet.
CPU 167.57s/4325.52u sec elapsed 7687.28 sec.
DEBUG: building index "values_idx1" on table "values"
DEBUG: building index "values_idx2" on table "values"
DEBUG: building index "values_idx3" on table "values"
DEBUG: building index "values_idx4" on table "values"
DEBUG: building index "values_idx5" on table "values"
DEBUG: building index "values_idx6" on table "values"
DEBUG: building index "values_idx7" on table "values"
DEBUG: building index "values_idx_cluster" on table "values"
CLUSTER
Time: 28997806.474 ms

Comments?

- --
Larry Rosenman http://www.lerctr.org/~ler
Phone: +1 512-248-2683 E-Mail: ler@lerctr.org
US Mail: 430 Valona Loop, Round Rock, TX 78681-3893
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.17 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iQEcBAEBAgAGBQJPV3GyAAoJENC8dtAvA1zmAzkIALJL/Ir7Ks3gYVy4bVB7Oamc
Etpg6/hmM3+g0Ry9Lv3yUbaeHLxwuAaW+Gv5nDuepZFbMfAxYjsUG+fVUu8n3Xo3
V42/4TFxI7QQUtnwqkkMo0Y1vBNsmIRFuxx3b2R+ePKAZaQFLoElU7dL1JOA1u3c
OQ0dUDtiUNTSa+ZrNYNbLhqOUUIooGrF8hWLKfmLOrbrRpAObrCeyaHW2qxRrIq/
wbvHG7YG1byRiDzZr4DNKrS4/88HXjgo2m8xmxyNf+1fKsa69fkIA+rbsqyEx4ui
RAih9fQVQcjcK15XTyDchT21YRdwDZnjVt/Yh0IMvDE19sIQFfrs1QTGPnUULpI=
=5bZG
-----END PGP SIGNATURE-----

On Wed, Mar 7, 2012 at 9:33 AM, Larry Rosenman <ler@lerctr.org> wrote:

Is there any way to get more info out of CLUSTER VERBOSE so it
says what index it's working on AFTER the table re-write?

INFO:  clustering "public.values" using sequential scan and sort
INFO:  "values": found 0 removable, 260953511 nonremovable row
versions in 4224437 pages DETAIL:  0 dead row versions cannot be
removed yet. CPU 168.02s/4324.68u sec elapsed 8379.12 sec.

And at this point it's doing something(tm), I assume re-doing the
indexes.

It would be nice(tm) to get more info.

Ideas?

Try setting client_min_messages=DEBUG1.  At least on current
sources that gives some additional, relevant output; I think that's
probably there in 9.1.x as well.

Thanks.  That helps some, but I'd like to see:
1) these moved up to INFO when CLUSTER VERBOSE
2) time/statistics on each index build

INFO:  clustering "public.values" using sequential scan and sort
INFO:  "values": found 0 removable, 260953511 nonremovable row
versions in 4224437 pages
DETAIL:  0 dead row versions cannot be removed yet.
CPU 167.57s/4325.52u sec elapsed 7687.28 sec.
DEBUG:  building index "values_idx1" on table "values"
DEBUG:  building index "values_idx2" on table "values"
DEBUG:  building index "values_idx3" on table "values"
DEBUG:  building index "values_idx4" on table "values"
DEBUG:  building index "values_idx5" on table "values"
DEBUG:  building index "values_idx6" on table "values"
DEBUG:  building index "values_idx7" on table "values"
DEBUG:  building index "values_idx_cluster" on table "values"
CLUSTER
Time: 28997806.474 ms

Comments?

Seems like a good enhancement to me, if someone can figure out how to
do it cleanly. Unfortunately those debug messages may not be in a
place where it's real easy for them to know whether they're being
called from CLUSTER VERBOSE or not, so it might take a little thought
to produce a clean patch for this.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Excerpts from Robert Haas's message of mié mar 07 11:57:41 -0300 2012:

Seems like a good enhancement to me, if someone can figure out how to
do it cleanly. Unfortunately those debug messages may not be in a
place where it's real easy for them to know whether they're being
called from CLUSTER VERBOSE or not, so it might take a little thought
to produce a clean patch for this.

Another thing that occured to me in this general area was whether it'd
be useful to do something with ps_status and pg_stat_activity.

Also, this isn't limited to CLUSTER; anything that rewrites the table
and indexes would benefit. Meaning ALTER TABLE that does a full
rewrite, and also VACUUM FULL.

--
Álvaro Herrera <alvherre@commandprompt.com>
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 3/7/2012 12:31 PM, Alvaro Herrera wrote:

Excerpts from Robert Haas's message of mié mar 07 11:57:41 -0300
2012:

Seems like a good enhancement to me, if someone can figure out
how to do it cleanly. Unfortunately those debug messages may not
be in a place where it's real easy for them to know whether
they're being called from CLUSTER VERBOSE or not, so it might
take a little thought to produce a clean patch for this.

Another thing that occured to me in this general area was whether
it'd be useful to do something with ps_status and
pg_stat_activity.

Also, this isn't limited to CLUSTER; anything that rewrites the
table and indexes would benefit. Meaning ALTER TABLE that does a
full rewrite, and also VACUUM FULL.

+1. I think we should update ps_status as well as pg_stat_activity as
all of these table rewrite processes are running.

Do I need to cogitate on the code, or is one of the hackers that knows
it better interested?

Thanks!

- --
Larry Rosenman http://www.lerctr.org/~ler
Phone: +1 512-248-2683 E-Mail: ler@lerctr.org
US Mail: 430 Valona Loop, Round Rock, TX 78681-3893
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.17 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iQEcBAEBAgAGBQJPV64WAAoJENC8dtAvA1zmItsH/ib0uAh3Jqy6WKXrxBrJoy5k
LBj/xfAs8Z3Xl0TQjoulgAgBV1NWo5DyKvvtmcxpEw1KkJZrpkWONB3I+Y3nQKiy
rfD3uJ6tWvoD9Ay+InPy0W8qReTSKSSI09au60OzU8Ez3UX5JEGhiibn1B6AvXKy
5JWGRJF64fKEnDOresVHqGGhlLM3lelsS7nMX0rs8kZ20BG3tLPjqZslm/qZ3w9M
OJJpJKOlZCoNs+YZTtNxGeRhKXWSfsao6tYc/8To7pbJ6m9MKyqcou7g8yJXZrJr
+BFwPyRG+/p6Li0tWmsuD8FtuPFFp37HxeduKzJNN9sqA3TSeadN8kZweb8zak8=
=jrEi
-----END PGP SIGNATURE-----

Larry Rosenman <ler@lerctr.org> writes:

On 3/7/2012 12:31 PM, Alvaro Herrera wrote:

Also, this isn't limited to CLUSTER; anything that rewrites the
table and indexes would benefit. Meaning ALTER TABLE that does a
full rewrite, and also VACUUM FULL.

+1. I think we should update ps_status as well as pg_stat_activity as
all of these table rewrite processes are running.

-1. Updating ps_status is expensive, seriously so on some platforms.
We could likely get away with tracking progress in pg_stat_activity
though.

However, this just reminds me that tracking intrastatement progress in
pg_stat_activity has been discussed before and not much has happened.
Let's please not have a quick kluge that just addresses CLUSTER and not
any of the other aspects of that problem.

regards, tom lane

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 3/7/2012 2:42 PM, Tom Lane wrote:

Larry Rosenman <ler@lerctr.org> writes:

On 3/7/2012 12:31 PM, Alvaro Herrera wrote:

Also, this isn't limited to CLUSTER; anything that rewrites
the table and indexes would benefit. Meaning ALTER TABLE that
does a full rewrite, and also VACUUM FULL.

+1. I think we should update ps_status as well as
pg_stat_activity as all of these table rewrite processes are
running.

-1. Updating ps_status is expensive, seriously so on some
platforms. We could likely get away with tracking progress in
pg_stat_activity though.

However, this just reminds me that tracking intrastatement progress
in pg_stat_activity has been discussed before and not much has
happened. Let's please not have a quick kluge that just addresses
CLUSTER and not any of the other aspects of that problem.

regards, tom lane

OOppss. I forgot that it's expensive on ps_status (I think my
favorite platform, FreeBSD, is one of those :().

I do think that pg_stat_activity should be updated, as well as pushing
more of the DEBUG1 progress messages up to INFO, and adding some sort
of timing / statistical info on the create index commands that are run.

Is any of the -hackers community interested, or should I try(!) to
look at the code?

- --
Larry Rosenman http://www.lerctr.org/~ler
Phone: +1 512-248-2683 E-Mail: ler@lerctr.org
US Mail: 430 Valona Loop, Round Rock, TX 78681-3893
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.17 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iQEcBAEBAgAGBQJPV8rRAAoJENC8dtAvA1zmt90IAL7M15RBl6k03Tq18ehUMdos
SKSAT/dSPEaQJx55GIPNy+uE6miiNS8Vo493SJ007hsyob/fuxdhXMfWalrc/qdE
BFsIBNiGJEsy0kyQxhXmXneQurgt1jbntGmCc/rSybd7aDq72fE81G6NaQGXqIOq
FMl3MqQpQuOjL8cCfGgwpsV9paipmlcQTzc52aAcj1Yj15twFySx/P3N18oNX9NP
6JUEgEl6FLP0UQ31roxzbulLR0imoACAThaOOp1swxPREahjkltoU08wk/MeR6xv
hR76is80/16I1hj6DLXwAl6C/Dmmt3ufrKTHKguXJU6RAJI11+05MbSiBIO5wCI=
=rWW2
-----END PGP SIGNATURE-----