Postgreslq Explain analyse : hidden time

Question

I've a long query and explain analyze isn't helping.

Version of PostgreSQL : 9.1

The current plan:

http://explain.depesz.com/s/sWG

The query :

SELECT temps_mois.rfoperyea      AS c0, 
       dwhinv.dwhinv___rfovsnide AS c1, 
       rfoadv_1.rfoadvsup        AS c2, 
       rfoadv_2.rfoadvsup        AS c3, 
       rsaaev_3.rsaaevsup        AS c4, 
       Sum(( CASE 
               WHEN dwhinv.dwhinv___rfodomide = 'LABO' 
                    AND dwhinv.dwhinv___rfoindide = '17' THEN dwhinv.dwhinvqte 
               ELSE 0 
             END ))              AS m0, 
       Sum(( CASE 
               WHEN dwhinv.dwhinv___rfodomide = 'LABO' 
                    AND dwhinv.dwhinv___rfoindide = '18' THEN dwhinv.dwhinvqte 
               ELSE 0 
             END ))              AS m1, 
       Sum(( CASE 
               WHEN dwhinv.dwhinv___rfodomide = 'LABO' 
                    AND dwhinv.dwhinv___rfoindide = '15' THEN dwhinv.dwhinvqte 
               ELSE 0 
             END ))              AS m2, 
       Sum(( CASE 
               WHEN dwhinv.dwhinv___rfodomide = 'LABO' 
                    AND dwhinv.dwhinv___rfoindide = '16' THEN dwhinv.dwhinvqte 
               ELSE 0 
             END ))              AS m3, 
       Sum(( CASE 
               WHEN dwhinv.dwhinv___rfodomide = 'ANAPATH' 
                    AND dwhinv.dwhinv___rfoindide = '20' THEN dwhinv.dwhinvqte 
               ELSE 0 
             END ))              AS m4, 
       Sum(( CASE 
               WHEN dwhinv.dwhinv___rfodomide = 'ANAPATH' 
                    AND dwhinv.dwhinv___rfoindide = '17' THEN dwhinv.dwhinvqte 
               ELSE 0 
             END ))              AS m5, 
       Sum(( CASE 
               WHEN dwhinv.dwhinv___rfodomide = 'ANAPATH' 
                    AND dwhinv.dwhinv___rfoindide = '18' THEN dwhinv.dwhinvqte 
               ELSE 0 
             END ))              AS m6, 
       Sum(( CASE 
               WHEN dwhinv.dwhinv___rfodomide = 'ANAPATH' 
                    AND dwhinv.dwhinv___rfoindide = '15' THEN dwhinv.dwhinvqte 
               ELSE 0 
             END ))              AS m7, 
       Sum(( CASE 
               WHEN dwhinv.dwhinv___rfodomide = 'ANAPATH' 
                    AND dwhinv.dwhinv___rfoindide = '19' THEN dwhinv.dwhinvqte 
               ELSE 0 
             END ))              AS m8, 
       Sum(( CASE 
               WHEN dwhinv.dwhinv___rfodomide = 'ANAPATH' 
                    AND dwhinv.dwhinv___rfoindide = '16' THEN dwhinv.dwhinvqte 
               ELSE 0 
             END ))              AS m9 
FROM   rfoper_temps_mois AS temps_mois, 
       dwhinv AS dwhinv, 
       rfoadv AS rfoadv_1, 
       rfoadv AS rfoadv_2, 
       rsaaev AS rsaaev_3 
WHERE  ( temps_mois.rfoper___rforefide = 'REF' ) 
       AND ( dwhinv.dwhinv___rforefide = 'REF' 
             AND ( ( dwhinv.dwhinv___rfodomide = 'LABO' 
                     AND dwhinv.dwhinv___rfoindide = '17' ) 
                    OR ( dwhinv.dwhinv___rfodomide = 'LABO' 
                         AND dwhinv.dwhinv___rfoindide = '18' ) 
                    OR ( dwhinv.dwhinv___rfodomide = 'LABO' 
                         AND dwhinv.dwhinv___rfoindide = '15' ) 
                    OR ( dwhinv.dwhinv___rfodomide = 'LABO' 
                         AND dwhinv.dwhinv___rfoindide = '16' ) 
                    OR ( dwhinv.dwhinv___rfodomide = 'ANAPATH' 
                         AND dwhinv.dwhinv___rfoindide = '20' ) 
                    OR ( dwhinv.dwhinv___rfodomide = 'ANAPATH' 
                         AND dwhinv.dwhinv___rfoindide = '17' ) 
                    OR ( dwhinv.dwhinv___rfodomide = 'ANAPATH' 
                         AND dwhinv.dwhinv___rfoindide = '18' ) 
                    OR ( dwhinv.dwhinv___rfodomide = 'ANAPATH' 
                         AND dwhinv.dwhinv___rfoindide = '15' ) 
                    OR ( dwhinv.dwhinv___rfodomide = 'ANAPATH' 
                         AND dwhinv.dwhinv___rfoindide = '19' ) 
                    OR ( dwhinv.dwhinv___rfodomide = 'ANAPATH' 
                         AND dwhinv.dwhinv___rfoindide = '16' ) ) ) 
       AND dwhinv.dwhinvdtd = temps_mois.rfoperdtd 
       AND temps_mois.rfoperyea IN ( '2011', '2012' ) 
       AND dwhinv.dwhinv___rfovsnide = 'version' 
       AND ( rfoadv_1.rfoadv___rfovdeide = 'STRC' 
             AND rfoadv_1.rfoadvrvs = 1 
             AND rfoadv_1.rfoadv___rforefide = 'REF' ) 
       AND dwhinv.dwhinv_d2rfodstide = rfoadv_1.rfoadvinf 
       AND rfoadv_1.rfoadvsup = 'REF' 
       AND ( rfoadv_2.rfoadv___rfovdeide = 'STRC_REF' 
             AND rfoadv_2.rfoadvrvs = 1 
             AND rfoadv_2.rfoadv___rforefide = 'REF' ) 
       AND dwhinv.dwhinv_p2rfodstide = rfoadv_2.rfoadvinf 
       AND rfoadv_2.rfoadvsup IN ( '01', '04', '05', '06', 
                                   '07', '99', 'REF', 'CR2107', 
                                   'CR2108', 'CR2109', 'CR2110', 'CR2111', 
                                   'CR2114', 'CR2116', 'CR2126', 'CR4101', 
                                   'CR4201' ) 
       AND ( rsaaev_3.rsaaev___rsavedide = 'PRESTA_ACTE' 
             AND rsaaev_3.rsaaevrvs = 1 
             AND rsaaev_3.rsaaev___rforefide = 'REF' ) 
       AND dwhinv.dwhinv___rsaedtide = rsaaev_3.rsaaevinf 
       AND rsaaev_3.rsaaevsup IN ( 'PRISE_EN_CHARGE', 'REG_EXT', 
                                   'REG_HOSPI_SEANCE' ) 
GROUP  BY temps_mois.rfoperyea, 
          dwhinv.dwhinv___rfovsnide, 
          rfoadv_1.rfoadvsup, 
          rfoadv_2.rfoadvsup, 
          rsaaev_3.rsaaevsup

It seems like several seconds elapse between the HashJoin and the Hashaggregate. Hashjoin takes 1200 to 1600ms. With the HashAggregate it jumps to 5645ms.

Might anyone else who ever encountered this problem be able to explain the difference?

Answer 1

The posted plan does not seem to match your description. For example, there is no "actual time" of 5645ms in the plan given, perhaps the top node was missing from your copy and paste.

But anyway, the time between 1600 and 5645 would be the time from when HashAggregate read the last row it needs to read, but cannot yet generate its first row. For example, because it needs to do some bulk operations on the data it read.