Filebeat Consumes High CPU:

Elastic Stack Beats
1

Hi,

I'm using filebeat to watch some bro logs. But the filebeat turns out to consume 60% cpu to catch up with new logs with speed of 8k to 10k eps.

Here's my filebeat config:

filebeat:
  prospectors:
  - close_inactive: 3m
    harvester_limit: 500
    input_type: log
    paths:
    - /home/ubuntu/bro/logs/conn.log
    - /home/ubuntu/bro/logs/capture_loss.log
    - /home/ubuntu/bro/logs/dns.log
    - /home/ubuntu/bro/logs/dpd.log
    - /home/ubuntu/bro/logs/files.log
    - /home/ubuntu/bro/logs/ftp.log
    - /home/ubuntu/bro/logs/http_eth0.log
    - /home/ubuntu/bro/logs/known_hosts.log
    - /home/ubuntu/bro/logs/known_services.log
    - /home/ubuntu/bro/logs/mysql.log
    - /home/ubuntu/bro/logs/notice.log
    - /home/ubuntu/bro/logs/smtp.log
    - /home/ubuntu/bro/logs/software.log
    - /home/ubuntu/bro/logs/ssh.log
    - /home/ubuntu/bro/logs/ssl.log
    - /home/ubuntu/bro/logs/stats.log
    - /home/ubuntu/bro/logs/syslog.log
    - /home/ubuntu/bro/logs/tunnel.log
    - /home/ubuntu/bro/logs/weird.log
    - /home/ubuntu/bro/logs/x509.log

And I run the filebeat with the httpprof option and the the following results:

File: filebeat
Type: cpu
Time: Apr 5, 2018 at 10:31am (PDT)
Duration: 5mins, Total samples = 1.82mins (36.43%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 42.27s, 38.68% of 109.29s total
Dropped 527 nodes (cum <= 0.55s)
Showing top 10 nodes out of 189
      flat  flat%   sum%        cum   cum%
     7.98s  7.30%  7.30%      7.98s  7.30%  runtime.duffcopy /usr/local/Cellar/go/1.9.2/libexec/src/runtime/duff_amd64.s
     5.12s  4.68% 11.99%      5.12s  4.68%  runtime.usleep /usr/local/Cellar/go/1.9.2/libexec/src/runtime/sys_linux_amd64.s
     4.87s  4.46% 16.44%      4.87s  4.46%  runtime.futex /usr/local/Cellar/go/1.9.2/libexec/src/runtime/sys_linux_amd64.s
     4.69s  4.29% 20.73%      9.18s  8.40%  runtime.runqgrab /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go
     4.41s  4.04% 24.77%     11.79s 10.79%  github.com/elastic/beats/filebeat/input/file.(*States).findPrevious /work/beats/src/github.com/elastic/beats/filebeat/input/file/state.go
     4.22s  3.86% 28.63%     20.34s 18.61%  runtime.findrunnable /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go
        3s  2.74% 31.38%      3.66s  3.35%  runtime.lock /usr/local/Cellar/go/1.9.2/libexec/src/runtime/lock_futex.go
     2.82s  2.58% 33.96%      6.84s  6.26%  runtime.selectgo /usr/local/Cellar/go/1.9.2/libexec/src/runtime/select.go
     2.58s  2.36% 36.32%      9.76s  8.93%  runtime.mallocgc /usr/local/Cellar/go/1.9.2/libexec/src/runtime/malloc.go
     2.58s  2.36% 38.68%      2.88s  2.64%  runtime.unlock /usr/local/Cellar/go/1.9.2/libexec/src/runtime/lock_futex.go

The logs rotates every 30 mins. And I also see that the same file path with different inode id appears in the registry file.

Any ideas for reducing the cpu usage or how this happened?

2

What is the size of your registry? I would recommend you to enabled clean_inactive: 1h in case the files are rotated every 30 minutes. This will reduce the number of entries in your registry file and with it the number of cycles that is spent on finding old files and comparing states.

Which version of filebeat are you using?

3

I'm using filebeat 5.1.2

The registry file is around 50k.

I noticed the registry file did grow. I tried to remove the registry file and start filebeat, the bottleneck is now the json encoder.

I also found that the states clean up process got triggered even without clean_inactive / ignore_older set. How often the cleanup process get trigger by default?

If we see multiple entries for the same file path in the registry file, does it mean that the file got rotated (usually renamed) that many times? If not, what could be the possible reasons for triggering this issue?

This is the latest cpu profiling result. Is there any clue for for reducing the cpu usage?

flat  flat%   sum%        cum   cum%
  0.09mins  5.23%  5.23%   0.09mins  5.23%  runtime.futex /usr/local/Cellar/go/1.9.2/libexec/src/runtime/sys_linux_amd64.s
  0.08mins  4.59%  9.83%   0.15mins  8.43%  runtime.runqgrab /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go
  0.08mins  4.56% 14.39%   0.08mins  4.56%  runtime.usleep /usr/local/Cellar/go/1.9.2/libexec/src/runtime/sys_linux_amd64.s
  0.08mins  4.33% 18.72%   0.35mins 19.78%  runtime.findrunnable /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go
  0.06mins  3.20% 21.91%   0.07mins  3.85%  runtime.lock /usr/local/Cellar/go/1.9.2/libexec/src/runtime/lock_futex.go
  0.06mins  3.16% 25.07%   0.14mins  7.66%  runtime.selectgo /usr/local/Cellar/go/1.9.2/libexec/src/runtime/select.go
  0.05mins  2.70% 27.77%   0.05mins  2.95%  runtime.unlock /usr/local/Cellar/go/1.9.2/libexec/src/runtime/lock_futex.go
  0.05mins  2.63% 30.40%   0.17mins  9.86%  runtime.mallocgc /usr/local/Cellar/go/1.9.2/libexec/src/runtime/malloc.go
4

Can you check how many entries there are in the registry file (it's an array). 50KB is still an ok size but I assume there are quite a few entries inside. We did some improvements on master to make the registry lookup much more efficient. If possible, it would be interesting if you could compare this version.

The cleanup check gets triggered after every scan to check if there are new items to clean up.

For the same path in the registry: yes.

Did you try the clean_* options to reduce the size of your registry?

5

The entry number is around 400.

Yes, the clean_inactive option works for controlling the registry size

To optimize the performance and reduce cpu usage, I moved out of the json encoding completely and use a format string output instead. But the cpu is still around 40%. The top 20 functions in the cpu profiling are from runtime. Do you have any idea of this?

(pprof) top20
Showing nodes accounting for 36680ms, 51.62% of 71060ms total
Dropped 390 nodes (cum <= 355.30ms)
Showing top 20 nodes out of 206
      flat  flat%   sum%        cum   cum%
    3260ms  4.59%  4.59%     3260ms  4.59%  runtime.futex /usr/local/Cellar/go/1.9.2/libexec/src/runtime/sys_linux_amd64.s
    2840ms  4.00%  8.58%     4680ms  6.59%  runtime.runqgrab /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go
    2690ms  3.79% 12.37%     3410ms  4.80%  runtime.lock /usr/local/Cellar/go/1.9.2/libexec/src/runtime/lock_futex.go
    2610ms  3.67% 16.04%     2610ms  3.67%  runtime.usleep /usr/local/Cellar/go/1.9.2/libexec/src/runtime/sys_linux_amd64.s
    2510ms  3.53% 19.58%     6150ms  8.65%  runtime.selectgo /usr/local/Cellar/go/1.9.2/libexec/src/runtime/select.go
    2450ms  3.45% 23.02%    11620ms 16.35%  runtime.findrunnable /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go
    2230ms  3.14% 26.16%     2600ms  3.66%  runtime.unlock /usr/local/Cellar/go/1.9.2/libexec/src/runtime/lock_futex.go
    2140ms  3.01% 29.17%     9320ms 13.12%  runtime.mallocgc /usr/local/Cellar/go/1.9.2/libexec/src/runtime/malloc.go
    2110ms  2.97% 32.14%     2130ms  3.00%  github.com/elastic/beats/vendor/github.com/golang/snappy.encodeBlock /Users/karenyang/work/beats/src/github.com/elastic/beats/vendor/github.com/golang/snappy/encode_amd64.s
    2040ms  2.87% 35.01%     2040ms  2.87%  runtime.memclrNoHeapPointers /usr/local/Cellar/go/1.9.2/libexec/src/runtime/memclr_amd64.s
    1970ms  2.77% 37.78%     4280ms  6.02%  runtime.mapassign_faststr /usr/local/Cellar/go/1.9.2/libexec/src/runtime/hashmap_fast.go
    1660ms  2.34% 40.12%     1660ms  2.34%  runtime.memmove /usr/local/Cellar/go/1.9.2/libexec/src/runtime/memmove_amd64.s
    1380ms  1.94% 42.06%     3250ms  4.57%  runtime.scanobject /usr/local/Cellar/go/1.9.2/libexec/src/runtime/mgcmark.go
    1230ms  1.73% 43.79%     1230ms  1.73%  runtime.heapBitsSetType /usr/local/Cellar/go/1.9.2/libexec/src/runtime/mbitmap.go
    1140ms  1.60% 45.40%     1140ms  1.60%  runtime.nextFreeFast /usr/local/Cellar/go/1.9.2/libexec/src/runtime/malloc.go
     960ms  1.35% 46.75%      960ms  1.35%  runtime.casgstatus /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go
     880ms  1.24% 47.99%      930ms  1.31%  runtime.mapiternext /usr/local/Cellar/go/1.9.2/libexec/src/runtime/hashmap.go
     880ms  1.24% 49.23%      940ms  1.32%  syscall.Syscall /usr/local/Cellar/go/1.9.2/libexec/src/syscall/asm_linux_amd64.s
     850ms  1.20% 50.42%      850ms  1.20%  runtime.aeshashbody /usr/local/Cellar/go/1.9.2/libexec/src/runtime/asm_amd64.s
     850ms  1.20% 51.62%     5590ms  7.87%  runtime.runqsteal /usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go
6

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