并发日志记录到 sql DB - 线程不并行运行

编程问答 2022-05-27

问题描述

我用 2.14.0 和 2.13.3 对此进行了测试 我将 JDBC Appender 与 DynamicThresholdFilter 结合使用，并尝试了一个普通的 Logger 以及 AsyncLogger。

在 JDBC Appender 中，我还尝试了 PoolingDriver 和 ConnectionFactory 方法。

事实证明，由于 Log4j2，线程没有并行启动。

使用 AsyncLogger 甚至使情况变得更糟，因为输出表示 Appender 未启动，并且在 15.000 个预期日志中只有 13.517 个在数据库中。

为了重现这个问题，我做了一个 github repo，请参见此处：https://github.com/stefanwendelmann/Log4j_JDBC_Test

Threads

编辑

我用 h2db 替换了 mssql-jdbc，并且线程不会阻塞。 JMC自动分析说有JdbcDatabaseManager的锁定实例。

我的 mssql-jdbc 的 PoolableConnectionFactory 是否有任何配置问题，或者 dbcp/jdbc 驱动程序池是否存在一般问题？

编辑 2

在 Apaches LOGJ2 Jira 上创建的票证：https://issues.apache.org/jira/browse/LOG4J2-3022

编辑 3

为 mssql 和 h2:file 添加了更长的飞行记录

https://github.com/stefanwendelmann/Log4j_JDBC_Test/blob/main/recording_local_docker_mssql_asynclogger_10000_runs.jfr

https://github.com/stefanwendelmann/Log4j_JDBC_Test/blob/main/recording_local_h2_file_asynclogger_10000_runs.jfr

解决方法

感谢您获取飞行记录。这是一个非常有趣的场景，但恐怕我无法给出结论性的答案，主要是因为某些原因

  1. 您的飞行记录中的信息非常不完整。我会稍微解释一下
  2. 您的系统中似乎还有其他事情可能会混淆诊断。您可能会因终止机器中正在运行的任何其他进程而受益。

那么，现在怎么办/（TL;DR）

  1. 你需要确保你的数据库连接源是池化的
  2. 确保在冷静、头脑清醒的 CPU 上开始负载测试
  3. 配置您的下一次飞行记录以进行足够的、间歇性的线程转储。如果您有兴趣弄清楚所有这些线程究竟在等待什么，这可能是最重要的下一步。不要发布另一个飞行记录，除非您确定它包含多个线程转储，这些转储具有所有 JVM 中的实时线程。
  4. 也许 10k 个线程对您的本地机器不合理
  5. 我还从飞行记录中注意到您的堆大小最大为 7GB。如果您使用的不是 64 位操作系统，那实际上可能是有害的。 32 位操作系统最多可寻址 4GB。
  6. 确保没有任何实际的数据库故障导致整个过程崩溃。你的连接用完了吗？是否有任何 SQLExceptions 在某处爆炸？有什么例外吗？

以下是我从你的录音中可以看出的：

中央处理器

两个飞行记录都显示您的 CPU 正在挣扎，以获取您两个记录的大部分内容：

MSSQL 录音（共 46 分钟）

enter image description here

JFR 甚至在 MSSQL 记录中警告：

42% 的平均 CPU 负载是由其他进程在 2/18/21 7:28:58 AM 开始的 1 分 17 秒内引起的。

H2 录音（共 20.3 秒）enter image description here

我注意到您的飞行记录标题为 XXXX_10000。如果这意味着“10k 并发请求”，则可能只是意味着您的机器根本无法处理您施加的负载。在开始另一项测试之前，首先确保您的核心没有一堆其他事情占用他们的时间，您也可能会受益。无论如何，由于上下文切换，达到 100% CPU 利用率必然会导致锁争用。您的飞行记录显示您在 8 核机器上运行；但是您注意到您正在运行一个 dockerized MSSQL。您为 Docker 分配了多少个内核？

阻塞的线程

您的设置中有很多障碍，而且到处都是冒烟的枪。由 Log4j2-TF-1-AsyncLoggerConfig-1 标识的线程被垃圾收集器阻塞了很多，就在 CPU 抖动时：

H2 飞行记录：

enter image description here

该图中除了最后 3 个滴答声之外，所有的滴答声都是 log4j2 线程的阻塞。 GC 仍然严重阻塞了其他池线程（更多相关内容）

MSSQL 飞行记录的 GC 更流畅，但两个飞行记录都存在 GC 阻塞和随之而来的超高 CPU 使用率。从 MSSQL 和 H2 记录中可以清楚地看出一件事：所有其他池线程都被阻塞，等待对同一对象 ID 的锁定

对于 MSSQL，锁 ID：0x1304EA4F#40；对于 H2，锁 ID：0x21A1100D7D0

除了 main 线程和 pool-1-thread-1（被垃圾回收阻塞）之外的每个线程都表现出这种行为。

这7个线程都在等待同一个对象。您的设置中肯定存在一些阻塞甚至死锁。

绿色的小斑点也证实了各个线程之间监视器锁的间歇传输，确认它们有点死锁。底部显示线程的窗格给出了每个线程阻塞的时间线。红色表示阻塞；绿色表示正在运行。如果您将鼠标悬停在每个线程的红色部分，它会显示

  1. 线程被阻塞，等待获取锁（红色）
  2. 线程试图获取但当前无法获取的锁的 ID
  3. 最后持有锁的线程ID
  4. 绿色表示一个正在运行的未阻塞线程。

当您将鼠标悬停在飞行记录中的红色切片上时，您会看到它们都在等待获取相同的锁。该锁在各个池线程之间间歇性地保持。

MSSQL（线程被阻塞，等待 0x1304EA4F40）：

enter image description here

H2（线程阻塞等待 0x21A1100D7D0）：

enter image description here

在两个飞行记录中，pool-1-thread-1 是唯一一个在尝试获取锁时未被阻塞的线程。 pool-1-thread-1 的空白行完全是由于我之前介绍过的垃圾收集。

转储

理想情况下，您的飞行记录应该包含一堆线程转储，尤其是您运行超过 40 分钟的那个；别介意20多岁的人。不幸的是，两个录音各只包含 2 个录音；其中只有一个甚至包含 pool-1-thread-1 的堆栈跟踪。 Singular thread dumps are worthless。您将需要一段时间内的多个快照才能使用它们。通过线程转储（或堆转储），可以识别 ID 0x1304EA4F40 和 0x21A1100D7D0 所指的对象。我从转储中最多能发现的是，它们都在等待“对象”的实例：

enter image description here

它实际上可以是任何东西。你的第一次飞行记录至少表明线程被锁定在 org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager:

enter image description here

第一个记录在锁窗格中显示了相同的模式，所有线程都在等待该单个对​​象：

enter image description here

第一次录音还向我们展示了 pool-1-thread-1 在那一刻的表现：

enter image description here

从那里，我会猜测那个线程正在关闭数据库连接？在多个连续的线程转储显示一段时间内的线程活动之前，无法得出任何结论。

,

我在 MySQL db 上进行了测试，发现锁定了以下方法：

org.apache.logging.log4j.core.appender.db.AbstractDatabaseManager.write(org.apache.logging.log4j.core.LogEvent,java.io.Serializable) (line: 261)

因为在源代码中你可以看到同步写入方法：

    /**
     * This method manages buffering and writing of events.
     *
     * @param event The event to write to the database.
     * @param serializable Serializable event
     */
    public final synchronized void write(final LogEvent event,final Serializable serializable) {
        if (isBuffered()) {
            buffer(event);
        } else {
            writeThrough(event,serializable);
        }
    }

我认为如果您指定缓冲区大小会增加吞吐量，因为日志将被分批收集并且同步会非常低。

使用 AsyncLogger 更新 log4j2 配置文件后，您将看到锁定：

org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor.enqueue(org.apache.logging.log4j.core.LogEvent,org.apache.logging.log4j.core.async.AsyncLoggerConfig) (line: 375)

以及该方法的实现：

private void enqueue(final LogEvent logEvent,final AsyncLoggerConfig asyncLoggerConfig) {
        if (synchronizeEnqueueWhenQueueFull()) {
            synchronized (queueFullEnqueueLock) {
                disruptor.getRingBuffer().publishEvent(translator,logEvent,asyncLoggerConfig);
            }
        } else {
            disruptor.getRingBuffer().publishEvent(translator,asyncLoggerConfig);
        }
    }

synchronizeEnqueueWhenQueueFull 默认是 true，它会在线程上产生锁，你可以管理这些参数：

    /**
     * LOG4J2-2606: Users encountered excessive CPU utilization with Disruptor v3.4.2 when the application
     * was logging more than the underlying appender could keep up with and the ringbuffer became full,* especially when the number of application threads vastly outnumbered the number of cores.
     * CPU utilization is significantly reduced by restricting access to the enqueue operation.
     */
    static final boolean ASYNC_LOGGER_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL = PropertiesUtil.getProperties()
            .getBooleanProperty("AsyncLogger.SynchronizeEnqueueWhenQueueFull",true);
    static final boolean ASYNC_CONFIG_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL = PropertiesUtil.getProperties()
            .getBooleanProperty("AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull",true);

但您应该了解使用这些参数的副作用，如代码片段中所述。

为什么数据库会成为瓶颈的想法？：

  • 远程数据库（vpn 等）
  • 检查用于 id 列（SEQUENCE、TABLE、IDENTITY）的策略以避免额外的数据库调用
  • 列上有索引吗？ （它可以对每个事务提交产生重新索引操作）
dbcpjavajavalog4j2sql-server