Received: from maia.hub.org (maia-5.hub.org [200.46.204.29]) by mail.postgresql.org (Postfix) with ESMTP id 9922463378D for ; Tue, 25 May 2010 13:19:49 -0300 (ADT) Received: from mail.postgresql.org ([200.46.204.86]) by maia.hub.org (mx1.hub.org [200.46.204.29]) (amavisd-maia, port 10024) with ESMTP id 57302-04 for ; Tue, 25 May 2010 16:19:41 +0000 (UTC) X-Greylist: from auto-whitelisted by SQLgrey-1.7.6 Received: from bill.kwcorp.com (mailx.kwcorp.com [65.118.99.196]) by mail.postgresql.org (Postfix) with ESMTP id DE3F2633450 for ; Tue, 25 May 2010 13:19:40 -0300 (ADT) X-TM-IMSS-Message-ID: <95149925000480c2@kwcorp.com> Received: from gw.homedecorators.com ([172.23.217.142]) by kwcorp.com ([192.168.85.25]) with ESMTP (TREND IMSS SMTP Service 7.0) id 95149925000480c2 ; Tue, 25 May 2010 11:19:37 -0500 Received: from HDC_MTA-MTA by gw.homedecorators.com with Novell_GroupWise; Tue, 25 May 2010 11:19:37 -0500 Message-Id: <4BFBB1F3.2E1C.0042.0@homedecorators.com> X-Mailer: Novell GroupWise Internet Agent 7.0.2 HP Date: Tue, 25 May 2010 11:18:11 -0500 From: "Jorge Montero" To: "Tyler Hildebrandt" , Subject: Re: Query timing increased from 3s to 55s when used as a function instead of select References: <20100525095943.GA18600@campbell-lange.net> In-Reply-To: <20100525095943.GA18600@campbell-lange.net> Mime-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: quoted-printable Content-Disposition: inline X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=-0.001 tagged_above=-10 required=5 tests=BAYES_40=-0.001 X-Spam-Level: X-Archive-Number: 201005/181 X-Sequence-Number: 38765 Have you read this? =20 http://blog.endpoint.com/2008/12/why-is-my-function-slow.html=20 =20 99% of the 'function is slow' problems are caused by this. Have you checked the difference between explain and prepare + explain = execute? >>> Tyler Hildebrandt 05/25/10 4:59 AM >>> We're using a function that when run as a select statement outside of = the=20 function takes roughly 1.5s to complete whereas running an identical query within a function is taking around 55s to complete. We are lost as to why placing this query within a function as opposed to substituting the variables in a select statement is so drastically = different. The timings posted here are from a 512MB memory virtual machine and are = not of major concern on their own but we are finding the same issue in our = production environment with far superior hardware. The function can be found here: http://campbell-lange.net/media/files/fn_medirota_get_staff_leave_summary.s= ql=20 --- Timings for the individual components on their own is as follows: select * from fn_medirota_validate_rota_master(6); Time: 0.670 ms select to_date(EXTRACT (YEAR FROM current_date)::text, 'YYYY'); Time: 0.749 ms select * from fn_medirota_people_template_generator(2, 6, date'2009-01-01',= date'2009-12-31', TRUE) AS templates; Time: 68.004 ms select * from fn_medirota_people_template_generator(2, 6, date'2010-01-01',= date'2010-12-31', TRUE) AS templates; Time: 1797.323 Copying the exact same for loop select statement from the query above into the psql query buffer and running them with variable substitution yields = the following: Running FOR loop SElECT with variable substitution: Time: 3150.585 ms Whereas invoking the function yields: select * from fn_medirota_get_staff_leave_summary(6); Time: 57375.477 ms We have tried using explain analyse to update the query optimiser, dropped = and recreated the function and have restarted both the machine and the = postgres server multiple times. Any help or advice would be greatly appreciated. Kindest regards, Tyler Hildebrandt --- EXPLAIN ANALYSE VERBOSE SELECT * FROM fn_medirota_get_staff_leave_summary(6= ); QUERY PLAN ---------------------------------------------------------------------------= ---------------------------------------------------------------------- {FUNCTIONSCAN :startup_cost 0.00 :total_cost 260.00 :plan_rows 1000 :plan_width 85 :targetlist ( {TARGETENTRY :expr {VAR :varno 1 :varattno 1 :vartype 23 :vartypmod -1 :varlevelsup 0 :varnoold 1 :varoattno 1 } :resno 1 :resname id :ressortgroupref 0 :resorigtbl 0 :resorigcol 0 :resjunk false } {TARGETENTRY :expr {VAR :varno 1 :varattno 2 :vartype 1043 :vartypmod -1 :varlevelsup 0 :varnoold 1 :varoattno 2 } :resno 2 :resname t_full_name :ressortgroupref 0 :resorigtbl 0 :resorigcol 0 :resjunk false } {TARGETENTRY :expr {VAR :varno 1 :varattno 3 :vartype 16 :vartypmod -1 :varlevelsup 0 :varnoold 1 :varoattno 3 } :resno 3 :resname b_enabled :ressortgroupref 0 :resorigtbl 0 :resorigcol 0 :resjunk false } {TARGETENTRY :expr {VAR :varno 1 :varattno 4 :vartype 1043 :vartypmod -1 :varlevelsup 0 :varnoold 1 :varoattno 4 } :resno 4 :resname t_anniversary :ressortgroupref 0 :resorigtbl 0 :resorigcol 0 :resjunk false } {TARGETENTRY :expr {VAR :varno 1 :varattno 5 :vartype 23 :vartypmod -1 :varlevelsup 0 :varnoold 1 :varoattno 5 } :resno 5 :resname n_last_year_annual :ressortgroupref 0 :resorigtbl 0 :resorigcol 0 :resjunk false } {TARGETENTRY :expr {VAR :varno 1 :varattno 6 :vartype 23 :vartypmod -1 :varlevelsup 0 :varnoold 1 :varoattno 6 } :resno 6 :resname n_last_year_other :ressortgroupref 0 :resorigtbl 0 :resorigcol 0 :resjunk false } {TARGETENTRY :expr {VAR :varno 1 :varattno 7 :vartype 23 :vartypmod -1 :varlevelsup 0 :varnoold 1 :varoattno 7 } :resno 7 :resname n_this_year_annual :ressortgroupref 0 :resorigtbl 0 :resorigcol 0 :resjunk false } {TARGETENTRY :expr {VAR :varno 1 :varattno 8 :vartype 23 :vartypmod -1 :varlevelsup 0 :varnoold 1 :varoattno 8 } :resno 8 :resname n_this_year_other :ressortgroupref 0 :resorigtbl 0 :resorigcol 0 :resjunk false } ) :qual <> :lefttree <> :righttree <> :initPlan <> :extParam (b) :allParam (b) :scanrelid 1 :funcexpr {FUNCEXPR :funcid 150447 :funcresulttype 149366 :funcretset true :funcformat 0 :args ( {CONST :consttype 23 :consttypmod -1 :constlen 4 :constbyval true :constisnull false :constvalue 4 [ 6 0 0 0 0 0 0 0 ] } ) } :funccolnames ("id" "t_full_name" "b_enabled" "t_anniversary" = "n_last_year_ annual" "n_last_year_other" "n_this_year_annual" "n_this_year_other") :funccoltypes <> :funccoltypmods <> } Function Scan on fn_medirota_get_staff_leave_summary (cost=3D0.00..260.00 rows=3D1000 width=3D85) (actual time=3D51877.812..51877.893 rows=3D94 = loops=3D1) Total runtime: 51878.008 ms (183 rows) --=20 Tyler Hildebrandt Software Developer tyler@campbell-lange.net=20 Campbell-Lange Workshop www.campbell-lange.net=20 020 7631 1555 3 Tottenham Street London W1T 2AF Registered in England No. 04551928 --=20 Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance