rsyslog磁盘辅助(Disk-Assisted)模式踩坑记

Posted 2022-09-25

最近公司为方便tracing、排查， 搞全链路日志收集，而我手上的10亿+pv的动态前端服务必然在考虑之列。

之前呢。 都是运维定制的收集方式：

如上图，rsyslog push kafka， 优点嘛： 稳定，肯定不会丢日志； 报点也很明显：性能差，IO略高，毕竟疯狂flush disk，不带buffer的。

最担心的一点是我目前是抽样1/5的mc/redis/curl等日志量， 如果按公司要求，最好收集100%的日志，那么IO得天天报警，（我们是0.8*cpu数），而且磁盘空间即使每天清理也不够用（目前每天是30G）。

 

所以最近想深入玩玩rsyslog没有没更好的方式接入日志。

踏遍了各种各样的文档，发现还是官方资料稍全点， 但也没几句是人话，讲得不够通俗易懂。

好在有chrome 翻译，结合原文看就好多了：

 

------------

说正题哈，官方支持的buffer或queue的模式有4种：
 来自​​​https://www.rsyslog.com/doc/v8-stable/concepts/queues.html
​

1. 直接队列

直接队列是非排队队列。直接模式下的队列既不排队也不缓冲任何队列元素，而是直接（并立即）将元素从生产者传递给消费者。这听起来很奇怪，但这种队列类型有充分的理由。

直接模式队列允许一般使用队列，即使在不总是需要排队的地方也是如此。一个很好的例子是输出动作前面的队列。虽然缓冲转发操作或数据库写入非常有意义，但在简单的本地文件写入之前构建队列的意义有限。然而，rsyslog仍然在每个动作前都有一个队列。因此，对于文件写入，队列模式可以简单地设置为“直接”，在这种情况下不会发生排队。

请注意，直接队列也是唯一一种将执行返回代码（成功/失败）从消费者传递回生产者的队列类型。例如，备份操作逻辑需要这样做。因此，备份操作要求待检查操作使用“直接”模式队列。

 

2. 磁盘队列

磁盘队列使用磁盘驱动器进行缓冲。重要的事实是它们总是使用磁盘并且不在内存中缓冲任何内容。因此，队列是超可靠的，但到目前为止是最慢的模式。对于常规用例，不建议使用此队列模式。如果日志数据非常重要，即使在极端情况下也不会丢失，这很有用。

写入磁盘队列时，它以块的形式完成。每个块都接收其单个文件。文件以前缀命名（通过“ $ <object> QueueFilename ”配置指令设置），后跟一个7位数字（从1开始，每个文件递增）。块默认为10mb，可以通过“ $ <object> QueueMaxFileSize ”配置指令设置不同的大小。请注意，大小限制不是很明显：rsyslog总是写入一个完整的队列条目，即使它违反了大小限制。所以块实际上比配置的大小稍微大一点（通常小于1k）。出于同样的原因，每个块也具有不同的大小。如果您观察到不同的块大小，您可以放松：这不是问题。

使用以块为单位进行写入，以便可以快速删除已处理的数据并且可以免费用于其他用途 - 同时保持对所使用的磁盘空间没有人为的上限。如果设置了磁盘配额（下面的说明），请确保配额/块大小允许写入至少两个块。Rsyslog目前没有检查，如果一个块超过配额，将会失败。

创建新块会降低性能，但可以更快地释放磁盘空间。10mb的默认值被认为是这两者之间的良好折衷。但是，将这些设置适应本地策略可能是有意义的。例如，如果磁盘队列写在专用的200gb磁盘上，则使用2gb（甚至更大）的块大小可能是有意义的。

但请注意，默认情况下磁盘队列在每次写入磁盘时都不会更新其内务处理结构。这是出于性能原因。如果发生故障，数据仍将丢失（除非手动修复文件结构）。但是，可以将磁盘队列设置为在检查点（每n个记录）上写入簿记信息，这样也可以使其更加可靠。如果检查点间隔设置为1，则不会丢失任何数据，但队列异常缓慢。

每个队列都可以放在不同的磁盘上，以获得最佳性能和/或隔离。目前通过在队列创建语句之前指定不同的$ WorkDirectory配置指令来选择此选项 。

要创建磁盘队列，请使用“ $ <object> QueueType Disk ”配置指令。可以通过“ $ <object> QueueCheckpointInterval ” 指定检查点间隔，0表示没有检查点。请注意，通过在每次写入操作后发出（f）同步，可以使基于磁盘的队列非常可靠。从版本4.3.2开始，可以通过“ <object> QueueSyncQueueFiles on / off，默认为关闭”来请求。激活此选项会降低性能，因此不应无故启用。

 

3. 内存中队列

内存队列模式是大多数人在考虑计算队列时的想法。这里，排队的数据元素保存在存储器中。因此，内存中的队列非常快。但是，当然，它们无法在任何程序或操作系统中止（通常是可以容忍的并且不太可能）。如果使用内存模式，请确保使用UPS，并且日志数据对您很重要。请注意，即使内存中的队列可能会在无限量的时间内保存数据，例如输出目标系统已关闭且没有理由将数据移出内存（在内存中长时间处于非存储状态）原因）。纯内存队列甚至无法将队列元素存储在核心内存中的任何其他位置。

存在两种不同的内存中队列模式：LinkedList和FixedArray。从用户的角度来看，两者都非常相似，但使用不同的算法。

FixedArray队列使用固定的预先分配的数组，该数组保存指向队列元素的指针。大多数空间由实际用户数据元素占用，数组中的指针指向该元素。指针数组本身相对较小。但是，即使队列为空，它也有一定的内存占用。由于无需动态分配任何内务处理结构，因此FixedArray提供了最佳的运行时性能（使用最少的CPU周期）。如果期望的队列元素数量相对较少且需要性能，则FixedArray是最佳的。它是主消息队列的默认模式（限制为10,000个元素）。

LinkedList队列恰恰相反。所有管家结构都是动态分配的（在链接列表中，顾名思义）。这需要更多的运行时处理开销，但确保仅在需要时分配内存。LinkedList队列尤其适用于只需偶尔需要排队大量元素的队列。用例可能是偶尔的消息突发。在内存允许的情况下，它可以限制为例如200,000个元素，如果在使用中则仅占用内存。在这种情况下，FixedArray队列可能具有太大的静态内存占用。

通常，如果有疑问，建议使用LinkedList模式。与FixedArray相比，处理开销很低，并且可能因内存使用的减少而被抵消。在大多数经常未使用的指针数组页面中进行分页可能比动态分配它们要慢得多。

要创建内存中队列，请使用“ $ <object> QueueType LinkedList ”或“ $ <object> QueueType FixedArray ”配置指令。

4. 磁盘辅助内存队列

如果为内存中队列定义了磁盘队列名称（通过 $ <object> QueueFileName），它们将自动变为“磁盘辅助”（DA）。在该模式下，数据根据需要写入磁盘（并回读）。

实际上，常规内存队列（称为“主队列”）和磁盘队列（称为“DA队列”）在此模式下协同工作。最重要的是，如果主队列已满或需要在关闭时保留，则会激活磁盘队列。磁盘辅助队列结合了纯内存队列和纯磁盘队列的优点。在正常操作下，它们非常快，消息永远不会触及磁盘。但是如果需要，可以缓冲无限量的消息（实际上仅受可用磁盘空间限制），并且可以在rsyslogd运行之间保持数据。

 

-----------以上来自官方-------------

很显然，直接队列是阻塞的，磁盘队列是目前我在用的，内存队列我也部分在使用，性能最好，丢数据的风险较大，不够智能。

这么一来的“磁盘辅助”（DA）就是我的菜了：优先走内存做buffer，到达高水位是写磁盘，到达低水位时恢复成写内存， 最重要的是shutdown时可以save到磁盘，除非kill -9。

 

------------开启踩坑之旅---------------

程序：

<?php
/**
 * Created by IntelliJ IDEA.
 * User: qiangjian
 * Date: 2019/3/14
 * Time: 09:59
 */

namespace Lib\\Logger\\Adapter;

class Syslog implements IWriter 
    protected $name;
    protected static $instances;
    private function __construct($name)
    
        $this->name = $name;
    
    private function __clone()

    static function create($name)
        if(isset(self::$instances[$name]))
            return self::$instances[$name];
        
        return self::$instances[$name] = new self($name);
    

    function write($msgStr, $level = LOG_INFO)
        openlog($this->name,  LOG_ODELAY, LOG_USER);
        return syslog($level, $msgStr);
    

 

rsyslog:

module(load="imuxsock") # provides support for local system logging (e.g. via logger command)
module(load="imklog")   # provides kernel logging support (previously done by rklogd)
module(load="impstats"
    interval="60"
    severity="7"
    resetCounters="on"
    log.syslog="off"
    log.file="/data1/ms/log/rsyslog/rsyslog_status.log")

*.info;mail.none;authpriv.none;cron.none;local6.none;local5.none;user.none                 /var/log/messages
# nginx template
template(name="kfk_log" type="string" string="%msg:2:$%")

# ruleset
ruleset(name="to_bip_kfk") 
    #日志转发kafka
    action(
        name="to_bip_kfk"
        type="omkafka"
        topic="cms-front-network"
        action.resumeRetryCount="-1"
        action.ResumeInterval="5"
        broker=["xxxxxx:9110"]
    confParam=["sasl.mechanisms=PLAIN","security.protocol=sasl_plaintext","sasl.username=xxx","sasl.password=xxx","debug=all","api.version.request=true"]
        partitions.auto="on"
        template="kfk_log"
        errorFile="/data1/ms/log/rsyslog/to_kfk_err.log"
        queue.filename="queue_filename"
        queue.type="linkedlist"
        queue.spoolDirectory="/data1/ms/log/rsyslog" #提前建目录
        queue.workerthreads="4"
        queue.workerthreadminimummessages="100000"
        queue.size="500000"
        queue.highwatermark="300000"
        queue.LowWatermark="100000" #当内存队列小于这些元素时，停止回写磁盘。
        queue.TimeoutEnqueue="0" 
        queue.dequeuebatchsize="500"
        queue.saveonshutdown="on"
        )



if $programname == front_network then 
  #/data1/debug.log
    call to_bip_kfk
        stop

 -------------上线后炸锅--------------

10台机器里， 有3太内存会异常升高，然后触发swap，最后IO从10， 30，100，200.。。。飙升。。接近死机。。

我和运维就分析，会不会是参数问题，随后就是一波又一波的调优，queue.size哪怕设置再小，负载一样很高。

我抽样几台机器，strace/ltrace看看。

0> strace -p 18268 -fciT
Process 18268 attached with 59 threads - interrupt to quit


^CProcess 18268 detached
Process 18269 detached
Process 18270 detached
Process 18271 detached
Process 18272 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 61.06   60.070903        2611     23008           poll    
 35.23   34.655613         532     65194     11769 futex
  1.53    1.505787          57     26257      8173 read
  1.29    1.265297         224      5644           select
  0.89    0.871452       16759        52        17 restart_syscall
  0.00    0.003077           0     23146      5820 recvmsg
  0.00    0.001816           0      8427           write
  0.00    0.001477           0      8213           sendmsg
  0.00    0.000386           0      3306           stat
  0.00    0.000021           0       425           madvise
  0.00    0.000000           0        36           close
  0.00    0.000000           0        36           socket
  0.00    0.000000           0        18        18 connect
  0.00    0.000000           0        20           sendto
  0.00    0.000000           0        18           bind
  0.00    0.000000           0        18           getsockname
  0.00    0.000000           0        54           getsockopt
  0.00    0.000000           0        36           fcntl
------ ----------- ----------- --------- --------- ----------------
100.00   98.375829                163908     25797

注意：60%的poll是等待connect消息的时间， 34%的futex是线程or进程调度的时间。

但这显然没能说明问题，对我没有用。

问题还在继续，什么restart程序、centos、rsyslogd，都无济于事。

最后不得已，把出问题的机器nginx停服，从VIP中自动剔除。

就这样，度过了，一个不安、焦虑的周末，随时留意手机报警...。

 

---------厘清思路，重新出发-----------

新的一周来临，我和运维重新思考回退到磁盘模式。然而，回退后，IO依然爆表。

这时隐约感觉到，应该是我们rsyslog新的变量导致的问题。于是diff下配置，

 

转发控制，debug.log正常，直接排除。

但ruleset依然比较复杂，在运维建议下，开启了rsyslog调试模式：

rsyslogd -dn |grep -i err|fail

rsyslogd: error in kafka parameter sasl.mechanisms=PLAIN: No such configuration property: "sasl.mechanisms" [v8.25.0..

于是立马google+baidu， 没有答案。

搜索官方wiki:​​https://www.rsyslog.com/doc/master/configuration/modules/omkafka.html​​

 简直是惊天一逼的提示我赶紧看看librdkafka的情况。

二话不说， 

wget  https://github.com/edenhill/librdkafka/archive/master.zip
unzip master 
cd librdkafka-master/
ls
./configure 
make 
make install 
ldconfig 


strings -a /usr/local/lib/librdkafka.so  |grep -E [0-9]\\.[0-9]+\\.[0-9]+$ #确认下版本，不低于0.9的kafka即可

 

0.10肯定兼容0.9.， 

再次 :

rsyslogd -dn |grep -i err|fail

错误没有了！错误没有了！错误没有了！

 

持续观察了1小时、1天:

 

检查rsyslog状态日志：

 

 至此，问题被解决，复盘历程：
新加ruleset, 启用磁盘辅助模式 -> 内存100% ->触发swap -> 触发死机或程序OOM -> 改回磁盘模式问题依旧 -> 排查rsyslog配置（无果） -> 开启rsyslog调试（只打印错误）->  报错： No such configuration property: "sasl.mechanisms"  -> google/baidu/查wiki（发现依赖librdkafka） -> 排查所有机器librdkafka版本 -> 发现不兼容的librdkafka（正好是3台问题机器）-> 安装最新librdkafka ->  开启rsyslog调试  -> 无报错 -> 重启syslogd，观察1天  -> 内存、IO稳定 -> 问题解决

 

 

 

PS:

 

queue.spoolDirectory="/data1/ms/log/rsyslog" #提前建目录
默认可能会把/var 打爆

 

​

作者：sunsky303