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

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