为何 filebeat 采集日志不是实时的？

注：本文中 filebeat 的版本为 7.5，不同版本的 filebeat 的行为可能有所差异。

filebeat 采集的日志的时间戳，和日志管理平台实际收到的日志时的时间戳，通常都会有几秒的延迟，有些情况下甚至能达到十几秒。其中固然有 filebeat 到日志管理平台之间的网络带来的影响，但最大的延迟还是出现在日志的产生到 filebeat 上报这个时间段。为何 filebeat 采集日志不是实时的？

如果是一个简单的类似于 tail -f 的日志采集程序，那么只要程序写入日志文件，不到一秒就应该输出出来。不过 filebeat 并非一个简单的 tail -f，出于减少对系统资源的占用和增大吞吐量的目的，filebeat 内部使用了五花八门的配置来管理其具体的行为。

首先，filebeat 并没有采用 inotify 这样的机制来监听目标文件/目录的状态变化，而是采用非常古老但是实用的方式 —— 轮询 —— 来采集日志文件。每隔一段时间，filebeat 就会检查目标路径下是否有可供采集的文件，对于已采集的文件，是否有新的写入。正是由于这个“每隔一段时间”，应用程序写入日志后，采集的工作往往没有接踵而来。之间的时间差就是延迟的主要来源。

filebeat 采用以下几个参数来控制轮询的行为：

- type: log
  # How often the input checks for new files in the paths that are specified
  # for harvesting. Specify 1s to scan the directory as frequently as possible
  # without causing Filebeat to scan too frequently. Default: 10s.
  scan_frequency: 10s
  
  # Backoff values define how aggressively filebeat crawls new files for updates
  # The default values can be used in most cases. Backoff defines how long it is waited
  # to check a file again after EOF is reached. Default is 1s which means the file
  # is checked every second if new lines were added. This leads to a near real time crawling.
  # Every time a new line appears, backoff is reset to the initial value.
  backoff: 1s
  
  # Max backoff defines what the maximum backoff time is. After having backed off multiple times
  # from checking the files, the waiting time will never exceed max_backoff independent of the
  # backoff factor. Having it set to 10s means in the worst case a new line can be added to a log
  # file after having backed off multiple times, it takes a maximum of 10s to read the new line
  max_backoff: 10s
  backoff_factor: 2

其中 scan_frequency 影响多长时间检查一次目标路径下是否有新增文件的出现。虽然这个默认是 10 秒，不过除非发生了 log rotation，一般不会出现新的日志文件。而后三个跟 "backoff" 相关的配置，则适用于已存在的日志的采集行为。当 filebeat 采集完一个文件的日志（一直读到文件结尾）时，它会隔一段时间再看看有没有新的日志 append 进来。这个一段时间就是 backoff 的值。如果 filebeat 再次查看时依然没有新的日志，那么它会隔 backoff * backoff_factor 也就是默认 2 秒之后才继续查看，直到整个 backoff 的时间达到 max_backoff 也即是 10 秒为止。所以对于一条偶尔出现的日志（比如错误日志），那么它有可能得过了 10 秒之后才会被 filebeat 采集到。

然而被 filebeat 采集到并不等于会被 filebeat 输出。整个 filebeat 的流程可以分成三段：不同的输入 - 通用的处理 - 不同的输出。

除了日志输入部分有延迟，filebeat 在做通用的处理时也会引入延迟。这是因为 filebeat 会把 event 给缓存到队列中，来追求更高吞吐量的成批输出。

queue:
  mem:
    # Max number of events the queue can buffer.
    events: 4096
    
    # Hints the minimum number of events stored in the queue,
    # before providing a batch of events to the outputs.
    # The default value is set to 2048.
    # A value of 0 ensures events are immediately available
    # to be sent to the outputs.
    flush.min_events: 2048
    
    # Maximum duration after which events are available to the outputs,
    # if the number of events stored in the queue is < `flush.min_events`.
    flush.timeout: 1s

默认情况下，filebeat 只会在以下两个条件中任一成立时才会刷洗缓存队列：

1. 当前缓存的事件多达 flush.min_events 以上
2. 上一次刷新缓存的操作在 flush.timeout 之前

当然，queue 带来的延迟最多也就 1 秒，比起 backoff 带来的开销并不大。

过了“通用的处理”，就是“不同的输出”了。这里也有一点批处理。大部分的输出类型中有 bulk_max_size 这一项，控制每次输出时批次的大小。不过考虑到 bulk_max_size 的值往往小于 queue 的缓存，所以带来的延迟可以忽略。

如果你选择减少 queue 的缓存效应，比如减少 flush.timeout 或者 flush.min_events，那么可以会带来一个意想不到的问题。

filebeat 每完成一个批次的输出后，会更新采集进度文件（在 7.5 里面是 data/data/registry/filebeat/data.json ）。如果没有及时更新这一文件，一旦 filebeat 崩溃了，就会丧失采集进度，导致日志的重复采集。如果把 queue 调小了，就会导致一个批次也随之变小，进而让进度文件的保存变得更加频繁了。由于对进度文件的写入都是重新写整个文件，且每次写入都会调用 fsync 保障写入的数据能够落到磁盘上，所以这个操作耗费的时间并不短。

好在 filebeat 还有一个配置项：

# The timeout value that controls when registry entries are written to disk
# (flushed). When an unwritten update exceeds this value, it triggers a write
# to disk. When flush is set to 0s, the registry is written to disk after each
# batch of events has been published successfully. The default value is 0s.
filebeat.registry.flush: 0s

默认情况下，就是每完成一批更新一次进度。但是我们可以设置成每隔几秒更新一次。由于 filebeat 正常退出时也会更新进度文件，另外毕竟这也不是需要保障数据一致性的数据库，所以一般情况下不用太担心丢失几秒的进度。