| Summary: | pacemaker daemons consume cpu on crash of lower level components | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | dan clark <2clarkd> | ||||
| Component: | pacemaker | Assignee: | Andrew Beekhof <andrew> | ||||
| Status: | CLOSED CURRENTRELEASE | QA Contact: | Fedora Extras Quality Assurance <extras-qa> | ||||
| Severity: | high | Docs Contact: | |||||
| Priority: | unspecified | ||||||
| Version: | 14 | CC: | 2clarkd, abeekhof, andrew, fdinitto, lhh | ||||
| Target Milestone: | --- | ||||||
| Target Release: | --- | ||||||
| Hardware: | x86_64 | ||||||
| OS: | Linux | ||||||
| Whiteboard: | |||||||
| Fixed In Version: | Doc Type: | Bug Fix | |||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | Environment: | ||||||
| Last Closed: | 2011-09-26 02:45:45 UTC | Type: | --- | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Attachments: |
|
||||||
|
Description
dan clark
2011-05-19 22:52:28 UTC
see related bug 706289 which provokes this problem with the use of an available test suite program. Is there a way to cleanup the orphaned components under this setup (service xxx restart)? see bug 706297 for details. Actually all components terminate if their connection to corosync is lost. Its not clear to me what the processes are doing during this time. Can you attach some logs please? Created attachment 502125 [details]
corosync log and corosync config file
Running corosync with the "-p" flag allowed the daemon to be killed without locking up the system, the pcmk daemons still peg the cpu at 100% across stonithd, cib, lrmd, attrd, pengine and crmd).
The attached configuration file is for a simple two node setup, although one node is sufficient and the problem occurs on three nodes as well.
This test was done with a minimal pacemaker configuration on two nodes.
# crm configure show
node tarnfd2.local
node tarnfd3.local
property $id="cib-bootstrap-options" \
dc-version="1.1.5-1.fc14-01e86afaaa6d4a8c4836f68df80ababd6ca3902f" \
cluster-infrastructure="openais" \
expected-quorum-votes="2" \
stonith-enabled="false" \
no-quorum-policy="ignore"
rsc_defaults $id="rsc-options" \
resource-stickiness="100"
gdb on the daemons indicates a loop
Finishing truncated messages from above:
the back trace indicates all pacemaker daemons resting on a poll in the main loop. The strace indicates that their may be an unhandled error condition polling on fd that may have an error (is it the broken client file descriptor to the corosync daemon?), thus causing the loop which repeats below (poll call trace resulted in about 600 poll system calls per second and about 1600 system calls per second).
-- sample of strace attached initially to a healthy system---
# initiate corosync -p to avoid running all daemons at high priority
Process 11835 attached - interrupt to quit
13:32:28.460837 restart_syscall(<... resuming interrupted call ...>) = 1 <325.498456>
13:37:53.960530 times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 447327323 <0.000116>
### note - wait 5 minutes with no activity, followed by 'killall -9 corosync'
13:37:53.960936 times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 447327323 <0.000033>
13:37:53.961052 recvfrom(7, 0x1c5c39d, 3795, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000047>
13:37:53.961332 poll([{fd=7, events=0}], 1, 0) = 0 (Timeout) <0.000838>
13:37:53.962481 recvfrom(7, 0x1c5c39d, 3795, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000036>
13:37:53.962591 poll([{fd=7, events=0}], 1, 0) = 0 (Timeout) <0.000033>
13:37:53.962691 times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 447327323 <0.000060>
13:37:53.962828 times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 447327323 <0.000031>
13:37:53.963026 poll([{fd=3, events=POLLIN}], 1, 0) = 1 ([{fd=3, revents=POLLIN|POLLHUP}]) <0.000098>
13:37:53.963218 times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 447327323 <0.000043>
13:37:53.963338 times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 447327323 <0.000019>
13:37:53.963507 recvfrom(7, 0x1c5c39d, 3795, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000020>
13:37:53.963614 poll([{fd=7, events=0}], 1, 0) = 0 (Timeout) <0.000019>
13:37:53.963733 recvfrom(7, 0x1c5c39d, 3795, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000019>
13:37:53.963836 poll([{fd=7, events=0}], 1, 0) = 0 (Timeout) <0.000019>
13:37:53.963940 recvfrom(7, 0x1c5c39d, 3795, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000020>
13:37:53.964057 poll([{fd=7, events=0}], 1, 0) = 0 (Timeout) <0.000033>
13:37:53.964174 times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 447327323 <0.000023>
13:37:53.964290 times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 447327323 <0.000019>
13:37:53.964395 recvfrom(8, 0x1c5dca5, 3531, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000021>
13:37:53.964567 poll([{fd=8, events=0}], 1, 0) = 0 (Timeout) <0.000020>
13:37:53.964685 recvfrom(8, 0x1c5dca5, 3531, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000019>
13:37:53.964792 poll([{fd=8, events=0}], 1, 0) = 0 (Timeout) <0.000018>
13:37:53.964898 recvfrom(8, 0x1c5dca5, 3531, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000018>
13:37:53.964998 poll([{fd=8, events=0}], 1, 0) = 0 (Timeout) <0.000018>
13:37:53.965098 times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 447327324 <0.000028>
13:37:53.965221 poll([{fd=7, events=POLLIN|POLLPRI}, {fd=3, events=POLLIN|POLLPRI}, {fd=8, events=POLLIN|POLLPRI}, {fd=5, events=POLLIN|POLLPRI}], 4, -1) = 1 ([{fd=3, revents=POLLIN|POLLHUP}]) <0.000021>
13:37:53.965507 times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 447327324 <0.000020>
13:37:53.965734 times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 447327324 <0.000018>
13:37:53.965837 recvfrom(7, 0x1c5c39d, 3795, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000018>
13:37:53.965953 poll([{fd=7, events=0}], 1, 0) = 0 (Timeout) <0.000018>
13:37:53.966055 recvfrom(7, 0x1c5c39d, 3795, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000029>
13:37:53.966171 poll([{fd=7, events=0}], 1, 0) = 0 (Timeout) <0.000018>
13:37:53.966271 times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 447327324 <0.000018>
13:37:53.966389 times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 447327324 <0.000019>
I need a coherent set of data, not fragments from unrelated tests. Please include corosync.log and the time at which corosync was killed. Be sure to include plenty of logs from after the kill signal is sent. Also, don't forget that I can't see what you see - if "gdb on the daemons indicates a loop", then it would be helpful to supply that data too. A colleague at SUSE has experienced the same issue. Apparently there are two fixes required to corosync and one to Pacemaker. We'll endeavour to get these applied asap. Corosync: http://corosync.org/git/?p=corosync.git;a=commitdiff_plain;h=2e5dc5f322a5a852d31f5775debbf51e062695ba and https://lists.linux-foundation.org/pipermail/openais/2011-June/016390.html Pacemaker: diff -r 75575ce39861 -r 0ac9baf90f8f lib/common/ais.c --- a/lib/common/ais.c Tue Jun 21 15:54:20 2011 +0200 +++ b/lib/common/ais.c Thu Jun 30 16:47:30 2011 +0200 @@ -562,15 +562,15 @@ gboolean ais_dispatch(int sender, gpoint do { rc = coroipcc_dispatch_get (ais_ipc_handle, (void**)&buffer, 0); - if (rc == 0 || buffer == NULL) { - /* Zero is a legal "no message afterall" value */ - return TRUE; - - } else if (rc != CS_OK) { + if (rc != CS_OK) { crm_perror(LOG_ERR,"Receiving message body failed: (%d) %s", rc, ais_error2text(rc)); goto bail; } - + if (buffer == NULL) { + /* NULL is a legal "no message afterall" value */ + return TRUE; + } + good = ais_dispatch_message((AIS_Message*)buffer, dispatch); coroipcc_dispatch_put (ais_ipc_handle); |