High cpu usage by worker thread

Elastic Stack Logstash
1

I am trying to parse some logs by logstash which is reading logs directly from a log file. While starting logstash using bin/logstash -f <config_file> logstash cpu usage go high(up to 80%). After some time logstash cpu become stable. But when logs are written into file and logstash parses logs, worker thread uses upto 40% of cpu.

In filter section of config file, I am using mutilline plugin also. It also contains 1 grok and 1 mutate filter per log.

What could be possible reason for high CPU usage?

2

How many messages per second is Logstash processing?

3

I am writing 1000 logs/sec to file...How do I check how many logs are actually parsed by logstash per second?

4

40% CPU usage for 1000 msg/s definitely seems high, but it depends on the grok expression and the kind of CPU.

If you're feeding the messages into Elasticsearch you can e.g. use the kopf plugin to monitor the ingestion rate. Otherwise, just measure how long it takes to process a known amount of messages. However, unless there's a reason to believe that Logstash is falling behind and can't keep up with the input rate (unlikely unless the CPU(s) are saturated) the output rate will by definition match the input rate.

5

I have installed kopf plugin for elastic search. I am assuming that value which is next to total number of docs, (in small fonts) is total number of logs coming to elastic search per second. This value is varying from 1000-8000/sec.

6

My sample log looks like

[2015-09-09T00:24:43.759-07:00] [AdminServer] [ERROR] [] [myapp.sample.Monitoring] [tid: 36] [userId: asgoswm] [ecid: f3dd5eb7-32b9-4d81-8f51-aa57e0cc80bd-00000048,0] [APP: Server-All] MyApp.persistValueLong: Error persisting metric value

first I am using grok filter to parse single fields.

grok {
break_on_match => false
match => ["message", "(?m)[(?[^]])] [(?[^]])] [(?[^]])] [(?[^]])] [(?[^]]*)] [%{USER}: (?\S+(?:[^[]])+)] %{GREEDYDATA:templogmessage}"]
}

now I am using ruby plugin to parse templogmessage to get key/value pairs.

7

Well, you can always disable filters one by one and see if any one of them is slowing things down.

8

Mangus,

I have removed all things from my filter, just one grok section is there(above grok). Still CPU is not showing any significant reduction. its spiking between 20-30%.

Is it normal for CPU usage to be 20-30% for this kind of processing or can it be optimized to below 5%?