Message-ID: <5102A5F7.2070103@gmail.com>
Date: Fri, 25 Jan 2013 13:34:15 -0200
From: alexandre - aldeia digital <adaldeia@gmail.com>
User-Agent: Mozilla/5.0 (X11; Linux x86_64;
	rv:17.0) Gecko/17.0 Thunderbird/17.0
MIME-Version: 1.0
To: pgsql-performance@postgresql.org
Subject: Nested loop and simple join query - slow after upgrade to 9.2
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

Hi,

Last weekend, we upgrade a PG from 8.4 to 9.2 version (full 
pg_dump/restore/vacuum/analyze). After this, some simple join querys
became very slow, maybe because the use of nested loops. Bellow, an 
example with nestedloop on and off:

base=# analyze verbose pc13t;
INFO:  analyzing "public.pc13t"
INFO:  "pc13t": scanned 30000 of 212313 pages, containing 268677 live 
rows and 764 dead rows; 30000 rows in sample, 1903065 estimated total rows
ANALYZE
base=# analyze verbose pc13t3;
INFO:  analyzing "public.pc13t3"
INFO:  "pc13t3": scanned 30000 of 883424 pages, containing 1274216 live 
rows and 3005 dead rows; 30000 rows in sample, 37553206 estimated total rows
ANALYZE
base=# set enable_nestloop = on;
SET
base=# explain (analyze,buffers) SELECT T1.Pc13Item, T1.PC13CodPed, 
T1.PC13AnoPed, T1.PC13Emp08P, T1.PC13Cor, T1.PC13Codigo, T1.PC13Emp08, 
T1.PC13ProEst AS PC13ProEst, T2.PC13Grade, T4.PC07GerPed, T2.PC13EmpGra, 
T1.PC13Emp06P AS PC13Emp06P, T4.PC07NaoTV, T3.co13PorTam, T4.PC07CodAlm, 
T4.PC07C_Cust AS PC13SecIns, T3.co13Bloq AS PC13ProBlq, T1.PC13InsEst AS 
PC13InsEst, T1.PC13TipIn2 AS PC13TipIn2, T1.PC13EmpIns AS PC13EmpIns 
FROM (((PC13T3 T1 LEFT JOIN PC13T T2 ON T2.PC13Emp08 = T1.PC13Emp08 AND 
T2.PC13Codigo = T1.PC13Codigo AND T2.PC13Cor = T1.PC13Cor AND 
T2.PC13Emp08P = T1.PC13Emp08P AND T2.PC13AnoPed = T1.PC13AnoPed AND 
T2.PC13CodPed = T1.PC13CodPed AND T2.Pc13Item = T1.Pc13Item) LEFT JOIN 
CO13T T3 ON T3.co13Emp06 = T1.PC13Emp06P AND T3.co13CodPro = 
T1.PC13ProEst) LEFT JOIN PC07T T4 ON T4.PC07CodEmp = T1.PC13EmpIns AND 
T4.PC07Tipo = T1.PC13TipIn2 AND T4.PC07Codigo = T1.PC13InsEst) WHERE 
T1.PC13Emp08 = '1' and T1.PC13Codigo = E'9487-491C           ' and 
T1.PC13Cor = '1' and T1.PC13Emp08P = '0' and T1.PC13AnoPed = '0' and 
T1.PC13CodPed = '0' and T1.Pc13Item = '0' ORDER BY T1.PC13Emp08, 
T1.PC13Codigo, T1.PC13Cor, T1.PC13Emp08P, T1.PC13AnoPed, T1.PC13CodPed, 
T1.Pc13Item, T1.PC13EmpIns, T1.PC13TipIn2, T1.PC13InsEst ;
 
                                                          QUERY PLAN 
 

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-----------------------------
  Nested Loop Left Join  (cost=0.00..20.61 rows=1 width=86) (actual 
time=0.870..1197.057 rows=39 loops=1)
    Buffers: shared hit=424602 read=5
    ->  Nested Loop Left Join  (cost=0.00..16.33 rows=1 width=74) 
(actual time=0.822..1196.583 rows=39 loops=1)
          Buffers: shared hit=424484 read=5
          ->  Nested Loop Left Join  (cost=0.00..12.01 rows=1 width=70) 
(actual time=0.779..1195.477 rows=39 loops=1)
                Join Filter: ((t2.pc13emp08 = t1.pc13emp08) AND 
(t2.pc13codigo = t1.pc13codigo) AND (t2.pc13cor = t1.pc13cor) AND 
(t2.pc13emp08p = t1.pc13emp08p) AND (t2.pc13anoped = t1.pc13anoped) AND 
(t2.pc13codped = t1.pc13codped) AND
(t2.pc13item = t1.pc13item))
                Buffers: shared hit=424329 read=5
                ->  Index Scan using ad_pc13t3_modpadrao on pc13t3 t1 
(cost=0.00..6.21 rows=1 width=65) (actual time=0.090..0.252 rows=39 loops=1)
                      Index Cond: ((pc13emp08p = 0) AND (pc13anoped = 0) 
AND (pc13codped = 0) AND (pc13codigo = '9487-491C           '::bpchar) 
AND (pc13cor = 1) AND (pc13emp08 = 1))
                      Buffers: shared hit=5 read=5
                ->  Index Scan using xpc13tc on pc13t t2 
(cost=0.00..5.77 rows=1 width=44) (actual time=0.254..30.638 rows=1 
loops=39)
                      Index Cond: ((pc13emp08p = 0) AND (pc13anoped = 0) 
AND (pc13codped = 0) AND (pc13item = 0))
                      Filter: ((pc13emp08 = 1) AND (pc13codigo = 
'9487-491C           '::bpchar) AND (pc13cor = 1))
                      Rows Removed by Filter: 45161
                      Buffers: shared hit=424324
          ->  Index Scan using co13t_pkey on co13t t3  (cost=0.00..4.31 
rows=1 width=10) (actual time=0.021..0.024 rows=1 loops=39)
                Index Cond: ((co13emp06 = t1.pc13emp06p) AND (co13codpro 
= t1.pc13proest))
                Buffers: shared hit=155
    ->  Index Scan using pc07t_pkey on pc07t t4  (cost=0.00..4.28 rows=1 
width=24) (actual time=0.008..0.009 rows=1 loops=39)
          Index Cond: ((pc07codemp = t1.pc13empins) AND (pc07tipo = 
t1.pc13tipin2) AND (pc07codigo = t1.pc13insest))
          Buffers: shared hit=118
  Total runtime: 1197.332 ms
(22 rows)

#######################################################

base=# set enable_nestloop = off;
SET
base=# explain (analyze,buffers) SELECT T1.Pc13Item, T1.PC13CodPed, 
T1.PC13AnoPed, T1.PC13Emp08P, T1.PC13Cor, T1.PC13Codigo, T1.PC13Emp08, 
T1.PC13ProEst AS PC13ProEst, T2.PC13Grade, T4.PC07GerPed, T2.PC13EmpGra, 
T1.PC13Emp06P AS PC13Emp06P, T4.PC07NaoTV, T3.co13PorTam, T4.PC07CodAlm, 
T4.PC07C_Cust AS PC13SecIns, T3.co13Bloq AS PC13ProBlq, T1.PC13InsEst AS 
PC13InsEst, T1.PC13TipIn2 AS PC13TipIn2, T1.PC13EmpIns AS PC13EmpIns 
FROM (((PC13T3 T1 LEFT JOIN PC13T T2 ON T2.PC13Emp08 = T1.PC13Emp08 AND 
T2.PC13Codigo = T1.PC13Codigo AND T2.PC13Cor = T1.PC13Cor AND 
T2.PC13Emp08P = T1.PC13Emp08P AND T2.PC13AnoPed = T1.PC13AnoPed AND 
T2.PC13CodPed = T1.PC13CodPed AND T2.Pc13Item = T1.Pc13Item) LEFT JOIN 
CO13T T3 ON T3.co13Emp06 = T1.PC13Emp06P AND T3.co13CodPro = 
T1.PC13ProEst) LEFT JOIN PC07T T4 ON T4.PC07CodEmp = T1.PC13EmpIns AND 
T4.PC07Tipo = T1.PC13TipIn2 AND T4.PC07Codigo = T1.PC13InsEst) WHERE 
T1.PC13Emp08 = '1' and T1.PC13Codigo = E'9487-491C           ' and 
T1.PC13Cor = '1' and T1.PC13Emp08P = '0' and T1.PC13AnoPed = '0' and 
T1.PC13CodPed = '0' and T1.Pc13Item = '0' ORDER BY T1.PC13Emp08, 
T1.PC13Codigo, T1.PC13Cor, T1.PC13Emp08P, T1.PC13AnoPed, T1.PC13CodPed, 
T1.Pc13Item, T1.PC13EmpIns, T1.PC13TipIn2, T1.PC13InsEst ;
 
                                                      QUERY PLAN 
 

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------
  Sort  (cost=7782.21..7782.21 rows=1 width=86) (actual 
time=108.672..108.677 rows=39 loops=1)
    Sort Key: t1.pc13empins, t1.pc13tipin2, t1.pc13insest
    Sort Method: quicksort  Memory: 30kB
    Buffers: shared hit=15960 read=2050
    ->  Hash Left Join  (cost=154.42..7782.20 rows=1 width=86) (actual 
time=49.398..108.413 rows=39 loops=1)
          Hash Cond: ((t1.pc13emp08 = t2.pc13emp08) AND (t1.pc13codigo = 
t2.pc13codigo) AND (t1.pc13cor = t2.pc13cor) AND (t1.pc13emp08p = 
t2.pc13emp08p) AND (t1.pc13anoped = t2.pc13anoped) AND (t1.pc13codped = 
t2.pc13codped) AND (t1.pc13
item = t2.pc13item))
          Buffers: shared hit=15960 read=2050
          ->  Hash Right Join  (cost=148.62..7776.37 rows=1 width=81) 
(actual time=6.392..65.317 rows=39 loops=1)
                Hash Cond: ((t3.co13emp06 = t1.pc13emp06p) AND 
(t3.co13codpro = t1.pc13proest))
                Buffers: shared hit=5073 read=2050
                ->  Seq Scan on co13t t3  (cost=0.00..7371.56 rows=34156 
width=10) (actual time=0.009..41.550 rows=34156 loops=1)
                      Buffers: shared hit=5043 read=1987
                ->  Hash  (cost=148.61..148.61 rows=1 width=77) (actual 
time=2.514..2.514 rows=39 loops=1)
                      Buckets: 1024  Batches: 1  Memory Usage: 5kB
                      Buffers: shared hit=27 read=63
                      ->  Hash Right Join  (cost=6.23..148.61 rows=1 
width=77) (actual time=0.141..2.484 rows=39 loops=1)
                            Hash Cond: ((t4.pc07codemp = t1.pc13empins) 
AND (t4.pc07tipo = t1.pc13tipin2) AND (t4.pc07codigo = t1.pc13insest))
                            Buffers: shared hit=27 read=63
                            ->  Seq Scan on pc07t t4  (cost=0.00..109.88 
rows=2888 width=24) (actual time=0.002..1.171 rows=2888 loops=1)
                                  Buffers: shared hit=18 read=63
                            ->  Hash  (cost=6.21..6.21 rows=1 width=65) 
(actual time=0.123..0.123 rows=39 loops=1)
                                  Buckets: 1024  Batches: 1  Memory 
Usage: 4kB
                                  Buffers: shared hit=9
                                  ->  Index Scan using 
ad_pc13t3_modpadrao on pc13t3 t1  (cost=0.00..6.21 rows=1 width=65) 
(actual time=0.041..0.090 rows=39 loops=1)
                                        Index Cond: ((pc13emp08p = 0) 
AND (pc13anoped = 0) AND (pc13codped = 0) AND (pc13codigo = '9487-491C 
          '::bpchar) AND (pc13cor = 1) AND (pc13emp08 = 1))
                                        Buffers: shared hit=9
          ->  Hash  (cost=5.77..5.77 rows=1 width=44) (actual 
time=42.937..42.937 rows=1 loops=1)
                Buckets: 1024  Batches: 1  Memory Usage: 1kB
                Buffers: shared hit=10880
                ->  Index Scan using xpc13tc on pc13t t2 
(cost=0.00..5.77 rows=1 width=44) (actual time=0.357..42.933 rows=1 loops=1)
                      Index Cond: ((pc13emp08p = 0) AND (pc13anoped = 0) 
AND (pc13codped = 0) AND (pc13item = 0))
                      Filter: ((pc13emp08 = 1) AND (pc13codigo = 
'9487-491C           '::bpchar) AND (pc13cor = 1))
                      Rows Removed by Filter: 45161
                      Buffers: shared hit=10880
  Total runtime: 108.884 ms
(35 rows)


Nested loop is ~12 times slower in this case. The server parameters are 
the same. Unfortunattly, I don't have the explain in 8.4 version.
And I noticed that the server load grew after the upgrade.

Best regards,

Alexandre


-- 
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance