Postgres Pro
Downloads
Home   >   mailing lists

Thread: BUG #6293: JDBC driver performance

BUG #6293: JDBC driver performance

From
"Teun Hoogendoorn"
Date:
The following bug has been logged online:

Bug reference:      6293
Logged by:          Teun Hoogendoorn
Email address:      th@atsc.nl
PostgreSQL version: 9.1
Operating system:   Linux
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.

Example:
LOG:  execute <unnamed>: SELECT c.oid, a.attnum, a.attname, c.relname,
n.nspname, a.attnotnull OR (t.typtype = 'd' AND t.typnotnull),
pg_catalog.pg_get_expr(d.adbin, d.adrelid) LIKE '%nextval(%' FROM
pg_catalog.pg_class c JOIN pg_catalog.pg_namespace n ON (c.relnamespace =
n.oid) JOIN pg_catalog.pg_attribute a ON (c.oid = a.attrelid) JOIN
pg_catalog.pg_type t ON (a.atttypid = t.oid) LEFT JOIN pg_catalog.pg_attrdef
d ON (d.adrelid = a.attrelid AND d.adnum = a.attnum) JOIN (SELECT 53886 AS
oid , 1 AS attnum UNION ALL SELECT 53886, 2 UNION ALL SELECT 53886, 3 UNION
ALL SELECT 53886, 4 UNION ALL SELECT 53886, 5 UNION ALL SELECT 53886, 6
UNION ALL SELECT 53886, 7 UNION ALL SELECT 53886, 8 UNION ALL SELECT 53886,
9 UNION ALL SELECT 53886, 10 UNION ALL SELECT 53886, 11 UNION ALL SELECT
53886, 12 UNION ALL SELECT 53886, 13 UNION ALL SELECT 53886, 14 UNION ALL
SELECT 53886, 15 UNION ALL SELECT 53886, 16 UNION ALL SELECT 53886, 17 UNION
ALL SELECT 53886, 18 UNION ALL SELECT 53886, 19 UNION ALL SELECT 53886, 20
UNION ALL SELECT 53886, 21 UNION ALL SELECT 53886, 22 UNION ALL SELECT
53886, 23 UNION ALL SELECT 53886, 24 UNION ALL SELECT 53886, 25 UNION ALL
SELECT 53886, 26 UNION ALL SELECT 53886, 27 UNION ALL SELECT 53886, 28 UNION
ALL SELECT 53886, 29 UNION ALL SELECT 53886, 30 UNION ALL SELECT 53886, 31
UNION ALL SELECT 53886, 32 UNION ALL SELECT 53886, 33 UNION ALL SELECT
53886, 34 UNION ALL SELECT 53886, 35 UNION ALL SELECT 53886, 36 UNION ALL
SELECT 53886, 37 UNION ALL SELECT 53886, 38 UNION ALL SELECT 53886, 39 UNION
ALL SELECT 53886, 40 UNION ALL SELECT 53886, 41 UNION ALL SELECT 53916, 1
UNION ALL SELECT 53916, 2 UNION ALL SELECT 53916, 3 UNION ALL SELECT 53916,
4 UNION ALL SELECT 53916, 5 UNION ALL SELECT 53916, 6 UNION ALL SELECT
53916, 7 UNION ALL SELECT 53916, 8 UNION ALL SELECT 53916, 9 UNION ALL
SELECT 53916, 10 UNION ALL SELECT 53916, 11 UNION ALL SELECT 53916, 12 UNION
ALL SELECT 53916, 13 UNION ALL SELECT 53916, 14 UNION ALL SELECT 53916, 15
UNION ALL SELECT 53916, 16 UNION ALL SELECT 53916, 17 UNION ALL SELECT
53916, 18 UNION ALL SELECT 53916, 19 UNION ALL SELECT 53916, 20) vals ON
(c.oid = vals.oid AND a.attnum = vals.attnum)

Re: BUG #6293: JDBC driver performance

From
Kris Jurka
Date:

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:

ResultSet rs = ...
ResultSetMetaData rsmd = rs.getMetaData();
for (int i=1; i<rsmd.getColumnCount(); i++) {
    // good
    System.out.println(rsmd.getAutoIncrement());
    // bad
    System.out.println(rs.getMetaData().getAutoIncrement());
}

The driver should probably be changed to hand back the same
ResultSetMetaData instance each time instead of a new one for each
MetaData call.

Does this explain your problem?  If not, can you provide more details on
how you access and use ResultSetMetaData?

Kris Jurka

Re: BUG #6293: JDBC driver performance

From
Teun Hoogendoorn
Date:
Hi Kris,
This is exactly what I'm doing. I understand your solution, but that's
not really an option for me (I have to change a lot of code).

Maybe the driver can cache the ResultSetMetaData for the ResultSet?
BTW. I looked into the driver code to look for a solution for my problem.
I came
across the following lines of code (in
AbstractJdbc2ResultSetMetaData.java):

Statement stmt = connection.createStatement();
        ResultSet rs = stmt.executeQuery(sql.toString());
        while (rs.next()) {
            int table = rs.getInt(1);
            int column = rs.getInt(2);
            String columnName = rs.getString(3);
            String tableName = rs.getString(4);
            String schemaName = rs.getString(5);
            int nullable = rs.getBoolean(6) ?
ResultSetMetaData.columnNoNulls : ResultSetMetaData.columnNullable;
            boolean autoIncrement = rs.getBoolean(7);
            for (int i=0; i<fields.length; i++) {
                if (fields[i].getTableOid() == table &&
fields[i].getPositionInTable() == column) {
                    fields[i].setColumnName(columnName);
                    fields[i].setTableName(tableName);
                    fields[i].setSchemaName(schemaName);
                    fields[i].setNullable(nullable);
                    fields[i].setAutoIncrement(autoIncrement);
                }
            }
        }

Shouldn't this ResultSet/Statement be closed?
Thanks,
Teun Hoogendoorn

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

From
Steven Schlansker
Date:
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