Hi all;

I have a customer who currently uses an application which had become slow. After doing some digging, I found the slow query:


SELECT c.accno, c.description, c.link, c.category, ac.project_id, p.projectnumber,
       a.department_id, d.description AS department
FROM chart c JOIN acc_trans ac ON (ac.chart_id = c.id)
       JOIN ar a ON (a.id = ac.trans_id)
       LEFT JOIN project p ON (ac.project_id = p.id)
       LEFT JOIN department d ON (d.id = a.department_id)
WHERE a.customer_id = 11373 AND a.id IN (
       SELECT max(id) FROM ar WHERE customer_id = 11373
);

(reformatted for readability)

This is taking 10 seconds to run.

Interestingly, both the project and department tables are blank, and if I omit them, the query becomes:
SELECT c.accno, c.description, c.link, c.category, ac.project_id
FROM chart c JOIN acc_trans ac ON (ac.chart_id = c.id)
       JOIN ar a ON (a.id = ac.trans_id)
WHERE a.customer_id = 11373 AND a.id IN (
       SELECT max(id) FROM ar WHERE customer_id = 11373
);

This takes 139ms.  1% of the previous query.

The plan for the long query is:

QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------
Hash IN Join (cost=87337.25..106344.93 rows=41 width=118) (actual time=7615.843..9850.209 rows=10 loops=1)
  Hash Cond: ("outer".trans_id = "inner".max)
-> Merge Right Join (cost=86620.57..100889.85 rows=947598 width=126) (actual time=7408.830..9200.435 rows=177769 loops=1)
        Merge Cond: ("outer".id = "inner".department_id)
-> Index Scan using department_id_key on department d (cost=0.00..52.66
rows=1060 width=36) (actual time=0.090..0.090 rows=0 loops=1)
-> Sort (cost=86620.57..87067.55 rows=178792 width=94) (actual time=7408.709..7925.843 rows=177769 loops=1)
              Sort Key: a.department_id
-> Merge Right Join (cost=45871.18..46952.83 rows=178792 width=94) (actual time=4962.122..6671.319 rows=177769 loops=1)
                    Merge Cond: ("outer".id = "inner".project_id)
-> Index Scan using project_id_key on project p (cost=0.00..49.80 rows=800 width=36) (actual time=0.007..0.007 rows=0 loops=1) -> Sort (cost=45871.18..46318.16 rows=178792 width=62) (actual time=4962.084..5475.636 rows=177769 loops=1)
                          Sort Key: ac.project_id
-> Hash Join (cost=821.20..13193.43 rows=178792 width=62) (actual time=174.905..4295.685 rows=177769 loops=1)
                                Hash Cond: ("outer".chart_id = "inner".id)
-> Hash Join (cost=817.66..10508.02 rows=178791
width=20) (actual time=173.952..2840.824 rows=177769 loops=1)
Hash Cond: ("outer".trans_id = "inner".id) -> Seq Scan on acc_trans ac (cost=0.00..3304.38 rows=181538 width=12) (actual time=0.062..537.753 rows=181322 loops=1) -> Hash (cost=659.55..659.55 rows=22844 width=8) (actual time=173.625..173.625 rows=0 loops=1) -> Seq Scan on ar a (cost=0.00..659.55 rows=22844 width=8) (actual time=0.022..101.828 rows=22844 loops=1) Filter: (customer_id = 11373) -> Hash (cost=3.23..3.23 rows=123 width=50) (actual time=0.915..0.915 rows=0 loops=1) -> Seq Scan on chart c (cost=0.00..3.23 rows=123 width=50) (actual time=0.013..0.528 rows=123 loops=1) -> Hash (cost=716.67..716.67 rows=1 width=4) (actual time=129.037..129.037 rows=0 loops=1) -> Subquery Scan "IN_subquery" (cost=716.66..716.67 rows=1 width=4) (actual time=129.017..129.025 rows=1 loops=1) -> Aggregate (cost=716.66..716.66 rows=1 width=4) (actual time=129.008..129.011 rows=1 loops=1) -> Seq Scan on ar (cost=0.00..659.55 rows=22844 width=4) (actual time=0.020..73.266 rows=22844 loops=1)
                          Filter: (customer_id = 11373)
Total runtime: 9954.133 ms
(28 rows)

The shorter query's plan is:

QUERY PLAN --------------------------------------------------------------------------------------------------------------------------------------------------------- Hash Join (cost=728.42..732.96 rows=8 width=50) (actual time=130.908..131.593 rows=10 loops=1)
  Hash Cond: ("outer".id = "inner".chart_id)
-> Seq Scan on chart c (cost=0.00..3.23 rows=123 width=50) (actual time=0.006..0.361 rows=123 loops=1) -> Hash (cost=728.40..728.40 rows=8 width=8) (actual time=130.841..130.841 rows=0 loops=1) -> Nested Loop (cost=716.67..728.40 rows=8 width=8) (actual time=130.692..130.805 rows=10 loops=1) -> Nested Loop (cost=716.67..720.89 rows=1 width=8) (actual time=130.626..130.639 rows=1 loops=1) -> HashAggregate (cost=716.67..716.67 rows=1 width=4) (actual time=130.484..130.487 rows=1 loops=1) -> Subquery Scan "IN_subquery" (cost=716.66..716.67 rows=1 width=4) (actual time=130.455..130.464 rows=1 loops=1) -> Aggregate (cost=716.66..716.66 rows=1 width=4) (actual time=130.445..130.448 rows=1 loops=1) -> Seq Scan on ar (cost=0.00..659.55 rows=22844 width=4) (actual time=0.020..74.174 rows=22844 loops=1)
                                            Filter: (customer_id = 11373)
-> Index Scan using ar_id_key on ar a (cost=0.00..4.20 rows=1 width=4) (actual time=0.122..0.125 rows=1 loops=1)
                          Index Cond: (a.id = "outer".max)
                          Filter: (customer_id = 11373)
-> Index Scan using acc_trans_trans_id_key on acc_trans ac (cost=0.00..7.41 rows=8 width=12) (actual time=0.051..0.097 rows=10 loops=1)
                    Index Cond: ("outer".max = ac.trans_id)
Total runtime: 131.879 ms
(17 rows)

I am not sure if I want to remove support for the other two tables yet. However, I wanted to submit this here as a (possibly corner-) case where the plan seems to be far slower than it needs to be.

Best Wishes,
Chris Travers
Metatron Technology Consulting

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

Reply via email to