[dev.icinga.com #11807] Command Pipe thread 100% CPU Usage

[icinga-migration]

This issue has been migrated from Redmine: https://dev.icinga.com/issues/11807

Created by mfrosch on 2016-05-18 13:29:01 +00:00

Assignee: mfrosch
Status: Resolved (closed on 2016-05-19 07:45:37 +00:00)
Target Version: 2.4.9
Last Update: 2016-05-19 07:45:37 +00:00 (in Redmine)

Icinga Version: 2.4.8
Backport?: Not yet backported
Include in Changelog: 1

---

Seems that the CommandPipe Thread is running a busy loop after submitting a few commands:

#0  0x00002b060a187add in read () at ../sysdeps/unix/syscall-template.S:81

No locals.

#1  0x00002b060a4706aa in read (__nbytes=8192, __buf=0x2b062df4de80, __fd=) at /usr/include/x86_64-linux-gnu/bits/unistd.h:44

No locals.

#2  icinga::Socket::Read (this=this@entry=0x2b0640000bb0, buffer=buffer@entry=0x2b062df4de80, count=count@entry=8192) at /build/icinga2-2.4.8/lib/base/socket.cpp:302

rc =

PRETTY_FUNCTION = "size_t icinga::Socket::Read(void*, size_t)"

#3  0x00002b062177609e in icinga::ExternalCommandListener::CommandPipeThread (this=, commandPath=...) at /build/icinga2-2.4.8/lib/compat/externalcommandlistener.cpp:116

buffer = "[1463577735] SCHEDULE_FORCED_SVC_CHECK;muria;https cert horde.lazyfrosch.de;1463577735\n", '\000' <repeats 8104 times>
rc =
fd =
fifo = {px = 0x2b0640000960}
sock = {px = 0x2b0640000bb0}
src = {Buffer = 0x2b0640000e40 "[1463577735] SCHEDULE_FORCED_SVC_CHECK;muria;https cert horde.lazyfrosch.de;1463577735\n", Size = 0, MustRead = true, Eof = false}
statbuf = {st_dev = 15, st_ino = 19188, st_nlink = 1, st_mode = 4528, st_uid = 108, st_gid = 33, __pad0 = 0, st_rdev = 0, st_size = 0, st_blksize = 4096, st_blocks = 0, st_atim = {tv_sec = 1463574270, tv_nsec = 832464975}, st_mtim = {tv_sec = 1463574270,
tv_nsec = 372488893}, st_ctim = {tv_sec = 1463574373, tv_nsec = 83147659}, __glibc_reserved = {0, 0, 0}}
fifo_ok =

PRETTY_FUNCTION = "void icinga::ExternalCommandListener::CommandPipeThread(const icinga::String&)"
mode =

#4  0x00002b06097dbaea in ?? () from /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.55.0

No symbol table info available.

#5  0x00002b060a1810a4 in start_thread (arg=0x2b062df50700) at pthread_create.c:309

__res =
pd = 0x2b062df50700
now =
unwind_buf = {cancel_jmp_buf = {{jmp_buf = {47305540830976, -2871906052433176024, 0, 47304928968800, 47305534523840, 47305540830976, -8203118426899801560, -8203055373650290136}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {
prev = 0x0, cleanup = 0x0, canceltype = 0}}}
not_first_call =
pagesize_m1 =
sp =
freesize =

PRETTY_FUNCTION = "start_thread"

#6  0x00002b060cd0187d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Changesets

2016-05-18 13:52:29 +00:00 by gbeutner 78705e7

Open the command pipe with O_RDWR

fixes #11807

2016-05-19 07:50:55 +00:00 by gbeutner 3746374

Open the command pipe with O_RDWR

fixes #11807

[icinga-migration]

Updated by gbeutner on 2016-05-18 13:51:08 +00:00

• Status changed from New to Assigned

• Assigned to set to gbeutner

  read(14, "", 8192) = 0
  poll([{fd=14, events=POLLIN}], 1, 4294967295) = 1 ([{fd=14, revents=POLLHUP}])

[icinga-migration]

Updated by gbeutner on 2016-05-18 13:55:03 +00:00

• Status changed from Assigned to Resolved
• Done % changed from 0 to 100

Applied in changeset 78705e7.

[icinga-migration]

Updated by mfrosch on 2016-05-18 17:29:11 +00:00

• Status changed from Resolved to Feedback

Running on v2.4.8-413-g4af6bde

a single "check now" command will cause the CommandListener Thread got haywire, 100% CPU usage.

#0  0x00007f7aacd20d3d in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f7aafe17f80 in icinga::Socket::Poll (this=0x7f7a6c000bb0, read=true, write=false, timeout=0x0) at ../../../lib/base/socket.cpp:394
#2  0x00007f7aa86e2034 in icinga::ExternalCommandListener::CommandPipeThread (this=0x7f7a88010c90, commandPath=...) at ../../../lib/compat/externalcommandlistener.cpp:110
#3  0x00007f7aa8778bf6 in boost::_mfi::mf1::operator() (this=0x7f7a80036ed8, p=0x7f7a88010c90, a1=...) at /usr/include/boost/bind/mem_fn_template.hpp:165
#4  0x00007f7aa87784ed in boost::_bi::list2, boost::_bi::value >::operator(), boost::_bi::list0> (

this=0x7f7a80036ee8, f=..., a=...) at /usr/include/boost/bind/bind.hpp:313

#5  0x00007f7aa8776c2f in boost::_bi::bind_t, boost::_bi::list2, boost::_bi::value > >::operator() (

this=0x7f7a80036ed8) at /usr/include/boost/bind/bind_template.hpp:20
...

Same goes for the thread of the main event loop in that case:

#0  0x00007f7aaccfaf2d in nanosleep () at ../sysdeps/unix/syscall-template.S:81

No locals.

#1  0x00007f7aacd23204 in usleep (useconds=) at ../sysdeps/unix/sysv/linux/usleep.c:32

ts = {tv_sec = 2, tv_nsec = 500000000}

#2  0x00007f7aafe2aeac in icinga::Utility::Sleep (timeout=2.5) at ../../../lib/base/utility.cpp:391

No locals.

#3  0x00007f7aafde3c97 in icinga::Application::RunEventLoop (this=0x7f7a7c00ca30) at ../../../lib/base/application.cpp:282

now = 1463592450.8741579
timeDiff = -2.5000579357147217
lastLoop = 1463592450.8741579

#4  0x00007f7aa985fa28 in icinga::IcingaApplication::Main (this=0x7f7a7c00ca30) at ../../../lib/icinga/icingaapplication.cpp:119

...

[icinga-migration]

Updated by mfrosch on 2016-05-18 17:29:19 +00:00

• Status changed from Feedback to New

[icinga-migration]

Updated by gbeutner on 2016-05-19 05:05:44 +00:00

• Status changed from New to Feedback
• Assigned to changed from gbeutner to mfrosch

That's not the latest commit. Please test with 78705e7 or later.

[icinga-migration]

Updated by mfrosch on 2016-05-19 07:45:37 +00:00

• Status changed from Feedback to Resolved

Had to trigger Jenkins, seems to work fine now.