Skip site navigation (1) Skip section navigation (2)

Re: Postgres query completion status?

From: Richard Neill <rn214(at)cam(dot)ac(dot)uk>
To: Richard Neill <rn214(at)cam(dot)ac(dot)uk>
Cc: Greg Williamson <gwilliamson39(at)yahoo(dot)com>, pgsql-performance(at)postgresql(dot)org
Subject: Re: Postgres query completion status?
Date: 2009-11-20 07:03:04
Message-ID: (view raw or flat)
Lists: pgsql-performance
> Greg Williamson wrote:
>> Richard --
>>  You might post the results of "EXPLAIN ANALYZE <your SQL here>;" ... 
>> be sure to run it in a transaction if you want to be able roll it 
>> back. Perhaps try "EXPLAIN <your SQL>;" first as it is faster, but 
>> EXPLAIN ANALYZE shows what the planner is doing.

Here's something very very odd.
Explain Analyze has now run, in about 4 minutes.  (result below)

However, I'd be willing to swear that the last time I ran explain on 
this query about half an hour ago, the final 2 lines were sequential scans.

So, I've just terminated the real job (which uses this select for an 
update) after 77 minutes of fruitless cpu-hogging, and re-started it....

...This time, the same job ran through in 24 minutes.
[This is running exactly the same transaction on exactly the same data!]


  Nested Loop  (cost=885367.03..1123996.87 rows=8686 width=12) (actual 
time=248577.879..253168.466 rows=347308 loops=1)
    ->  Merge Join  (cost=885367.03..1115452.17 rows=8688 width=16) 
(actual time=248577.834..252092.536 rows=347308 loops=1)
          Merge Cond: ((core.demand.target_id = 
wave_genreorders_map.target_id) AND (core.demand.material_id =
          ->  Index Scan using demand_target_id_key on demand 
(cost=0.00..186520.46 rows=3800715 width=24) (actual 
time=0.031..2692.661 rows=3800715 loops=1)
          ->  Sort  (cost=885364.61..893425.30 rows=3224275 width=24) 
(actual time=248577.789..248659.751 rows=347308 loops=1)
                Sort Key: wave_genreorders_map.target_id,
                Sort Method:  quicksort  Memory: 39422kB
                ->  Hash Join  (cost=511934.12..536811.73 rows=3224275 
width=24) (actual time=247444.988..248263.151 rows=347308 loops=1)
                      Hash Cond: (core.material.tag = 
                      ->  Append  (cost=0.00..10723.27 rows=689377 
width=28) (actual time=0.008..177.076 rows=690647 loops=1)
                            ->  Seq Scan on material 
(cost=0.00..5474.75 rows=397675 width=21) (actual time=0.008..59.234 
rows=395551 loops=1)
                            ->  Seq Scan on container material 
(cost=0.00..5248.52 rows=291702 width=37) (actual time=0.008..52.844 
rows=295096 loops=1)
                      ->  Hash  (cost=506657.25..506657.25 rows=422149 
width=42) (actual time=247444.555..247444.555 rows=347308 loops=1)
                            ->  Hash Join  (cost=474610.85..506657.25 
rows=422149 width=42) (actual time=182224.904..247282.711 rows=347308 
                                  Hash Cond: ((wave_gol.sid)::text = 
                                  ->  Merge Left Join 
(cost=463919.35..487522.78 rows=422149 width=29) (actual 
time=182025.065..246638.762 rows=347308 loops=1)
                                        Merge Cond: 
(((wave_gol.wid)::text = (du_report_sku.wid)::text) AND 
((wave_gol.storeorderid)::text = (du_report_sku.storeorderid)::text) AND 
((wave_gol.genreorderid)::text = (du_report_sku.genreorderid)::text))
                                        Join Filter: 
((wave_gol.sid)::text = (du_report_sku.sid)::text)
                                        ->  Merge Join 
(cost=183717.70..197229.24 rows=422149 width=44) (actual 
time=859.551..1506.515 rows=347308 loops=1)
                                              Merge Cond: 
(((wave_genreorders_map.wid)::text = (wave_gol.wid)::text) AND 
((wave_genreorders_map.storeorderid)::text = 
(wave_gol.storeorderid)::text) AND 
((wave_genreorders_map.genreorderid)::text = (wave_gol.genreorderid)::text))
                                              ->  Index Scan using 
"wave_genreorders_map_ERR_GENREORDERID_EXISTS" on wave_genreorders_map 
(cost=0.00..4015.36 rows=116099 width=27) (actual time=0.018..23.599 
rows=116099 loops=1)
                                              ->  Sort 
(cost=183717.70..184818.90 rows=440483 width=47) (actual 
time=782.102..813.753 rows=347308 loops=1)
                                                    Sort Key: 
wave_gol.wid, wave_gol.storeorderid, wave_gol.genreorderid
                                                    Sort Method: 
quicksort  Memory: 39422kB
                                                    ->  Nested Loop 
(cost=9769.36..142425.22 rows=440483 width=47) (actual 
time=33.668..138.668 rows=347308 loops=1)
                                                          ->  Index Scan 
using "wave_rxw_ERR_WID_EXISTS" on wave_rxw  (cost=0.00..7.08 rows=1 
width=11) (actual time=0.021..0.031 rows=1 loops=1)
                                                          ->  Bitmap 
Heap Scan on wave_gol  (cost=9769.36..136912.11 rows=440483 width=36) 
(actual time=33.628..75.091 rows=347308 loops=1)
Cond: ((wave_gol.wid)::text = (wave_rxw.wid)::text)
Bitmap Index Scan on "wave_gol_ERR_SID_EXISTS"  (cost=0.00..9659.24 
rows=440483 width=0) (actual time=33.104..33.104 rows=347308 loops=1)
Index Cond: ((wave_gol.wid)::text = (wave_rxw.wid)::text)
                                        ->  Sort 
(cost=280201.66..281923.16 rows=688602 width=300) (actual 
time=177511.806..183486.593 rows=41317448 loops=1)
                                              Sort Key: 
du_report_sku.wid, du_report_sku.storeorderid, du_report_sku.genreorderid
                                              Sort Method:  external 
sort  Disk: 380768kB
                                              ->  HashAggregate 
(cost=197936.75..206544.27 rows=688602 width=36) (actual 
time=7396.426..11224.839 rows=6282564 loops=1)
                                                    ->  Seq Scan on 
du_report_sku  (cost=0.00..111861.61 rows=6886011 width=36) (actual 
time=0.006..573.419 rows=6897682 loops=1)
                                  ->  Hash  (cost=5681.22..5681.22 
rows=400822 width=13) (actual time=199.422..199.422 rows=400737 loops=1)
                                        ->  Seq Scan on product_info_sku 
  (cost=0.00..5681.22 rows=400822 width=13) (actual time=0.004..78.357 
rows=400737 loops=1)
    ->  Index Scan using demand_pkey on demand  (cost=0.00..0.97 rows=1 
width=12) (actual time=0.002..0.003 rows=1 loops=347308)
          Index Cond: ( =
  Total runtime: 253455.603 ms
(41 rows)

In response to


pgsql-performance by date

Next:From: Tom LaneDate: 2009-11-20 07:08:10
Subject: Re: Partitions and max_locks_per_transaction
Previous:From: Richard NeillDate: 2009-11-20 06:50:14
Subject: Re: Postgres query completion status?

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group