乐趣区

关于log4j2:近期业务大量突增微服务性能优化总结3针对-x86-云环境改进异步日志等待策略

jiezi

最近，业务增长的很迅猛，对于咱们后盾这块也是一个不小的挑战，这次遇到的外围业务接口的性能瓶颈，并不是独自的一个问题导致的，而是几个问题揉在一起：咱们解决一个之后，发上线，之后发现还有另一个的性能瓶颈问题。这也是我经验不足，导致没能一下子定位解决；而我又对咱们后盾整个团队有着执著的自尊，不想通过大量程度扩容这种形式挺过压力顶峰，导致线上间断几晚都呈现了不同水平的问题，必定对于咱们的业务增长是有影响的。这也是我不成熟和要反思的中央。这系列文章次要记录下咱们针对这次业务增长，对于咱们后盾微服务零碎做的通用技术优化，针对业务流程和缓存的优化因为只实用于咱们的业务，这里就不再赘述了。本系列会分为如下几篇：

  1. 改良客户端负载平衡算法
  2. 开发日志输入异样堆栈的过滤插件
  3. 针对 x86 云环境改良异步日志期待策略
  4. 减少对于同步微服务的 HTTP 申请期待队列的监控以及云上部署，须要小心达到实例网络流量下限导致的申请响应迟缓
  5. 针对零碎要害业务减少必要的侵入式监控

针对 x86 云环境改良异步日志期待策略

因为线上业务量级比拟大（日申请上亿，日活用户几十万），同时业务波及逻辑很简单，线上日志级别咱们采纳的是 info 级别，导致线上日志量十分宏大，所以咱们很早就应用了 Log4j2 异步日志。Log4j2 异步日志基于 Disruptor，其中的期待策略，本次优化前，咱们选用的是 BLOCK。

Log4j2 异步日志的期待策略

Disruptor 的消费者做的事件其实就是一直查看是否有音讯到来，其实就是某个状态位是否就绪，就绪后读取音讯进行生产。至于如何一直查看，这个就是期待策略。Disruptor 中有很多期待策略，相熟多处理器编程的对于期待策略必定不会生疏，在这里能够简略了解为当工作没有到来时，线程应该如何期待并且让出 CPU 资源能力在工作到来时尽量快的开始工作。在 Log4j2 中，异步日志基于 Disruptor，同时应用 AsyncLoggerConfig.WaitStrategy 这个环境变量对于 Disruptor 的期待策略进行配置，目前最新版本的 Log4j2 中能够配置：

switch (strategyUp) {
    case "SLEEP":
        final long sleepTimeNs =
                parseAdditionalLongProperty(propertyName, "SleepTimeNs", 100L);
        final String key = getFullPropertyKey(propertyName, "Retries");
        final int retries =
                PropertiesUtil.getProperties().getIntegerProperty(key, 200);
        return new SleepingWaitStrategy(retries, sleepTimeNs);
    case "YIELD":
        return new YieldingWaitStrategy();
    case "BLOCK":
        return new BlockingWaitStrategy();
    case "BUSYSPIN":
        return new BusySpinWaitStrategy();
    case "TIMEOUT":
        return new TimeoutBlockingWaitStrategy(timeoutMillis, TimeUnit.MILLISECONDS);
    default:
        return new TimeoutBlockingWaitStrategy(timeoutMillis, TimeUnit.MILLISECONDS);
}

原本，咱们应用的是基于 Wait/Notify 的 BlockingWaitStrategy。然而这种策略导致业务量突增的时候，日志写入线程在一段时间内始终未能被唤醒，导致 RingBuffer 中积压了很多日志事件。

为何日志写入线程未能被唤醒

首先简略说一下一些硬件根底。CPU 不是间接从内存中读取数据，两头有好几层 CPU 缓存。以后大多是多 CPU 架构，单机中应用 MESI 缓存一致性协定，当一个处理器拜访另一个处理器曾经装载入高速缓存的主存地址的时候，就会产生 共享 （sharing，或者称为 争用 contention）。须要思考缓存一致性的问题，因为如果一个处理器要更新共享的缓存行，则另一个处理器的正本须要作废免得读取到过期的值。

MESI 缓存一致性协定，缓存行存在以下四种状态：

  • Modified：缓存行被批改，最终肯定会被写回入主存，在此之前其余处理器不能再缓存这个缓存行。
  • Exclusive：缓存行还未被批改，然而其余的处理器不能将这个缓存行载入缓存
  • Shared：缓存行未被批改，其余处理器能够加载这个缓存行到缓存
  • Invalid：缓存行中没有有意义的数据

举例：假如处理器和主存由总线连贯，如图所示：

a) 处理器 A 从地址 a 读取数据，将数据存入他的高速缓存并置为 Exclusive

b) 处理器 B 从地址 a 读取数据，处理器 A 检测到地址抵触，响应缓存中 a 地址的数据，之后，地址 a 的数据被 A 和 B 以 Shared 状态装入缓存

c) 处理器 B 对于 a 进行写操作，状态批改为 Modified，并播送揭示 A（所有其余曾经将该数据装入缓存的处理器），状态置为 Invalid。

d) 随后 A 还须要拜访 a，它会播送这个申请，B 将批改过的数据发到 A 和主存上，并且置两个正本状态为 Shared。

而后咱们来看 Log4j2 异步日志的原理：Log4j2 异步日志基于高性能数据结构 Disruptor，Disruptor 是一个环形 buffer，做了很多性能优化（具体原理能够参考我的另一系列：高并发数据结构（disruptor）），Log4j2 对此的利用如下所示：

在生产端，只有一个单线程进行生产。当没有日志到来时，线程须要期待，如何期待就是下面提到的期待策略。那么如何判断就绪呢？其实这个线程就是一直的查看一个状态位是否就绪，这里就是查看 RingBuffer 的生产 offset 是否大于以后生产到的值，如果大于则代表有新音讯须要生产。对于这种一直查看一个状态位的代码，被称为 spin-wait loop。

那么为何业务顶峰的时候，这个单线程唤醒的慢呢？次要起因是，业务量突增时，通常随同着大量远大于 CPU 数量的线程进入 Runnable 状态，同时随同着大量的 CPU 计算以及缓存行更新和生效，这会引起 很大的总线流量 ，导致 Notify 信号被日志生产单线程感知受到影响的同时，日志生产单线程进入 Runnable 同时占有 CPU 资源进行运行也会受到影响。在这期间， 可能沉闷的业务线程占用较久的 CPU 工夫，导致生产了很多日志事件进入 RingBuffer。

改用 SleepingWaitStrategy

咱们这里改用其中策略最为平衡的 SleepingWaitStrategy。在以后的大多数利用中，线程的个数都远大于 CPU 的个数，甚至是 RUNNABLE 的线程个数都远大于 CPU 个数，应用基于 Wait 的 BusySpinWaitStrategy 会导致业务闲时忽然来业务顶峰的时候，日志生产线程唤醒的不够及时（CPU 始终被大量的 RUNNABLE 业务线程抢占）。如果应用比拟激进的 BusySpinWaitStrategy（始终调用 Thread.onSpinWait()）或者 YieldingWaitStrategy（先 SPIN 之后始终调用 Thread.yield()），则闲时也会有较高的 CPU 占用。咱们冀望的是一种递进的期待策略，例如：

  1. 在肯定次数内，一直 SPIN，应答日志量特地多的时候，缩小线程切换耗费。
  2. 在超过肯定次数之后，开始一直的调用 Thread.onSpinWait() 或者 Thread.yield()，使以后线程让出 CPU 资源，应答间断性的日志顶峰。
  3. 在第二步达到肯定次数后，应用 Wait，或者 Thread.sleep() 这样的函数阻塞以后线程，应答日志低峰的时候，缩小 CPU 耗费。

SleepingWaitStrategy 就是这样一个策略，第二步采纳的是 Thread.yield()，第三步采纳的是 Thread.sleep()。

public final class SleepingWaitStrategy implements WaitStrategy
{

    @Override
    public long waitFor(final long sequence, Sequence cursor, final Sequence dependentSequence, final SequenceBarrier barrier)
        throws AlertException
    {
        long availableSequence;
        int counter = retries;

        while ((availableSequence = dependentSequence.get()) < sequence)
        {counter = applyWaitMethod(barrier, counter);
        }

        return availableSequence;
    }

    @Override
    public void signalAllWhenBlocking()
    { }

    private int applyWaitMethod(final SequenceBarrier barrier, int counter)
        throws AlertException
    {barrier.checkAlert();
        // 大于 100 的时候，spin
        // 默认 counter 从 200 开始
        if (counter > 100)
        {--counter;}
        // 在 0~ 100 之间
        else if (counter > 0)
        {
            --counter;
            Thread.yield();}
        // 最初，应用 sleep
        else
        {LockSupport.parkNanos(sleepTimeNs);
        }

        return counter;
    }
}

将其中的 Thread.yield 改为 Thread.onSpinWait

咱们发现，应用 SleepingWaitStrategy 之后，通过咱们自定义的 JFR 事件发现，在业务低峰到业务突增的时候，线程总是在 Thread.yield() 的时候有日志事件到来。然而每次线程执行 Thread.yield() 的工夫距离还是有点长，并且有日志事件到来了然而还是能察看到再过几个 Thread.yield() 之后，线程才发现有日志过去的状况。

所以，咱们批改其中的 Thread.yield() 为 Thread.onSpinWait()，起因是：咱们部署到的环境是 x86 的机器，在 x86 的环境下 Thread.onSpinWait() 在被调用肯定次数后，C1 编译器就会将其替换成应用 PAUSE 这个 x86 指令实现。参考 JVM 源码：

x86.ad

instruct onspinwait() %{match(OnSpinWait);
  ins_cost(200);

  format %{
    $$template
    $$emit$$"pause\t! membar_onspinwait"
  %}
  ins_encode %{__ pause();
  %}
  ins_pipe(pipe_slow);
%}

咱们晓得，CPU 并不会总间接操作内存，而是以缓存行读取后，缓存在 CPU 高速缓存上。然而对于这种一直查看查看某个状态位是否就绪的代码，一直读取 CPU 高速缓存，会在以后 CPU 从总线收到这个 CPU 高速缓存曾经生效之前，都认为这个状态为没有变动。在业务忙时，总线可能十分忙碌，导致 SleepingWaitStrategy 的第二步始终查看不到状态位的更新导致进入第三步。

PAUSE 指令（参考：https://www.felixcloutier.com…）是针对这种期待策略实现而产生的一个非凡指令，它会通知处理器所执行的代码序列是一个一直查看某个状态位是否就绪的代码（即 spin-wait loop），这样的话，而后 CPU 分支预测就会据这个提醒而避开内存序列抵触，CPU 就不会将这块读取的内存进行缓存 ，也就是说对 spin-wait loop 不做缓存，不做指令
从新排序等动作。从而进步 spin-wait loop 的执行效率。

这个指令使得针对 spin-wait loop 这种场景，Thread.onSpinWait()的效率要比 Thread.yield() 的效率要高。所以，咱们批改 SleepingWaitStrategy 的 Thread.yield() 为 Thread.onSpinWait()。

微信搜寻“我的编程喵”关注公众号，每日一刷，轻松晋升技术，斩获各种 offer：

退出移动版