search

elastic / logstash

Logstash - transport and process your logs, events, or other data
https://www.elastic.co/products/logstash
Other
14.17k stars 3.49k forks source link

cpu usage 100% ,I find the filter hogging the cpu. #5665

Open york0xiong opened 8 years ago

york0xiong commented 8 years ago

the jstack :

"[main]>worker1" #23 daemon prio=5 os_prio=0 tid=0x00007f4fd40b5000 nid=0x786c runnable [0x00007f4fc7bf9000] java.lang.Thread.State: RUNNABLE at org.joni.ByteCodeMachine.matchAt(ByteCodeMachine.java:229) at org.joni.Matcher.matchCheck(Matcher.java:304) at org.joni.Matcher.searchInterruptible(Matcher.java:457) at org.jruby.RubyRegexp$SearchMatchTask.run(RubyRegexp.java:273) at org.jruby.RubyThread.executeBlockingTask(RubyThread.java:1066) at org.jruby.RubyRegexp.matcherSearch(RubyRegexp.java:235) at org.jruby.RubyRegexp.search19(RubyRegexp.java:1780) at org.jruby.RubyRegexp.matchPos(RubyRegexp.java:1720) at org.jruby.RubyRegexp.match19Common(RubyRegexp.java:1701) at org.jruby.RubyRegexp.match_m19(RubyRegexp.java:1680) at org.jruby.RubyRegexp$INVOKER$i$match_m19.call(RubyRegexp$INVOKER$i$match_m19.gen) at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneOrNBlock.call(JavaMethod.java:350) at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168) at rubyjit.Grok$$match_and_capture_5fff680283e4b4ebc4c0eb1732d88dbb187668931028566121.file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/jls-grok-0.11.2/lib/grok-pure.rb:177) at rubyjit.Grok$$match_and_capture_5fff680283e4b4ebc4c0eb1732d88dbb187668931028566121.file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/jls-grok-0.11.2/lib/grok-pure.rb) at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:201) at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:177) at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:188) at rubyjit.LogStash::Filters::Grok$$match_against_groks_329a76b8714eb799f1ad4b6ad1484d7896693b861028566121.block_0$RUBY$file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-2.0.5/lib/logstash/filters/grok.rb:316) at rubyjit$LogStash::Filters::Grok$$match_against_groks_329a76b8714eb799f1ad4b6ad1484d7896693b861028566121$block_0$RUBY$file.call(rubyjit$LogStash::Filters::Grok$$match_against_groks_329a76b8714eb799f1ad4b6ad1484d7896693b861028566121$block_0$RUBY$file) at org.jruby.runtime.CompiledBlock19.yield(CompiledBlock19.java:135) at org.jruby.runtime.Block.yield(Block.java:142) at org.jruby.RubyArray.eachCommon(RubyArray.java:1606) at org.jruby.RubyArray.each(RubyArray.java:1613) at org.jruby.RubyArray$INVOKER$i$0$0$each.call(RubyArray$INVOKER$i$0$0$each.gen) at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:143) at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:154) at rubyjit.LogStash::Filters::Grok$$match_against_groks_329a76b8714eb799f1ad4b6ad1484d7896693b861028566121.file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-2.0.5/lib/logstash/filters/grok.rb:314) at rubyjit.LogStash::Filters::Grok$$match_against_groks_329a76b8714eb799f1ad4b6ad1484d7896693b861028566121.file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-2.0.5/lib/logstash/filters/grok.rb) at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:261) at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:236) at rubyjit.LogStash::Filters::Grok$$match_ecb12619d5a54f294146c89c246df899c3df835a1028566121.chained_0_rescue_1$RUBY$SYNTHETICfile(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-2.0.5/lib/logstash/filters/grok.rb:305) at rubyjit.LogStash::Filters::Grok$$match_ecb12619d5a54f294146c89c246df899c3df835a1028566121.file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-2.0.5/lib/logstash/filters/grok.rb) at rubyjit.LogStash::Filters::Grok$$match_ecb12619d5a54f294146c89c246df899c3df835a1028566121.file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-2.0.5/lib/logstash/filters/grok.rb) at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:261) at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:236) at rubyjit.LogStash::Filters::Grok$$filter_428454220f2f91b7ec1ad9e019332db0555035611028566121.block_0$RUBY$file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-2.0.5/lib/logstash/filters/grok.rb:279) at rubyjit$LogStash::Filters::Grok$$filter_428454220f2f91b7ec1ad9e019332db0555035611028566121$block_0$RUBY$file.call(rubyjit$LogStash::Filters::Grok$$filter_428454220f2f91b7ec1ad9e019332db0555035611028566121$block_0$RUBY$file) at org.jruby.runtime.CompiledBlock19.yield(CompiledBlock19.java:135) at org.jruby.runtime.Block.yield(Block.java:142) at org.jruby.RubyHash$13.visit(RubyHash.java:1355) at org.jruby.RubyHash.visitLimited(RubyHash.java:648) at org.jruby.RubyHash.visitAll(RubyHash.java:634) at org.jruby.RubyHash.iteratorVisitAll(RubyHash.java:1306) at org.jruby.RubyHash.each_pairCommon(RubyHash.java:1351) at org.jruby.RubyHash.each19(RubyHash.java:1342) at org.jruby.RubyHash$INVOKER$i$0$0$each19.call(RubyHash$INVOKER$i$0$0$each19.gen) at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:143) at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:154) at rubyjit.LogStash::Filters::Grok$$filter_428454220f2f91b7ec1ad9e019332db0555035611028566121.file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-2.0.5/lib/logstash/filters/grok.rb:278) at rubyjit.LogStash::Filters::Grok$$filter_428454220f2f91b7ec1ad9e019332db0555035611028566121.file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-2.0.5/lib/logstash/filters/grok.rb) at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:201) at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:336) at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:179) at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:188) at rubyjit.LogStash::Filters::Base$$multi_filter_01135e7048cf29d1ffa54e153def77da0a7b31831028566121.block_0$RUBY$file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.3-java/lib/logstash/filters/base.rb:151) at rubyjit$LogStash::Filters::Base$$multi_filter_01135e7048cf29d1ffa54e153def77da0a7b31831028566121$block_0$RUBY$file.call(rubyjit$LogStash::Filters::Base$$multi_filter_01135e7048cf29d1ffa54e153def77da0a7b31831028566121$block_0$RUBY$file) at org.jruby.runtime.CompiledBlock19.yield(CompiledBlock19.java:135) at org.jruby.runtime.Block.yield(Block.java:142) at org.jruby.RubyArray.eachCommon(RubyArray.java:1606) at org.jruby.RubyArray.each(RubyArray.java:1613) at org.jruby.RubyArray$INVOKER$i$0$0$each.call(RubyArray$INVOKER$i$0$0$each.gen) at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:143) at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:154) at rubyjit.LogStash::Filters::Base$$multi_filter_01135e7048cf29d1ffa54e153def77da0a7b31831028566121.file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.3-java/lib/logstash/filters/base.rb:148) at rubyjit.LogStash::Filters::Base$$multi_filter_01135e7048cf29d1ffa54e153def77da0a7b31831028566121.file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.3-java/lib/logstash/filters/base.rb) at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:181) at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168) at org.jruby.ast.CallOneArgNode.interpret(CallOneArgNode.java:57) at org.jruby.ast.DAsgnNode.interpret(DAsgnNode.java:110) at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105) at org.jruby.ast.BlockNode.interpret(BlockNode.java:71) at org.jruby.ast.IfNode.interpret(IfNode.java:116) at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105) at org.jruby.ast.BlockNode.interpret(BlockNode.java:71) at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112) at org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206) at org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:157) at org.jruby.runtime.Block.yield(Block.java:142) at org.jruby.RubyArray.eachCommon(RubyArray.java:1606) at org.jruby.RubyArray.each(RubyArray.java:1613) at org.jruby.RubyArray$INVOKER$i$0$0$each.call(RubyArray$INVOKER$i$0$0$each.gen) at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:143) at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:154) at org.jruby.ast.CallNoArgBlockNode.interpret(CallNoArgBlockNode.java:64) at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105) at org.jruby.ast.BlockNode.interpret(BlockNode.java:71) at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112) at org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206) at org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:194) at org.jruby.runtime.Interpreted19Block.call(Interpreted19Block.java:125) at org.jruby.runtime.Block.call(Block.java:101) at org.jruby.RubyProc.call(RubyProc.java:300) at org.jruby.RubyProc.call19(RubyProc.java:281) at org.jruby.RubyProc$INVOKER$i$0$0$call19.call(RubyProc$INVOKER$i$0$0$call19.gen) at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:210) at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:206) at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168) at org.jruby.ast.CallOneArgNode.interpret(CallOneArgNode.java:57) at org.jruby.ast.DAsgnNode.interpret(DAsgnNode.java:110) at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105) at org.jruby.ast.BlockNode.interpret(BlockNode.java:71) at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112) at org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206) at org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:194) at org.jruby.runtime.Interpreted19Block.call(Interpreted19Block.java:125) at org.jruby.runtime.Block.call(Block.java:101) at org.jruby.RubyProc.call(RubyProc.java:300) at org.jruby.internal.runtime.methods.ProcMethod.call(ProcMethod.java:64) at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:210) at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:206) at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168) at rubyjit.LogStash::Pipeline$$filter_batch_0b21c86b210b64a38e10430dce5d7faf239ce9691028566121.block_0$RUBY$file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.3-java/lib/logstash/pipeline.rb:267) at rubyjit$LogStash::Pipeline$$filter_batch_0b21c86b210b64a38e10430dce5d7faf239ce9691028566121$block_0$RUBY$file.call(rubyjit$LogStash::Pipeline$$filter_batch_0b21c86b210b64a38e10430dce5d7faf239ce9691028566121$block_0$RUBY$file) at org.jruby.runtime.CompiledBlock19.yield(CompiledBlock19.java:159) at org.jruby.runtime.CompiledBlock19.yield(CompiledBlock19.java:145) at org.jruby.runtime.Block.yieldArray(Block.java:158) at org.jruby.RubyEnumerable$25.call(RubyEnumerable.java:835) at org.jruby.runtime.CallBlock.yield(CallBlock.java:90) at org.jruby.runtime.Block.yield(Block.java:142) at org.jruby.RubyArray.eachCommon(RubyArray.java:1606) at org.jruby.RubyArray.each(RubyArray.java:1613) at org.jruby.RubyArray$INVOKER$i$0$0$each.call(RubyArray$INVOKER$i$0$0$each.gen) at org.jruby.RubyClass.finvoke(RubyClass.java:528) at org.jruby.runtime.Helpers.invoke(Helpers.java:486) at org.jruby.RubyEnumerable.callEach(RubyEnumerable.java:98) at org.jruby.RubyEnumerable.injectCommon(RubyEnumerable.java:831) at org.jruby.RubyEnumerable.inject(RubyEnumerable.java:852) at org.jruby.RubyEnumerable$INVOKER$s$inject.call(RubyEnumerable$INVOKER$s$inject.gen) at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:177) at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:188) at rubyjit.LogStash::Pipeline$$filter_batch_0b21c86b210b64a38e10430dce5d7faf239ce9691028566121.chained_0_rescue_1$RUBY$SYNTHETICfile(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.3-java/lib/logstash/pipeline.rb:265) at rubyjit.LogStash::Pipeline$$filter_batch_0b21c86b210b64a38e10430dce5d7faf239ce9691028566121.file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.3-java/lib/logstash/pipeline.rb) at rubyjit.LogStash::Pipeline$$filter_batch_0b21c86b210b64a38e10430dce5d7faf239ce9691028566121.file(/usr/local/elk/logstash-2.3.3/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.3-java/lib/logstash/pipeline.rb) at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:181) at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168) at org.jruby.ast.FCallOneArgNode.interpret(FCallOneArgNode.java:36) at org.jruby.ast.LocalAsgnNode.interpret(LocalAsgnNode.java:123) at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105) at org.jruby.ast.BlockNode.interpret(BlockNode.java:71) at org.jruby.ast.WhileNode.interpret(WhileNode.java:131) at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105) at org.jruby.ast.BlockNode.interpret(BlockNode.java:71) at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74) at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:225) at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:219) at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:346) at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:204) at org.jruby.ast.FCallTwoArgNode.interpret(FCallTwoArgNode.java:38) at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105) at org.jruby.ast.BlockNode.interpret(BlockNode.java:71) at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112) at org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206) at org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:194) at org.jruby.runtime.Interpreted19Block.call(Interpreted19Block.java:125) at org.jruby.runtime.Block.call(Block.java:101) at org.jruby.RubyProc.call(RubyProc.java:300) at org.jruby.RubyProc.call(RubyProc.java:230) at org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:99) at java.lang.Thread.run(Thread.java:745)

the config: input { beats { port => 5044 type => "xzb_logs" congestion_threshold => 10 } } filter{ if[type] == "xzblogs"{ grok{ match =>{ message => "(?)/(?[\w]) (?[\w]) (?[\d\w]+-[\d\w]+)/(?\w+(.[\w]+)) %{WORD:LOGLEVEL}/(?[^:]):(?[\s\S]_)" } } date{ match => ["TIME","yyyy-MM-dd HH:mm:ss Z"]

            }
    }

} output { elasticsearch { hosts => ["10.10.45.60:9200"] index => "logstash-%{type}-%{+YYYY.MM.dd}" document_type => "%{type}" workers => 1 flush_size => 100 } stdout{ codec => rubydebug } }

and logstash log: {:timestamp=>"2016-07-20T17:40:26.104000+0800", :message=>"Beats input: the pipeline is blocked, temporary refusing new connection.", :reconnect_backoff_sleep=>0.5, :level=>:warn} {:timestamp=>"2016-07-20T17:40:26.604000+0800", :message=>"Beats input: the pipeline is blocked, temporary refusing new connection.", :reconnect_backoff_sleep=>0.5, :level=>:warn}

jsvd commented 7 years ago

I'm guessing here that the manually constructed regex (?[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2} (?:Z|+-(?::?(?:[0-5][0-9])))) (?[\w])/(?[\w]) (?[\w]) (?[\d\w]+-[\d\w]+)/(?\w+(.[\w]+)) %{WORD:LOGLEVEL}/(?[^:]):(?[\s\S]) can be very slow specially when the input doesn't match.

this regex is causing CPU to go high, thus causing the pipeline to clog and thus producing the beats input error messages.

[edit] please check https://www.elastic.co/blog/do-you-grok-grok for some tips on using grok

TheVastyDeep commented 1 year ago

Without seeing the [message] field that this is trying to match and the regexp itself (some of which is being consumed as formatting) it is not possible to say what is wrong, but to me it seems likely that grok{ match =>{ message => " %{WORD:LOGLEVEL}/" } } would do the job much more efficiently, since none of the other matched fields are being stored.