Обсуждение: "explain analyze" a procedure verbosely - to find which statement in it takes longer

Hello,

I've read in the docs, that every table should
better have primary key and so I've rearranged
my 8.4.13 database: added primary keys to
each table (some of the primary keys are
pairs of columns) and dropped all other indices.

And I've probably dropped few indices too many,
because a stored procedure takes very long now:

# explain analyze select pref_delete_user('DE17795', 'agr. comment');
                                           QUERY PLAN

--------------------------------------------------------------------------------
----------------
 Result  (cost=0.00..0.26 rows=1 width=0) (actual time=1144672.341..1144672.342
rows=1 loops=1)
 Total runtime: 1144672.457 ms
(2 rows)

Is there maybe a way to make the
"explain analyze" output more verbose?

Or do I have to run each of procedure's
statements by hand, preprending them
with "explain analyze"?

My code is below, thanks for any advices

Regards
Alex

        create or replace function pref_delete_user(_id varchar,
            _reason varchar) returns void as $BODY$
                begin

                insert into pref_ban2 select
                        id,
                        first_name,
                        last_name,
                        city,
                        last_ip
                from pref_users where id=_id;

                update pref_ban2 set reason=_reason where id=_id;

                create temporary table temp_gids (gid int not null) on
commit drop;
                insert into temp_gids (gid) select gid from
pref_scores where id=_id;

                delete from pref_games p
                using temp_gids t
                where p.gid = t.gid;

                create temporary table temp_rids (rid int not null) on
commit drop;
                insert into temp_rids (rid) select rid from pref_cards
where id=_id;

                delete from pref_rounds r
                using temp_rids t
                where r.rid = t.rid;

                delete from pref_users where id=_id;

                end;
        $BODY$ language plpgsql;

        create table pref_users (
                id varchar(32) primary key,
                first_name varchar(64),
                last_name varchar(64),
                female boolean,
                avatar varchar(128),
                city varchar(64),
                login timestamp default current_timestamp,
                logout timestamp,
                last_ip inet,
                vip timestamp,
                mail varchar(256),
                medals integer not null default 0
        );

        create table pref_rounds (
                rid serial primary key,
                cards text,
                stamp timestamp default current_timestamp
        );

        create table pref_cards (
                rid integer references pref_rounds on delete cascade,
                id varchar(32) references pref_users on delete cascade,
                bid varchar(32) not null,
                trix integer not null,
                pos integer not null,
                money integer not null,
                last_ip inet,
                quit boolean,
                stamp timestamp default current_timestamp,
                primary key(id, rid)               /* added recently */
        );

        create table pref_games (
                gid serial primary key,
                rounds integer not null,
                stamp timestamp default current_timestamp
        );

        create table pref_scores (
                id varchar(32) references pref_users on delete cascade,
                gid integer references pref_games on delete cascade,
                money integer not null,
                last_ip inet,
                quit boolean,
                primary key(id, gid);              /* added recently */
        );

        create table pref_ban2 (
                id varchar(32) primary key,  /* not a foreign key,
since banned */
                first_name varchar(64),
                last_name varchar(64),
                city varchar(64),
                last_ip inet,
                reason varchar(128),
                created timestamp default current_timestamp
        );

Hello


2013/2/6 Alexander Farber <alexander.farber@gmail.com>:
> Hello,
>
> I've read in the docs, that every table should
> better have primary key and so I've rearranged
> my 8.4.13 database: added primary keys to
> each table (some of the primary keys are
> pairs of columns) and dropped all other indices.
>
> And I've probably dropped few indices too many,
> because a stored procedure takes very long now:
>
> # explain analyze select pref_delete_user('DE17795', 'agr. comment');
>                                            QUERY PLAN
>
> --------------------------------------------------------------------------------
> ----------------
>  Result  (cost=0.00..0.26 rows=1 width=0) (actual time=1144672.341..1144672.342
> rows=1 loops=1)
>  Total runtime: 1144672.457 ms
> (2 rows)
>
> Is there maybe a way to make the
> "explain analyze" output more verbose?
>
> Or do I have to run each of procedure's
> statements by hand, preprending them
> with "explain analyze"?
>

no, it is not possible

http://blog.guillaume.lelarge.info/index.php/post/2012/03/31/Profiling-PL/pgsql-functions

or autoexplain with active auto_explain.log_nested_statements

Regards

Pavel Stehule

> My code is below, thanks for any advices
>
> Regards
> Alex
>
>         create or replace function pref_delete_user(_id varchar,
>             _reason varchar) returns void as $BODY$
>                 begin
>
>                 insert into pref_ban2 select
>                         id,
>                         first_name,
>                         last_name,
>                         city,
>                         last_ip
>                 from pref_users where id=_id;
>
>                 update pref_ban2 set reason=_reason where id=_id;
>
>                 create temporary table temp_gids (gid int not null) on
> commit drop;
>                 insert into temp_gids (gid) select gid from
> pref_scores where id=_id;
>
>                 delete from pref_games p
>                 using temp_gids t
>                 where p.gid = t.gid;
>
>                 create temporary table temp_rids (rid int not null) on
> commit drop;
>                 insert into temp_rids (rid) select rid from pref_cards
> where id=_id;
>
>                 delete from pref_rounds r
>                 using temp_rids t
>                 where r.rid = t.rid;
>
>                 delete from pref_users where id=_id;
>
>                 end;
>         $BODY$ language plpgsql;
>
>         create table pref_users (
>                 id varchar(32) primary key,
>                 first_name varchar(64),
>                 last_name varchar(64),
>                 female boolean,
>                 avatar varchar(128),
>                 city varchar(64),
>                 login timestamp default current_timestamp,
>                 logout timestamp,
>                 last_ip inet,
>                 vip timestamp,
>                 mail varchar(256),
>                 medals integer not null default 0
>         );
>
>         create table pref_rounds (
>                 rid serial primary key,
>                 cards text,
>                 stamp timestamp default current_timestamp
>         );
>
>         create table pref_cards (
>                 rid integer references pref_rounds on delete cascade,
>                 id varchar(32) references pref_users on delete cascade,
>                 bid varchar(32) not null,
>                 trix integer not null,
>                 pos integer not null,
>                 money integer not null,
>                 last_ip inet,
>                 quit boolean,
>                 stamp timestamp default current_timestamp,
>                 primary key(id, rid)               /* added recently */
>         );
>
>         create table pref_games (
>                 gid serial primary key,
>                 rounds integer not null,
>                 stamp timestamp default current_timestamp
>         );
>
>         create table pref_scores (
>                 id varchar(32) references pref_users on delete cascade,
>                 gid integer references pref_games on delete cascade,
>                 money integer not null,
>                 last_ip inet,
>                 quit boolean,
>                 primary key(id, gid);              /* added recently */
>         );
>
>         create table pref_ban2 (
>                 id varchar(32) primary key,  /* not a foreign key,
> since banned */
>                 first_name varchar(64),
>                 last_name varchar(64),
>                 city varchar(64),
>                 last_ip inet,
>                 reason varchar(128),
>                 created timestamp default current_timestamp
>         );
>
>
> --
> Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-general

On 6 February 2013 11:03, Alexander Farber <alexander.farber@gmail.com>wrote:

>                 begin
>
>                 insert into pref_ban2 select
>                         id,
>                         first_name,
>                         last_name,
>                         city,
>                         last_ip
>                 from pref_users where id=_id;
>
>                 update pref_ban2 set reason=_reason where id=_id;
>

It's not the answer to your query, but why don't you do the above in a
single statement?

--
If you can't see the forest for the trees,
Cut the trees and you'll see there is no forest.

Thank you for the replies -

Using a shared library seemed too difficult
for me at this moment, so I've prepended
"explain analyze" to each query in my proc
and the worst offender is this one:

# explain analyze delete from pref_rounds r
                 using temp_rids t
                 where r.rid = t.rid;
                                                                QUERY PLAN

------------------------------------------------------------------------------------------------------------------
------------------------
 Nested Loop  (cost=0.00..20270.01 rows=2880 width=6) (actual
time=4.246..120.058 rows=3022 loops=1)
   ->  Seq Scan on temp_rids t  (cost=0.00..40.80 rows=2880 width=4)
(actual time=0.008..1.194 rows=3022 loops=1)
   ->  Index Scan using pref_rounds_pkey on pref_rounds r
(cost=0.00..7.01 rows=1 width=10) (actual time=0.037..0
.038 rows=1 loops=3022)
         Index Cond: (r.rid = t.rid)
 Trigger for constraint pref_cards_rid_fkey: time=1106450.109 calls=3022
 Trigger for constraint pref_discuss_rid_fkey: time=171.322 calls=3022
 Trigger for constraint pref_votes_rid_fkey: time=85.484 calls=3022
 Total runtime: 1107082.899 ms
(8 rows)

So it probably spends most of its time
in the pref_cards, thorugh the FK "rid"?

Which index would be to add here best?

Regards
Alex

On Wed, Feb 6, 2013 at 11:03 AM, Alexander Farber >
>         create or replace function pref_delete_user(_id varchar,
>             _reason varchar) returns void as $BODY$
>                 begin
>
>                 insert into pref_ban2 select
>                         id,
>                         first_name,
>                         last_name,
>                         city,
>                         last_ip
>                 from pref_users where id=_id;
>
>                 update pref_ban2 set reason=_reason where id=_id;
>
>                 create temporary table temp_gids (gid int not null) on
> commit drop;
>                 insert into temp_gids (gid) select gid from
> pref_scores where id=_id;
>
>                 delete from pref_games p
>                 using temp_gids t
>                 where p.gid = t.gid;
>
>                 create temporary table temp_rids (rid int not null) on
> commit drop;
>                 insert into temp_rids (rid) select rid from pref_cards
> where id=_id;
>
>                 delete from pref_rounds r
>                 using temp_rids t
>                 where r.rid = t.rid;
>
>                 delete from pref_users where id=_id;
>
>                 end;
>         $BODY$ language plpgsql;
>
>         create table pref_users (
>                 id varchar(32) primary key,
>                 first_name varchar(64),
>                 last_name varchar(64),
>                 female boolean,
>                 avatar varchar(128),
>                 city varchar(64),
>                 login timestamp default current_timestamp,
>                 logout timestamp,
>                 last_ip inet,
>                 vip timestamp,
>                 mail varchar(256),
>                 medals integer not null default 0
>         );
>
>         create table pref_rounds (
>                 rid serial primary key,
>                 cards text,
>                 stamp timestamp default current_timestamp
>         );
>
>         create table pref_cards (
>                 rid integer references pref_rounds on delete cascade,
>                 id varchar(32) references pref_users on delete cascade,
>                 bid varchar(32) not null,
>                 trix integer not null,
>                 pos integer not null,
>                 money integer not null,
>                 last_ip inet,
>                 quit boolean,
>                 stamp timestamp default current_timestamp,
>                 primary key(id, rid)               /* added recently */
>         );
>
>         create table pref_games (
>                 gid serial primary key,
>                 rounds integer not null,
>                 stamp timestamp default current_timestamp
>         );
>
>         create table pref_scores (
>                 id varchar(32) references pref_users on delete cascade,
>                 gid integer references pref_games on delete cascade,
>                 money integer not null,
>                 last_ip inet,
>                 quit boolean,
>                 primary key(id, gid);              /* added recently */
>         );
>
>         create table pref_ban2 (
>                 id varchar(32) primary key,  /* not a foreign key,
> since banned */
>                 first_name varchar(64),
>                 last_name varchar(64),
>                 city varchar(64),
>                 last_ip inet,
>                 reason varchar(128),
>                 created timestamp default current_timestamp
>         );

This seems to have helped:

# create index pref_cards_rid_index on pref_cards(rid);
CREATE INDEX

# \d pref_cards;
               Table "public.pref_cards"
 Column  |            Type             |   Modifiers
---------+-----------------------------+---------------
 rid     | integer                     | not null
 id      | character varying(32)       | not null
 bid     | character varying(32)       | not null
 trix    | integer                     | not null
 pos     | integer                     | not null
 money   | integer                     | not null
 last_ip | inet                        |
 quit    | boolean                     |
 stamp   | timestamp without time zone | default now()
Indexes:
    "pref_cards_pkey" PRIMARY KEY, btree (id, rid)
    "pref_cards_rid_index" btree (rid)
Foreign-key constraints:
    "pref_cards_id_fkey" FOREIGN KEY (id) REFERENCES pref_users(id) ON
DELETE CASCADE
    "pref_cards_rid_fkey" FOREIGN KEY (rid) REFERENCES
pref_rounds(rid) ON DELETE CASCADE

# explain analyze delete from pref_rounds r
                using temp_rids t
                where r.rid = t.rid;
                                                                QUERY PLAN

------------------------------------------------------------------------------------------------------------------
------------------------
 Nested Loop  (cost=0.00..20270.01 rows=2880 width=6) (actual
time=0.110..117.658 rows=3022 loops=1)
   ->  Seq Scan on temp_rids t  (cost=0.00..40.80 rows=2880 width=4)
(actual time=0.047..1.413 rows=3022 loops=1)
   ->  Index Scan using pref_rounds_pkey on pref_rounds r
(cost=0.00..7.01 rows=1 width=10) (actual time=0.036..0
.037 rows=1 loops=3022)
         Index Cond: (r.rid = t.rid)
 Trigger for constraint pref_cards_rid_fkey: time=762.161 calls=3022
 Trigger for constraint pref_discuss_rid_fkey: time=115.801 calls=3022
 Trigger for constraint pref_votes_rid_fkey: time=74.814 calls=3022
 Total runtime: 1316.472 ms
(8 rows)

On Thu, Feb 7, 2013 at 11:34 AM, Alexander Farber
<alexander.farber@gmail.com> wrote:
> # explain analyze delete from pref_rounds r
>                  using temp_rids t
>                  where r.rid = t.rid;
>                                                                 QUERY PLAN
>
> ------------------------------------------------------------------------------------------------------------------
> ------------------------
>  Nested Loop  (cost=0.00..20270.01 rows=2880 width=6) (actual
> time=4.246..120.058 rows=3022 loops=1)
>    ->  Seq Scan on temp_rids t  (cost=0.00..40.80 rows=2880 width=4)
> (actual time=0.008..1.194 rows=3022 loops=1)
>    ->  Index Scan using pref_rounds_pkey on pref_rounds r
> (cost=0.00..7.01 rows=1 width=10) (actual time=0.037..0
> .038 rows=1 loops=3022)
>          Index Cond: (r.rid = t.rid)
>  Trigger for constraint pref_cards_rid_fkey: time=1106450.109 calls=3022
>  Trigger for constraint pref_discuss_rid_fkey: time=171.322 calls=3022
>  Trigger for constraint pref_votes_rid_fkey: time=85.484 calls=3022
>  Total runtime: 1107082.899 ms
> (8 rows)
>
> So it probably spends most of its time
> in the pref_cards, thorugh the FK "rid"?
>
> Which index would be to add here best?
>
> Regards
> Alex
>
> On Wed, Feb 6, 2013 at 11:03 AM, Alexander Farber >
>>         create or replace function pref_delete_user(_id varchar,
>>             _reason varchar) returns void as $BODY$
>>                 begin
>>
>>                 insert into pref_ban2 select
>>                         id,
>>                         first_name,
>>                         last_name,
>>                         city,
>>                         last_ip
>>                 from pref_users where id=_id;
>>
>>                 update pref_ban2 set reason=_reason where id=_id;
>>
>>                 create temporary table temp_gids (gid int not null) on
>> commit drop;
>>                 insert into temp_gids (gid) select gid from
>> pref_scores where id=_id;
>>
>>                 delete from pref_games p
>>                 using temp_gids t
>>                 where p.gid = t.gid;
>>
>>                 create temporary table temp_rids (rid int not null) on
>> commit drop;
>>                 insert into temp_rids (rid) select rid from pref_cards
>> where id=_id;
>>
>>                 delete from pref_rounds r
>>                 using temp_rids t
>>                 where r.rid = t.rid;
>>
>>                 delete from pref_users where id=_id;
>>
>>                 end;
>>         $BODY$ language plpgsql;
>>
>>         create table pref_users (
>>                 id varchar(32) primary key,
>>                 first_name varchar(64),
>>                 last_name varchar(64),
>>                 female boolean,
>>                 avatar varchar(128),
>>                 city varchar(64),
>>                 login timestamp default current_timestamp,
>>                 logout timestamp,
>>                 last_ip inet,
>>                 vip timestamp,
>>                 mail varchar(256),
>>                 medals integer not null default 0
>>         );
>>
>>         create table pref_rounds (
>>                 rid serial primary key,
>>                 cards text,
>>                 stamp timestamp default current_timestamp
>>         );
>>
>>         create table pref_cards (
>>                 rid integer references pref_rounds on delete cascade,
>>                 id varchar(32) references pref_users on delete cascade,
>>                 bid varchar(32) not null,
>>                 trix integer not null,
>>                 pos integer not null,
>>                 money integer not null,
>>                 last_ip inet,
>>                 quit boolean,
>>                 stamp timestamp default current_timestamp,
>>                 primary key(id, rid)               /* added recently */
>>         );
>>
>>         create table pref_games (
>>                 gid serial primary key,
>>                 rounds integer not null,
>>                 stamp timestamp default current_timestamp
>>         );
>>
>>         create table pref_scores (
>>                 id varchar(32) references pref_users on delete cascade,
>>                 gid integer references pref_games on delete cascade,
>>                 money integer not null,
>>                 last_ip inet,
>>                 quit boolean,
>>                 primary key(id, gid);              /* added recently */
>>         );
>>
>>         create table pref_ban2 (
>>                 id varchar(32) primary key,  /* not a foreign key,
>> since banned */
>>                 first_name varchar(64),
>>                 last_name varchar(64),
>>                 city varchar(64),
>>                 last_ip inet,
>>                 reason varchar(128),
>>                 created timestamp default current_timestamp
>>         );