Обсуждение: Two different execution plan for the same request
<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>
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
<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:part1.05090402.04010005@dgfip.finances.gouv.fr" 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:part2.02010002.07070406@dgfip.finances.gouv.fr"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:yebhavinga@gmail.com"><yebhavinga@gmail.com></a><br /> Pour : JOUANIN Nicolas(44) <a class="moz-txt-link-rfc2396E" href="mailto:nicolas.jouanin@dgfip.finances.gouv.fr"><nicolas.jouanin@dgfip.finances.gouv.fr></a><br/> Copie à : <aclass="moz-txt-link-abbreviated" href="mailto:pgsql-performance@postgresql.org">pgsql-performance@postgresql.org</a><br/> Date : 07/07/2010 10:27<br /><blockquotecite="mid:4C343A59.7050908@gmail.com" 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 />
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
Hi Nicolas, On Wed, Jul 7, 2010 at 10:47 AM, JOUANIN Nicolas (44) <nicolas.jouanin@dgfip.finances.gouv.fr> 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
<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:guillaume.smet@gmail.com"><guillaume.smet@gmail.com></a><br/> Pour : JOUANIN Nicolas (44) <a class="moz-txt-link-rfc2396E" href="mailto:nicolas.jouanin@dgfip.finances.gouv.fr"><nicolas.jouanin@dgfip.finances.gouv.fr></a><br/> Copie à : YebHavinga <a class="moz-txt-link-rfc2396E" href="mailto:yebhavinga@gmail.com"><yebhavinga@gmail.com></a>, <a class="moz-txt-link-abbreviated"href="mailto:pgsql-performance@postgresql.org">pgsql-performance@postgresql.org</a><br />Date : 07/07/2010 10:59<br /><blockquote cite="mid:AANLkTimrF-p7o2iFzRcRFhH1hPbLT85SVoR6gxynKeRp@mail.gmail.com" 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:nicolas.jouanin@dgfip.finances.gouv.fr"><nicolas.jouanin@dgfip.finances.gouv.fr></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 />
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