Suddenly slow logstash after upgrade(s)


(Hvisage) #1

Hi there,

I had this config: http://pastebin.com/aZr0uGtg running with (I recall) 1.5.4 and it was chucking along quite nicely on a Ubuntu 14.04
We've had a problem with other parts of the system, so we did an update of the os etc. at the same time.
This update to Logstash 1.5.5., and then I started having strange problems, and I decided to also update to Java8 & Logstash 2.1.0 to get that out of the way: HOWever, now my logstash java process is stuck at 100% CPU utilization, and doing a Ctrl-C, it sends warnings about 20 events queed for filter grok.
Please advise how/were to start debugging this issue, , as I see only concerns for jruby and java8: https://github.com/jruby/jruby/issues/1858 to add -Xcompile.invokedynamics=false


(Hvisage) #2

Okay,

I'ts not Java 8 (per se), but it is definately 1.5.5 or later, as Logstash 1.5.4. (I've downlaoded and isntalled that) and now my grok filter are working like a charm again, with 2.1.0 this is the type of error when trying to shutdown:

Exception: java.lang.ThreadDeath thrown from the UncaughtExceptionHandler in thread "Thread-381"
{:timestamp=>"2015-12-02T19:31:15.300000+0000", :message=>"SIGTERM received. Shutting down the pipeline.", :level=>:warn}
{:timestamp=>"2015-12-02T19:31:20.317000+0000", :level=>:warn, "INFLIGHT_EVENT_COUNT"=>{"input_to_filter"=>20, "total"=>20}, "STALLING_THREADS"=>{["LogStash::Filters::Grok", {"match"=>["message", "(?%{DAY} %{MONTH} [ ]?%{MONTHDAY} %{TIME} %{YEAR}) %{NUMBER:xferTime} %{IP:remoteHost} %{NUMBER:fileSize} %{UNIXPATH:dirName}?/(?(?>[\w_%!$@:.,-]+|\\.)*) %{WORD:transferType} %{WORD:specialActionFlag} %{WORD:direction} %{WORD:accessmode} %{WORD:username} %{WORD:serviceName} %{WORD:authenticationMethod} %{DATA:aut} %{WORD:completionStatus}"], "add_tag"=>["xfer_grokked", "grokked"]}]=>[{"thread_id"=>20, "name"=>"|filterworker.0", "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/jls-grok-0.11.2/lib/grok-pure.rb:177:in match'"}]}} {:timestamp=>"2015-12-02T19:31:20.325000+0000", :message=>"The shutdown process appears to be stalled due to busy or blocked plugins. Check the logs for more information.", :level=>:error} {:timestamp=>"2015-12-02T19:31:25.310000+0000", :level=>:warn, "INFLIGHT_EVENT_COUNT"=>{"input_to_filter"=>20, "total"=>20}, "STALLING_THREADS"=>{["LogStash::Filters::Grok", {"match"=>["message", "(?<atime>%{DAY} %{MONTH} [ ]?%{MONTHDAY} %{TIME} %{YEAR}) %{NUMBER:xferTime} %{IP:remoteHost} %{NUMBER:fileSize} %{UNIXPATH:dirName}?/(?<fileName>(?>[\\w_%!$@:.,-]+|\\\\.)*) %{WORD:transferType} %{WORD:specialActionFlag} %{WORD:direction} %{WORD:accessmode} %{WORD:username} %{WORD:serviceName} %{WORD:authenticationMethod} %{DATA:aut} %{WORD:completionStatus}"], "add_tag"=>["xfer_grokked", "grokked"]}]=>[{"thread_id"=>20, "name"=>"|filterworker.0", "current_call"=>"[...]/vendor/bundle/jruby/1.9/gems/jls-grok-0.11.2/lib/grok-pure.rb:177:inmatch'"}]}}


(system) #3