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}}}}}}