How to monitor slow SQL queries executed by JPA and Hibernate

Is there any Hibernate property I could set to see all the slow queries? I', interested in queries that take too much time to return the result set.

I'm using开发者_运维技巧 Spring with Hibernate, configured via an applicationContext.xml Spring configuration file.

---

Hibernate 5.4

This slow query log feature has been available since Hibernate ORM 5.4.5 and notifies you when the execution time of a given JPQL, Criteria API or native SQL query exceeds a certain threshold value you have previously configured.

Configuration

In order to activate the Hibernate slow query log, you need to set the hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS property to a value that's greater than 0, representing the query execution threshold.

In our case, any query that takes more than 25 milliseconds will trigger the Hibernate slow query log.

The Spring Boot configuration

If you're using Spring Boot, you can set this Hibernate setting in the application.properties configuration file:

spring.jpa.properties.hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS=25

The Java EE configuration

If you're using Java EE, you can set it in the persistence.xml configuration file:

<property
    name="hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS"
    value="25"
/>

Logger configuration

You also need to set org.hibernate.SQL_SLOW logger to at least the INFO level.

If you're using Logback, you can set it as follows:

<logger name="org.hibernate.SQL_SLOW" level="info"/>

That's it!

Testing time

Let's assume we have the following Post entity class defined in our application:

The Post entity is mapped as follows:

@Entity(name = "Post")
@Table(name = "post")
public class Post {
 
    @Id
    private Long id;
 
    private String title;
 
    @Column(name = "created_on")
    @CreationTimestamp
    private Date createdOn;
 
    @Column(name = "created_by")
    private String createdBy;
 
    //Getters and setters omitted for brevity
}

We will persist 5000 Post entities so that we have enough data to generate querie sthat take more than 25 milliseconds:

LongStream
.rangeClosed(1, 5000)
.forEach(i -> {
    entityManager.persist(
        new Post()
        .setId(i)
        .setTitle(
            String.format(
                "High-Performance Java Persistence book - page %d review",
                i
            )
        )
        .setCreatedBy("Vlad Mihalcea")
    );
     
    if(i % 50 == 0 && i > 0) {
        entityManager.flush();
    }
});

Detecting slow JPQL queries

When executing the following JPQL query:

List<Post> posts = entityManager
.createQuery(
    "select p " +
    "from Post p " +
    "where lower(title) like :titlePattern " +
    "order by p.createdOn desc", Post.class)
.setParameter(
    "titlePattern", 
    "%Java%book%review%".toLowerCase()
)
.setFirstResult(1000)
.setMaxResults(100)
.getResultList();

Hibernate generates the following slow query log entry:

o.h.SQL_SLOW -
    SlowQuery: 32 milliseconds.
    SQL:
    'PgPreparedStatement [
        select
            p.id as id1_0_,
            p.created_by as created_2_0_,
            p.created_on as created_3_0_,
            p.title as title4_0_
        from
            post p
        where lower(p.title) like '%java%book%review%'
        order by p.created_on desc
        limit 100
        offset 1000
    ]'

Detecting slow Criteria API queries

When executing this Criteria API query:

CriteriaBuilder builder = entityManager
    .getCriteriaBuilder();
 
CriteriaQuery<Post> postQuery = builder
    .createQuery(Post.class);
     
Root<Post> post = postQuery.from(Post.class);
 
postQuery
    .where(
        builder.like(
            builder.lower(post.get("title")),
            "%Java%book%review%".toLowerCase()
        )
    )
    .orderBy(
        builder.desc(post.get("createdOn"))
    );
 
List<Post> posts = entityManager.createQuery(
    postQuery
)
.setFirstResult(1000)
.setMaxResults(100)
.getResultList();

Hibernate generates a slow query log entry, like this one:

o.h.SQL_SLOW -
    SlowQuery: 27 milliseconds.
    SQL: 'PgPreparedStatement [
        select
            p.id as id1_0_,
            p.created_by as created_2_0_,
            p.created_on as created_3_0_,
            p.title as title4_0_
        from
            post p
        where
            lower(p.title) like '%java%book%review%'
        order by p.created_on desc
        limit 100
        offset 1000
    ]'

Detecting slow native SQL queries

List<Post> posts = entityManager
.createNativeQuery(
    "SELECT p.* " +
    "FROM post p " +
    "WHERE LOWER(p.title) LIKE :titlePattern " +
    "ORDER BY p.created_on DESC", Post.class)
.setParameter(
    "titlePattern",
    "%Java%book%review%".toLowerCase()
)
.setFirstResult(1000)
.setMaxResults(100)
.getResultList();

We get a slow query log message written by Hibernate:

o.h.SQL_SLOW -
    SlowQuery: 27 milliseconds.
    SQL: 'PgPreparedStatement [
        SELECT
            p.*
        FROM post
            p
        WHERE
            LOWER(p.title) LIKE '%java%book%review%'
        ORDER BY p.created_on DESC
        LIMIT 100
        OFFSET 1000
    ]'

In our case, the application query type doesn't influence the slow query log since both JPQL and Criteria API generate SQL queries that are similar to the native SQL one we used in the last test case.

---

I have 2 suggestions:

• you could use Oracle's Statspack.
• you could use some kind of JDBC proxy driver logging execution time P6Spy or log4jdbc.

I used P6Spy and IronTrack SQL from IronGrid in the past and this was a decent combo (see this blog post). But note that:

• P6Spy isn't really maintained (5 years without a change).
• The measures weren't totally accurate (that's not a huge problem when chasing greedy pigs).
• IronTrack SQL doesn't seem to be available anymore (but you can still find it, for example here).

I'm personally using log4jdbc now which provides similar features (without the fancy GUI but who cares, either use Excel or the script they provide to produce a report). From its website:

Features

• Full support for JDBC 3 and JDBC 4!
• Easy to configure, in most cases all you need to do is change the driver class name to net.sf.log4jdbc.DriverSpy and prepend "jdbc:log4" to your existing jdbc url, set up your logging categories and you're ready to go!
• In the logged output, for prepared statements, the bind arguments are automatically inserted into the SQL output. This greatly Improves readability and debugging for many cases.
• SQL timing information can be generated to help identify how long SQL statements take to run, helping to identify statements that are running too slowly and this data can be post processed with an included tool to produce profiling report data for quickly identifying slow SQL in your application.
• SQL connection number information is generated to help identify connection pooling or threading problems.
• Works with any underlying JDBC driver, with JDK 1.4 and above, and SLF4J 1.x.
• Open source software, licensed under the business friendly Apache 2.0 license: http://www.apache.org/licenses/LICENSE-2.0

---

You can enable logging of all SQL in the hibernate by setting the hibernate.show_sql property to true (see http://www.javalobby.org/java/forums/t44119.html). However there is no way to filter to only see slow queries. However, if you are using mysql you can enable its slow query log and see the queries that are slower than a set threshold there.

See: http://adminlinux.blogspot.com/2009/07/mysql-slow-queries-log.html

I'm sure most other databases will offer a similar feature.

---

This has been added natively in Hibernate 5.4.5.Final. The configuration parameter is available at AvailableSettings.LOG_SLOW_QUERY.

The description is:

Setting that logs query which executed slower than specified milliseconds. Default is 0 (disabled).