"explain analyze" a procedure verbosely - to find which statement in it takes longer

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

--
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
);

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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
);

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general