Re: Why is JDBC so slow?

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 stored as 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 even if 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