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

Am Mittwoch, 17. November 2004 01:00 schrieben Sie:
> Guido Fiala wrote:
> > 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.

Oh! Didn't hear about that. I started using "hprof" but found the output hard
to interpret (the top ~40 are just cryptically named? and took most time)

Ok, currently running:
AMD Duron 1GHz, 512 MB Ram
2.6.7-gentoo-r11
java -version "1.4.2_04 mixed mode", Sun
(no special options to the jvm)
postgresql-7.3.6-r2
jdbc-cvs-snapshot from 20040312

>
> > 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 :(

Well - if it waits 60ms for the socket?
>
> > 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.

Ok, i almost certainly don't have this, one thing to try (but i have only
around 10..20 columns in my ResultSets so far).

>
> > 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.

Exactly - i looked through the source code (nothing there but calls) , if
theres something taking time its in th jvm/native-code or its just bogus.

>
> [...]
>
> 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 would appriaciate it - still looking for a reliable way to profile...

How about java 1.5x ?

Guido