Re: Why is JDBC so slow? - Mailing list pgsql-jdbc

On Wed, Sep 03, 2003 at 09:59:51AM +1200, Oliver Jowett wrote:
> On Tue, Sep 02, 2003 at 02:05:15PM -0400, Joseph Shraibman wrote:
> > For this test I created a table named tt with ten entries in it.  These
> > selects thus select 10^6 rows.  As you can see time for jdbc is much
> > slower than psql.  Why is this?
>
> > ]$ time java -Xmx256m JDBCclient -U postgres -h localhost -c "select
> > 'blah' from tt tta, tt ttb, tt ttc, tt ttd, tt tte, tt ttf;" playpen >
> > /dev/null
> >
> > real    0m27.271s
> > user    0m21.040s
> > sys     0m0.710s
>
> With those heap settings you spend a lot of time doing GC. As pointed out by
> others you can reduce the memory footprint of the driver via setFetchSize().
> A quick estimate from the GC output shows that about 50% of allocations
> immediately become garbage, which can probably be improved on if it's coming
> from the driver. That's not an unusual allocation pattern for java programs,
> though.

Some quick heap profiling gives me (10^5 dataset):

          percent         live       alloc'ed  stack class
 rank   self  accum    bytes objs   bytes objs trace name
    1 31.39% 31.39%  9321928  272 9321928  272     1 [I
        (this is a profiling artifact)

    2  8.08% 39.47%  2400048 100002 2400048 100002   763 java.lang.String
        org.postgresql.core.Encoding.decodeUTF8(Encoding.java:283)
        org.postgresql.core.Encoding.decode(Encoding.java:181)
        org.postgresql.core.Encoding.decode(Encoding.java:197)
        org.postgresql.jdbc1.AbstractJdbc1ResultSet.getString(AbstractJdbc1ResultSet.java:179)

    3  8.08% 47.55%  2400048 100002 2400048 100002   764 [C
        java.lang.String.<init>(String.java:200)
        org.postgresql.core.Encoding.decodeUTF8(Encoding.java:283)
        org.postgresql.core.Encoding.decode(Encoding.java:181)
        org.postgresql.core.Encoding.decode(Encoding.java:197)

    4  5.39% 52.94%  1600160 100004 1600160 100004   709 [B
        org.postgresql.core.PGStream.Receive(PGStream.java:369)
        org.postgresql.core.PGStream.ReceiveTupleV2(PGStream.java:354)
        org.postgresql.core.QueryExecutor.receiveTupleV2(QueryExecutor.java:399)
        org.postgresql.core.QueryExecutor.executeV2(QueryExecutor.java:247)

    5  5.39% 58.33%  1600064 100004 1600064 100004   708 [B
        org.postgresql.core.PGStream.ReceiveTupleV2(PGStream.java:331)
        org.postgresql.core.QueryExecutor.receiveTupleV2(QueryExecutor.java:399)
        org.postgresql.core.QueryExecutor.executeV2(QueryExecutor.java:247)
        org.postgresql.core.QueryExecutor.execute(QueryExecutor.java:104)

    6  5.39% 63.71%  1600056 100003 1600056 100003   708 <Unknown_class>
        (same trace as above; this appears to be a byte[][] object)

    7  5.39% 69.10%  1600048 100003 1600048 100003   707 [B
        org.postgresql.core.PGStream.Receive(PGStream.java:369)
        org.postgresql.core.PGStream.ReceiveTupleV2(PGStream.java:330)
        org.postgresql.core.QueryExecutor.receiveTupleV2(QueryExecutor.java:399)
        org.postgresql.core.QueryExecutor.executeV2(QueryExecutor.java:247)

    8  5.39% 74.49%  1600000 100000 1600000 100000   795 java.lang.Object
        JDBCclient.getResults(JDBCclient.java:26)
        JDBCclient.doQuery(JDBCclient.java:15)
        JDBCclient.main(JDBCclient.java:95)

    9  5.39% 79.88%  1600000 100000 1600000 100000   815 java.lang.Integer
        org.postgresql.jdbc1.AbstractJdbc1Connection.getPGType(AbstractJdbc1Connection.java:1670)
        org.postgresql.core.Field.getPGType(Field.java:100)
        org.postgresql.jdbc2.AbstractJdbc2ResultSet.getObject(AbstractJdbc2ResultSet.java:150)
        JDBCclient.getResults(JDBCclient.java:30)

   10  5.39% 85.26%  1600000 100000 1600000 100000   797 java.lang.Integer
        org.postgresql.jdbc1.AbstractJdbc1Connection.getSQLType(AbstractJdbc1Connection.java:1593)
        org.postgresql.core.Field.getSQLType(Field.java:111)
        org.postgresql.jdbc2.AbstractJdbc2ResultSet.getObject(AbstractJdbc2ResultSet.java:105)
        JDBCclient.getResults(JDBCclient.java:30)

   11  5.39% 90.65%  1600000 100000 1600000 100000   796 <Unknown_class>
        org.postgresql.jdbc1.AbstractJdbc1ResultSet.next(AbstractJdbc1ResultSet.java:152)
        JDBCclient.getResults(JDBCclient.java:28)
        JDBCclient.doQuery(JDBCclient.java:15)
        JDBCclient.main(JDBCclient.java:95)

   12  4.41% 95.06%  1310864   14 1310864   14   785 java.lang.Object
        java.util.Vector.ensureCapacityHelper(Vector.java:222)
        java.util.Vector.addElement(Vector.java:584)
        org.postgresql.core.QueryExecutor.receiveTupleV2(QueryExecutor.java:403)
        org.postgresql.core.QueryExecutor.executeV2(QueryExecutor.java:247)

   13  1.35% 96.41%   400016    1  400016    1   795 <Unknown_class>
        JDBCclient.getResults(JDBCclient.java:26)
        JDBCclient.doQuery(JDBCclient.java:15)
        JDBCclient.main(JDBCclient.java:95)

Of these:

 #1 is a profiling artifact.
 #2 and #3 are unavoidable without changing the client.
 #4, #5, #7 are unavoidable without using setFetchSize() or a major resultset overhaul (resultsets are internally
storedas a byte[][]) 
 #8 is directly client-generated.
 #9, #10 could be fixed (temporary Integer objects used only to key the oid/type caches)
 #11 could be fixed (row_buffer is reallocated on every row even if it has not changed size.. and is always copied into
evenif no updates are ever done) 
 #12 is unavoidable unless the backend protocol provides a row count ahead of time (I don't think it does?)
 #13 is directly client-generated.

So some lowhanging fruit there, but not much.

-O