Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1VqVFj-00047F-LQ for pgsql-performance@arkaria.postgresql.org; Tue, 10 Dec 2013 21:54:04 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.80) (envelope-from ) id 1VqVFi-0002Ho-SI for pgsql-performance@arkaria.postgresql.org; Tue, 10 Dec 2013 21:54:02 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1VqVFh-0002Hi-R0 for pgsql-performance@postgresql.org; Tue, 10 Dec 2013 21:54:02 +0000 Received: from nm29-vm4.bullet.mail.ne1.yahoo.com ([98.138.91.189]) by magus.postgresql.org with smtp (Exim 4.80) (envelope-from ) id 1VqVFd-0003J9-50 for pgsql-performance@postgresql.org; Tue, 10 Dec 2013 21:54:01 +0000 Received: from [98.138.100.117] by nm29.bullet.mail.ne1.yahoo.com with NNFMP; 10 Dec 2013 21:53:54 -0000 Received: from [98.138.89.160] by tm108.bullet.mail.ne1.yahoo.com with NNFMP; 10 Dec 2013 21:53:54 -0000 Received: from [127.0.0.1] by omp1016.mail.ne1.yahoo.com with NNFMP; 10 Dec 2013 21:53:54 -0000 X-Yahoo-Newman-Property: ymail-3 X-Yahoo-Newman-Id: 537232.55404.bm@omp1016.mail.ne1.yahoo.com Received: (qmail 84813 invoked by uid 60001); 10 Dec 2013 21:53:54 -0000 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=yahoo.com; s=s1024; t=1386712434; bh=a5rew5LTOkc1qEb8Izm31eLNpguyfcQ5FZGaaA++oSM=; h=X-YMail-OSG:Received:X-Rocket-MIMEInfo:X-Mailer:References:Message-ID:Date:From:Reply-To:Subject:To:Cc:In-Reply-To:MIME-Version:Content-Type; b=wkKKq8dV4M+OxrrQ5aA5e/PxaAXR0NNypk/lB8tb6PKQBMnW+hcZH2c9f8El4LvztNHcrPyvGbTP2ZGG8NCGee5OBnjE9NI1h+NIxl7Qlf+6Hm+KxphxtZqFwdc10aRiRndkgUq5qkXFR7RJw64Ii4J143wfSjp8/0VDb6kBCj0= DomainKey-Signature: a=rsa-sha1; q=dns; c=nofws; s=s1024; d=yahoo.com; h=X-YMail-OSG:Received:X-Rocket-MIMEInfo:X-Mailer:References:Message-ID:Date:From:Reply-To:Subject:To:Cc:In-Reply-To:MIME-Version:Content-Type; b=lKtmUl6p3GWTvweEHWxgGjLB558gFba+FqROit2iyGzAtZ955aJF7m8bjJ8xhnaA8Jt+YpWEl0X36ZI1OAkq84OI0PSm8r0VWNuR5/a3o8IQLCRjf2Toi6hgNLnrEaMI+R1vKNRZSd4CVCIJQgshLYmCnsAC2po8Y18gi1Sci7Y=; X-YMail-OSG: TaXbQAUVM1mlr_9FM01_du5W_MxzmqRsaScwGuyqsOHMksT HZP2uL9xLtsgUDP9TNHXYWhXqdFqw_LpVImSO4Tb0hkjJEvCqvjtvoDIoHYn cfSXM.oms7H42wU.87bVnIHA2UK.K40x.00N6LQcDJkO1DDXvwYI6WwuDtAc 8a9dOwmboZ5XBr2ntzvgxvqfX087AbQ.8plOS3h2thAJ423htQvgYRGmcka8 QZF3Wxqnij6PyOvuoUKwl5WtWxbjCDOjm80l3FDe6PDjDNLxDGLHa6Yd2Cnu vqao3BsFY1xYLKNQnczFtnJwY7LyBGEMlzUjYRl0AmaYcigB70E_4ZI49rGR M.ahkAiycjB8REmNXG4cqT5DiMH8LEEG43smsEPM7sHEmaJYmcYduFFJkaYd 31hvui.34.j98u28jq49bxwlfQ3RRVVo9Pvwh5zDYUphRR.zzycqqH6QVXjz 7mLbNFnHbkoE.JOVyh8.dKu_q_yZwxJyv2HBgp4_MLNtVxEz9IsP8.yNoZ29 2SzjKvKRRx.wbXr6spABnPFtXE4mHj0tVCeR..9OWAyhQqCNgrUdLmFKa19U CUujrSuC5BP4X.P0WvAeU1ekcsOZ_q0f6PnlSutyRU0Vj5sGk6w2_7ViSCgI iyLsRbQJf9kQ3vYmX07Rht8UljLkanevv9hjC41c7qUCp5hLk8yxGAOojIi9 mHxQ- Received: from [93.194.249.166] by web122201.mail.ne1.yahoo.com via HTTP; Tue, 10 Dec 2013 13:53:54 PST X-Rocket-MIMEInfo: 002.001, Cgo.Pj5PbiBUaHUsIERlY8KgIDUsIDIwMTMgYXQgMDk6MjI6MTRBTSAtMDUwMCwgVG9tIExhbmUgd3JvdGU6Cj4.PiBzYWxhaCBqdWJlaCA8c19qdWJlaEB5YWhvby5jb20.IHdyaXRlczoKPj4.IFdoZW4gSSBleGN1dGUgYSBxdWVyeSzvv710aGUgZXhlY3Rpb24gdGltZSBpcyBhYm91dCAxIG1pbnV0ZTsgCmhvd2V2ZXIsIHdoZW4gSSBleGVjdXRlIHRoZSBxdWVyeSB3aXRoIGV4cGxhaW4gYW5hbHl6ZSB0aGUgZXhjdXRpb24gdGltZQoganVtcHMgdG8gMTAgbWludXRlcy4gCj4.IAo.PiBUaGlzIGlzbid0IGUBMAEBAQE- X-Mailer: YahooMailWebService/0.8.169.609 References: <1386252540.32882.YahooMailNeo@web122206.mail.ne1.yahoo.com> <14363.1386253334@sss.pgh.pa.us> <20131210204009.GA14636@momjian.us> Message-ID: <1386712434.33313.YahooMailNeo@web122201.mail.ne1.yahoo.com> Date: Tue, 10 Dec 2013 13:53:54 -0800 (PST) From: salah jubeh Reply-To: salah jubeh Subject: Re: Explain analyze time overhead To: Bruce Momjian , Tom Lane Cc: "pgsql-performance@postgresql.org" In-Reply-To: <20131210204009.GA14636@momjian.us> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="-1572413313-1682259811-1386712434=:33313" X-Pg-Spam-Score: -2.2 (--) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org ---1572413313-1682259811-1386712434=:33313 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable =0A=0A>>>On Thu, Dec=C2=A0 5, 2013 at 09:22:14AM -0500, Tom Lane wrote:=0A>= >> salah jubeh writes:=0A>>> When I excute a query,=EF= =BF=BDthe exection time is about 1 minute; =0Ahowever, when I execute the q= uery with explain analyze the excution time=0A jumps to 10 minutes. =0A>> = =0A>> This isn't exactly unheard of, although it sounds like you have a=0A>= > particularly bad case.=C2=A0 Cheap commodity PCs tend to have clock hardw= are=0A>> that takes multiple microseconds to read ... which was fine thirty= years=0A>> ago when that hardware design was set, but with modern CPUs tha= t's=0A>> painfully slow.=0A>> =0A>> Short of getting a better machine, you = might look into whether you can run=0A>> a 64-bit instead of 32-bit operati= ng system.=C2=A0 In some cases that allows=0A>> a clock reading to happen w= ithout a context switch to the kernel.=0A>> =0A>> > This is a little bit st= arnge for me; did any one experience somthing like this? Can I trust the ge= nerated plans?=0A>> =0A>> The numbers are fine as far as they go, but you s= hould realize that the=0A>> relative cost of the cheaper plan nodes is bein= g overstated, since the=0A>> added instrumentation cost is the=0A same per = node call regardless of how=0A>> much work happens within the node.=0A=0A>T= he original poster might also want to run pg_test_timing to get=0A>hardware= timing overhead:=0A> =C2=A0 http://www.postgresql.org/docs/9.3/static/pgte= sttiming.html=0A=0AThanks for the link, I find it very useful,=C2=A0 unfort= unatly I am using 9.1.11 version. =0A=0AAfter digging a little bit, I find = out that the gettimeofday is indeed a little bit slower on this particular = machine than other machines, but it is not that significanat difference. Th= e query I am running is not optimized, and for some=C2=A0 reason the materi= al operator is the one which causes most of the overhead. The whole issue i= s due to cross colums statistics and highly correlated predicates, the numb= er of estimated records are much less than the actual number.=C2=A0 Still, = I did not understand completly, why the material operator consume about 9 m= inutes when I run explain analyze. i.e how many times we call gettimeofday = for the material operator -I need to calculate this-? Finally, for testing = purposes, I have disabled material=C2=A0 and the query execution time dropp= ed from 1 minute to 12 second.=0A=0ARegards=0A-- =0A=0A=0A=0AOn Tuesday, De= cember 10, 2013 9:42 PM, Bruce Momjian wrote:=0A =0AOn T= hu, Dec=C2=A0 5, 2013 at 09:22:14AM -0500, Tom Lane wrote:=0A> salah jubeh = writes:=0A> > When I excute a query,=EF=BF=BDthe execti= on time is about 1 minute; however, when I execute the query with explain a= nalyze the excution time jumps to 10 minutes. =0A> =0A> This isn't exactly = unheard of, although it sounds like you have a=0A> particularly bad case.= =C2=A0 Cheap commodity PCs tend to have clock hardware=0A> that takes multi= ple microseconds to read ... which was fine thirty years=0A> ago when that = hardware design was set, but with modern CPUs that's=0A> painfully slow.=0A= > =0A> Short of getting a better machine, you might look into whether you c= an run=0A> a 64-bit instead of 32-bit operating system.=C2=A0 In some cases= that allows=0A> a clock reading=0A to happen without a context switch to t= he kernel.=0A> =0A> > This is a little bit starnge for me; did any one expe= rience somthing like this? Can I trust the generated plans?=0A> =0A> The nu= mbers are fine as far as they go, but you should realize that the=0A> relat= ive cost of the cheaper plan nodes is being overstated, since the=0A> added= instrumentation cost is the same per node call regardless of how=0A> much = work happens within the node.=0A=0AThe original poster might also want to r= un pg_test_timing to get=0Ahardware timing overhead:=0A=0A=C2=A0=C2=A0=C2= =A0 http://www.postgresql.org/docs/9.3/static/pgtesttiming.html=0A=0A-- =0A= =C2=A0 Bruce Momjian=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 ht= tp://momjian.us=0A=C2=A0 EnterpriseDB=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 http://enterpri= sedb.com=0A=0A=C2=A0 + Everyone has their own god. +=0A=0A=0A-- =0ASent via= pgsql-performance mailing list (pgsql-performance@postgresql.org)=0ATo mak= e changes to your subscription:=0Ahttp://www.postgresql.org/mailpref/pgsql-= performance ---1572413313-1682259811-1386712434=:33313 Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: quoted-printable

&g= t;>>On Thu, Dec  5, 2013 at 09:22:14AM -0500, Tom Lane wrote:>>> salah jubeh <s_jubeh@yahoo.com> writes:
>>> When I excute a query,=EF=BF=BDthe exection time i= s about 1 minute; =0Ahowever, when I execute the query with explain analyze= the excution time=0A jumps to 10 minutes.
>>
>> This isn't exactly unheard of, although it sounds l= ike you have a
>> particularly bad case.  Chea= p commodity PCs tend to have clock hardware
>> that= takes multiple microseconds to read ... which was fine thirty years
>> ago when that hardware design was set, but with modern= CPUs that's
>> painfully slow.
&= gt;>
>> Short of getting a better machine, you = might look into whether you can run
>> a 64-bit ins= tead of 32-bit operating system.  In some cases that allows
>> a clock reading to happen without a context switch to th= e kernel.
>>
>> > This = is a little bit starnge for me; did any one experience somthing like this? = Can I trust the generated plans?
>>
>> The numbers are fine a= s far as they go, but you should realize that the
>>= ; relative cost of the cheaper plan nodes is being overstated, since the>> added instrumentation cost is the=0A same per node= call regardless of how
>> much work happens within= the node.

>The original poster mig= ht also want to run pg_test_timing to get
>hardware ti= ming overhead:
>   ht= tp://www.postgresql.org/docs/9.3/static/pgtesttiming.html

Thanks= for the link, I find it very useful,  unfortunatly I am using 9.1.11 = version.

After digging a little bit, I find out that the gettimeofd= ay is indeed a little bit slower on this particular machine than other mach= ines, but it is not that significanat difference. The query I am running is= not optimized, and for some  reason the material operator is the one = which causes most of the overhead. The whole issue is due to cross colums statistics and highly correlated predicates, the number of estimated recor= ds are much less than the actual number.  Still, I did not understand = completly, why the material operator consume about 9 minutes when I run exp= lain analyze. i.e how many times we call gettimeofday for the material oper= ator -I need to calculate this-? Finally, for testing purposes, I have disa= bled material  and the query execution time dropped from 1 minute to 1= 2 second.

Regards
--


On Tuesday, December 10, 2013 9:42 PM, Bruce Momjian <br= uce@momjian.us>=0A wrote:
On Thu, Dec  5, 2013 at 09:22:14AM -= 0500, Tom Lane wrote:
> salah jubeh <s_jubeh@yahoo.com> writes:
> > When I excute a query,=EF=BF=BDthe exection time is a= bout 1 minute; however, when I execute the query with explain analyze the e= xcution time jumps to 10 minutes.
>
> This isn't exactly unheard of, although it sounds like you have a> particularly bad case.  Cheap commodity PCs tend = to have clock hardware
> that takes multiple microseco= nds to read ... which was fine thirty years
> ago when= that hardware design was set, but with modern CPUs that's
> painfully slow.
>
> Short of getting a better machine, you might look into= whether you can run
> a 64-bit instead of 32-bit oper= ating system.  In some cases that allows
> a cloc= k reading=0A to happen without a context switch to the kernel.
>
> > This is a little bit starnge for me= ; did any one experience somthing like this? Can I trust the generated plan= s?
>
> The numbers are fine as f= ar as they go, but you should realize that the
> relat= ive cost of the cheaper plan nodes is being overstated, since the
> added instrumentation cost is the same per node call regardl= ess of how
> much work happens within the node.

The original poster might also want to run p= g_test_timing to get
hardware timing overhead:

    http://www.postgresql.org/docs/9.3/static/pgtesttimin= g.html

--
  Bruce Momjian  <bruce@momjian.us>  &nb= sp;     http://momjian.us
  Ente= rpriseDB                  &nbs= p;         http://enterprisedb.com
  + Everyone has their own god. +<= br clear=3D"none">

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


---1572413313-1682259811-1386712434=:33313--