Processbufferprocessor threads consuming very high CPU load

Graylog Central (peer support)
1

thread 10889/0x2a89 and some other processbufferprocessor threads comsume too much CPU continuously. And process buffer is full.

Graylog Version: Graylog 2.2.3+7adc951 (Oracle Corporation 1.8.0_60 on Linux 3.10.0-229.el7.x86_64)

 [1] Busy(12.7%) thread(10889/0x2a89) stack of java process(10792) under user(root):
 "processbufferprocessor-4" #50 prio=5 os_prio=0 tid=0x00007f5c493f5000 nid=0x2a89 runnable [0x00007f5bbdee8000]
   java.lang.Thread.State: RUNNABLE
	at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3797)
	at java.util.regex.Pattern$Curly.match0(Pattern.java:4272)
	at java.util.regex.Pattern$Curly.match(Pattern.java:4234)
	at java.util.regex.Pattern$Start.match(Pattern.java:3461)
	at java.util.regex.Matcher.search(Matcher.java:1248)
	at java.util.regex.Matcher.find(Matcher.java:637)
	at com.google.code.regexp.Matcher.find(Unknown Source)
	at oi.thekraken.grok.api.Grok.match(Grok.java:311)
	at org.graylog.plugins.pipelineprocessor.functions.strings.GrokMatch.evaluate(GrokMatch.java:65)
	at org.graylog.plugins.pipelineprocessor.functions.strings.GrokMatch.evaluate(GrokMatch.java:34)
	at org.graylog.plugins.pipelineprocessor.ast.expressions.FunctionExpression.evaluateUnsafe(FunctionExpression.java:63)
	at org.graylog.plugins.pipelineprocessor.ast.expressions.Expression.evaluate(Expression.java:41)
	at org.graylog.plugins.pipelineprocessor.ast.statements.VarAssignStatement.evaluate(VarAssignStatement.java:33)
	at org.graylog.plugins.pipelineprocessor.ast.statements.VarAssignStatement.evaluate(VarAssignStatement.java:22)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.evaluateStatement(PipelineInterpreter.java:372)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.executeRuleActions(PipelineInterpreter.java:359)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.evaluateStage(PipelineInterpreter.java:302)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.processForResolvedPipelines(PipelineInterpreter.java:264)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.process(PipelineInterpreter.java:144)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.process(PipelineInterpreter.java:100)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.handleMessage(ProcessBufferProcessor.java:119)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.dispatchMessage(ProcessBufferProcessor.java:105)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:82)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:45)
	at com.lmax.disruptor.WorkProcessor.run(WorkProcessor.java:143)
	at com.codahale.metrics.InstrumentedThreadFactory$InstrumentedRunnable.run(InstrumentedThreadFactory.java:66)
	at java.lang.Thread.run(Thread.java:745)

[2] Busy(12.4%) thread(10899/0x2a93) stack of java process(10792) under user(root):
"processbufferprocessor-14" #60 prio=5 os_prio=0 tid=0x00007f5c49349000 nid=0x2a93 runnable [0x00007f5bbd4de000]
   java.lang.Thread.State: RUNNABLE
	at java.util.regex.Pattern$CharProperty.match(Pattern.java:3776)
	at java.util.regex.Pattern$Curly.match0(Pattern.java:4260)
	at java.util.regex.Pattern$Curly.match(Pattern.java:4234)
	at java.util.regex.Pattern$Start.match(Pattern.java:3461)
	at java.util.regex.Matcher.search(Matcher.java:1248)
	at java.util.regex.Matcher.find(Matcher.java:637)
	at com.google.code.regexp.Matcher.find(Unknown Source)
	at oi.thekraken.grok.api.Grok.match(Grok.java:311)
	at org.graylog.plugins.pipelineprocessor.functions.strings.GrokMatch.evaluate(GrokMatch.java:65)
	at org.graylog.plugins.pipelineprocessor.functions.strings.GrokMatch.evaluate(GrokMatch.java:34)
	at org.graylog.plugins.pipelineprocessor.ast.expressions.FunctionExpression.evaluateUnsafe(FunctionExpression.java:63)
	at org.graylog.plugins.pipelineprocessor.ast.expressions.Expression.evaluate(Expression.java:41)
	at org.graylog.plugins.pipelineprocessor.ast.statements.VarAssignStatement.evaluate(VarAssignStatement.java:33)
	at org.graylog.plugins.pipelineprocessor.ast.statements.VarAssignStatement.evaluate(VarAssignStatement.java:22)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.evaluateStatement(PipelineInterpreter.java:372)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.executeRuleActions(PipelineInterpreter.java:359)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.evaluateStage(PipelineInterpreter.java:302)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.processForResolvedPipelines(PipelineInterpreter.java:264)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.process(PipelineInterpreter.java:144)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.process(PipelineInterpreter.java:100)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.handleMessage(ProcessBufferProcessor.java:119)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.dispatchMessage(ProcessBufferProcessor.java:105)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:82)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:45)
	at com.lmax.disruptor.WorkProcessor.run(WorkProcessor.java:143)
	at com.codahale.metrics.InstrumentedThreadFactory$InstrumentedRunnable.run(InstrumentedThreadFactory.java:66)
	at java.lang.Thread.run(Thread.java:745)

[3] Busy(12.3%) thread(10895/0x2a8f) stack of java process(10792) under user(root):
"processbufferprocessor-10" #56 prio=5 os_prio=0 tid=0x00007f5c48488800 nid=0x2a8f runnable [0x00007f5bbd8e3000]
   java.lang.Thread.State: RUNNABLE
	at java.util.regex.Pattern$Curly.match0(Pattern.java:4260)
	at java.util.regex.Pattern$Curly.match(Pattern.java:4234)
	at java.util.regex.Pattern$Start.match(Pattern.java:3461)
	at java.util.regex.Matcher.search(Matcher.java:1248)
	at java.util.regex.Matcher.find(Matcher.java:637)
	at com.google.code.regexp.Matcher.find(Unknown Source)
	at oi.thekraken.grok.api.Grok.match(Grok.java:311)
	at org.graylog.plugins.pipelineprocessor.functions.strings.GrokMatch.evaluate(GrokMatch.java:65)
	at org.graylog.plugins.pipelineprocessor.functions.strings.GrokMatch.evaluate(GrokMatch.java:34)
	at org.graylog.plugins.pipelineprocessor.ast.expressions.FunctionExpression.evaluateUnsafe(FunctionExpression.java:63)
	at org.graylog.plugins.pipelineprocessor.ast.expressions.Expression.evaluate(Expression.java:41)
	at org.graylog.plugins.pipelineprocessor.ast.statements.VarAssignStatement.evaluate(VarAssignStatement.java:33)
	at org.graylog.plugins.pipelineprocessor.ast.statements.VarAssignStatement.evaluate(VarAssignStatement.java:22)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.evaluateStatement(PipelineInterpreter.java:372)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.executeRuleActions(PipelineInterpreter.java:359)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.evaluateStage(PipelineInterpreter.java:302)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.processForResolvedPipelines(PipelineInterpreter.java:264)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.process(PipelineInterpreter.java:144)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.process(PipelineInterpreter.java:100)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.handleMessage(ProcessBufferProcessor.java:119)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.dispatchMessage(ProcessBufferProcessor.java:105)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:82)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:45)
	at com.lmax.disruptor.WorkProcessor.run(WorkProcessor.java:143)
	at com.codahale.metrics.InstrumentedThreadFactory$InstrumentedRunnable.run(InstrumentedThreadFactory.java:66)
	at java.lang.Thread.run(Thread.java:745)

[4] Busy(12.3%) thread(10893/0x2a8d) stack of java process(10792) under user(root):
"processbufferprocessor-8" #54 prio=5 os_prio=0 tid=0x00007f5c48484800 nid=0x2a8d runnable [0x00007f5bbdae4000]
   java.lang.Thread.State: RUNNABLE
	at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3797)
	at java.util.regex.Pattern$Curly.match0(Pattern.java:4272)
	at java.util.regex.Pattern$Curly.match(Pattern.java:4234)
	at java.util.regex.Pattern$Start.match(Pattern.java:3461)
	at java.util.regex.Matcher.search(Matcher.java:1248)
	at java.util.regex.Matcher.find(Matcher.java:637)
	at com.google.code.regexp.Matcher.find(Unknown Source)
	at oi.thekraken.grok.api.Grok.match(Grok.java:311)
	at org.graylog.plugins.pipelineprocessor.functions.strings.GrokMatch.evaluate(GrokMatch.java:65)
	at org.graylog.plugins.pipelineprocessor.functions.strings.GrokMatch.evaluate(GrokMatch.java:34)
	at org.graylog.plugins.pipelineprocessor.ast.expressions.FunctionExpression.evaluateUnsafe(FunctionExpression.java:63)
	at org.graylog.plugins.pipelineprocessor.ast.expressions.Expression.evaluate(Expression.java:41)
	at org.graylog.plugins.pipelineprocessor.ast.statements.VarAssignStatement.evaluate(VarAssignStatement.java:33)
	at org.graylog.plugins.pipelineprocessor.ast.statements.VarAssignStatement.evaluate(VarAssignStatement.java:22)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.evaluateStatement(PipelineInterpreter.java:372)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.executeRuleActions(PipelineInterpreter.java:359)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.evaluateStage(PipelineInterpreter.java:302)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.processForResolvedPipelines(PipelineInterpreter.java:264)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.process(PipelineInterpreter.java:144)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.process(PipelineInterpreter.java:100)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.handleMessage(ProcessBufferProcessor.java:119)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.dispatchMessage(ProcessBufferProcessor.java:105)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:82)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:45)
	at com.lmax.disruptor.WorkProcessor.run(WorkProcessor.java:143)
	at com.codahale.metrics.InstrumentedThreadFactory$InstrumentedRunnable.run(InstrumentedThreadFactory.java:66)
	at java.lang.Thread.run(Thread.java:745)

[5] Busy(12.3%) thread(10891/0x2a8b) stack of java process(10792) under user(root):
"processbufferprocessor-6" #52 prio=5 os_prio=0 tid=0x00007f5c493f8800 nid=0x2a8b runnable [0x00007f5bbdce6000]
   java.lang.Thread.State: RUNNABLE
	at java.util.regex.Pattern$CharProperty.match(Pattern.java:3776)
	at java.util.regex.Pattern$Curly.match0(Pattern.java:4260)
	at java.util.regex.Pattern$Curly.match(Pattern.java:4234)
	at java.util.regex.Pattern$Start.match(Pattern.java:3461)
	at java.util.regex.Matcher.search(Matcher.java:1248)
	at java.util.regex.Matcher.find(Matcher.java:637)
	at com.google.code.regexp.Matcher.find(Unknown Source)
	at oi.thekraken.grok.api.Grok.match(Grok.java:311)
	at org.graylog.plugins.pipelineprocessor.functions.strings.GrokMatch.evaluate(GrokMatch.java:65)
	at org.graylog.plugins.pipelineprocessor.functions.strings.GrokMatch.evaluate(GrokMatch.java:34)
	at org.graylog.plugins.pipelineprocessor.ast.expressions.FunctionExpression.evaluateUnsafe(FunctionExpression.java:63)
	at org.graylog.plugins.pipelineprocessor.ast.expressions.Expression.evaluate(Expression.java:41)
	at org.graylog.plugins.pipelineprocessor.ast.statements.VarAssignStatement.evaluate(VarAssignStatement.java:33)
	at org.graylog.plugins.pipelineprocessor.ast.statements.VarAssignStatement.evaluate(VarAssignStatement.java:22)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.evaluateStatement(PipelineInterpreter.java:372)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.executeRuleActions(PipelineInterpreter.java:359)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.evaluateStage(PipelineInterpreter.java:302)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.processForResolvedPipelines(PipelineInterpreter.java:264)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.process(PipelineInterpreter.java:144)
	at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.process(PipelineInterpreter.java:100)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.handleMessage(ProcessBufferProcessor.java:119)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.dispatchMessage(ProcessBufferProcessor.java:105)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:82)
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:45)
	at com.lmax.disruptor.WorkProcessor.run(WorkProcessor.java:143)
	at com.codahale.metrics.InstrumentedThreadFactory$InstrumentedRunnable.run(InstrumentedThreadFactory.java:66)
	at java.lang.Thread.run(Thread.java:745)

graylog’s log is here:

2017-10-23 10:28:59,910 WARN : org.graylog2.shared.rest.resources.ProxiedResource - Node <79ee427e-1229-46a0-8de5-1a2fef592362> not found while trying to call org.graylog2.shared.rest.resources.system.RemoteMetricsResource on it.
2017-10-23 10:29:07,019 INFO : org.elasticsearch.monitor.jvm - [graylog-79ee427e-1229-46a0-8de5-1a2fef592362] [gc][old][236585][6513] duration [5.7s], collections [1]/[6.2s], total [5.7s]/[42.6m], memory [1.8gb]->[1.7gb]/[1.9gb], all_pools {[young] [819.2mb]->[764.9mb]/[819.2mb]}{[survivor] [73.7mb]->[0b]/[102.3mb]}{[old] [1023.9mb]->[1023.9mb]/[1gb]}
2017-10-23 10:29:07,033 WARN : org.graylog2.periodical.NodePingThread - Did not find meta info of this node. Re-registering.
2017-10-23 10:29:11,899 WARN : org.graylog2.periodical.NodePingThread - Did not find meta info of this node. Re-registering.
2017-10-23 10:29:17,969 WARN : org.graylog2.shared.rest.resources.ProxiedResource - Node <79ee427e-1229-46a0-8de5-1a2fef592362> not found while trying to call org.graylog2.shared.rest.resources.system.RemoteMetricsResource on it.
2017-10-23 10:29:18,147 WARN : org.graylog2.periodical.NodePingThread - Did not find meta info of this node. Re-registering.
2017-10-23 10:29:23,100 WARN : org.graylog2.periodical.NodePingThread - Did not find meta info of this node. Re-registering.

Rules:

rule "add app_host"
when
    has_field("message") AND to_string($message.app_name) == "contract"
then
   set_field("app_host", to_string($message.source));
end


rule "ngx_log"
when
  to_string($message.app_loglevel) == "ACCESS"
then
  let r = grok("%{IPORHOST:http_clientip}\t%{HTTPDATE:http_timestamp}\t%{WORD:http_method}\t%{IPORHOST:http_host}(?::%{NUMBER}|)\t%{NUMBER:http_port}\t(:?%{IPORHOST:http_upstream_ip}:%{POSINT:http_upstream_port}|-|)(\t|)%{URIPATH:http_uri}(?:%{GREEDYDATA:http_param})?\tHTTP/%{NUMBER:http_protocol}\t%{NUMBER:http_status}\t%{NUMBER:http_content_length}\t(?:%{GREEDYDATA:http_referer}|-)\tUA:%{GREEDYDATA:http_user_agent}\t(:?%{GREEDYDATA:http_xforwardedfor}|-|)\t%{NUMBER:http_request_duration}\t(:?%{NUMBER:http_upstream_request_duration}|-)",to_string($message.message));
  set_field("http_clientip",r.http_clientip);
  set_field("http_timestamp",r.http_timestamp);
  set_field("http_method",r.http_method);
  set_field("http_host",r.http_host);
  set_field("http_port",r.http_port);
  set_field("http_upstream_ip",r.http_upstream_ip);
  set_field("http_upstream_port",r.http_upstream_port);
  set_field("http_uri",r.http_uri);
  set_field("http_param",r.http_param);
  set_field("http_protocol",r.http_protocol);
  set_field("http_status",r.http_status);
  set_field("http_content_length",r.http_content_length);
  set_field("http_referer",r.http_referer);
  set_field("http_user_agent",r.http_user_agent);
  set_field("http_xforwardedfor",r.http_xforwardedfor);
  set_field("http_request_duration",r.http_request_duration);
  set_field("http_upstream_request_duration",r.http_upstream_request_duration);
end
2

hi,

it seems it uses its time in matching regexps. You should consider optimizing your regular expressions. Look for example this: https://www.regular-expressions.info/catastrophic.html

In your grok statement, you have used several times GREEDYDATA. Can you instead define something more specific?

1 Like
3

Hej @tuxknight

first your rule can be smaller:

rule "ngx_log"
when
  to_string($message.app_loglevel) == "ACCESS"
then
  let r = grok("%{IPORHOST:http_clientip}\t%{HTTPDATE:http_timestamp}\t%{WORD:http_method}\t%{IPORHOST:http_host}(?::%{NUMBER}|)\t%{NUMBER:http_port}\t(:?%{IPORHOST:http_upstream_ip}:%{POSINT:http_upstream_port}|-|)(\t|)%{URIPATH:http_uri}(?:%{GREEDYDATA:http_param})?\tHTTP/%{NUMBER:http_protocol}\t%{NUMBER:http_status}\t%{NUMBER:http_content_length}\t(?:%{GREEDYDATA:http_referer}|-)\tUA:%{GREEDYDATA:http_user_agent}\t(:?%{GREEDYDATA:http_xforwardedfor}|-|)\t%{NUMBER:http_request_duration}\t(:?%{NUMBER:http_upstream_request_duration}|-)",to_string($message.message));
  set_fields(r);

In addition as @jtkarvo said - the Grok Pattern will translate to a very long/complicated regex. Numerous GREEDYDATA and backstabbing should be more optimized. Remember, Grok is a Shortcut for regex and if your regex is two pages long it will eat some CPU Power to apply that to every matching message.

1 Like
4

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