Re: [JDBC] BUG #6293: JDBC driver performance

On Nov 16, 2011, at 1:29 PM, Kris Jurka wrote:

>
>
> On Tue, 15 Nov 2011, Teun Hoogendoorn wrote:
>
>>
>> The following bug has been logged online:
>>
>> Bug reference: 6293
>> PostgreSQL version: 9.1
>> Description: JDBC driver performance
>> Details:
>>
>> Using the postgresql-9.1-901.jdbc3.jar driver instead of
>> postgresql-9.0-801.jdbc3.jar drops performance dramatically.
>>
>> I think it has something to do with using ResultSetMetaData in Java. The
>> postgres log shows me hundreds of identical query's when retrieving the
>> ResultSetMetaData for a single query. I'm not using an ORM framework, just
>> simple JDBC calls.
>
> The 9.1 JDBC driver was changed to try and fetch all metadata for the
> entire resultset in one query instead of potentially issuing multiple
> queries for each column. So this change was supposed to improve things.
>
> Looking at the code, the caching pattern has changed slightly, so now it's
> important to hold onto the same ResultSetMetaData instance. That is you
> need to do:
>
...
>
> Does this explain your problem? If not, can you provide more details on
> how you access and use ResultSetMetaData?

I can independently confirm this problem, and it was quite a surprise to
us when we upgraded!

There is another unfortunate side effect - the updateXXX methods
(i.e. AbstractJdbc2ResultSet.updateString) now are horrifyingly slow. Every
invocation seems to call AbstractJdbc2ResultSetMetaData.getBaseColumnName on
a *new* ResultSetMetaData. We have some code which reads like:

row.updateString("address", addr.getAddress());
row.updateString("address2", addr.getAddress2());
row.updateString("city", addr.getCity());
row.updateString("state", addr.getState());
row.updateString("zip", addr.getPostalCode());
… (snip 20-some similar lines)

Each of these does (AbstractJdbc2ResultSet:2932)

PGResultSetMetaData md = (PGResultSetMetaData)getMetaData();
updateValues.put(md.getBaseColumnName(columnIndex), value);

And each getMetaData() gets a new one (Jdbc4ResultSet:31)

public java.sql.ResultSetMetaData getMetaData() throws SQLException
{
checkClosed();
return new Jdbc4ResultSetMetaData(connection, fields);
}

Which then builds the huge query referred to in the original bug report.
On my (very small) database, it takes ~400ms to execute the giant query
that is constructed.

So the end result is that something that used to work now becomes
terrifyingly slow if you update to 9.1-901.

You can definitely argue that doing a bunch of updateString calls is not
the right thing to do, but this *did* use to work so I would call this
a potentially very serious regression.

An easy way to mitigate this a little bit would be to cache the metadata
within the ResultSet so it is only constructed once. This would alleviate
the immediate problem from my viewpoint.

If you would like more information, I do have the problem reproduced here
in a controlled environment and would love nothing more than to test
patches or provide whatever information might be helpful to fix this bug.
I'll even throw in a patch if you can tell me the "right" way to fix this :-)

Regards,
Steven Schlansker