Thread: Force another plan.
I have some quite huge queries, inside functions, so debugging is kind of hard. But I have located the query that for some reason gets 4 times as slow after an analyze. Before analyze the plan for the query is this: Nested Loop (cost=16.80..34.33 rows=1 width=28) Join Filter: (ischildof(2, "outer".calendar) OR (hashed subplan)) -> Nested Loop (cost=0.00..11.66 rows=1 width=32) -> Index Scan using t_events_eventype on t_events e (cost=0.00..5.82 rows=1 width=28) Index Cond: (eventtype = 1) Filter: (rrfreq IS NOT NULL) -> Index Scan using t_entities_pkey on t_entities te (cost=0.00..5.83 rows=1 width=4) Index Cond: (te."ID" = "outer".entity) Filter: (partof = 'events'::name) -> Index Scan using t_entities_pkey on t_entities (cost=0.00..5.85 rows=1 width=4) Index Cond: (t_entities."ID" = "outer".entity) Filter: ((haveaccess(createdby, responsible, "class", false) OR CASE WHEN (partof = 'contacts'::name) THEN ischildof(ancestorof(me()), "ID") ELSE false END) AND (subplan)) SubPlan -> Function Scan on alleventoccurances (cost=0.00..12.50 rows=1000 width=8) SubPlan -> Seq Scan on t_attendees (cost=0.00..16.38 rows=170 width=4) Filter: ischildof(2, contact) In reality this takes approximately 1.0s in the general case. After an analyze the plan becomes: Nested Loop (cost=2.09..4.82 rows=1 width=28) Join Filter: ("inner"."ID" = "outer"."ID") -> Hash Join (cost=2.09..3.59 rows=1 width=32) Hash Cond: ("outer"."ID" = "inner".entity) Join Filter: (ischildof(2, "inner".calendar) OR (hashed subplan)) -> Seq Scan on t_entities (cost=0.00..1.46 rows=6 width=4) Filter: ((haveaccess(createdby, responsible, "class", false) OR CASE WHEN (partof = 'contacts'::name) THEN ischildof(ancestorof(me()), "ID") ELSE false END) AND (subplan)) SubPlan -> Function Scan on alleventoccurances (cost=0.00..12.50 rows=1000 width=8) -> Hash (cost=1.06..1.06 rows=2 width=28) -> Seq Scan on t_events e (cost=0.00..1.06 rows=2 width=28) Filter: ((rrfreq IS NOT NULL) AND (eventtype = 1)) SubPlan -> Seq Scan on t_attendees (cost=0.00..1.02 rows=1 width=4) Filter: ischildof(2, contact) -> Seq Scan on t_entities te (cost=0.00..1.16 rows=5 width=4) Filter: (partof = 'events'::name) This takes on approximately 4.5s. So obviously it has degraded. I count myself as a newbie here, so any hints on what goes on, why a plan might be chosen, and how I can make is better is appreciated. Naturally the I can provide scripts to set up all or parts of the database if anyone like. regards -- //Fredrik Olsson Treyst AB +46-(0)19-362182 fredrik.olsson@treyst.se
Fredrik Olsson <fredrik.olsson@treyst.se> writes: > I have some quite huge queries, inside functions, so debugging is kind > of hard. But I have located the query that for some reason gets 4 times > as slow after an analyze. Could we see EXPLAIN ANALYZE output for these cases, not just EXPLAIN? It seems a bit premature to be discussing ways to "force" a plan choice when you don't even have a clear idea what's going wrong. regards, tom lane
Tom Lane skrev: > Fredrik Olsson <fredrik.olsson@treyst.se> writes: > >> I have some quite huge queries, inside functions, so debugging is kind >> of hard. But I have located the query that for some reason gets 4 times >> as slow after an analyze. >> > > Could we see EXPLAIN ANALYZE output for these cases, not just EXPLAIN? > It seems a bit premature to be discussing ways to "force" a plan choice > when you don't even have a clear idea what's going wrong. > Sorry about that, my fault. Here comes EXPLAIN ANALYZE: Before VACUUM ANALYZE: === Nested Loop (cost=16.80..34.33 rows=1 width=28) (actual time=54.197..98.598 rows=1 loops=1) Join Filter: (ischildof(2, "outer".calendar) OR (hashed subplan)) -> Nested Loop (cost=0.00..11.66 rows=1 width=32) (actual time=0.307..0.458 rows=3 loops=1) -> Index Scan using t_events_eventype on t_events e (cost=0.00..5.82 rows=1 width=28) (actual time=0.241..0.307 rows=3 loops=1) Index Cond: (eventtype = 1) Filter: (rrfreq IS NOT NULL) -> Index Scan using t_entities_pkey on t_entities te (cost=0.00..5.83 rows=1 width=4) (actual time=0.035..0.039 rows=1 loops=3) Index Cond: (te."ID" = "outer".entity) Filter: (partof = 'events'::name) -> Index Scan using t_entities_pkey on t_entities (cost=0.00..5.85 rows=1 width=4) (actual time=28.445..28.447 rows=0 loops=3) Index Cond: (t_entities."ID" = "outer".entity) Filter: ((haveaccess(createdby, responsible, "class", false) OR CASE WHEN (partof = 'contacts'::name) THEN ischildof(ancestorof(me()), "ID") ELSE false END) AND (subplan)) SubPlan -> Function Scan on alleventoccurances (cost=0.00..12.50 rows=1000 width=8) (actual time=19.745..19.745 rows=0 loops=3) SubPlan -> Seq Scan on t_attendees (cost=0.00..16.38 rows=170 width=4) (actual time=0.422..0.447 rows=2 loops=1) Filter: ischildof(2, contact) Total runtime: 99.814 ms After VACUUM ANALYZE: === Nested Loop (cost=2.11..4.92 rows=1 width=28) (actual time=434.321..439.102 rows=1 loops=1) Join Filter: ("inner"."ID" = "outer"."ID") -> Hash Join (cost=2.11..3.67 rows=1 width=32) (actual time=434.001..438.775 rows=1 loops=1) Hash Cond: ("outer"."ID" = "inner".entity) Join Filter: (ischildof(2, "inner".calendar) OR (hashed subplan)) -> Seq Scan on t_entities (cost=0.00..1.49 rows=7 width=4) (actual time=404.539..409.302 rows=2 loops=1) Filter: ((haveaccess(createdby, responsible, "class", false) OR CASE WHEN (partof = 'contacts'::name) THEN ischildof(ancestorof(me()), "ID") ELSE false END) AND (subplan)) SubPlan -> Function Scan on alleventoccurances (cost=0.00..12.50 rows=1000 width=8) (actual time=27.871..27.871 rows=0 loops=14) -> Hash (cost=1.07..1.07 rows=3 width=28) (actual time=0.063..0.063 rows=3 loops=1) -> Seq Scan on t_events e (cost=0.00..1.07 rows=3 width=28) (actual time=0.023..0.034 rows=3 loops=1) Filter: ((rrfreq IS NOT NULL) AND (eventtype = 1)) SubPlan -> Seq Scan on t_attendees (cost=0.00..1.02 rows=1 width=4) (actual time=0.205..0.228 rows=2 loops=1) Filter: ischildof(2, contact) -> Seq Scan on t_entities te (cost=0.00..1.18 rows=6 width=4) (actual time=0.029..0.045 rows=6 loops=1) Filter: (partof = 'events'::name) Total runtime: 440.385 ms As I read it, the villain is the sequential sqan on t_entities with the huge filter; haveacces() ... And that is understandable, doing haveaccess() on all rows is not good. A much better solution in this case would be to first get the set that conforms to (partof = 'events'::name), that would reduce the set to a third. Secondly applying (eventtype=1) would reduce that to half. Then it is time to do the (haveaccess() ...). Perhaps a small explanation of the tables, and their intent is in order. What I have is one "master table" with entities (t_entitites), and two child tables t_contacts and t_events. In a perfect world rt_contacts and t_events would have inherited from t_entities as they share muuch data, but then I would not be able to have foreign key referencing just events, or just contacts. So instead every row in events and contacts have a corresponding one to one row in entities. The fourth table used in this query is t_attendees, that links well attendees for an event to contacts. Here goes a simplified example (SQL says more then 1000 words): CREATE TABLE t_entities ( "ID" integer PRIMARY KEY, "createdby" integer NOT NULL, "class" integer NOT NULL, -- Defines visibility for entity and is used by haveaccess() "partof" name NOT NULL ); CREATE TABLE t_contacts ( "entity" integer PRIMARY KEY REFERENCES t_entities ("ID"), "undercontact" integer REFERENCES t_contacts ("entity"), -- Tree structure, used by haveaccess() "name" varchar(48) ); ALTER TABLE t_entities ADD FOREIGN KEY ("createdby") REFERENCES t_contacts ("entity"); CREATE TABLE t_events ( "entity" integer PRIMARY KEY REFERENCES t_entities ("ID"), "calendar" integer NOT NULL REFERENCES t_entities ("ID"), "eventtype" integer NOT NULL, "start" timestamptz, "end" timestamptz ); CREATE TABLE t_attendees ( "event" integer NOT NULL REFERENCES t_events ("entity"), "contact" integer NOT NULL REFERENCES t_contacts ("entity"), PRIMARY KEY ("event", "contact") ); No user have privileges to select, update or delete in any of these tables. They are instead accessed with views that are made updatable using rules. These rules uses the function haveaccess() to sort out the rows that each user is allowed to see. Users are also contacts in the t_contacts table. Well the complete database, with a shell script for setting it up can as I said be provided if wanted. -- //Fredrik Olsson Treyst AB +46-(0)19-362182 fredrik.olsson@treyst.se
Fredrik Olsson <fredrik.olsson@treyst.se> writes: > -> Seq Scan on t_entities (cost=0.00..1.49 rows=7 width=4) > (actual time=404.539..409.302 rows=2 loops=1) > Filter: ((haveaccess(createdby, responsible, "class", > false) OR CASE WHEN (partof = 'contacts'::name) THEN > ischildof(ancestorof(me()), "ID") ELSE false END) AND (subplan)) > SubPlan > -> Function Scan on alleventoccurances > (cost=0.00..12.50 rows=1000 width=8) (actual time=27.871..27.871 rows=0 > loops=14) This seems to be your problem right here: evaluating that subplan for each row of t_entities is pretty expensive, and yet the planner's estimating a total cost of only 1.49 to run the scan. What PG version is this? AFAICT we've accounted for subplan costs in scan quals for a long time, certainly since 7.4. Can you put together a self-contained test case for this? regards, tom lane
Tom Lane skrev: > Fredrik Olsson <fredrik.olsson@treyst.se> writes: > >> -> Seq Scan on t_entities (cost=0.00..1.49 rows=7 width=4) >> (actual time=404.539..409.302 rows=2 loops=1) >> Filter: ((haveaccess(createdby, responsible, "class", >> false) OR CASE WHEN (partof = 'contacts'::name) THEN >> ischildof(ancestorof(me()), "ID") ELSE false END) AND (subplan)) >> SubPlan >> -> Function Scan on alleventoccurances >> (cost=0.00..12.50 rows=1000 width=8) (actual time=27.871..27.871 rows=0 >> loops=14) >> > > This seems to be your problem right here: evaluating that subplan for > each row of t_entities is pretty expensive, and yet the planner's > estimating a total cost of only 1.49 to run the scan. What PG version > is this? AFAICT we've accounted for subplan costs in scan quals for > a long time, certainly since 7.4. Can you put together a self-contained > test case for this? > > I have found the real bottle-neck, looks like I trusted PG to do a bit too much magic. Since all table accesses go through views, and the first 11 columns always look the same, I did a "proxy-view" to simplify my "real-views" to: SELECT pv.*, ... The "proxy-view" fetches from t_entities, and so does the "real-views" to do a filter on "partof". This resulted in two scans on t_entities when only one is needed. Skipping the "proxy-view" allows PG to chose the best plan for every case. I guess I stressed the optimizer a bit too far :). Is a self contained test-case for the old way with the "proxy-view" is still wanted? -- //Fredrik Olsson Treyst AB +46-(0)19-362182 fredrik.olsson@treyst.se
Fredrik Olsson <fredrik.olsson@treyst.se> writes: > Is a self contained test-case for the old way with the "proxy-view" is > still wanted? Yes, something still seems funny there. And for that matter it wasn't clear what was wrong with your proxy view, either. regards, tom lane