5

我用 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

线程

编辑

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

我的 PoolableConnectionFactory 中是否存在 mssql-jdbc 的配置问题，或者 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

4

2 回答 2

1

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

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

那么，现在怎么办/(TL;DR)

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

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

中央处理器

两个飞行记录都表明您的 CPU 正在努力获取两个记录的大部分内容：

MSSQL 记录（共 46 分钟）

在此处输入图像描述

JFR 甚至在 MSSQL 记录中警告说：

从 2/18/21 上午 7:28:58 开始，在 1 分 17 秒内，平均 CPU 负载为 42%。

H2 录音（共 20.3 秒）在此处输入图像描述

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

阻塞的线程

你的设置中有大量的阻塞，到处都是确凿的证据。由 标识的线程Log4j2-TF-1-AsyncLoggerConfig-1被垃圾收集器阻塞了很多，就像 CPU 颠簸一样：

H2飞行记录：

在此处输入图像描述

该图上除了最后 3 个刻度之外的所有时钟都是 log4j2 线程的阻塞。GC 仍然严重阻塞了其他池线程（更多内容）

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

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

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

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

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

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

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

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

在此处输入图像描述

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

在此处输入图像描述

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

转储

理想情况下，您的飞行记录应该包含一堆线程转储，尤其是您运行超过 40 分钟的线程转储；别介意20多岁的。不幸的是，这两个录音每个都只包含 2 个录音；其中只有一个甚至包含pool-1-thread-1. 单一的线程转储毫无价值。您需要在一段时间内创建多个快照才能使用它们。使用线程转储（或堆转储），可以识别 ID0x1304EA4F40和0x21A1100D7D0引用的对象。我可以从转储中找出的最多的是它们都在等待“对象”的实例：

在此处输入图像描述

它实际上可以是任何东西。您的第一次飞行记录至少显示线程已锁定org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager：

在此处输入图像描述

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

在此处输入图像描述

第一段录音也向我们展示了pool-1-thread-1当时的情况：

在此处输入图像描述

从那里，我会冒险猜测该线程正在关闭数据库连接？在多个连续的线程转储显示一段时间内的线程活动之前，没有任何结论可以说。

于 2021-02-19T04:31:10.220 回答
0

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

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

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

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

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

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

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, logEvent, 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）使用什么策略以避免额外的数据库调用
  • 列上有索引吗？（它可以在每个事务提交上产生重新索引操作）
于 2021-02-15T19:20:32.900 回答