Thread: Inefficient filter order in query plan
I'd like to understand why PostgreSQL is choosing to filter on the most inefficient predicate first in the query below.
Version: PostgreSQL 9.3.2 on x86_64-unknown-linux-gnu, compiled by gcc (SUSE Linux) 4.7.1 20120723 [gcc-4_7-branch revision 189773], 64-bit
Hardware: 24 2.93GHz Xeon cores and 32GB RAM
Table in question:
------------------------------------------------------------
CREATE TABLE audit_trail (
id int PRIMARY KEY NOT NULL,
model varchar(128) NOT NULL,
model_id int NOT NULL,
created bool,
updated bool,
deleted bool,
change_set text,
created_by varchar(64) NOT NULL,
created_date timestamp NOT NULL,
updated_by varchar(64) NOT NULL,
updated_date timestamp NOT NULL
);
CREATE UNIQUE INDEX audit_trail_pkey ON audit_trail(id);
Row count: 5,306,596
Min / Avg / Max character length of change_set column values: 11 / 165 / 12717859
Number of unique values in model column: 196
Query and plan:
------------------------------------------------------------
SET track_io_timing = on;
EXPLAIN (ANALYZE, BUFFERS)
SELECT * FROM audit_trail WHERE model = 'User' AND model_id = 304 AND change_set ILIKE '%test%';
Seq Scan on audit_trail (cost=0.00..243427.98 rows=1 width=189) (actual time=15509.722..17943.896 rows=6 loops=1)
Filter: ((change_set ~~* '%test%'::text) AND ((model)::text = 'User'::text) AND (model_id = 304))
Rows Removed by Filter: 5306590
Buffers: shared hit=10410 read=164384
I/O Timings: read=310.189
Total runtime: 17943.930 ms
Observations:
------------------------------------------------------------
1) Without the change_set predicate, the query runs in 1 second and returns 461 rows.
2) Turning statistics off for the change_set column has no effect on the plan or execution time:
ALTER TABLE audit_trail ALTER COLUMN change_set SET STATISTICS 0;
ANALYZE audit_trail(change_set);
3) Setting statistics to the max value has no effect on the plan or execution time:
ALTER TABLE audit_trail ALTER COLUMN change_set SET STATISTICS 10000;
ANALYZE audit_trail(change_set);
4) Adding an index on (model, model_id) changes the plan so that it starts with an index scan. Query time < 1s.
CREATE INDEX audit_trail_model_idx ON audit_trail (model, model_id);
Aggregate (cost=12.29..12.30 rows=1 width=4) (actual time=1.455..1.456 rows=1 loops=1)
-> Index Scan using audit_trail_model_idx on audit_trail this_ (cost=0.56..12.29 rows=1 width=4) (actual time=1.446..1.446 rows=0 loops=1)
Index Cond: (((model)::text = 'User'::text) AND (model_id = 304))
Filter: (change_set ~~* '%test%'::text)
Rows Removed by Filter: 461
Although adding the index will fix the performance problem, I'd like to understand why, in absence of the index, PostgreSQL would choose to filter on the change_set value first. Since it is not specified first in the predicate and its column ordinality is higher than model and model_id, the plan generator must be choosing it first for some particular reason.
Any insight is appreciated.
Version: PostgreSQL 9.3.2 on x86_64-unknown-linux-gnu, compiled by gcc (SUSE Linux) 4.7.1 20120723 [gcc-4_7-branch revision 189773], 64-bit
Hardware: 24 2.93GHz Xeon cores and 32GB RAM
Table in question:
------------------------------------------------------------
CREATE TABLE audit_trail (
id int PRIMARY KEY NOT NULL,
model varchar(128) NOT NULL,
model_id int NOT NULL,
created bool,
updated bool,
deleted bool,
change_set text,
created_by varchar(64) NOT NULL,
created_date timestamp NOT NULL,
updated_by varchar(64) NOT NULL,
updated_date timestamp NOT NULL
);
CREATE UNIQUE INDEX audit_trail_pkey ON audit_trail(id);
Row count: 5,306,596
Min / Avg / Max character length of change_set column values: 11 / 165 / 12717859
Number of unique values in model column: 196
Query and plan:
------------------------------------------------------------
SET track_io_timing = on;
EXPLAIN (ANALYZE, BUFFERS)
SELECT * FROM audit_trail WHERE model = 'User' AND model_id = 304 AND change_set ILIKE '%test%';
Seq Scan on audit_trail (cost=0.00..243427.98 rows=1 width=189) (actual time=15509.722..17943.896 rows=6 loops=1)
Filter: ((change_set ~~* '%test%'::text) AND ((model)::text = 'User'::text) AND (model_id = 304))
Rows Removed by Filter: 5306590
Buffers: shared hit=10410 read=164384
I/O Timings: read=310.189
Total runtime: 17943.930 ms
Observations:
------------------------------------------------------------
1) Without the change_set predicate, the query runs in 1 second and returns 461 rows.
2) Turning statistics off for the change_set column has no effect on the plan or execution time:
ALTER TABLE audit_trail ALTER COLUMN change_set SET STATISTICS 0;
ANALYZE audit_trail(change_set);
3) Setting statistics to the max value has no effect on the plan or execution time:
ALTER TABLE audit_trail ALTER COLUMN change_set SET STATISTICS 10000;
ANALYZE audit_trail(change_set);
4) Adding an index on (model, model_id) changes the plan so that it starts with an index scan. Query time < 1s.
CREATE INDEX audit_trail_model_idx ON audit_trail (model, model_id);
Aggregate (cost=12.29..12.30 rows=1 width=4) (actual time=1.455..1.456 rows=1 loops=1)
-> Index Scan using audit_trail_model_idx on audit_trail this_ (cost=0.56..12.29 rows=1 width=4) (actual time=1.446..1.446 rows=0 loops=1)
Index Cond: (((model)::text = 'User'::text) AND (model_id = 304))
Filter: (change_set ~~* '%test%'::text)
Rows Removed by Filter: 461
Although adding the index will fix the performance problem, I'd like to understand why, in absence of the index, PostgreSQL would choose to filter on the change_set value first. Since it is not specified first in the predicate and its column ordinality is higher than model and model_id, the plan generator must be choosing it first for some particular reason.
Any insight is appreciated.
Tom Coogan <nocera@gmail.com> writes: > I'd like to understand why PostgreSQL is choosing to filter on the most > inefficient predicate first in the query below. It doesn't know that LIKE is any more expensive than the other operators, so there's no reason to do them in any particular order. You could try increasing the cost attributed to the texticlike() function if you don't like the results you're getting here. regards, tom lane
* Tom Lane (tgl@sss.pgh.pa.us) wrote: > Tom Coogan <nocera@gmail.com> writes: > > I'd like to understand why PostgreSQL is choosing to filter on the most > > inefficient predicate first in the query below. > > It doesn't know that LIKE is any more expensive than the other operators, > so there's no reason to do them in any particular order. > > You could try increasing the cost attributed to the texticlike() function > if you don't like the results you're getting here. Perhaps we should be attributing some additional cost to operations which (are likely to) require de-TOAST'ing a bunch of values? It's not obvious from the original email, but it's at least my suspicion that the difference is amplified due to de-TOAST'ing of the values in that text column, in addition to the straight-up function execution time differences. Costing integer (or anything that doesn't require pointer maniuplations) operations as cheaper than text-based operations also makes sense to me, even though of course there's more things happening when we do these comparisons than the simple CPU-level act of doing the cmp. Thanks, Stephen
Attachment
Stephen Frost <sfrost@snowman.net> writes: > * Tom Lane (tgl@sss.pgh.pa.us) wrote: >> You could try increasing the cost attributed to the texticlike() function >> if you don't like the results you're getting here. > Perhaps we should be attributing some additional cost to operations > which (are likely to) require de-TOAST'ing a bunch of values? It's not > obvious from the original email, but it's at least my suspicion that the > difference is amplified due to de-TOAST'ing of the values in that text > column, in addition to the straight-up function execution time > differences. Could be. We've discussed adding some charge for touching likely-to-be-toasted columns in the past, but nobody's done anything about it. Note that I'd rather see that implemented as a nonzero cost for Vars than as a charge for functions per se. > Costing integer (or anything that doesn't require pointer maniuplations) > operations as cheaper than text-based operations also makes sense to me, > even though of course there's more things happening when we do these > comparisons than the simple CPU-level act of doing the cmp. Right. We've bumped up the cost numbers for some extremely expensive functions, but I would like to have some actual data rather than just seat of the pants guesses before we go fooling with the standard CPU cost estimates for things at the level of regex matches. regards, tom lane
On Thu, Feb 27, 2014 at 12:04 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote: > > It doesn't know that LIKE is any more expensive than the other operators, > so there's no reason to do them in any particular order. > Thanks Tom but why would strict equality checking (e.g. model = 'User') have the same cost as LIKE operations which (may) have to do pattern matching? I understand from the optimizer's perspective that the actual cost could be equivalent depending upon what value is searched (and the optimizer wouldn't know that value ahead of time). But doesn't the potential for pattern matching warrant some difference in cost? From my experience, LIKE is almost always used with some form of pattern match in the supplied value. On Thu, Feb 27, 2014 at 1:24 PM, Stephen Frost <sfrost@snowman.net> wrote: > > Perhaps we should be attributing some additional cost to operations > which (are likely to) require de-TOAST'ing a bunch of values? It's not > obvious from the original email, but it's at least my suspicion that the > difference is amplified due to de-TOAST'ing of the values in that text > column, in addition to the straight-up function execution time > differences. Let me know if this is the wrong way to find this information but it doesn't appear that any values in this particular table are TOAST'ed: SELECT oid, relname, reltoastrelid, relpages FROM pg_class WHERE relname = 'audit_trail' OR oid = 7971231; oid | relname | reltoastrelid | relpages ---------+------------------+---------------+---------- 7971228 | audit_trail | 7971231 | 150502 7971231 | pg_toast_7971228 | 0 | 0
Tom Coogan <nocera@gmail.com> writes: > Thanks Tom but why would strict equality checking (e.g. model = > 'User') have the same cost as LIKE operations which (may) have to do > pattern matching? A bit of consultation of pg_proc.procost will show you that just about the only internal functions with costs different from 1X cpu_operator_cost are those that do some sort of database access (and, in consequence, have true costs a couple orders of magnitude higher than a simple comparison). We may eventually get around to refining the cost model so that it can tell the difference between = and LIKE, but nobody's yet done the work to decide which functions ought to get assigned what costs. I'm disinclined to single out LIKE for special treatment in the absence of some sort of framework for deciding which functions are worth penalizing. regards, tom lane
On Thu, Feb 27, 2014 at 3:47 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote: > A bit of consultation of pg_proc.procost will show you that just about > the only internal functions with costs different from 1X cpu_operator_cost > are those that do some sort of database access (and, in consequence, have > true costs a couple orders of magnitude higher than a simple comparison). > We may eventually get around to refining the cost model so that it can > tell the difference between = and LIKE, but nobody's yet done the work > to decide which functions ought to get assigned what costs. I'm > disinclined to single out LIKE for special treatment in the absence of > some sort of framework for deciding which functions are worth penalizing. > > regards, tom lane I agree that LIKE should not be singled out for special treatment since the cost values should be determined with respect to all other operators and not just one. My original question still remained though. The clause order of my predicate is being re-arranged due to factors unrelated to cost: Predicate: model = 'User' AND model_id = 304 AND change_set ILIKE '%test%' --> Plan filter: (change_set ~~* '%test%'::text) AND ((model)::text = 'User'::text) AND (model_id = 304) For anyone looking for an answer to a similar question in the future, the following is summary of why this appears to be happening. Using PostgreSQL 9.1.12 source: /src/backend/optimizer/plan/planmain.c:193 - A call to deconstruct_jointree(PlannerInfo *root) is made. The jointree inside of root still has the clause order preserved. /src/backend/optimizer/plan/initsplan.c:259 - A call to deconstruct_recurse(PlannerInfo *root, Node *jtnode, ....) is made. /src/backend/optimizer/plan/initsplan.c:353 - The quals are looped over and a call to distribute_qual_to_rels(PlannerInfo *root, Node *clause, ....) is made for each. /src/backend/optimizer/plan/initsplan.c:1099 - LIKE and equivalence clauses are handled differently. - Equivalence clauses are encountered first in my scenario and get processed by process_equivalence() on line 1104. return is then immediately called. - A comment explains that equivalence clauses will be added to the restriction list at a later time: "If it is a true equivalence clause, send it to the EquivalenceClass machinery. We do *not* attach it directly to any restriction or join lists. The EC code will propagate it to the appropriate places later." - The LIKE clause is last and gets processed by distribute_restrictinfo_to_rels on line 1152. - Unlike equivalences, this results in the LIKE clause getting added to the restriction list immediately and therefore is first in the list. /src/backend/optimizer/plan/planmain.c:207 - Equivalence clauses finally get added to the restriction list via a call to generate_base_implied_equalities(PlannerInfo *root) I don't understand the reason for delaying the addition of equivalence clauses to the restriction list but, for whatever reason, it appears to be by design.