Обсуждение: Two different execution plan for the same request

От:
"JOUANIN Nicolas (44)"
Дата:

<font size="-1"><font face="Arial">Hi,<br /><br /> I've trouble with some SQL request which have different execution
planswhen ran on two different servers. One server is the development environment, the othe rone is th pre-production
env.<br/> Both servers run postgreSQL 8.3.0 on Linux and :<br />  - both databases contains the same data
(pg_dump/pg_restorebetween servers)<br />  - instances have the same configuration parameters<br />  - vaccum and
analyzeis run every day.<br /> The only difference I can see is the hardware. The pre-preoduction env. has more RAM,
moreCPU and a RAID5 disk array through LVM where data are stored. <br /> Performances should be better on the
pre-productionbut unfortunatelly this is not the case.<br /> Below are the execution plan on development env and
pre-production.As you can see pre-production performance are poor, far slower than dev. env !<br /> For information,
enable_seqscanis turned off (some DBA advice). <br /> Also I can get the same execution plan on both environment by
turningoff enable_mergejoin and enable_hashjoin on the pre-production. Then execution matches and performances are much
better.<br/> Could anyone help to guess why both servers don't have the same execution plans ? Can this be due to
hardwaredifference ?<br /><br /> Let me know if you need more detailed informations on these configurations.<br /><br
/>Thanks.<br /><br /> Dev. environment :<br /></font></font><font size="-1"><tt>EXPLAIN analyze SELECT DISTINCT
ConstantesTableNBienService.id,ConstantesTableNBienService.code,ConstantesTableNBienService.lib_code<br/> FROM
T_DEMANDEConstantesTableDemande<br /> LEFT OUTER JOIN  T_OPERATION ConstantesTableOperation<br />     ON
ConstantesTableDemande.id_tech= ConstantesTableOperation.id_demande<br /> LEFT OUTER JOIN T_BIEN_SERVICE
ConstantesTableBienService<br/>     ON  ConstantesTableBienService.id_operation = ConstantesTableOperation.id_tech<br
/>LEFT OUTER JOIN N_BIEN_SERVICE ConstantesTableNBienService<br />     ON ConstantesTableBienService.bs_code =
ConstantesTableNBienService.id<br/> WHERE<br />     ConstantesTableDemande.id_tech = 'y+3eRapRQjW8mtL4wHd4/A=='<br />
   AND ConstantesTableOperation.type_operation = 'acq'<br />     AND ConstantesTableNBienService.parent is null<br />
ORDERBY ConstantesTableNBienService.code ASC;<br />
                                                                                            QUERY
PLAN                                                     <br />
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------<br
/> Unique  (cost=3586307.73..3586341.94 rows=205 width=123) (actual time=440.626..440.875 rows=1 loops=1)<br />   
-> Sort  (cost=3586307.73..3586316.28 rows=3421 width=123) (actual time=440.624..440.723 rows=187 loops=1)<br />
        Sort Key: constantestablenbienservice.code, constantestablenbienservice.id,
constantestablenbienservice.lib_code<br/>          Sort Method:  quicksort  Memory: 24kB<br />          ->  Nested
LoopLeft Join  (cost=40.38..3586106.91 rows=3421 width=123) (actual time=71.696..440.240 rows=187 loops=1)<br />
              Filter: (constantestablenbienservice.parent IS NULL)<br />                ->  Nested Loop Left Join 
(cost=40.38..3554085.80rows=6842 width=4) (actual time=66.576..433.797 rows=187 loops=1)<br />                     
-> Nested Loop  (cost=0.00..5041.46 rows=1246 width=25) (actual time=22.923..23.054 rows=30 loops=1)<br />
                          ->  Index Scan using t_demande_pkey on t_demande constantestabledemande  (cost=0.00..8.32
rows=1width=25) (actual time=5.534..5.537 rows=1 loops=1)<br />                                  Index Cond:
((id_tech)::text= 'y+3eRapRQjW8mtL4wHd4/A=='::text)<br />                            ->  Index Scan using
idx_operation_demandeon t_operation constantestableoperation  (cost=0.00..5020.68 rows=1246 width=50) (actual
time=17.382..17.460rows=30 loops=1)<br />                                  Index Cond:
((constantestableoperation.id_demande)::text= 'y+3eRapRQjW8mtL4wHd4/A=='::text)<br />                                 
Filter:((constantestableoperation.type_operation)::text = 'acq'::text)<br />                      ->  Bitmap Heap
Scanon t_bien_service constantestablebienservice  (cost=40.38..2836.96 rows=911 width=29) (actual time=13.511..13.677
rows=6loops=30)<br />                            Recheck Cond: ((constantestablebienservice.id_operation)::text =
(constantestableoperation.id_tech)::text)<br/>                            ->  Bitmap Index Scan on
idx_bien_service_operation (cost=0.00..40.15 rows=911 width=0) (actual time=13.144..13.144 rows=6 loops=30)<br />
                                Index Cond: ((constantestablebienservice.id_operation)::text =
(constantestableoperation.id_tech)::text)<br/>                ->  Index Scan using n_bien_service_pkey on
n_bien_serviceconstantestablenbienservice  (cost=0.00..4.67 rows=1 width=127) (actual time=0.030..0.031 rows=1
loops=187)<br/>                      Index Cond: (constantestablebienservice.bs_code =
constantestablenbienservice.id)<br/><b><font color="#ff0000"> Total runtime: 2.558 ms<br /></font></b>(20
lignes)</tt></font><br/><font size="-1"><font face="Arial"><br /><br /> Pre-production:<br /></font></font><font
size="-1"><tt>EXPLAINanalyze SELECT DISTINCT
ConstantesTableNBienService.id,ConstantesTableNBienService.code,ConstantesTableNBienService.lib_code<br/> FROM
T_DEMANDEConstantesTableDemande<br /> LEFT OUTER JOIN  T_OPERATION ConstantesTableOperation<br />     ON
ConstantesTableDemande.id_tech= ConstantesTableOperation.id_demande<br /> LEFT OUTER JOIN T_BIEN_SERVICE
ConstantesTableBienService<br/>     ON  ConstantesTableBienService.id_operation = ConstantesTableOperation.id_tech<br
/>LEFT OUTER JOIN N_BIEN_SERVICE ConstantesTableNBienService<br />     ON ConstantesTableBienService.bs_code =
ConstantesTableNBienService.id<br/> WHERE<br />     ConstantesTableDemande.id_tech = 'y+3eRapRQjW8mtL4wHd4/A=='<br />
   AND ConstantesTableOperation.type_operation = 'acq'<br />     AND ConstantesTableNBienService.parent is null<br />
ORDERBY ConstantesTableNBienService.code ASC;<br />
                                                                                                       QUERY
PLAN                                          <br />
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------<br
/> Unique  (cost=2679729.52..2679763.24 rows=205 width=123) (actual time=740448.007..740448.269 rows=1 loops=1)<br />
  ->  Sort  (cost=2679729.52..2679737.95 rows=3372 width=123) (actual time=740448.004..740448.111 rows=187
loops=1)<br/>          Sort Key: constantestablenbienservice.code, constantestablenbienservice.id,
constantestablenbienservice.lib_code<br/>          Sort Method:  quicksort  Memory: 24kB<br />          ->  Hash
LeftJoin  (cost=2315662.87..2679531.93 rows=3372 width=123) (actual time=723479.640..740447.597 rows=187 loops=1)<br />
              Hash Cond: (constantestablebienservice.bs_code = constantestablenbienservice.id)<br />               
Filter:(constantestablenbienservice.parent IS NULL)<br />                ->  Hash Left Join 
(cost=2315640.98..2679417.33rows=6743 width=4) (actual time=723464.693..740432.218 rows=187 loops=1)<br />
                    Hash Cond: ((constantestableoperation.id_tech)::text =
(constantestablebienservice.id_operation)::text)<br/>                      ->  Nested Loop  (cost=39.49..4659.51
rows=1228width=25) (actual time=0.131..0.309 rows=30 loops=1)<br />                            ->  Index Scan using
t_demande_pkeyon t_demande constantestabledemande  (cost=0.00..8.32 rows=1 width=25) (actual time=0.047..0.050 rows=1
loops=1)<br/>                                  Index Cond: ((id_tech)::text = 'y+3eRapRQjW8mtL4wHd4/A=='::text)<br />
                          ->  Bitmap Heap Scan on t_operation constantestableoperation  (cost=39.49..4638.90
rows=1228width=50) (actual time=0.079..0.192 rows=30 loops=1)<br />                                  Recheck Cond:
((constantestableoperation.id_demande)::text= 'y+3eRapRQjW8mtL4wHd4/A=='::text)<br />                                 
Filter:((constantestableoperation.type_operation)::text = 'acq'::text)<br />                                  -> 
BitmapIndex Scan on idx_operation_demande  (cost=0.00..39.18 rows=1228 width=0) (actual time=0.061..0.061 rows=30
loops=1)<br/>                                        Index Cond: ((constantestableoperation.id_demande)::text =
'y+3eRapRQjW8mtL4wHd4/A=='::text)<br/>                      ->  Hash  (cost=1486192.10..1486192.10 rows=42894672
width=29)(actual time=723119.538..723119.538 rows=42894671 loops=1)<br />                            ->  Index Scan
usingidx_bien_service_code on t_bien_service constantestablebienservice  (cost=0.00..1486192.10 rows=42894672 width=29)
(actualtime=21.546..671603.500 rows=42894671 loops=1)<br />                ->  Hash  (cost=19.33..19.33 rows=205
width=127)(actual time=14.706..14.706 rows=205 loops=1)<br />                      ->  Index Scan using
n_bien_service_pkeyon n_bien_service constantestablenbienservice  (cost=0.00..19.33 rows=205 width=127) (actual
time=10.262..14.401rows=205 loops=1)<br /><b><font color="#ff0000"> Total runtime: 740465.922 ms</font></b><br /> (22
lignes)<br/></tt></font><font size="-1"><font face="Arial"><br /></font></font> 
От:
Yeb Havinga
Дата:

JOUANIN Nicolas (44) wrote:
> Hi,
>
> I've trouble with some SQL request which have different execution
> plans when ran on two different servers. One server is the development
> environment, the othe rone is th pre-production env.
> Both servers run postgreSQL 8.3.0 on Linux and :
>  - both databases contains the same data (pg_dump/pg_restore between
> servers)
>  - instances have the same configuration parameters
>  - vaccum and analyze is run every day.
> The only difference I can see is the hardware. The pre-preoduction
> env. has more RAM, more CPU and a RAID5 disk array through LVM where
> data are stored.
Hello Jouanin,

Could you give some more information following the guidelines from
http://wiki.postgresql.org/wiki/SlowQueryQuestions ?

Essential are the contents from both conf files (comments may be removed).

regards,
Yeb Havinga


От:
"JOUANIN Nicolas (44)"
Дата:

<font size="-1"><font face="Arial">Please find attached schema of tables and indexes involved.<br /> Here is the
pre-prod.environment config file:<br /> listen_addresses = '*'<br /> max_connections = 200<br /> shared_buffers =
1024MB<br/> work_mem = 24MB<br /> maintenance_work_mem = 128MB<br /> max_stack_depth = 6MB<br /> max_fsm_pages =
204800<br/> wal_buffers = 921MB<br /> checkpoint_segments = 10<br /> checkpoint_completion_target = 0.9<br />
archive_mode= on<br /> archive_command = 'cp -i %p /postgres/INST1/backup_xlog/%f'<br /> enable_seqscan = off<br />
random_page_cost= 4.0<br /> effective_cache_size = 1536MB<br /> log_destination = 'stderr'<br /> logging_collector =
on<br/> log_directory = 'pg_log'<br /> log_truncate_on_rotation = on<br /> log_rotation_age = 1d<br />
log_rotation_size= 0<br /> log_min_duration_statement = 5000<br /> log_duration = on<br /> log_line_prefix='%t -
user=%u,db=%d,sess=%c,proc=%p'<br /> log_statement = 'all'<br /> datestyle = 'iso, dmy'<br /> lc_messages = 'C'<br />
lc_monetary= 'C'<br /> lc_numeric = 'C'<br /> lc_time = 'C'<br /> default_text_search_config = 'pg_catalog.english'<br
/><br/> The development environment has :<br /> listen_addresses = '*'<br /> max_connections = 200<br /> shared_buffers
=1024MB<br /> work_mem = 24MB<br /> maintenance_work_mem = 128MB<br /> max_stack_depth = 6MB<br /> max_fsm_pages =
204800<br/> wal_buffers = 921MB<br /> checkpoint_segments = 10<br /> checkpoint_completion_target = 0.9<br />
enable_seqscan= off<br /> random_page_cost = 4.0<br /> effective_cache_size = 1536MB<br /> log_destination =
'stderr'<br/> logging_collector = on<br /> log_directory = 'pg_log'<br /> log_truncate_on_rotation = on<br />
log_rotation_age= 1d<br /> log_rotation_size = 100MB<br /> syslog_facility = 'LOCAL0'<br /> syslog_ident =
'postgres'<br/> silent_mode = on<br /> log_duration = on<br /> log_line_prefix = '%t - user=%u,db=%d '<br />
log_statement= 'all'<br /> datestyle = 'iso, mdy'<br /> lc_messages = 'C'<br /> lc_monetary = 'C'<br /> lc_numeric =
'C'<br/> lc_time = 'C'<br /> default_text_search_config = 'pg_catalog.english'<br /><br /> The strange thing is that
thismorning explain analyze now gives a much better duration : <br /> EXPLAIN analyze SELECT DISTINCT
ConstantesTableNBienService.id,ConstantesTableNBienService.code,ConstantesTableNBienService.lib_code<br/> FROM
T_DEMANDEConstantesTableDemande<br /> LEFT OUTER JOIN  T_OPERATION ConstantesTableOperation<br />     ON
ConstantesTableDemande.id_tech= ConstantesTableOperation.id_demande<br /> LEFT OUTER JOIN T_BIEN_SERVICE
ConstantesTableBienService<br/>     ON  ConstantesTableBienService.id_operation = ConstantesTableOperation.id_tech<br
/>LEFT OUTER JOIN N_BIEN_SERVICE ConstantesTableNBienService<br />     ON ConstantesTableBienService.bs_code =
ConstantesTableNBienService.id<br/> WHERE<br />     ConstantesTableDemande.id_tech = 'y+3eRapRQjW8mtL4wHd4/A=='<br />
   AND ConstantesTableOperation.type_operation = 'acq'<br />     AND ConstantesTableNBienService.parent is null<br />
ORDERBY ConstantesTableNBienService.code ASC;<br />
                                                                                           QUERY
PLAN                                                      <br />
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------<br
/> Unique  (cost=3186430.11..3186466.21 rows=205 width=123) (actual time=3.075..3.325 rows=1 loops=1)<br />    -> 
Sort (cost=3186430.11..3186439.13 rows=3610 width=123) (actual time=3.073..3.176 rows=187 loops=1)<br />          Sort
Key:constantestablenbienservice.code, constantestablenbienservice.id, constantestablenbienservice.lib_code<br />
        Sort Method:  quicksort  Memory: 24kB<br />          ->  Hash Left Join  (cost=57.27..3186216.80 rows=3610
width=123)(actual time=0.913..2.795 rows=187 loops=1)<br />                Hash Cond:
(constantestablebienservice.bs_code= constantestablenbienservice.id)<br />                Filter:
(constantestablenbienservice.parentIS NULL)<br />                ->  Nested Loop Left Join  (cost=35.39..3186095.62
rows=7221width=4) (actual time=0.308..1.896 rows=187 loops=1)<br />                      ->  Nested Loop 
(cost=0.00..5315.38rows=1315 width=25) (actual time=0.164..0.250 rows=30 loops=1)<br />                           
-> Index Scan using t_demande_pkey on t_demande constantestabledemande  (cost=0.00..8.32 rows=1 width=25) (actual
time=0.107..0.108rows=1 loops=1)<br />                                  Index Cond: ((id_tech)::text =
'y+3eRapRQjW8mtL4wHd4/A=='::text)<br/>                            ->  Index Scan using idx_operation_demande on
t_operationconstantestableoperation  (cost=0.00..5293.91 rows=1315 width=50) (actual time=0.053..0.107 rows=30
loops=1)<br/>                                  Index Cond: ((constantestableoperation.id_demande)::text =
'y+3eRapRQjW8mtL4wHd4/A=='::text)<br/>                                  Filter:
((constantestableoperation.type_operation)::text= 'acq'::text)<br />                      ->  Bitmap Heap Scan on
t_bien_serviceconstantestablebienservice  (cost=35.39..2409.22 rows=770 width=29) (actual time=0.040..0.044 rows=6
loops=30)<br/>                            Recheck Cond: ((constantestablebienservice.id_operation)::text =
(constantestableoperation.id_tech)::text)<br/>                            ->  Bitmap Index Scan on
idx_bien_service_operation (cost=0.00..35.19 rows=770 width=0) (actual time=0.037..0.037 rows=6 loops=30)<br />
                                Index Cond: ((constantestablebienservice.id_operation)::text =
(constantestableoperation.id_tech)::text)<br/>                ->  Hash  (cost=19.33..19.33 rows=205 width=127)
(actualtime=0.566..0.566 rows=205 loops=1)<br />                      ->  Index Scan using n_bien_service_pkey on
n_bien_serviceconstantestablenbienservice  (cost=0.00..19.33 rows=205 width=127) (actual time=0.045..0.294 rows=205
loops=1)<br/>  Total runtime: 3.518 ms<br /> (21 lignes)<br /><br /> There were no modification made on the database
excepta restart yesterday evening and a vacuumdb --analyse ran at night.<br /><br /><br /><br /></font></font><div
class="moz-signature"><tableborder="0" cellpadding="0" cellspacing="0"><tbody><tr><td colspan="3"><hr
/></td></tr><tr><tdvalign="middle" width="50"><img align="middle" alt="DGFIP" border="0" height="48"
moz-do-not-send="false"name="Image1" src="cid:" width="41" /></td><td
valign="top"width="184"><font color="#023854" face="Arial, sans-serif" size="1" style="font-size: 8pt;"> <b>Nicolas
Jouanin</b></font><br /><font color="#c28f28" face="Arial, sans-serif" size="1" style="font-size: 8pt;"> <b>Analyste -
TVA8ièmedirective</b> </font><br /><font color="#c28f28" face="Arial, sans-serif" size="1" style="font-size: 8pt;">
<b>BureauSI-1C / DAP2</b> </font><br /></td><td align="right" valign="top" width="124"><font color="#023854"
face="Arial,sans-serif" size="1" style="font-size: 8pt;"> <b>Tel: 02.51.88.50.18</b> </font><br
/></td></tr></tbody></table><br/><table border="0" cellpadding="0" cellspacing="0"><tbody><tr><td align="center"
valign="middle"width="50"><img align="middle" alt="Eco-attitude" border="0" height="27" moz-do-not-send="false"
src="cid:"width="27" /></td><td valign="top" width="250"><font
color="#36a629"face="Arial, sans-serif" size="1" style="font-size: 8pt;"> <b>Adoptez l'éco-attitude.</b> </font><br
/><fontcolor="#36a629" face="Arial, sans-serif" size="1" style="font-size: 7pt;">N'imprimez ce courriel que si c'est
vraimentnécessaire</font><br /></td></tr></tbody></table></div><br /><br /> -------- Message original --------<br />
Sujet :Re: [PERFORM] Two different execution plan for the same request<br /> De : Yeb Havinga <a
class="moz-txt-link-rfc2396E"href="mailto:"><></a><br /> Pour : JOUANIN
Nicolas(44) <a class="moz-txt-link-rfc2396E"
href="mailto:"><></a><br/> Copie à :
<aclass="moz-txt-link-abbreviated"
href="mailto:"></a><br/> Date : 07/07/2010 10:27<br
/><blockquotecite="mid:" type="cite">JOUANIN Nicolas (44) wrote: <br /><blockquote
type="cite">Hi,<br /><br /> I've trouble with some SQL request which have different execution plans when ran on two
differentservers. One server is the development environment, the othe rone is th pre-production env. <br /> Both
serversrun postgreSQL 8.3.0 on Linux and : <br />  - both databases contains the same data (pg_dump/pg_restore between
servers)<br />  - instances have the same configuration parameters <br />  - vaccum and analyze is run every day. <br
/>The only difference I can see is the hardware. The pre-preoduction env. has more RAM, more CPU and a RAID5 disk array
throughLVM where data are stored. <br /></blockquote> Hello Jouanin, <br /><br /> Could you give some more information
followingthe guidelines from <a class="moz-txt-link-freetext"
href="http://wiki.postgresql.org/wiki/SlowQueryQuestions">http://wiki.postgresql.org/wiki/SlowQueryQuestions</a>? <br
/><br/> Essential are the contents from both conf files (comments may be removed). <br /><br /> regards, <br /> Yeb
Havinga<br /><br /><br /><br /></blockquote><br /> 
От:
Yeb Havinga
Дата:

JOUANIN Nicolas (44) wrote:
>
> The strange thing is that this morning explain analyze now gives a
> much better duration :
>
> There were no modification made on the database except a restart
> yesterday evening and a vacuumdb --analyse ran at night.
If the earlier bad query was run on a fresh imported database that was
not ANALYZEd, it would explain the different and likely bad plan. If you
want to know for sure this is the cause, instead of e.g. faulty
hardware, you could verify redoing the import + query without analyze.

regards,
Yeb Havinga


От:
Guillaume Smet
Дата:

Hi Nicolas,

On Wed, Jul 7, 2010 at 10:47 AM, JOUANIN Nicolas (44)
<> wrote:
> There were no modification made on the database except a restart yesterday evening and a vacuumdb --analyse ran at
night.

It's not really surprising considering you probably kept the
default_statistics_target to 10 (it's the default in 8.3).

Consider raising it to 100 in your postgresql.conf (100 is the default
for newer versions), then reload, and run a new ANALYZE.

You might need to set it higher on specific columns if you have a lot
of data and your data distribution is weird.

And, btw, please upgrade to the latest 8.3.x.

HTH

--
Guillaume

От:
"JOUANIN Nicolas (44)"
Дата:

<font size="-1"><font face="Arial">It seems to work fine (same execution plan and less duration) after :<br />  -
settingdefault_statistics_target to 100<br />  - full vacuum with analyze<br />  - reindexdb<br /><br /> Thanks.<br
/></font></font><br/><br /> -------- Message original --------<br /> Sujet : Re: [PERFORM] Two different execution plan
forthe same request<br /> De : Guillaume Smet <a class="moz-txt-link-rfc2396E"
href="mailto:"><></a><br/> Pour : JOUANIN Nicolas (44) <a
class="moz-txt-link-rfc2396E"
href="mailto:"><></a><br/> Copie à :
YebHavinga <a class="moz-txt-link-rfc2396E" href="mailto:"><></a>, <a
class="moz-txt-link-abbreviated"href="mailto:"></a><br
/>Date : 07/07/2010 10:59<br /><blockquote cite="mid:"
type="cite"><prewrap="">Hi Nicolas,
 

On Wed, Jul 7, 2010 at 10:47 AM, JOUANIN Nicolas (44)
<a class="moz-txt-link-rfc2396E"
href="mailto:"><></a>wrote:
</pre><blockquotetype="cite"><pre wrap="">There were no modification made on the database except a restart yesterday
eveningand a vacuumdb --analyse ran at night.   </pre></blockquote><pre wrap="">
 
It's not really surprising considering you probably kept the
default_statistics_target to 10 (it's the default in 8.3).

Consider raising it to 100 in your postgresql.conf (100 is the default
for newer versions), then reload, and run a new ANALYZE.

You might need to set it higher on specific columns if you have a lot
of data and your data distribution is weird.

And, btw, please upgrade to the latest 8.3.x.

HTH
 </pre></blockquote><br />
От:
Matthew Wakeling
Дата:

On Wed, 7 Jul 2010, JOUANIN Nicolas (44) wrote:
> It seems to work fine (same execution plan and less duration) after :
>  - setting default_statistics_target to 100
>  - full vacuum with analyze

Don't do VACUUM FULL.

Matthew

--
 I suppose some of you have done a Continuous Maths course. Yes? Continuous
 Maths? <menacing stares from audience> Whoah, it was like that, was it!
                                        -- Computer Science Lecturer