Debug Logstash hot_threads

Elastic Stack Logstash
1

I've got an issue since upgrading to v6 where the logstash process will use 100% of a CPU core even though it is idle with no events being processed. I've checked through the JVM heap and whilst I'd like it to have more ram it seems ok and changing it hasn't had any effect anyway.

I've tried the hot_threads part of the monitoring API and it does indeed show a thread using high CPU but I'm at a loss as to how to proceed to narrow this down any further?

I've added the hot thread output below in case it means more to someone else?

::: {}
Hot threads at 2017-12-17T21:09:10+00:00, busiestThreads=3:
================================================================================
93.01 % of cpu usage, state: runnable, thread name: 'Ruby-0-Thread-1', thread id: 17
/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/stud-0.0.23/lib/stud/task.rb:22
    java.io.UnixFileSystem.getBooleanAttributes0(Native Method)
    java.io.UnixFileSystem.getBooleanAttributes(UnixFileSystem.java:242)
    java.io.File.isFile(File.java:882)
--------------------------------------------------------------------------------
3.39 % of cpu usage, state: timed_waiting, thread name: 'Ruby-0-Thread-40@[main]>worker1', thread id: 66
/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:392
    sun.misc.Unsafe.park(Native Method)
    java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
--------------------------------------------------------------------------------
3.38 % of cpu usage, state: timed_waiting, thread name: 'Ruby-0-Thread-39@[main]>worker0', thread id: 65
/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:392
    sun.misc.Unsafe.park(Native Method)
    java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
--------------------------------------------------------------------------------
2

Just to follow this up, I managed to trace it down through doing debug logging, between 5 and 6 it seems the config.automatic.reload setting changed from being in seconds to microseconds if it hasn't got a time unit suffix and I had it set to 3 so logstash was constantly reloading the configuration causing the high CPU usage.

I've changed the setting from 3 to 3s and it's dropped the logstash CPU usage from 100% to circa 10-15% which is where it was before.

3

To be fair this change is listed in the breaking changes docs for v 6.0 and 6.1
https://www.elastic.co/guide/en/logstash/6.0/breaking-changes.html#_application_settings
https://www.elastic.co/guide/en/logstash/6.1/breaking-changes.html#_application_settings

4

Yes it's completely my bad, I'd even read that previously. :man_facepalming:

5

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