java - 为什么通过主键进行简单的 Hibernate findOne() 需要这么长时间？

Question

我将它从 an earlier question 中分离出来，以消除“保存前选择”的混淆。在这个例子中，我试图通过主键做一个简单的 findOne() 。这是针对现有的 sqlserver 数据库，具有最新版本的 spring boot 和 spring 数据。

我设置了日志记录，所以我可以看到 hibernate 生成的 sql。本例中，根据日志记录时间，本次查询耗时约4秒。这是使用主键查询。当我运行 hibernate 在 dbvisualizer 等数据库工具中生成的 sql 时，它会在亚秒内返回，正如我所期望的那样。

我将 hibernate 打包日志记录增加到 TRACE 级别，试图查看延迟的位置，并在 4 秒延迟之前和之后发现以下内容:

2017-08-14 09:51:35.345 DEBUG 7532 --- [nio-8085-exec-1] org.hibernate.SQL                        : select customer0_.customer_id as customer1_4_0_, customer0_.first_name as first_na2_4_0_, customer0_.last_name as last_nam3_4_0_ from xbr_customer_tab customer0_ where customer0_.customer_id=?
Hibernate: select customer0_.customer_id as customer1_4_0_, customer0_.first_name as first_na2_4_0_, customer0_.last_name as last_nam3_4_0_ from xbr_customer_tab customer0_ where customer0_.customer_id=?
2017-08-14 09:51:35.470 TRACE 7532 --- [nio-8085-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy[Proxy=25287222; Query=select customer0_.customer_id as customer1_4_0_, customer0_.first_name as first_na2_4_0_, customer0_.last_name as last_nam3_4_0_ from xbr_customer_tab customer0_ where customer0_.customer_id=?; Delegate=SQLServerPreparedStatement:6]]
2017-08-14 09:51:35.471 TRACE 7532 --- [nio-8085-exec-1] o.h.e.jdbc.internal.JdbcCoordinatorImpl  : Registering last query statement [org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy[Proxy=25287222; Query=select customer0_.customer_id as customer1_4_0_, customer0_.first_name as first_na2_4_0_, customer0_.last_name as last_nam3_4_0_ from xbr_customer_tab customer0_ where customer0_.customer_id=?; Delegate=SQLServerPreparedStatement:6]]
2017-08-14 09:51:35.479 TRACE 7532 --- [nio-8085-exec-1] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [VARCHAR] - [40666316]
2017-08-14 09:51:35.488 TRACE 7532 --- [nio-8085-exec-1] o.h.l.p.e.i.AbstractLoadPlanBasedLoader  : Bound [2] parameters total
2017-08-14 09:51:39.426 TRACE 7532 --- [nio-8085-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering result set [SQLServerResultSet:6]
2017-08-14 09:51:39.434 TRACE 7532 --- [nio-8085-exec-1] o.h.l.p.e.p.i.ResultSetProcessorImpl     : Processing result set
2017-08-14 09:51:39.434 DEBUG 7532 --- [nio-8085-exec-1] o.h.l.p.e.p.i.ResultSetProcessorImpl     : Starting ResultSet row #0
2017-08-14 09:51:39.436 DEBUG 7532 --- [nio-8085-exec-1] l.p.e.p.i.EntityReferenceInitializerImpl : On call to EntityIdentifierReaderImpl#resolve, EntityKey was already known; should only happen on root returns with an optional identifier specified
2017-08-14 09:51:39.436 TRACE 7532 --- [nio-8085-exec-1] l.p.e.p.i.EntityReferenceInitializerImpl : hydrating entity state

我也想知道为什么它说绑定(bind)了 2 个参数，而 sql 中只有 1 个参数。

知道为什么这个选择要花这么长时间吗？特别是只在我的 spring 应用程序中，而不是在 dbvisualizer 等其他客户端中？

这是实体:

import javax.persistence.Entity;
import javax.persistence.Id;
import javax.persistence.Table;

@Entity
@Table(name = "my_customer_table")
public class Customer {

    @Id
    private String customer_id;
    private String first_name;
    private String last_name;

    protected Customer() {}


    public Customer(String firstName, String lastName) {
        this.first_name = firstName;
        this.last_name = lastName;
    }

}

这是 CustomerRepository

import com.....Customer;
import org.springframework.data.repository.CrudRepository;

public interface CustomerRepository extends CrudRepository<Customer, String> {
}

以及从 @Service 类中查找客户的代码，其中 CustomerRepository 位于 @Autowired 中:

Customer customer = customerRepository.findOne(customerId);

这里是生成的sql:

select customer0_.customer_id as customer1_4_0_, customer0_.first_name as first_na2_4_0_, customer0_.last_name as last_nam3_4_0_ from my_customer_table customer0_ where customer0_.customer_id=?

Answer 1

通过将以下参数添加到数据源中的连接字符串来修复。

sendStringParametersAsUnicode=false 

更多细节: http://www.jochenhebbrecht.be/site/2014-05-01/java/fixing-slow-queries-running-sql-server-using-jpa-hibernate-and-jtds