Thread: "explain analyze" a procedure verbosely - to find which statement in it takes longer
"explain analyze" a procedure verbosely - to find which statement in it takes longer
From
Alexander Farber
Date:
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
);
Re: "explain analyze" a procedure verbosely - to find which statement in it takes longer
From
Pavel Stehule
Date:
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
Re: "explain analyze" a procedure verbosely - to find which statement in it takes longer
From
Alban Hertroys
Date:
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.
Re: "explain analyze" a procedure verbosely - to find which statement in it takes longer
From
Alexander Farber
Date:
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
> );
Re: "explain analyze" a procedure verbosely - to find which statement in it takes longer
From
Alexander Farber
Date:
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
>> );