CODEWITHSUNDEEP
oracle-databasehibernatesessionloggingjdbc
StrongSteve
StrongSteve

Reputation: 91

Hibernate Statistics Logging

I am a little stuck interpreting hibernate session logs. I have the main problem that many queries are kind of slow - based on some TimeWatch loggings I have implemented. To track down the problem further I have enabled hibernate session logging with the goal of seeing if the time is lost for executing the query or for getting a connection (which would mean a misconfiguration, I guess).

Little bit about the use case - Oracle DB, Spring, Hibernate. At "busy times" there are a max. of 15 threads executing queries against the database. So nothing special, I would guess.

Now I see hibernate session logs like.

2017-03-30 13:35:13.834+0200 [process-documents-task-6] I [/] o.h.e.i.StatisticalLoggingSessionEventListener - Session Metrics {
    636713687 nanoseconds spent acquiring 1 JDBC connections;
    57993 nanoseconds spent releasing 1 JDBC connections;
    636859879 nanoseconds spent preparing 1 JDBC statements;
    2231526 nanoseconds spent executing 1 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    9261 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)

or 

2017-03-30 13:35:16.073+0200 [process-documents-task-8] I [/] o.h.e.i.StatisticalLoggingSessionEventListener - Session Metrics {
    2893793341 nanoseconds spent acquiring 1 JDBC connections;
    22196 nanoseconds spent releasing 1 JDBC connections;
    2893869403 nanoseconds spent preparing 1 JDBC statements;
    1509926 nanoseconds spent executing 1 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    4056 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)

But what exactly does that mean?

What I interpret at the moment

What does preparing statement mean? From what I read from the javadoc it can mean that the query is sent to the database for optimization. But why is it always around the time acquiring a connection needs?

Any advice on how to track down the problem, root cause even further?

Or any hints on what the problem could be?

Thanks for your help!

Best regards, Stefan

Upvotes: 4

Views: 2133

Answers (1)

Vlad Mihalcea
Vlad Mihalcea

Reputation: 153890

The default Hibernate statistics are not very informative. We plan on enhancing this aspect in a future version of Hibernate.

However, you can provide your own Statistics implementation that builds on top of Dropwizard Metrics.

In short, assuming you have a TransactionStatistics class that extends org.hibernate.stat.internal.ConcurrentStatisticsImpl:

public class TransactionStatistics extends ConcurrentStatisticsImpl {

    private static final ThreadLocal<AtomicLong> startNanos = new ThreadLocal<AtomicLong>() {
        @Override protected AtomicLong initialValue() {
            return new AtomicLong();
        }
    };

    private static final ThreadLocal<AtomicLong> connectionCounter = new ThreadLocal<AtomicLong>() {
        @Override protected AtomicLong initialValue() {
            return new AtomicLong();
        }
    };

    private StatisticsReport report = new StatisticsReport();

    @Override public void connect() {
        connectionCounter.get().incrementAndGet();
        startNanos.get().compareAndSet(0, System.nanoTime());
        super.connect();
    }

    @Override public void endTransaction(boolean success) {
        try {
            report.transactionTime(System.nanoTime() - startNanos.get().get());
            report.connectionsCount(connectionCounter.get().get());
            report.generate();
        } finally {
            startNanos.remove();
            connectionCounter.remove();
        }
        super.endTransaction(success);
    }
}

You need to create a StatisticsFactory implementation:

public class TransactionStatisticsFactory implements StatisticsFactory {

    @Override
    public StatisticsImplementor buildStatistics(SessionFactoryImplementor sessionFactory) {
        return new TransactionStatistics();
    }
}

And configure it like this:

<property 
    name="hibernate.stats.factory", 
    value="com.vladmihalcea.book.hpjp.hibernate.statistics.TransactionStatisticsFactory"
/>

Et voilà!

Now you can monitor and export statistics to any format that Dropwizard Metrics supports. And, Dropwizard Metrics uses various Reservoirs, so you can choose the best one for your use case.

To see the real power for Dropwizard Metrics, check out FlexyPool as well.

Upvotes: 1

Related Questions