与JDBC (h2数据库)相比hibernate的长SQL查询

Question

我已经发布了一个相关的问题，但我在这里问这个问题，还有更多的细节：

我使用hibernate和以下代码从我的应用程序中执行SQL查询：

Query query = session.getNamedQuery("sql.namedquery.captureinfo");
Long t0 = System.currentTimeMillis();
List<Object[]> sqlList = query.list();
Long t1 = System.currentTimeMillis();
System.err.println("SQL query took" + (t1 - t0));

处理此查询的时间约为6s。我使用H2作为底层数据库。命名查询的定义如下：

<sql-query name="sql.namedquery.captureinfo">
<return-scalar column="eoid"                        type="int"/>
<return-scalar column="oid"                         type="int"/>
<return-scalar column="capture.obs_sys_id"          type="int"/>
<return-scalar column="capture.obs_mys_id"          type="int"/>
<return-scalar column="mid"                         type="int"/>
<return-scalar column="hdwr.type_hdwr"              type="string"/>
<return-scalar column="element_capture.description" type="string"/>
<return-scalar column="element_capture.dataf"       type="string"/>
<return-scalar column="geometrie.point"             type="materialized_blob"/>
<return-scalar column="geometrie.polygon"           type="materialized_blob"/>
<return-scalar column="element_capture.date_min"    type="date"/>
<return-scalar column="gid"                         type="int"/>
<return-scalar column="hdwr.nom"                    type="string"/>
select eo.id as eoid,o.id as oid,o.obs_sys_id,o.obs_mys_id,m.id as mid,m.type_hdwr,eo.description,eo.dataf,g.point,g.polygon,eo.date_min,g.id as gid,m.nom from element_capture eo left outer join geometrie g on eo.eo_geometrie_id = g.id left outer join hdwr m on eo.eo_hdwr_id = m.id left outer join capture o on eo.eo_capture_id = o.id
</sql-query>

使用用于H2的嵌入式second来执行完全相同的查询，它将在不到一秒钟的时间内执行。我还直接使用JDBC进行测试，以检查开销是否是由JDBC驱动程序造成的。以下是代码：

package test;
import java.sql.Blob;
import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.ResultSet;
import java.sql.SQLException;

public class JDBCTest
{

    public static void main(String[] args) throws ClassNotFoundException, SQLException
    {

        Class.forName("org.h2.Driver");

        Connection connection = DriverManager.getConnection("jdbc:h2:data/mydatabase", "XXX", "YYY");
        Long start = System.currentTimeMillis();

        String request =
            "select eo.id as eoid,o.id as oid,o.obs_sys_id,o.obs_mys_id,m.id as mid,m.type_hdwr,eo.description,eo.dataf,g.point,g.polygon,eo.date_min,g.id as gid,m.nom from element_capture eo left outer join geometrie g on eo.eo_geometrie_id = g.id left outer join hdwr m on eo.eo_hdwr_id = m.id left outer join capture o on eo.eo_capture_id = o.id";
        PreparedStatement statement = connection.prepareStatement(request);

        ResultSet res = statement.executeQuery();
        while(res.next())
        {
            System.out.println(res.getInt(1) + "|" + res.getInt(2) + "|" + res.getInt(3) + "|" + res.getInt(4) + "|"
                + res.getInt(5) + "|" + res.getString(6) + "|" + res.getString(7) + "|" + res.getString(8) + "|"
                + res.getDate(11) + "|" + res.getInt(12) + "|" + res.getString(13));
            Blob a = res.getBlob(9);
            Blob b = res.getBlob(10);
            a.getBytes(0, (int)a.length()); // make sure to stream out the blob
            //b.getBytes(0, (int)b.length());  // commented out as b is null in every record

        }
        Long end = System.currentTimeMillis();
        System.out.println((end - start) + "ms");
        res.close();
        statement.close();
        connection.close();
    }
}

执行这段代码也需要大约一秒钟的时间(包括在控制台中打印结果，从数据库检索6398条记录)。

因此，对于同一个查询，hibernate和JDBC版本之间存在相当大的开销，我不明白这一点。我希望能有一点点的开销，但没有那么多。我启用了hibernate的详细日志记录，下面是日志的开头：

11:42:49,083 TRACE QueryPlanCache:200 - Located native-sql query plan in cache (select eo.id as eoid,o.id as oid,o.obs_sys_id,o.obs_mys_id,m.id as mid,m.type_hdwr,eo.description,eo.dataf,g.point,g.polygon,eo.date_min,g.id as gid,m.nom from element_capture eo left outer join geometrie g on eo.eo_geometrie_id = g.id left outer join hdwr m on eo.eo_hdwr_id = m.id left outer join capture o on eo.eo_capture_id = o.id)
11:42:49,112 TRACE ConnectionProxyHandler:110 - Handling invocation of connection method [prepareStatement]
11:42:49,113 DEBUG LogicalConnectionImpl:295 - Obtaining JDBC connection
11:42:49,115 TRACE DriverManagerConnectionProviderImpl:171 - Total checked-out connections: 1
11:42:49,116 DEBUG DriverManagerConnectionProviderImpl:192 - Opening new JDBC connection
11:42:49,121 DEBUG DriverManagerConnectionProviderImpl:202 - Created connection to: jdbc:h2:data/mydatabase, Isolation Level: 2
11:42:49,122 DEBUG LogicalConnectionImpl:301 - Obtained JDBC connection
11:42:49,142 DEBUG SQL:104 - select eo.id as eoid,o.id as oid,o.obs_sys_id,o.obs_mys_id,m.id as mid,m.type_hdwr,eo.description,eo.dataf,g.point,g.polygon,eo.date_min,g.id as gid,m.nom from element_capture eo left outer join geometrie g on eo.eo_geometrie_id = g.id left outer join hdwr m on eo.eo_hdwr_id = m.id left outer join capture o on eo.eo_capture_id = o.id
11:42:49,144 TRACE JdbcResourceRegistryImpl:65 - Registering statement [org.hibernate.engine.jdbc.internal.proxy.PreparedStatementProxyHandler@bf831db[valid=true]]
11:42:49,146 TRACE JdbcResourceRegistryImpl:75 - Registering last query statement [org.hibernate.engine.jdbc.internal.proxy.PreparedStatementProxyHandler@bf831db[valid=true]]
11:42:49,146 TRACE AbstractStatementProxyHandler:88 - Handling invocation of statement method [getWrappedObject]
11:42:49,147 TRACE JdbcResourceRegistryImpl:75 - Registering last query statement [prep3: select eo.id as eoid,o.id as oid,o.obs_sys_id,o.obs_mys_id,m.id as mid,m.type_hdwr,eo.description,eo.dataf,g.point,g.polygon,eo.date_min,g.id as gid,m.nom from element_capture eo left outer join geometrie g on eo.eo_geometrie_id = g.id left outer join hdwr m on eo.eo_hdwr_id = m.id left outer join capture o on eo.eo_capture_id = o.id]
11:42:49,148 TRACE Loader:1798 - Bound [1] parameters total
11:42:49,148 TRACE AbstractStatementProxyHandler:88 - Handling invocation of statement method [executeQuery]
11:42:53,537 TRACE JdbcResourceRegistryImpl:118 - Registering result set [org.hibernate.engine.jdbc.internal.proxy.ResultSetProxyHandler@42ea7f9f[valid=true]]
11:42:53,538 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getStatement]
11:42:53,540 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getStatement]
11:42:53,540 TRACE Loader:870 - Processing result set
11:42:53,541 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [next]
11:42:53,542 DEBUG Loader:873 - Result set row: 0
11:42:53,544 DEBUG Loader:1377 - Result row: 
11:42:53,545 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getInt]
11:42:53,549 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,550 TRACE BasicExtractor:72 - Found [-6398] as column [eoid]
11:42:53,551 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getInt]
11:42:53,552 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,553 TRACE BasicExtractor:72 - Found [-6398] as column [oid]
11:42:53,554 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getInt]
11:42:53,555 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,556 TRACE BasicExtractor:72 - Found [-14] as column [capture.obs_sys_id]
11:42:53,557 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getInt]
11:42:53,558 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,558 TRACE BasicExtractor:72 - Found [13] as column [capture.obs_mys_id]
11:42:53,559 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getInt]
11:42:53,560 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,560 TRACE BasicExtractor:72 - Found [1] as column [mid]
11:42:53,561 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getString]
11:42:53,562 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,562 TRACE BasicExtractor:72 - Found [APN] as column [hdwr.type_hdwr]
11:42:53,563 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getString]
11:42:53,564 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,564 TRACE BasicExtractor:72 - Found [obsstatus=NON_VU;meta.filename=tap_1387464655536.zip] as column [element_capture.description]
11:42:53,565 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getString]
11:42:53,565 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,566 TRACE BasicExtractor:72 - Found [tap_1387464655536.jpg] as column [element_capture.dataf]
11:42:53,567 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getBlob]
11:42:53,590 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,591 TRACE BasicExtractor:72 - Found [[B@2dce2a8d] as column [geometrie.point]
11:42:53,592 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getBlob]
11:42:53,593 TRACE BasicExtractor:67 - Found [null] as column [geometrie.polygon]
11:42:53,596 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getDate]
11:42:53,598 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,599 TRACE BasicExtractor:72 - Found [2013-12-19] as column [element_capture.date_min]
11:42:53,600 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getInt]
11:42:53,602 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,603 TRACE BasicExtractor:72 - Found [-6412] as column [gid]
11:42:53,604 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getString]
11:42:53,605 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,606 TRACE BasicExtractor:72 - Found [TQ9GY] as column [hdwr.nom]
11:42:53,608 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [next]
11:42:53,609 DEBUG Loader:873 - Result set row: 1
11:42:53,610 DEBUG Loader:1377 - Result row: 
11:42:53,611 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getInt]
11:42:53,612 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,613 TRACE BasicExtractor:72 - Found [-6397] as column [eoid]
11:42:53,614 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getInt]
11:42:53,619 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,620 TRACE BasicExtractor:72 - Found [-6397] as column [oid]
11:42:53,621 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getInt]
11:42:53,623 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,624 TRACE BasicExtractor:72 - Found [-14] as column [capture.obs_sys_id]
11:42:53,625 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getInt]
11:42:53,626 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,627 TRACE BasicExtractor:72 - Found [13] as column [capture.obs_mys_id]
11:42:53,628 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getInt]
11:42:53,629 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,630 TRACE BasicExtractor:72 - Found [1] as column [mid]
11:42:53,631 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getString]
11:42:53,632 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,633 TRACE BasicExtractor:72 - Found [APN] as column [hdwr.type_hdwr]
11:42:53,634 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getString]
11:42:53,634 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,635 TRACE BasicExtractor:72 - Found [obsstatus=A_REVOIR;meta.filename=tap_1387464653290.zip] as column [element_capture.description]
11:42:53,636 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getString]
11:42:53,636 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,637 TRACE BasicExtractor:72 - Found [tap_1387464653290.jpg] as column [element_capture.dataf]
11:42:53,637 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getBlob]
11:42:53,639 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,639 TRACE BasicExtractor:72 - Found [[B@3f46a7e8] as column [geometrie.point]
11:42:53,640 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getBlob]
11:42:53,641 TRACE BasicExtractor:67 - Found [null] as column [geometrie.polygon]
11:42:53,642 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getDate]
11:42:53,644 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,645 TRACE BasicExtractor:72 - Found [2013-12-19] as column [element_capture.date_min]
11:42:53,646 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getInt]
11:42:53,647 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,647 TRACE BasicExtractor:72 - Found [-6411] as column [gid]
11:42:53,648 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [getString]
11:42:53,649 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [wasNull]
11:42:53,650 TRACE BasicExtractor:72 - Found [TQ9GY] as column [hdwr.nom]
11:42:53,650 TRACE AbstractResultSetProxyHandler:72 - Handling invocation of ResultSet method [next]
so on until  DEBUG Loader:873 - Result set row: 6397

正如您可以看到的那样，SQL查询返回标量值，而不是实体，因此没有由于实体管理而造成的开销。那么，hibernate在解析结果时执行的所有这些操作是否解释了这种极端的开销？我认为，在命名查询中为所有参数指定返回类型将简化hibernate作业，因为它不让它猜测结果类型。我还能做些什么来加快hibernate的速度？

Answer 1

具体地为标量定义结果类型似乎还不够，hibernate为解析结果集而产生的开销仍然很大。我特别为我的查询设置了一个PassThroughResultTransformer，与JDBC相比，它有效地加快了解析的速度，仅增加了一点点开销。我的问题的第一个代码摘录的修改如下：

Query query = session.getNamedQuery("sql.namedquery.captureinfo");
query.setResultTransformer(PassThroughResultTransformer.INSTANCE);
Long t0 = System.currentTimeMillis();
List<Object[]> sqlList = query.list();
Long t1 = System.currentTimeMillis();
System.err.println("SQL query took" + (t1 - t0));