Why is a simple Hibernate findOne() by primary key taking so long?

Question

I'm splitting this off from an earlier question to eliminate the 'select before save' confusion. In this example, I'm trying to do a simple findOne() by primary key. This is against an existing sqlserver db, with the latest versions of spring boot and spring data.

I have the logging set so I can see the sql that hibernate has generated. In this example, according to the logging timing, this query takes about 4 seconds. This is querying with a primary key. When I run the sql that hibernate generated in a db tool like dbvisualizer, it returns in sub-second, as I would expect.

I increased the hibernate packaging logging to TRACE level, to try to see where the delay is, and found the following, before and after the 4 second delay:

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

I'm also wondering why it says 2 parameters bound, when there was only 1 in the sql.

Any ideas why this select is taking so long? Especially only in my spring app, and not in another client like dbvisualizer?

Here is the entity:

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;
    }

}

Here's the CustomerRepository

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

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

and the code to look up a Customer, from a @Service class where CustomerRepository is @Autowired in:

Customer customer = customerRepository.findOne(customerId);

Here is the generated 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=?

..and why is it binding as `VARCHAR`. Oh, your primary key is a varchar...that's an interesting choice. — Kayaman, Aug 14 '17 at 15:31
primary key as varchar...yea like I said, pre-existing db...not sure who did it or when; we're writing a new app against this old db — user26270, Aug 14 '17 at 15:33
@AmerQarabsa there's plenty more logging; how much do you want? — user26270, Aug 14 '17 at 15:34
@user26270, could it be blocking occurs while the query is being run from the app code? Try capturing rpc_starting and rpc_completed events using a SQL Server extended events trace. That will verify the server execution time. The number of logical reads should be single-digits with a single-row select by the PK index. — Dan Guzman, Aug 14 '17 at 15:43

score 2 · Answer 1 · answered Aug 14 '17 at 19:28

2

Fixed by adding the following parameter to your connection string in the datasource.

sendStringParametersAsUnicode=false

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

answered Aug 14 '17 at 19:28

user26270

6,904
13
62
94

wow, this parameter reduced our average query time by a factor of 10, thanks a lot! – m.w. Mar 26 '19 at 08:58

Why is a simple Hibernate findOne() by primary key taking so long?

1 Answers1