Filebeat high CPU usage during reading a huge file

Hello fellow ELKstackers,

Filebeat (6.3.1 on x64 old RedHat) runs with very high CPU when has been behind and needs to read some large log-files. It used 100% of 1/8 cpus (top said around 100%). After it was done processing the files (total 8GB in two files), it uses around 1% cpu.

filebeat.inputs:
- type: log
  enabled: true
  paths:
    - /home/ott/internet_bookings/logs/main-trace.log
    - /home/ott/internet_bookings/logs/20??-??/main-trace*.log

  multiline.pattern: ^20(1|2)\d-\d\d-\d\d
  multiline.negate: true
  multiline.match: after
output.logstash:
  hosts: ["localhost:5044"]

The localhost:5044 is connected to logstash on another machine via an SSH reverse tunnel

ssh -t -t -R 5044:localhost:5044 root@osloA bash -c 'cd /opt/filebeat; nice -n9 filebeat'

Admittedly the prod-machine is very old, but it seems filebeat was much harder on the machine than unzipping the file.

Its the filebeat process that has high CPU so I would expect it cannot be the ssh-encryption.

Any thoughts? Is this normal?

Could it just be the default gzip compression of Filebeat? I doubt it could be just this, as gzip -3 runs much faster than the Filebeat takes to complete the files, but both were at 100% CPU.

Thank you

Here's some data

$ cat  /etc/*release
Red Hat Enterprise Linux Server release 5.5 (Tikanga)
$ filebeat -e --cpuprofile=cpuprofile.pprof
2021-08-24T16:14:47.909+0200    INFO    instance/beat.go:492    Home path: [/opt/filebeat-6.3.1-linux-x86_64] Config path: [/opt/filebeat-6.3.1-linux-x86_64] Data path: [/opt/filebeat-6.3.1-linux-x86_64/data] Logs path: [/opt/filebeat-6.3.1-linux-x86_64/logs]
2021-08-24T16:14:47.909+0200    INFO    instance/beat.go:499    Beat UUID: 356ccbc3-91ca-4d71-852d-a3225c64e3cc
2021-08-24T16:14:47.910+0200    INFO    [beat]  instance/beat.go:716    Beat info       {"system_info": {"beat": {"path": {"config": "/opt/filebeat-6.3.1-linux-x86_64", "data": "/opt/filebeat-6.3.1-linux-x86_64/data", "home": "/opt/filebeat-6.3.1-linux-x86_64", "logs": "/opt/filebeat-6.3.1-linux-x86_64/logs"}, "type": "filebeat", "uuid": "356ccbc3-91ca-4d71-852d-a3225c64e3cc"}}}
2021-08-24T16:14:47.910+0200    INFO    [beat]  instance/beat.go:725    Build info      {"system_info": {"build": {"commit": "ed42bb85e72ae58cc09748dc1825159713e0ffd4", "libbeat": "6.3.1", "time": "2018-06-29T21:09:35.000Z", "version": "6.3.1"}}}
2021-08-24T16:14:47.910+0200    INFO    [beat]  instance/beat.go:728    Go runtime info {"system_info": {"go": {"os":"linux","arch":"amd64","max_procs":8,"version":"go1.9.4"}}}
2021-08-24T16:14:47.912+0200    INFO    [beat]  instance/beat.go:761    Process info    {"system_info": {"process": {"capabilities": {"inheritable":null,"permitted":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap"],"effective":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap"],"bounding":null,"ambient":null}, "cwd": "/opt/filebeat-6.3.1-linux-x86_64", "exe": "/opt/filebeat-6.3.1-linux-x86_64/filebeat", "name": "filebeat", "pid": 30458, "ppid": 30098, "seccomp": {"mode":""}, "start_time": "2021-08-24T16:14:47.260+0200"}}}
2021-08-24T16:14:47.913+0200    INFO    instance/beat.go:225    Setup Beat: filebeat; Version: 6.3.1
2021-08-24T16:14:47.913+0200    INFO    pipeline/module.go:81   Beat name: OsloA
2021-08-24T16:14:47.913+0200    INFO    instance/beat.go:315    filebeat start running.
2021-08-24T16:14:47.913+0200    INFO    registrar/registrar.go:116      Loading registrar data from /opt/filebeat-6.3.1-linux-x86_64/data/registry
2021-08-24T16:14:47.914+0200    INFO    [monitoring]    log/log.go:97   Starting metrics logging every 30s
2021-08-24T16:14:47.915+0200    INFO    registrar/registrar.go:127      States Loaded from registrar: 101
2021-08-24T16:14:47.915+0200    WARN    beater/filebeat.go:354  Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.
2021-08-24T16:14:47.915+0200    INFO    crawler/crawler.go:48   Loading Inputs: 1
2021-08-24T16:14:47.985+0200    INFO    log/input.go:113        Configured paths: [/home/ott/internet_bookings/logs/app.log /home/ott/internet_bookings/logs/20??-??/app*.log /home/ott/internet_bookings/logs/main-trace.log /home/ott/internet_bookings/logs/20??-??/main-trace*.log /home/wildfly/internet_bookings/logs/app.log /home/wildfly/internet_bookings/logs/20??-??/app*.log /home/wildfly/internet_bookings/logs/main-trace.log /home/wildfly/internet_bookings/logs/20??-??/main-trace*.log /home/wildfly/app-api/logs/20??-??/main-trace*.log /home/wildfly/app-api/logs/main-trace.log /home/wildfly/business-api/logs/20??-??/main-trace*.log /home/wildfly/business-api/logs/main-trace.log /home/wildfly/business-profile/logs/20??-??/main-trace*.log /home/wildfly/business-profile/logs/main-trace.log /home/wildfly/central-service/logs/20??-??/main-trace*.log /home/wildfly/central-service/logs/main-trace.log /home/wildfly/dispatch-service/logs/20??-??/main-warn*.log /home/wildfly/dispatch-service/logs/main-warn.log /home/wildfly/external-api/logs/20??-??/main-trace*.log /home/wildfly/external-api/logs/main-trace.log /home/wildfly/ott/logs/20??-??/main-info*.log /home/wildfly/ott/logs/main-trace.log /home/wildfly/payment-service/logs/20??-??/main-info*.log /home/wildfly/payment-service/logs/main-trace.log /home/wildfly/public-profile/logs/20??-??/main-trace*.log /home/wildfly/public-profile/logs/main-trace.log /home/wildfly/user-service/logs/20??-??/main-trace*.log /home/wildfly/user-service/logs/main-trace.log /home/wildfly/vehicle-service/logs/20??-??/main-trace*.log /home/wildfly/vehicle-service/logs/main-trace.log /var/log/wildfly/app-api/main-trace.log /var/log/wildfly/business-api/main-trace.log /var/log/wildfly/business-profile/main-trace.log /var/log/wildfly/central-service/main-trace.log /var/log/wildfly/communication-service/main-trace.log /var/log/wildfly/dispatch-service/main-trace.log /var/log/wildfly/external-api/main-trace.log /var/log/wildfly/internet_booking/main-trace.log /var/log/wildfly/internet_booking/app.log /var/log/wildfly/ott/main-trace.log /var/log/wildfly/payment-service/main-trace.log /var/log/wildfly/public-profile/main-trace.log /var/log/wildfly/test-data/main-trace.log /var/log/wildfly/user-service/main-trace.log /var/log/wildfly/vehicle-service/main-trace.log /var/log/wildfly/app-api/20??-??/main-trace*.log /var/log/wildfly/business-api/20??-??/main-trace*.log /var/log/wildfly/business-profile/20??-??/main-trace*.log /var/log/wildfly/central-service/20??-??/main-trace*.log /var/log/wildfly/communication-service/20??-??/main-trace*.log /var/log/wildfly/dispatch-service/20??-??/main-trace*.log /var/log/wildfly/external-api/20??-??/main-trace*.log /var/log/wildfly/internet_booking/20??-??/main-trace*.log /var/log/wildfly/internet_booking/20??-??/app*.log /var/log/wildfly/ott/20??-??/main-trace*.log /var/log/wildfly/payment-service/20??-??/main-trace*.log /var/log/wildfly/public-profile/20??-??/main-trace*.log /var/log/wildfly/test-data/20??-??/main-trace*.log /var/log/wildfly/user-service/20??-??/main-trace*.log /var/log/wildfly/vehicle-service/20??-??/main-trace*.log]
2021-08-24T16:14:47.985+0200    INFO    input/input.go:88       Starting input of type: log; ID: 6335642959546396507
2021-08-24T16:14:47.985+0200    INFO    crawler/crawler.go:82   Loading and starting Inputs completed. Enabled inputs: 1
2021-08-24T16:14:47.990+0200    INFO    log/harvester.go:228    Harvester started for file: /home/ott/internet_bookings/logs/app.log
2021-08-24T16:14:47.991+0200    INFO    log/harvester.go:228    Harvester started for file: /home/wildfly/vehicle-service/logs/main-trace.log
2021-08-24T16:14:47.991+0200    INFO    log/harvester.go:228    Harvester started for file: /home/wildfly/user-service/logs/main-trace.log
2021-08-24T16:14:47.991+0200    INFO    log/harvester.go:228    Harvester started for file: /home/wildfly/public-profile/logs/main-trace.log
2021-08-24T16:14:47.992+0200    INFO    log/harvester.go:228    Harvester started for file: /home/wildfly/external-api/logs/main-trace.log
2021-08-24T16:14:47.993+0200    INFO    log/harvester.go:228    Harvester started for file: /home/ott/internet_bookings/logs/main-trace.log
2021-08-24T16:14:47.993+0200    INFO    log/harvester.go:228    Harvester started for file: /home/wildfly/ott/logs/main-trace.log
2021-08-24T16:14:47.995+0200    INFO    log/harvester.go:228    Harvester started for file: /home/wildfly/business-profile/logs/main-trace.log
2021-08-24T16:15:17.918+0200    INFO    [monitoring]    log/log.go:124  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":50,"time":{"ms":55}},"total":{"ticks":310,"time":{"ms":316},"value":310},"user":{"ticks":260,"time":{"ms":261}}},"info":{"ephemeral_id":"9bb64fd4-e3a5-4f90-a5cf-dfceaa934e17","uptime":{"ms":30013}},"memstats":{"gc_next":8377360,"memory_alloc":6664440,"memory_total":91903608,"rss":25010176}},"filebeat":{"events":{"active":56,"added":3423,"done":3367},"harvester":{"open_files":8,"running":8,"started":8}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":3299,"batches":29,"total":3299},"read":{"bytes":174},"type":"logstash","write":{"bytes":559312}},"pipeline":{"clients":1,"events":{"active":56,"filtered":68,"published":3355,"retry":831,"total":3423},"queue":{"acked":3299}}},"registrar":{"states":{"current":101,"update":3367},"writes":{"success":91,"total":91}},"system":{"cpu":{"cores":8},"load":{"1":2.84,"15":2.69,"5":2.56,"norm":{"1":0.355,"15":0.3363,"5":0.32}}}}}}

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.