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

"Maxim Boguk" <Maxim(dot)Boguk(at)gmail(dot)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