Ulrich.Windl at rz
Jan 30, 2012, 11:28 PM
Views: 210
Permalink
|
|
Antw: Re: RA timeouts / Remote node did not respond
|
|
>>> Sascha Reimann <sascha.reimann [at] hostway> schrieb am 30.01.2012 um 11:28 in
Nachricht <4F2670E5.5000408 [at] hostway>:
> Hi Dejan,
>
> thanks for hints!
>
> It's indeed a bigger cluster with currently 9 nodes and approximately 50
> resources, but we've planned to build an even bigger one, which will
> probably not possible due to the frequent updates. The timeout for start
Hi!
Yes, coming from HP ServiceGuard, where the cluster communication in idle state is mostly the heartbeat messages, I found that pacemaker, even when idle, send messages like crazy. And when you make a moderate configuration change, a 100Mbit LAN seems too slow, because corosync marks the ring as faulty then (while we have another ring a 1Gbit).
> and stop is set to 300s, monitor operations are just set for a few
> resources, but also with a timeout of 300s.
And some RAs show terrible performance for the monitoring operations. Combined with pacemaker's virtual inpatience, you may see timeouts from time to time. Especially as there is a tendancy that monitoring operations "cluster" at certain times, especially if the resources were started at the same time with the same monitoring interval.
Most notably that can be experienced with the LVM monitor.
>
> This is the current CIB with 30 resources (I've deleted the 50
> productive ones for testing):
>
> :~$ cibadmin -Q|wc
> 1686 7802 193120
>
> I'm using location rules with variable scoring (example: rule free_ram:
> free_ram gte 4096 and free_cores gte 2) to determine to best location
> for a virtual machine. Could that required condition also cause updates
> of the CIB? Each node is writing its free resources to the CIB, which is
> definitely a reason and I will try to reduce them.
While on scores: Another thing that doesn't work well is resource groups: If one resource in a group cannot fulfill ist requirements, the group remains partially activated, even if another node could fulfill the requirements. That's true even if the partially started resources have no stickiness applied.
>
> ocf-tester was complaining about meta-data and permissions, which I've
> corrected.
I's good to use ocf-tester IMHO.
> "crm configure verify" looks good, just a couple complains about a
> meta-data attributes I've set manually.
>
> Can you explain "client gone before receiving answer" a bit more?
Sorry for not answering any of your questions!
Regards,
Ulrich
>
> thanks!
> Sascha
>
> On 01/27/2012 08:05 PM, Dejan Muhamedagic wrote:
> > Hi,
> >
> > On Fri, Jan 27, 2012 at 10:49:52AM +0100, Sascha Reimann wrote:
> >> hello,
> >>
> >> I have a problem with timeouts from my RA for virtual Xen machines.
> >> Since xm commands are very slow, I have replaced them by some xentop and
> >> pgrep commands to avoid timeouts from xm. Unfortunately, this didn't
> >> solved the problem, as corosync/pacemaker gets a timeout requesting the
> >> status of a resource and ends up in "Remote node did not respond" messages.
> >
> > That has nothing to do with the RA performance.
> >
> >> Any idea how to increase the performance of communication between the
> nodes?
> >
> > Reduce the configuration, if possible. Split one big cluster into
> > two smaller ones, if possible. How many resources do you have?
> > How big your CIB gets (cibadmin -Q | wc)?
> >
> >> This is an example config of a resource:
> >>
> >> primitive VM_24_435 ocf:hostway:Xen \
> >> params xmfile="/etc/xen/conf.d/VM_24_435.cfg" \
> >> op start interval="0" timeout="60s" on-fail="restart" \
> >> op stop interval="0" timeout="40s" \
> >> meta target-role="Started" allow-migrate="true"
> >> [...]
> >>
> >> ...and the basic configuration:
> >>
> >> no-quorum-policy="ignore" \
> >> stonith-enabled="false" \
> >> dc-version="1.1.6-9971ebba4494012a93c03b40a2c58ec0eb60f50c" \
> >> cluster-infrastructure="openais" \
> >> expected-quorum-votes="9" \
> >> last-lrm-refresh="1327655374" \
> >> symmetric-cluster="true" \
> >> default-resource-stickiness="INFINITY" \
> >> maintenance-mode="false" \
> >>
> >> corosync/pacemaker is installed from debian backports:
> >>
> >> Version: 1.1.6-9971ebba4494012a93c03b40a2c58ec0eb60f50c
> >> 9 Nodes configured, 9 expected votes
> >>
> >> When I start a cleanup (crm resource cleanup VM_24_435) while the cib
> >> process is already busy, this is what crm_mon tells me:
> >> Failed actions:
> >> VM_24_435_monitor_0 (node=vnode04, call=-1, rc=1, status=Timed
> >> Out): unknown error
> >> VM_24_435_monitor_0 (node=vnode06, call=-1, rc=1, status=Timed
> >> Out): unknown error
> >
> > This looks like a real monitor timeout, but not easy to tell
> > without looking at the configuration and logs. Are the timeouts
> > sufficiently big? Did you do crm configure verify?
> >
> >> The monitor request itself is quick:
> >>
> >> :~$ time bash -x /usr/lib/ocf/resource.d/hostway/Xen monitor
> >> + . /usr/lib/ocf/resource.d/heartbeat/.ocf-returncodes
> >> ++ OCF_SUCCESS=0
> >> ++ OCF_ERR_GENERIC=1
> >> ++ OCF_ERR_ARGS=2
> >> ++ OCF_ERR_UNIMPLEMENTED=3
> >> ++ OCF_ERR_PERM=4
> >> ++ OCF_ERR_INSTALLED=5
> >> ++ OCF_ERR_CONFIGURED=6
> >> ++ OCF_NOT_RUNNING=7
> >> ++ OCF_RUNNING_MASTER=8
> >> ++ OCF_FAILED_MASTER=9
> >> + . /root/hep/scripts/funcs
> >> +++ basename /usr/lib/ocf/resource.d/hostway/Xen
> >> ++ prog=Xen
> >> ++ cib=/tmp/cib
> >> + : /etc/xen/vm/MyDomU
> >> + DOMAIN_NAME=VM_24_435
> >> + '[' 1 -ne 1 ']'
> >> + case $1 in
> >> + '[' x '!=' x ']'
> >> + '[' -f /etc/xen/vm/MyDomU ']'
> >> + DOMAIN_NAME=VM_24_435
> >> + case $1 in
> >> + Xen_Monitor
> >> + Xen_Status VM_24_435
> >> + /usr/bin/pgrep -lf 'qemu-dmbin.*domain-name VM_24_435'
> >> + '[' 0 = 0 ']'
> >> + return 0
> >> + [[ 0 -eq 7 ]]
> >> + '[' X = X ']'
> >> + return 0
> >> + exit 0
> >>
> >> real 0m0.122s
> >>
> >> My corosync-config was debian default, I modified max_messages
> >> (increased from 20 to 500), tried transport udpu and secauth with 8
> >> threads on a 8 core machine, but still the cib process gets up to 100%
> >> cpu usage in a 1Gig network.
> >
> > The cib process is mostly processing the CIB, the kind of
> > transport won't have much impact. Such a high load is probably
> > coming from too frequent CIB updates.
> >
> >> Here's the logfile:
> >>
> >> Jan 27 09:49:16 vnode10 crmd: [27990]: ERROR: send_msg_via_ipc: Unknown
> >> Sub-system (9593_crm_resource)... discarding message.
> >> Jan 27 09:49:18 vnode10 crmd: [27990]: ERROR: send_msg_via_ipc: Unknown
> >> Sub-system (9593_crm_resource)... discarding message.
> >
> > This is probably client gone before receiving answer.
> >
> >> Jan 27 09:49:18 vnode10 crmd: [27990]: info: config_query_callback:
> >> Shutdown escalation occurs after: 1200000ms
> >> Jan 27 09:49:18 vnode10 crmd: [27990]: info: config_query_callback:
> >> Checking for expired actions every 900000ms
> >> Jan 27 09:49:18 vnode10 crmd: [27990]: info: config_query_callback:
> >> Sending expected-votes=9 to corosync
> >> Jan 27 09:49:18 vnode10 crmd: [27990]: info: config_query_callback:
> >> Shutdown escalation occurs after: 1200000ms
> >> Jan 27 09:49:18 vnode10 crmd: [27990]: info: config_query_callback:
> >> Checking for expired actions every 900000ms
> >> Jan 27 09:49:18 vnode10 crmd: [27990]: info: config_query_callback:
> >> Sending expected-votes=9 to corosync
> >> Jan 27 09:49:18 vnode10 crmd: [27990]: info: ais_dispatch_message:
> >> Membership 6204: quorum retained
> >> Jan 27 09:49:18 vnode10 crmd: [27990]: info: ais_dispatch_message:
> >> Membership 6204: quorum retained
> >> Jan 27 09:49:56 vnode10 crmd: [27990]: info: do_lrm_rsc_op: Performing
> >> key=17:117:7:4ac4f5c1-f61a-48f6-bef8-6b2223c973f2 op=VM_24_435_monitor_0 )
> >> Jan 27 09:49:56 vnode10 lrmd: [27987]: info: rsc:VM_24_435:48: probe
> >> Jan 27 09:49:57 vnode10 crmd: [27990]: info: process_lrm_event: LRM
> >> operation VM_24_435_monitor_0 (call=48, rc=0, cib-update=260,
> >> confirmed=true) ok
> >> Jan 27 09:49:58 vnode10 crmd: [27990]: info: do_lrm_rsc_op: Performing
> >> key=75:118:0:4ac4f5c1-f61a-48f6-bef8-6b2223c973f2 op=VM_24_435_stop_0 )
> >> Jan 27 09:49:58 vnode10 lrmd: [27987]: info: rsc:VM_24_435:49: stop
> >> Jan 27 09:50:05 vnode10 crmd: [27990]: info: process_lrm_event: LRM
> >> operation VM_24_435_stop_0 (call=49, rc=0, cib-update=261,
> >> confirmed=true) ok
> >> Jan 27 09:50:05 vnode10 crmd: [27990]: info: do_lrm_rsc_op: Performing
> >> key=76:118:0:4ac4f5c1-f61a-48f6-bef8-6b2223c973f2 op=VM_24_435_start_0 )
> >> Jan 27 09:50:05 vnode10 lrmd: [27987]: info: rsc:VM_24_435:50: start
> >> Jan 27 09:50:13 vnode10 lrmd: [27987]: WARN: on_msg_get_metadata: empty
> >> metadata for ocf::hostway::Xen.
> >> Jan 27 09:50:13 vnode10 lrmd: [27987]: WARN: G_SIG_dispatch: Dispatch
> >> function for SIGCHLD was delayed 200 ms (> 100 ms) before being called
> >> (GSource: 0x2412430)
> >
> > Host too busy? Did you check uptime and performance statistics?
> >
> >> Jan 27 09:50:13 vnode10 lrmd: [27987]: info: G_SIG_dispatch: started at
> >> 1838690515 should have started at 1838690495
> >> Jan 27 09:50:13 vnode10 crmd: [27990]: ERROR:
> >> lrm_get_rsc_type_metadata(578): got a return code HA_FAIL from a reply
> >> message of rmetadata with function get_ret_from_msg.
> >> Jan 27 09:50:13 vnode10 crmd: [27990]: WARN: get_rsc_metadata: No
> >> metadata found for Xen::ocf:hostway
> >> Jan 27 09:50:13 vnode10 crmd: [27990]: ERROR: string2xml: Can't parse
> >> NULL input
> >> Jan 27 09:50:13 vnode10 crmd: [27990]: ERROR: get_rsc_restart_list:
> >> Metadata for hostway::ocf:Xen is not valid XML
> >
> > Your OCF RA is not OCF compliant. Fix it and use ocf-tester to
> > make sure that all required functionality is correct.
> >
> >> Jan 27 09:50:13 vnode10 crmd: [27990]: info: process_lrm_event: LRM
> >> operation VM_24_435_start_0 (call=50, rc=0, cib-update=262,
> >> confirmed=true) ok
> >>
> >>
> >> Eventually, the cib gets unresponsable:
> >>
> >> :~$ crm resource manage VM_24_435
> >> Call cib_replace failed (-41): Remote node did not respond
> >> <null>
> >>
> >> Jan 27 10:22:14 nfscc01 cib: [1318]: info: cib_process_diff: Diff
> >> 0.12146.136 -> 0.12146.137 not applied to 0.12145.4: current "epoch" is
> >> less than required
> >> Jan 27 10:22:14 nfscc01 cib: [1318]: info: cib_server_process_diff:
> >> Requesting re-sync from peer
> >> Jan 27 10:22:14 nfscc01 cib: [1318]: notice: cib_server_process_diff:
> >> Not applying diff 0.12146.137 -> 0.12146.138 (sync in progress)
> >> Jan 27 10:22:14 nfscc01 cib: [1318]: notice: cib_server_process_diff:
> >> Not applying diff 0.12146.138 -> 0.12146.139 (sync in progress)
> >> Jan 27 10:23:10 nfscc01 crmd: [1322]: WARN: cib_rsc_callback: Resource
> >> update 314 failed: (rc=-41) Remote node did not respond
> >> Jan 27 10:23:30 nfscc01 cib: [1318]: notice: cib_server_process_diff:
> >> Not applying diff 0.12146.139 -> 0.12146.140 (sync in progress)
> >> Jan 27 10:23:30 nfscc01 cib: [1318]: notice: cib_server_process_diff:
> >> Not applying diff 0.12146.140 -> 0.12146.141 (sync in progress)
> >> Jan 27 10:23:30 nfscc01 cib: [1318]: notice: cib_server_process_diff:
> >> Not applying diff 0.12146.141 -> 0.12146.142 (sync in progress)
> >> Jan 27 10:23:30 nfscc01 cib: [1318]: info: cib_process_diff: Diff
> >> 0.12146.142 -> 0.12146.143 not applied to 0.12145.4: current "epoch" is
> >> less than required
> >> Jan 27 10:23:30 nfscc01 cib: [1318]: info: cib_server_process_diff:
> >> Requesting re-sync from peer
> >> Jan 27 10:23:30 nfscc01 cib: [1318]: notice: cib_server_process_diff:
> >> Not applying diff 0.12146.143 -> 0.12146.144 (sync in progress)
> >> Jan 27 10:23:30 nfscc01 cib: [1318]: notice: cib_server_process_diff:
> >> Not applying diff 0.12146.144 -> 0.12146.145 (sync in progress)
> >> Jan 27 10:23:31 nfscc01 crmd: [1322]: info: do_lrm_rsc_op: Performing
> >> key=3:161:0:4ac4f5c1-f61a-48f6-bef8-6b2223c973f2 op=VM_24_435_stop_0 )
> >> Jan 27 10:23:31 nfscc01 lrmd: [1319]: info: rsc:VM_24_435:65: stop
> >> Jan 27 10:23:31 nfscc01 crmd: [1322]: info: process_lrm_event: LRM
> >> operation VM_24_435_stop_0 (call=65, rc=0, cib-update=315,
> >> confirmed=true) ok
> >> Jan 27 10:23:41 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1594 for last-failure-VM_24_435=1327655960 failed: Remote node did not
> >> respond
> >> Jan 27 10:23:41 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1596 for probe_complete=true failed: Remote node did not respond
> >> Jan 27 10:23:42 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1603 for probe_complete=true failed: Remote node did not respond
> >> Jan 27 10:23:42 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1611 for probe_complete=true failed: Remote node did not respond
> >> Jan 27 10:23:42 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1616 for last-failure-VM_24_435=1327655960 failed: Remote node did not
> >> respond
> >> Jan 27 10:23:42 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1621 for probe_complete=true failed: Remote node did not respond
> >> Jan 27 10:23:43 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1626 for last-failure-VM_24_435=1327655960 failed: Remote node did not
> >> respond
> >> Jan 27 10:23:43 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1631 for probe_complete=true failed: Remote node did not respond
> >> Jan 27 10:23:43 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1633 for last-failure-VM_24_435=1327655960 failed: Remote node did not
> >> respond
> >> Jan 27 10:23:43 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1635 for probe_complete=true failed: Remote node did not respond
> >> Jan 27 10:23:44 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1642 for probe_complete=true failed: Remote node did not respond
> >> Jan 27 10:23:44 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1649 for probe_complete=true failed: Remote node did not respond
> >> Jan 27 10:23:44 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1656 for probe_complete=true failed: Remote node did not respond
> >> Jan 27 10:23:44 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1661 for last-failure-VM_24_435=1327655960 failed: Remote node did not
> >> respond
> >> Jan 27 10:23:44 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1666 for probe_complete=true failed: Remote node did not respond
> >> Jan 27 10:23:44 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1671 for last-failure-VM_24_435=1327655960 failed: Remote node did not
> >> respond
> >> Jan 27 10:23:44 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1676 for probe_complete=true failed: Remote node did not respond
> >> Jan 27 10:23:44 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1684 for probe_complete=true failed: Remote node did not respond
> >> Jan 27 10:24:04 nfscc01 attrd: [1320]: notice: attrd_ais_dispatch:
> >> Update relayed from vnode06
> >> Jan 27 10:24:04 nfscc01 cib: [1318]: notice: cib_server_process_diff:
> >> Not applying diff 0.12146.145 -> 0.12146.146 (sync in progress)
> >> Jan 27 10:24:04 nfscc01 cib: [1318]: notice: cib_server_process_diff:
> >> Not applying diff 0.12146.145 -> 0.12146.146 (sync in progress)
> >> Jan 27 10:24:04 nfscc01 cib: [1318]: notice: cib_server_process_diff:
> >> Not applying diff 0.12146.146 -> 0.12147.1 (sync in progress)
> >> Jan 27 10:24:05 nfscc01 cib: [1318]: info: cib_process_diff: Diff
> >> 0.12147.1 -> 0.12147.2 not applied to 0.12145.4: current "epoch" is less
> >> than required
> >> Jan 27 10:24:05 nfscc01 cib: [1318]: info: cib_server_process_diff:
> >> Requesting re-sync from peer
> >> Jan 27 10:24:08 nfscc01 attrd: [1320]: WARN: attrd_cib_callback: Update
> >> 1691 for probe_complete=true failed: Remote node did not respond
> >> Jan 27 10:24:31 nfscc01 crmd: [1322]: WARN: cib_rsc_callback: Resource
> >> update 315 failed: (rc=-41) Remote node did not respond
> >
> > It could be that your CIB is very large and very often updated
> > which brings cib to a crawl. You can also try to reduce the
> > interval of monitoring operations.
> >
> > Thanks,
> >
> > Dejan
> >
> >> _______________________________________________
> >> Linux-HA mailing list
> >> Linux-HA [at] lists
> >> http://lists.linux-ha.org/mailman/listinfo/linux-ha
> >> See also: http://linux-ha.org/ReportingProblems
> _______________________________________________
> Linux-HA mailing list
> Linux-HA [at] lists
> http://lists.linux-ha.org/mailman/listinfo/linux-ha
> See also: http://linux-ha.org/ReportingProblems
>
_______________________________________________
Linux-HA mailing list
Linux-HA [at] lists
http://lists.linux-ha.org/mailman/listinfo/linux-ha
See also: http://linux-ha.org/ReportingProblems
|
Antw: Re: RA timeouts / Remote node did not respond