集中式日志分析平台 - ELK Stack - Filebeat 压测

2019年5月16日 292次阅读来源: 大数据之心

前言

任何一款采集 agent 进行公司内全面推广前都需要进行性能测试以及资源限制功能测试，以保证：

清楚了解性能瓶颈在哪里；
清楚了解数据暴涨时的性能瓶颈在哪里；
清楚了解数据暴涨时的资源限制功能是否生效；

对于 Filebeat 这款号称 golang 编写，性能强于 logstahs-forwarder 的采集 agent，我们也需要这样进行严谨对待。

测试详情

硬件环境和版本

硬件选择虚拟机，6cores + 16GB Mem + 175GB SSD + 1000Mbps 带宽；

Filebeat 为 5.2.1 版本，Kafka 为 2.11-0.10.1.1；
172.16.134.3: kafka broker
172.16.134.8: Filebeat

测试方案

Filebeat 输出到 console，6 进程写入采集文件，单行数据 247B；
Filebeat 输出到 kafka，6进程写入采集文件，单行数据 247B，采用 gzip 压缩；
Filebeat 输出到 kafka，限制只使用 1 core，6进程写入采集文件，单行数据 247B，采用 gzip 压缩；
Filebeat 输出到 kafka，限制只使用 1 core，6进程写入采集文件，单行数据 1KB，采用 gzip 压缩；
Filebeat 输出到 kafka，限制只使用 1 core，6进程写入采集文件，单行数据 5KB，采用 gzip 压缩；

测试配置

Filebeat 配置，输出到 console：

Filebeat.prospectors:
 - input_type: log
  paths:
    - /home/admin/soft/Filebeat-5.2.1-linux-x86_64/logs/test
  document_type: Filebeat
output.console:
  pretty: true

Filebeat 配置，输出到 Kafka：

Filebeat.prospectors:
 - input_type: log
  paths:
    - /home/admin/soft/Filebeat-5.2.1-linux-x86_64/logs/test
  document_type: Filebeat
output.kafka:
  hosts: ["172.16.134.3:9092"]
  topic: '%{[type]}'
  partition.round_robin:
    reachable_only: false
  required_acks: 1
  compression: gzip
  max_message_bytes: 1000000

统计方式

我们开启 Filebeat 的 6060 端口，并使用 python 脚本进行指标采集。
expvar_rates.py，每秒统计出 Filebeat 指标，主要看：

libeat.publisher.published_events, avg
publish.events, avg
libbeat.kafka.published_and_acked_events, avg
系统指标方面我们主要关注 CPU 使用率，这块使用 top 或者 tsar 都OK。

import requests
import argparse
import time
import curses
import re


def main():
    parser = argparse.ArgumentParser(
        description="Print per second stats from expvars")
    parser.add_argument("--url", default="http://localhost:6060",
                        help="The URL from where to read the values")
    parser.add_argument("--filter", default=None,
                        help="Filter metrics by this search regexp")
    args = parser.parse_args()

    stdscr = curses.initscr()
    curses.noecho()
    curses.cbreak()

    last_vals = {}

    # running average for last 30 measurements
    N = 30
    avg_vals = {}
    now = time.time()

    while True:
        try:
            time.sleep(1.0)
            stdscr.erase()

            r = requests.get(args.url + "/debug/vars")
            json = r.json()

            last = now
            now = time.time()
            dt = now - last

            for key, total in json.items():
                if args.filter is not None:
                    if re.search(args.filter, key) is None:
                        continue

                if isinstance(total, (int, long, float)):
                    if key in last_vals:
                        per_sec = (total - last_vals[key])/dt
                        if key not in avg_vals:
                            avg_vals[key] = []
                        avg_vals[key].append(per_sec)
                        if len(avg_vals[key]) > N:
                            avg_vals[key] = avg_vals[key][1:]
                        avg_sec = sum(avg_vals[key])/len(avg_vals[key])
                    else:
                        per_sec = "na"
                        avg_sec = "na"
                    last_vals[key] = total
                    try:
                        stdscr.addstr("{}: {}/s (avg: {}/s) (total: {})\n"
                                      .format(key, per_sec, avg_sec, total))
                    except Exception, e:
                        raise Exception("curses.addstr fail. Resize the " +
                                        "terminal window or use the filter" +
                                        "option: {}".format(e))
            stdscr.refresh()
        except requests.ConnectionError:
            stdscr.addstr("Waiting for connection...\n")
            stdscr.refresh()
            last_vals = {}
            avg_vals = {}

if __name__ == "__main__":
    main()

测试详情

我们可以通过脚本

time for i in {1..10000000};do echo "${log_message}" >> /home/admin/soft/filebeat-5.2.1-linux-x86_64/logs/test;done;

执行时间得知日志写入速率为 ~ 250K/s。我们可以通过 ls -l /proc/${pid}/fd | grep -v total | wc -l 得知采集单文件的 Filebeat 的文件句柄数为 9，采集 2 个文件的句柄数为 10, 所以基础句柄数为 9，每增加一个采集点，句柄数 + 1。

Case A: Filebeat 输出到 console，6 进程写入采集文件，单行数据 247B；

Step1. 启动 Filebeat (172.16.134.8)

/home/admin/soft/filebeat-5.2.1-linux-x86_64/filebeat -c /home/admin/soft/filebeat-5.2.1-linux-x86_64/filebeat.yml -httpprof 0.0.0.0:6060 > /home/admin/soft/filebeat-5.2.1-linux-x86_64/logs/filebeat 2>&1 &

Step2. 启动统计脚本

python expvar_rates.py

Step3. 启动 tsar

tsar --cpu --live -i 1

Step4. 写入压测数据(6个进程写入，6千万条日志)

for i in {1..10000000};do echo "2017-03-16T19:21:14+08:00 INFO Non-zero metrics in the last 30s: libbeat.publisher.published_events=2 registrar.states.update=3 libbeat.kafka.call_count.PublishEvents=2 publish.events=3 libbeat.kafka.published_and_acked_events=2 registrar.writes=2" >> /home/admin/soft/filebeat-5.2.1-linux-x86_64/logs/test;done;

在 6 进程数据写入日志文件时，我们在开启 python 统计脚本的窗口得到如下稳定的统计数据：

libbeat.publisher.published_events: 18014.370905/s (avg: 19641.6123106/s) 
publish.events: 21920.7951289/s (avg: 19610.1652594/s)

我们在 tsar 看到的统计数据为：

user     sys    wait    hirq    sirq    util
67.3    22.8     0.0     0.0     0.0    90.2

我们在 top 中可以看到 Filebeat 大致占据了 0.8 cores。
在 6 进程数据写入日志文件后，我们在开启 python 统计脚本的窗口得到如下稳定的统计数据：

libbeat.publisher.published_events: 40691.6042823/s (avg: 39300.4436095/s) 
publish.events: 38676.4998717/s (avg: 39370.3604289/s)

我们在 tsar 看到的统计数据为：

user     sys    wait    hirq    sirq    util
24.6     2.0     0.2     0.0     0.0    26.9

我们在 top 中可以看到 Filebeat 大致占据了 1.6 cores。
小结：

6 进程的日志文件写入，应用本身会吃满所有 CPU 资源，此时 Filebeat 采集速率无法跟上数据生成速度，大约为 19K/s，CPU 开销为 0.8 cores；
在 6 千万条日志写入完后，Filebeat 采集数据全速推送到 console 的速率大致为 39K/s，CPU 开销为1.6 cores；

Case B: Filebeat 输出到 kafka，6进程写入采集文件，单行数据 247B，采用 gzip 压缩；

测试步骤和上述一致，区别在于配置文件需要输出到 Kafka。
在 6 进程数据写入日志文件时，我们在开启 python 统计脚本的窗口得到如下稳定的统计数据：

libbeat.kafka.published_and_acked_events: 14125.0820764/s (avg: 16282.8981012/s) 
libbeat.publisher.published_events: 17357.7280373/s (avg: 16419.7944927/s)
publish.events: 16251.4829085/s (avg: 16510.4781086/s)

我们在 tsar 看到的统计数据为：

user     sys    wait    hirq    sirq    util
67.9    23.1     0.0     0.0     0.0    91.1

我们在 top 中可以看到 Filebeat 大致占据了 0.7~0.8 cores。
在 6 进程数据写入日志文件后，我们在开启 python 统计脚本的窗口得到如下稳定的统计数据：

libbeat.kafka.published_and_acked_events: 40614.7704231/s (avg: 39698.759785/s) 
libbeat.publisher.published_events: 40722.3439941/s (avg: 39628.4561631/s) 
publish.events: 38671.5053801/s (avg: 38930.2225183/s)

我们在 tsar 看到的统计数据为：

user     sys    wait    hirq    sirq    util
29.2     0.9     0.0     0.0     0.0    30.5

我们在 top 中可以看到 Filebeat 大致占据了 2.0 cores。
小结：

6 进程的日志文件写入，应用本身会吃满所有 CPU 资源，此时 Filebeat 采集速率无法跟上数据生成速度，大约为 16~17K/s，CPU 开销为 0.7~0.8 cores；
在 6 千万条日志写入完后，Filebeat 采集数据全速推送到 Kafka 的速率大致为 39~40K/s，CPU 开销为 2.0 cores；

Case C: Filebeat 输出到 kafka，限制只使用 1 core，6进程写入采集文件，单行数据 247B，采用 gzip 压缩；

测试步骤和上述一致，区别在于配置文件需要输出到 Kafka。
和上述步骤不同的是，启动 Filebeat 时需要 systemd 限制 CPU、句柄数，根据之前的理论，句柄数限制在 100 已经非常够用，CPU 限制在 1 core。
修改 /usr/lib/systemd/system/filebeat.service：

[Unit]
Description=Filebeat
Documentation=https://www.elastic.co/guide
After=network.target

[Service]
Type=Simple
ExecStart=/home/admin/soft/filebeat-5.2.1-linux-x86_64/filebeat -c /home/admin/soft/filebeat-5.2.1-linux-x86_64/filebeat.yml -httpprof 0.0.0.0:6060
ExecStop=/bin/kill -WINCH ${MAINPID}
Restart=always
RestartSec=0
WatchdogSec=1min
LimitNOFILE=100
LimitNPROC=100

[Install]
WantedBy=multi-user.target

执行 reload：

sudo systemctl daemon-reload

对 CPU 进行限制：

sudo systemctl set-property filebeat CPUQuota=100%

确认是否限制成功：

sudo systemctl show filebeat | grep -E "CPUQuota|LimitNOFILE|LimitNPROC"

有如下输出表示OK：

CPUQuotaPerSecUSec=1s
LimitNOFILE=100
LimitNPROC=100
DropInPaths=/etc/systemd/system/filebeat.service.d/50-CPUQuota.conf

在 6 进程数据写入日志文件时，我们在开启 python 统计脚本的窗口得到如下稳定的统计数据：

libbeat.kafka.published_and_acked_events: 19844.7720225/s (avg: 16837.4773012/s) 
libbeat.publisher.published_events: 18030.6556898/s (avg: 16764.6918644/s) 
publish.events: 15644.7977205/s (avg: 16910.2166832/s)

我们在 tsar 看到的统计数据为：

user     sys    wait    hirq    sirq    util
79.2    11.3     0.0     0.0     0.0    90.6

我们在 top 中可以看到 Filebeat 大致占据了 0.7 ~ 0.8 cores。
在 6 进程数据写入日志文件后，我们在开启 python 统计脚本的窗口得到如下稳定的统计数据：

libbeat.kafka.published_and_acked_events: 18337.7079915/s (avg: 18923.3234652/s) 
libbeat.publisher.published_events: 20376.3669159/s (avg: 18848.5970484/s) 
publish.events: 20323.8510655/s (avg: 18914.4681101/s)

我们在 tsar 看到的统计数据为：

user     sys    wait    hirq    sirq    util
14.4     0.5     0.0     0.0     0.0    15.2

我们在 top 中可以看到 Filebeat 大致占据了 1.0 cores，限制生效。
小结：

6 进程的日志文件写入，应用本身会吃满所有 CPU 资源，此时 Filebeat 采集速率无法跟上数据生成速度，大约为 16~17K/s，CPU 开销为 0.7~0.8 cores；
在 6 千万条日志写入完后，Filebeat 采集数据全速推送到 Kfaka 的速率大致为 18~19K/s，CPU 开销为 1.0 cores；

Case D: Filebeat 输出到 kafka，限制只使用 1 core，6进程写入采集文件，单行数据 1KB，采用 gzip 压缩；

在 6 进程数据写入日志文件时，我们在开启 python 统计脚本的窗口得到如下稳定的统计数据：

libbeat.kafka.published_and_acked_events: 11954.3900946/s (avg: 13256.2128845/s) 
libbeat.publisher.published_events: 14084.2447431/s (avg: 13241.4999292/s)
publish.events: 11998.8163015/s (avg: 13205.6630096/s)

我们在 tsar 看到的统计数据为：

user     sys    wait    hirq    sirq    util
85.4     5.0     0.1     0.0     0.0    90.5

我们在 top 中可以看到 Filebeat 大致占据了 0.75 ~ 0.9 cores。
在 6 进程数据写入日志文件后，我们在开启 python 统计脚本的窗口得到如下稳定的统计数据：

libbeat.kafka.published_and_acked_events: 14257.5686603/s (avg: 15411.161373/s)
libbeat.publisher.published_events: 16297.7185003/s (avg: 15475.6613026/s)
publish.events: 16292.4519132/s (avg: 15545.8192101/s)

我们在 tsar 看到的统计数据为：

user     sys    wait    hirq    sirq    util
14.5     0.6     0.0     0.0     0.0    15.3

我们在 top 中可以看到 Filebeat 大致占据了 1.0 cores，限制生效。
小结：

6 进程的日志文件写入，应用本身会吃满所有 CPU 资源，此时 Filebeat 采集速率无法跟上数据生成速度，大约为 13~14K/s，CPU 开销为 0.75~0.9 cores；
在 6 千万条日志写入完后，Filebeat 采集数据全速推送到 console 的速率大致为 15~16K/s，CPU 开销为 1.0 cores；

Case E: Filebeat 输出到 kafka，限制只使用 1 core，6进程写入采集文件，单行数据 5KB，采用 gzip 压缩；

在 6 进程数据写入日志文件时，我们在开启 python 统计脚本的窗口得到如下稳定的统计数据：

libbeat.kafka.published_and_acked_events: 5853.48499116/s (avg: 6142.33474568/s) 
libbeat.publisher.published_events: 6052.63549446/s (avg: 6066.04758752/s) 
publish.events: 5979.76512269/s (avg: 6063.20532399/s)

我们在 tsar 看到的统计数据为：

user     sys    wait    hirq    sirq    util
89.2     2.2     0.1     0.0     0.0    91.5

我们在 top 中可以看到 Filebeat 大致占据了 0.7 ~ 0.75 cores。
在 6 进程数据写入日志文件后，我们在开启 python 统计脚本的窗口得到如下稳定的统计数据：

libbeat.kafka.published_and_acked_events: 6110.43003481/s (avg: 7030.51292764/s)
libbeat.publisher.published_events: 8144.14448334/s (avg: 7030.65813196/s) 
publish.events: 6112.44754178/s (avg: 6977.26856088/s)

我们在 tsar 看到的统计数据为：

user     sys    wait    hirq    sirq    util
12.1     0.5     0.1     0.0     0.0    12.9

我们在 top 中可以看到 Filebeat 大致占据了 0.9 cores，未达到限制。
小结：

6 进程的日志文件写入，应用本身会吃满所有 CPU 资源，此时 Filebeat 采集速率无法跟上数据生成速度，大约为 6K/s，CPU 开销为 0.7~0.75 cores；
在 6 千万条日志写入完后，Filebeat 采集数据全速推送到 Kafka 的速率大致为 7K/s，CPU 开销为 0.9 cores；

测试结论

Situation	Thoughput(K/s)	CPU(Cores)
输出到Console, 应用写入+FB采集，247B	19	0.8
输出到Console, FB采集，247B	39	1.6
输出到Kafka, 应用写入+FB采集，247B	16.5	0.75
输出到Kafka, FB采集，247B	39.5	2.0
输出到Kafka, 应用写入+FB采集，247B，1Core	16.5	0.75
输出到Kafka, FB采集，247B，1Core	18.5	1.0
输出到Kafka, 应用写入+FB采集，1KB，1Core	13.5	0.83
输出到Kafka, FB采集，1KB，1Core	15.5	1.0
输出到Kafka, 应用写入+FB采集，5KB，1Core	6	0.73
输出到Kafka, FB采集，5KB，1Core	7	0.9

A. FB 全力采集 247B 数据(真实环境类似日志长度)，速率为 ~ 40K/s，CPU 开销为 2 cores；

B. FB 在 CPU 限制 1 cores 情况下，采集 247B 数据速率为 ~ 20K/s，可以认为单核采集速率为 ~ 20K/s/core；

C. 日志单行数据越大，吞吐越小，5KB 每行已经非常夸张，即使如此，没有压缩的情况下带宽消耗 35MBps，gzip 压缩率一般为 0.3~0.4，占用带宽为 10.5~14MBps，对于千兆网卡来说压力较小；

在生产的情况下，即使有 gzip 压缩，也必须有降级措施，以避免日志因异常暴涨情况下的网络带宽占用。

    原文作者：大数据之心
    原文地址: https://www.jianshu.com/p/0802cf22a135
    本文转自网络文章，转载此文章仅为分享知识，如有侵权，请联系博主进行删除。