Relying on java.sql.ResultSet.findColumn(String) which throws SQLException is slow

[asherwin]

Some background info: after going through a bit of a nightmare trying
to maintain many ResultMaps for various levels associations, etc we
decided to maintain common ones and re-use them into larger "deep"
result maps per Object.  This approach is much simpler for us to
create and maintain, however we started to notice a performance
problem (but we were unaware it was related to this).

I spent my whole day today investigating what the performance problem
is and finally found it, and created a workaround to restore our
applications performance back to normal.

In org.apache.ibatis.executor.resultset.NestedResultSetHandler,
whenever ResultSet.getString(columnName) is invoked (there's a few
places, one of which his layered through the TypeHandler abstraction)
if the MyBatis ResultMap contains entries for columns which are not
returned by the ResultSet, ResultSet.getString(columnName) is throwing
SQLException.

I can see that this was known, and the exception is ignored as seen in
org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyForMappedProperties(ResultSet,
CacheKey, List<ResultMapping>)

Since we're using result maps which can have 4 .. 8 .. 12 levels of
associations and a SQL query which may return anywhere from a single
table, to joining all of its associations, this exception was being
silently ignored (a lot [read: the mapper method I was invoking was
resulting in this exception being thrown and silently ignored upwards
of 100,000 times per mapper invocation]).

Some basic profiling showed that a SQL query which utilized all of the
elements of a ResultMap averaged about .0028 ms per invocation of
org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyForMappedProperties(ResultSet,
CacheKey, List<ResultMapping>), where a SQL query which utilized only
a single table of a ResultMap with 7 associations (8 tables mapped
total), this
method averaged .312 ms per invocation, roughly 111 times slower, for
a query with 1,000 rows and about 40 result map entries with no
columns to  map to, this adds up to a significant amount of time very
quickly.

My workaround for now is to override the NestedResultSetHandler class,
I added this method:

  protected boolean resultSetHasColumn(final ResultSet rs, final
String column) {
    try {
      final ResultSetMetaData rsmd = rs.getMetaData();
      final int columnCount = rsmd.getColumnCount();
      for (int i = 1; i <= columnCount; i++) {
        final String label = rsmd.getColumnLabel(i);
        if (column.equalsIgnoreCase(label)) {
          return true;
        }
      }
    } catch (final SQLException e) {
      // ignore
    }
    return false;
  }

And I use it in:

org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyForMappedProperties(ResultSet,
CacheKey, List<ResultMapping>)

org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyForUnmappedProperties(ResultMap,
ResultSet, CacheKey)

and

org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyForMap(ResultSet,
CacheKey)

I simply check the new method at the beginning of each iteration,
after the columName String is set, and continue to the next iteration
if the column doesn't exist.

Some basic profiling showed a practical speed improvement of about
107x for this ResultMap situation (there is now no discernible
difference between a ResultMap that is not being fully filled in vs.
one that is).

[Clinton Begin]

Excellent post.  Thanks for this.  I do recall writing that code, and I hated it.  But I'm surprised that checking RSMD is faster... I specifically went with the exception thinking that it theoretically should be faster (even though it's a complete abuse of exceptions).  

If you can post this exact email body into an issue in the issue tracker, I'll see what I can do to get it in ASAP.  

I wonder if caching the columns from RSMD in a HashSet would be that much faster, to avoid the repeated iteration?

Clinton

On Tue, Sep 21, 2010 at 3:49 PM, asherwin <[hidden email]> wrote:

Some background info: after going through a bit of a nightmare trying
to maintain many ResultMaps for various levels associations, etc we
decided to maintain common ones and re-use them into larger "deep"
result maps per Object.  This approach is much simpler for us to
create and maintain, however we started to notice a performance
problem (but we were unaware it was related to this).

I spent my whole day today investigating what the performance problem
is and finally found it, and created a workaround to restore our
applications performance back to normal.

In org.apache.ibatis.executor.resultset.NestedResultSetHandler,
whenever ResultSet.getString(columnName) is invoked (there's a few
places, one of which his layered through the TypeHandler abstraction)
if the MyBatis ResultMap contains entries for columns which are not
returned by the ResultSet, ResultSet.getString(columnName) is throwing
SQLException.

I can see that this was known, and the exception is ignored as seen in
org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyForMappedProperties(ResultSet,
CacheKey, List<ResultMapping>)

Since we're using result maps which can have 4 .. 8 .. 12 levels of
associations and a SQL query which may return anywhere from a single
table, to joining all of its associations, this exception was being
silently ignored (a lot [read: the mapper method I was invoking was
resulting in this exception being thrown and silently ignored upwards
of 100,000 times per mapper invocation]).

Some basic profiling showed that a SQL query which utilized all of the
elements of a ResultMap averaged about .0028 ms per invocation of
org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyForMappedProperties(ResultSet,
CacheKey, List<ResultMapping>), where a SQL query which utilized only
a single table of a ResultMap with 7 associations (8 tables mapped
total), this
method averaged .312 ms per invocation, roughly 111 times slower, for
a query with 1,000 rows and about 40 result map entries with no
columns to  map to, this adds up to a significant amount of time very
quickly.

My workaround for now is to override the NestedResultSetHandler class,
I added this method:

 protected boolean resultSetHasColumn(final ResultSet rs, final
String column) {
   try {
     final ResultSetMetaData rsmd = rs.getMetaData();
     final int columnCount = rsmd.getColumnCount();
     for (int i = 1; i <= columnCount; i++) {
       final String label = rsmd.getColumnLabel(i);
       if (column.equalsIgnoreCase(label)) {
         return true;
       }
     }
   } catch (final SQLException e) {
     // ignore
   }
   return false;
 }

And I use it in:

org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyForMappedProperties(ResultSet,
CacheKey, List<ResultMapping>)

org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyForUnmappedProperties(ResultMap,
ResultSet, CacheKey)

and

org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyForMap(ResultSet,
CacheKey)

I simply check the new method at the beginning of each iteration,
after the columName String is set, and continue to the next iteration
if the column doesn't exist.

Some basic profiling showed a practical speed improvement of about
107x for this ResultMap situation (there is now no discernible
difference between a ResultMap that is not being fully filled in vs.
one that is).

[asherwin]

I'd like to note that there was a significant difference between
testing the impact of this usage of exceptions..

On my development laptop, a quad core i7 machine running windows 7 and
a jdk1.6.0_21 64-bit, the impact was not as significant as the
machine(s) we deploy our apps to.  Specifically, the machine I was
testing on that had the largest impact on performance was a dell
server with dual xeon 3.2ghz processors (total of 16 cores) running
solaris 10 x86_64 on jdk 1.6.0_21 64-bit.

It's hard to believe, but somehow the Windows JVM performs exception
handling better then the Solaris JVM (at least, in this case).

There was still a significant speed impact on the Windows JVM, just
not as pronounced as on Solaris.

On another note, I did consider caching the results but I wasn't 100%
clear on the lifecycle of a ResultSetHandler instance, and the
(hopefully temporary) fix I have performs  adequately and safely; but
I'm sure you can employ caching properly when fixing the issue with a
better knowledge of this objects lifecycle.

On Sep 21, 7:44 pm, Clinton Begin <[hidden email]> wrote:

> Excellent post.  Thanks for this.  I do recall writing that code, and I
> hated it.  But I'm surprised that checking RSMD is faster... I specifically
> went with the exception thinking that it theoretically should be faster
> (even though it's a complete abuse of exceptions).
>
> If you can post this exact email body into an issue in the issue tracker,
> I'll see what I can do to get it in ASAP.
>
> I wonder if caching the columns from RSMD in a HashSet would be that much
> faster, to avoid the repeated iteration?
>
> Clinton
>
>
>
> On Tue, Sep 21, 2010 at 3:49 PM, asherwin <[hidden email]> wrote:
> > Some background info: after going through a bit of a nightmare trying
> > to maintain many ResultMaps for various levels associations, etc we
> > decided to maintain common ones and re-use them into larger "deep"
> > result maps per Object.  This approach is much simpler for us to
> > create and maintain, however we started to notice a performance
> > problem (but we were unaware it was related to this).
>
> > I spent my whole day today investigating what the performance problem
> > is and finally found it, and created a workaround to restore our
> > applications performance back to normal.
>
> > In org.apache.ibatis.executor.resultset.NestedResultSetHandler,
> > whenever ResultSet.getString(columnName) is invoked (there's a few
> > places, one of which his layered through the TypeHandler abstraction)
> > if the MyBatis ResultMap contains entries for columns which are not
> > returned by the ResultSet, ResultSet.getString(columnName) is throwing
> > SQLException.
>
> > I can see that this was known, and the exception is ignored as seen in
>
> > org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyFor MappedProperties(ResultSet,
> > CacheKey, List<ResultMapping>)
>
> > Since we're using result maps which can have 4 .. 8 .. 12 levels of
> > associations and a SQL query which may return anywhere from a single
> > table, to joining all of its associations, this exception was being
> > silently ignored (a lot [read: the mapper method I was invoking was
> > resulting in this exception being thrown and silently ignored upwards
> > of 100,000 times per mapper invocation]).
>
> > Some basic profiling showed that a SQL query which utilized all of the
> > elements of a ResultMap averaged about .0028 ms per invocation of
>
> > org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyFor MappedProperties(ResultSet,
> > CacheKey, List<ResultMapping>), where a SQL query which utilized only
> > a single table of a ResultMap with 7 associations (8 tables mapped
> > total), this
> > method averaged .312 ms per invocation, roughly 111 times slower, for
> > a query with 1,000 rows and about 40 result map entries with no
> > columns to  map to, this adds up to a significant amount of time very
> > quickly.
>
> > My workaround for now is to override the NestedResultSetHandler class,
> > I added this method:
>
> >  protected boolean resultSetHasColumn(final ResultSet rs, final
> > String column) {
> >    try {
> >      final ResultSetMetaData rsmd = rs.getMetaData();
> >      final int columnCount = rsmd.getColumnCount();
> >      for (int i = 1; i <= columnCount; i++) {
> >        final String label = rsmd.getColumnLabel(i);
> >        if (column.equalsIgnoreCase(label)) {
> >          return true;
> >        }
> >      }
> >    } catch (final SQLException e) {
> >      // ignore
> >    }
> >    return false;
> >  }
>
> > And I use it in:
>
> > org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyFor MappedProperties(ResultSet,
> > CacheKey, List<ResultMapping>)
>
> > org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyFor UnmappedProperties(ResultMap,
> > ResultSet, CacheKey)
>
> > and
>
> > org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyFor Map(ResultSet,
> > CacheKey)
>
> > I simply check the new method at the beginning of each iteration,
> > after the columName String is set, and continue to the next iteration
> > if the column doesn't exist.
>
> > Some basic profiling showed a practical speed improvement of about
> > 107x for this ResultMap situation (there is now no discernible
> > difference between a ResultMap that is not being fully filled in vs.
> > one that is).

[asherwin]

Issue 114 created:

http://code.google.com/p/mybatis/issues/detail?id=114

On Sep 21, 7:44 pm, Clinton Begin <[hidden email]> wrote:

> Excellent post.  Thanks for this.  I do recall writing that code, and I
> hated it.  But I'm surprised that checking RSMD is faster... I specifically
> went with the exception thinking that it theoretically should be faster
> (even though it's a complete abuse of exceptions).
>
> If you can post this exact email body into an issue in the issue tracker,
> I'll see what I can do to get it in ASAP.
>
> I wonder if caching the columns from RSMD in a HashSet would be that much
> faster, to avoid the repeated iteration?
>
> Clinton
>
>
>
> On Tue, Sep 21, 2010 at 3:49 PM, asherwin <[hidden email]> wrote:
> > Some background info: after going through a bit of a nightmare trying
> > to maintain many ResultMaps for various levels associations, etc we
> > decided to maintain common ones and re-use them into larger "deep"
> > result maps per Object.  This approach is much simpler for us to
> > create and maintain, however we started to notice a performance
> > problem (but we were unaware it was related to this).
>
> > I spent my whole day today investigating what the performance problem
> > is and finally found it, and created a workaround to restore our
> > applications performance back to normal.
>
> > In org.apache.ibatis.executor.resultset.NestedResultSetHandler,
> > whenever ResultSet.getString(columnName) is invoked (there's a few
> > places, one of which his layered through the TypeHandler abstraction)
> > if the MyBatis ResultMap contains entries for columns which are not
> > returned by the ResultSet, ResultSet.getString(columnName) is throwing
> > SQLException.
>
> > I can see that this was known, and the exception is ignored as seen in
>
> > org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyFor MappedProperties(ResultSet,
> > CacheKey, List<ResultMapping>)
>
> > Since we're using result maps which can have 4 .. 8 .. 12 levels of
> > associations and a SQL query which may return anywhere from a single
> > table, to joining all of its associations, this exception was being
> > silently ignored (a lot [read: the mapper method I was invoking was
> > resulting in this exception being thrown and silently ignored upwards
> > of 100,000 times per mapper invocation]).
>
> > Some basic profiling showed that a SQL query which utilized all of the
> > elements of a ResultMap averaged about .0028 ms per invocation of
>
> > org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyFor MappedProperties(ResultSet,
> > CacheKey, List<ResultMapping>), where a SQL query which utilized only
> > a single table of a ResultMap with 7 associations (8 tables mapped
> > total), this
> > method averaged .312 ms per invocation, roughly 111 times slower, for
> > a query with 1,000 rows and about 40 result map entries with no
> > columns to  map to, this adds up to a significant amount of time very
> > quickly.
>
> > My workaround for now is to override the NestedResultSetHandler class,
> > I added this method:
>
> >  protected boolean resultSetHasColumn(final ResultSet rs, final
> > String column) {
> >    try {
> >      final ResultSetMetaData rsmd = rs.getMetaData();
> >      final int columnCount = rsmd.getColumnCount();
> >      for (int i = 1; i <= columnCount; i++) {
> >        final String label = rsmd.getColumnLabel(i);
> >        if (column.equalsIgnoreCase(label)) {
> >          return true;
> >        }
> >      }
> >    } catch (final SQLException e) {
> >      // ignore
> >    }
> >    return false;
> >  }
>
> > And I use it in:
>
> > org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyFor MappedProperties(ResultSet,
> > CacheKey, List<ResultMapping>)
>
> > org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyFor UnmappedProperties(ResultMap,
> > ResultSet, CacheKey)
>
> > and
>
> > org.apache.ibatis.executor.resultset.NestedResultSetHandler.createRowKeyFor Map(ResultSet,
> > CacheKey)
>
> > I simply check the new method at the beginning of each iteration,
> > after the columName String is set, and continue to the next iteration
> > if the column doesn't exist.
>
> > Some basic profiling showed a practical speed improvement of about
> > 107x for this ResultMap situation (there is now no discernible
> > difference between a ResultMap that is not being fully filled in vs.
> > one that is).