Thread: BUG #5649: strange (probably bugged) explain analyze output

The following bug has been logged online:

Bug reference:      5649
Logged by:          Maxim Boguk
Email address:      Maxim.Boguk@gmail.com
PostgreSQL version: 8.4.4
Operating system:   FreeBSD 7.2
Description:        strange (probably bugged) explain analyze output
Details:

I not sure it is actual bug. But it is look like bug for me in expain
analyze output (or even in plan but unlikely).

All tables was analyzed just before test. All statistic data look reasonable
good for me. Query plan is the same for the master and the slave servers so
it isn't some single server random error.

Here is details (most simplified version of very long analytical query where
effect can be observed):

EXPLAIN ANALYZE
SELECT
*
FROM resstat_2010_08
JOIN services
    ON resstat_2010_08.service_id=services.id
JOIN service_types
    ON service_types.shortname = services.shortname
LEFT JOIN plan_s
    ON  service_types.abonent_service=true
    AND plan_s.shortname=service_types.shortname
    AND resstat_2010_08.tarif_id=plan_s.tarif_id


          QUERY PLAN
----------------------------------------------------------------------------
----------------------------------------------------------------------------
--------------------------------
 Merge Left Join  (cost=85621.96..88523.79 rows=277396 width=572) (actual
time=20128.316..93314.317 rows=272430 loops=1)
   Merge Cond: ((resstat_2010_08.tarif_id = plan_s.tarif_id) AND
((service_types.shortname)::text = (plan_s.shortname)::text))
   Join Filter: service_types.abonent_service
   ->  Sort  (cost=85302.62..85996.11 rows=277396 width=411) (actual
time=20110.866..20517.657 rows=272159 loops=1)
         Sort Key: resstat_2010_08.tarif_id, service_types.shortname
         Sort Method:  quicksort  Memory: 147305kB
         ->  Hash Join  (cost=51.47..60223.82 rows=277396 width=411) (actual
time=3.413..16929.164 rows=272159 loops=1)
               Hash Cond: ((services.shortname)::text =
(service_types.shortname)::text)
               ->  Merge Join  (cost=42.97..56401.12 rows=277396 width=246)
(actual time=1.967..15198.751 rows=272159 loops=1)
                     Merge Cond: (resstat_2010_08.service_id = services.id)
                     ->  Index Scan using resstat_2010_08_service_id_key on
resstat_2010_08  (cost=0.00..4260.35 rows=277396 width=83) (actual
time=0.025..874.850 rows=277396 loops=1)
                     ->  Index Scan using services_pkey on services
(cost=0.00..42226.11 rows=2770621 width=163) (actual time=0.017..7966.282
rows=2812840 loops=1)
               ->  Hash  (cost=3.83..3.83 rows=374 width=165) (actual
time=1.421..1.421 rows=374 loops=1)
                     ->  Seq Scan on service_types  (cost=0.00..3.83
rows=374 width=165) (actual time=0.016..0.605 rows=374 loops=1)
   ->  Sort  (cost=233.86..242.35 rows=3399 width=161) (actual
time=15.138..26960.441 rows=19164919 loops=1)
         Sort Key: plan_s.tarif_id, plan_s.shortname
         Sort Method:  quicksort  Memory: 604kB
         ->  Seq Scan on plan_s  (cost=0.00..34.49 rows=3399 width=161)
(actual time=0.021..5.129 rows=3399 loops=1)
 Total runtime: 93715.497 ms

All plan look reasonable for me except that part:
   ->  Sort  (cost=233.86..242.35 rows=3399 width=161) (actual
time=15.138..26960.441 rows=19164919 loops=1)
         Sort Key: plan_s.tarif_id, plan_s.shortname
         Sort Method:  quicksort  Memory: 604kB
         ->  Seq Scan on plan_s  (cost=0.00..34.49 rows=3399 width=161)
(actual time=0.021..5.129 rows=3399 loops=1)

It looks very strange, in that part of the query 3399 rows of result was
translated to 19164920 rows after sort. And that sort took almost 27
seconds.

And one more strange things is merge join with that result took almost 50
seconds (more then half time of total work time).

I feel here something definitely wrong here, but I can't say what.

PS: all field types in the query except shortname have integer type, and
shortname have type character varying(32).

"Maxim Boguk" <Maxim.Boguk@gmail.com> writes:
> All plan look reasonable for me except that part:
>    ->  Sort  (cost=233.86..242.35 rows=3399 width=161) (actual
> time=15.138..26960.441 rows=19164919 loops=1)
>          Sort Key: plan_s.tarif_id, plan_s.shortname
>          Sort Method:  quicksort  Memory: 604kB
>          ->  Seq Scan on plan_s  (cost=0.00..34.49 rows=3399 width=161)
> (actual time=0.021..5.129 rows=3399 loops=1)

> It looks very strange, in that part of the query 3399 rows of result was
> translated to 19164920 rows after sort. And that sort took almost 27
> seconds.

What is probably happening here is that the merge join is hitting a lot
of duplicate merge keys in its left input, and as a result is rescanning
rows from the right input many times.  There are clearly only 3399 rows
in the sort result, but they are being delivered on average over 5000
times apiece.  The sort itself didn't take very long (only about 15ms);
most of the time shown by EXPLAIN is just re-fetch visits to the node.

The planner generally avoids mergejoins when it expects there to be a
lot of duplicate keys in the left input.  Not sure why it didn't
recognize that that would happen here.  Maybe there is some weird
correlation between tarif_id and shortname?

            regards, tom lane