Skip site navigation (1) Skip section navigation (2)

Re: Why is PGStream.flush() taking so much time?

From: Oliver Jowett <oliver(at)opencloud(dot)com>
To: Guido Fiala <guido(dot)fiala(at)dka-gmbh(dot)de>
Cc: pgsql-jdbc(at)postgresql(dot)org
Subject: Re: Why is PGStream.flush() taking so much time?
Date: 2004-11-17 00:00:31
Message-ID: 419A949F.6010300@opencloud.com (view raw or flat)
Thread:
Lists: pgsql-jdbc
Guido Fiala wrote:
> Am Montag, 15. November 2004 20:15 schrieben Sie:
> 
>>Guido Fiala wrote:
>>
>>>Due to performance problems profiling showed the PGStream.flush() - thats
>>>pg_output buffered Stream - takes the most time although we do not really
>>>send much sql-queries at that time, at least we get much more data than
>>>we send. System and database is also almost idle at that time.
>>
>>Can you show us the whole profile? I can't see why flush() should be
>>expensive at all. Are you sure that you are not counting time spent
>>blocked in native code as busy time? (hprof likes to do that)
> 
> Used jtreeprofiler for that, and yes, after explizitely including 
> java.lang.Object things look different (although flush still shows up and 
> some other expensive things are there too):

I notice that jtreeprofiler appears to use the JVPMI 
GetCurrentThreadCpuTime() call to do its profiling measurements. I've 
found that this is quite unreliable in unpredicable ways -- you get 
random CPU time charged to your thread for no apparent reason. I gave up 
on building a profiler around it, it was so unreliable :(  It seems that 
there are weird things that happens such as the full CPU cost of any GCs 
that occur being charged to the thread that happens to be doing the 
allocation that triggers the GC, which massively skews the profile.

Anyway..

> method calls time   [ms]
> Object.wait 109 6035.474

There is no way that Object.wait() should take ~60ms per call. I don't 
trust this profile :(

> PGStream.ReceiveChar 789 1368.841

Again this is highly suspect, all this does is read a single character 
from a buffered input stream and that should not take 2ms even if you're 
running in fully interpreted mode.

> AbstractJdbc1ResultSet.findColumn 2923 425.492

Which driver version are you using? There was a recent fix to findColumn 
that should improve performance a lot if you are using findColumn() 
frequently on wide result sets.

> PGStream.flush 80 416.933

Again, very suspect, since all this does is flush the output stream, 
which at worst should turn into a write call on the underlying socket. 
That should not take 5ms per call.

[...]

It would be useful to know what JVM, JVM version, JDBC driver version, 
and CPU/OS you are using for profiling.. but I really don't trust these 
profiling results so far.

I've had some success with hprof's cpu=samples mode, some magic JVM 
options to turn off JIT inlining, and postprocessing of the output to 
eliminate time spent in methods that are known to be "mostly blocking" 
e.g. read(), select(). I can probably send you my Python analysis script 
if you want to go down that route.

I've also had success with OProfile plus some nasty hacks to push 
information about JIT compilation into the OProfile output so you get 
symbols for JITed code that lives in anonymous mmapped regions.. but 
that is considerably less releasable.

-O

In response to

pgsql-jdbc by date

Next:From: Kris JurkaDate: 2004-11-17 02:45:54
Subject: Re: JDBC calling PL/pgSQL with array parameter
Previous:From: Oliver JowettDate: 2004-11-16 23:47:21
Subject: Re: JDBC CTS 1.2.1

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group