休眠统计日志答案

【问题标题】：Hibernate Statistics Logging休眠统计日志
【发布时间】：2017-08-24 12:05:16
【问题描述】：

我在解释休眠会话日志时有点卡住了。我的主要问题是许多查询有点慢 - 基于我已经实现的一些 TimeWatch 日志记录。为了进一步追踪问题，我启用了休眠会话日志记录，目的是查看执行查询或获取连接的时间是否丢失（我猜这意味着配置错误）。

关于用例的一点点 - Oracle DB、Spring、Hibernate。在“忙碌的时候”有一个最大值。 15 个线程对数据库执行查询。所以没什么特别的，我猜。

现在我看到了类似的休眠会话日志。

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)

或

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)

但这究竟是什么意思？

我现在的解释

1509926 纳秒执行查询（1.5 毫秒）：似乎没问题
2893793341 纳秒获取连接（2.8 秒）：不正常 :(
2893869403 纳秒用于准备语句（2.8 秒）：不好 :(

准备语句是什么意思？根据我从 javadoc 中读到的内容，这可能意味着查询已发送到数据库进行优化。但是为什么总是在获取连接需求的时候呢？

关于如何进一步追查问题、根本原因的任何建议？

或者任何关于问题可能是什么的提示？

感谢您的帮助！

最好的问候，斯蒂芬

【问题讨论】：

我建议也提供DB连接池配置。
池：最小大小 2，最大大小 15 每个线程打开都有一个单独的事务，线程连接到不同的数据库（都具有相同的池设置）
当 SO 上的某人请求配置时，他希望看到实际配置（即 xml 或属性文件等）例如看这里：stackoverflow.com/a/11827895/25429。下一步是了解如何检查数据库连接池的日志。来自 c3p0 的关于此处连接的示例日志：stackoverflow.com/questions/11819610/… 它告诉池可以提供给应用程序的 4 个空闲连接。您应该查阅您正在使用的数据库池的文档。
还可以查看this article，它解释了当应用程序请求 JDBC 连接时会发生什么以及 DB 连接池如何提供帮助。在您的 Hibernate 会话中启用日志，您已经设法清除了“应用程序”框。链中要检查的下一件事是数据库连接池。如果在检查 DB 连接池行为后没有明显问题，您将不得不进一步要求 DB 管理员为您提供从 DB 角度观察事情的情况。

标签： oracle hibernate session logging jdbc

【解决方案1】：

默认的 Hibernate 统计信息不是很丰富。我们计划在 Hibernate 的未来版本中增强这一方面。

但是，您可以提供自己的 Statistics 实现，该实现建立在 Dropwizard Metrics 之上。

简而言之，假设您有一个扩展 org.hibernate.stat.internal.ConcurrentStatisticsImpl 的 TransactionStatistics 类：

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

您需要创建一个StatisticsFactory 实现：

public class TransactionStatisticsFactory implements StatisticsFactory {

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

并像这样配置它：

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

等等！

现在您可以监控统计数据并将其导出为 Dropwizard Metrics 支持的任何格式。而且，Dropwizard Metrics 使用各种 Reservoirs，因此您可以选择最适合您的用例的一个。

要了解 Dropwizard Metrics 的真正威力，请同时查看 FlexyPool。

【讨论】：