Hibernation log
I am a bit stuck interpreting the hibernate session logs. The main problem I have is that a lot of requests are slow - based on some TimeWatch entries that I have implemented. To track down the problem, I turned on hibernation logging to see if time wasted making a request or getting a connection (which I think would mean misconfiguration).
A little about the use case - Oracle DB, Spring, Hibernate. In "Working time" there is a max. of 15 threads executing database queries. So nothing special, I would not have guessed.
Now I can see the hibernate session logs for example.
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 this mean?
What I am interpreting at the moment
- 1509926 nanoseconds to complete the request (1.5ms): seems ok
- 2893793341 nanoseconds to get a connection (2.8 sec): not valid :(
- 2893869403 nanoseconds to prepare the statement (2.8 sec): dislike :(
What does approval for preparation mean? From what I read from the javadoc, this could mean that the request is being sent to the database for optimization. But why is it always around the time when a connection is required?
Any tips on how to track down the problem, the root cause is even greater?
Or any hints as to what the problem might be?
Thank you for your help!
Regards, Stefan
source to share
Hibernate default statistics are not very informative. We plan to improve this aspect in a future version of Hibernate.
However, as I explained in my book , you can provide your own implementation Statistics
based on the Dropwizard metrics .
In short, if you have a class TransactionStatistics
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 an implementation StatisticsFactory
:
public class TransactionStatisticsFactory implements StatisticsFactory {
@Override
public StatisticsImplementor buildStatistics(SessionFactoryImplementor sessionFactory) {
return new TransactionStatistics();
}
}
And set it up like this:
Et voilà!
Now you can track and export statistics in any format supported by Dropwizard Metrics. Plus, Dropwizard Metrics uses a variety of reservoirs, so you can pick the best one for your use case.
To see the real power of Dropwizard metrics, also check out FlexyPool .
source to share