Re: Postgres query completion status? - Mailing list 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!]


Richard






-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  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 =
core.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, core.material.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 =
(product_info_sku.sid)::text)
                      ->  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
loops=1)
                                  Hash Cond: ((wave_gol.sid)::text =
(product_info_sku.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)
                                                                Filter:
is_previous
                                                          ->  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)
                                                                Recheck
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: (core.demand.id = core.demand.id)
  Total runtime: 253455.603 ms
(41 rows)