Обсуждение: "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
От
Alexander Farber
Дата:
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
От
Pavel Stehule
Дата:
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
От
Alban Hertroys
Дата:
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
От
Alexander Farber
Дата:
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
От
Alexander Farber
Дата:
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 >> );