Hi Andrew,<br><br> I took oprofile of 120 seconds before Time-out occurs.<br> However, sorted_xml function seems not to be called it so much as far as I watch log of Oprofile.<br><br> I took Oprofile by a sample program. <br>
But, the contents of Oprofile did not agree with the contents of the sample program. <br> Therefore I used systemtap because I was not able to do internal bottleneck analysis from information of this Oprofile.<br><br><br>
<div class="gmail_quote">2010$BG/(B8$B7n(B4$BF|(B18:56 nozawat <span dir="ltr"><<a href="mailto:nozawat@gmail.com">nozawat@gmail.com</a>></span>:<br><blockquote class="gmail_quote" style="margin: 0pt 0pt 0pt 0.8ex; border-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;">
Hi Andrew,<br><br> I send the cib file of the point in time when environmental construction was completed.<div class="im"><br> <br>>Maybe oprofile can suggest something.<br></div>OK, I measure even Oprofile.<br><br>-- <br>
Regards,<br>Tomo<br>
<br><br><div class="gmail_quote">2010/8/4 Andrew Beekhof <span dir="ltr"><<a href="mailto:andrew@beekhof.net" target="_blank">andrew@beekhof.net</a>></span><div><div></div><div class="h5"><br><blockquote class="gmail_quote" style="margin: 0pt 0pt 0pt 0.8ex; border-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;">
2010/8/3 nozawat <<a href="mailto:nozawat@gmail.com" target="_blank">nozawat@gmail.com</a>>:<br>
<div>> Hi Andrew,<br>
><br>
> I changed cluster option to batch-limit=3,I re-tried it.<br>
> However, similar time-out occurs.<br>
><br>
> I measured processing just before the time-out(120s) in systemtap.<br>
> The following only the function long time.<br>
> -----<br>
> probe start! ---------------------------------<br>
> cib_process_request [call-count:179][117,540,173,155 nsec]<br>
> cib_process_command [call:179] [116,471,047,275 nsec]<br>
> cib_process_command call function ---<br>
> cib_config_changed [call:179] [101,169,909,572 nsec]<br>
> cib_config_changed call function ---<br>
> calculate_xml_digest [call:179] [ 68,820,560,745 nsec]<br>
> create_xml_node [call:3012263] [ 19,855,469,976 nsec]$B"((B<br>
<br>
</div>But, but, create_xml_node() barely does _anything_.<br>
<br>
It's hard to imagine how this could take 19s:<br>
<br>
xmlNode*<br>
create_xml_node(xmlNode *parent, const char *name)<br>
{<br>
xmlDoc *doc = NULL;<br>
xmlNode *node = NULL;<br>
<br>
if (name == NULL || name[0] == 0) {<br>
return NULL;<br>
}<br>
<br>
if(parent == NULL) {<br>
doc = xmlNewDoc((const xmlChar*)"1.0");<br>
node = xmlNewDocRawNode(doc, NULL, (const xmlChar*)name, NULL);<br>
xmlDocSetRootElement(doc, node);<br>
<br>
} else {<br>
doc = getDocPtr(parent);<br>
node = xmlNewDocRawNode(doc, NULL, (const xmlChar*)name, NULL);<br>
xmlAddChild(parent, node);<br>
}<br>
return node;<br>
}<br>
<br>
Is this data all from the CIB process?<br>
What was the load from the other processes like? (Ie. using top)<br>
<div><br>
> xpath_search [call:179] [ 145,030,232 nsec]<br>
> diff_xml_object [call:179] [ 32,677,359,476 nsec]$B"((B<br>
> calculate_xml_digest call function ---<br>
> sorted_xml [call:1505799] [ 52,512,465,838 nsec]$B"((B<br>
<br>
</div>Yikes, these are also really high.<br>
Could you send me the CIB so that we can profile these operations on it?<br>
<div><br>
> copy_xml [call:179] [ 3,692,232,073 nsec]<br>
> dump_xml [call:536] [ 6,177,606,232 nsec]<br>
> -----<br>
> Is there the method to make these processing early?<br>
<br>
</div>You mean faster?<br>
Maybe oprofile can suggest something.<br>
<div><div></div><div><br>
><br>
><br>
> 2010/6/14 <<a href="mailto:renayama19661014@ybb.ne.jp" target="_blank">renayama19661014@ybb.ne.jp</a>><br>
>><br>
>> Hi Andrew,<br>
>><br>
>> Thank you for comment.<br>
>><br>
>> > More likely of the underlying messaging infrastructure, but I'll take a<br>
>> > look.<br>
>> > Perhaps the default cib operation timeouts are too low for larger<br>
>> > clusters.<br>
>> ><br>
>> > ><br>
>> > > The log attached it to next Bugzilla.<br>
>> > > &#65533;*<br>
>> > > <a href="http://developerbugs.linux-foundation.org/show_bug.cgi?id=2443" target="_blank">http://developerbugs.linux-foundation.org/show_bug.cgi?id=2443</a><br>
>> ><br>
>> > Ok, I'll follow up there.<br>
>><br>
>> If it is necessary for us to work for the solution of the problem, please<br>
>> order it.<br>
>><br>
>> Best Regards,<br>
>> Hideo Yamauchi.<br>
>><br>
>> --- Andrew Beekhof <<a href="mailto:andrew@beekhof.net" target="_blank">andrew@beekhof.net</a>> wrote:<br>
>><br>
>> > On Mon, Jun 14, 2010 at 4:46 AM, <<a href="mailto:renayama19661014@ybb.ne.jp" target="_blank">renayama19661014@ybb.ne.jp</a>> wrote:<br>
>> > > We tested 16 node constitution (15+1).<br>
>> > ><br>
>> > > We carried out the next procedure.<br>
>> > ><br>
>> > > Step1) Start 16 nodes.<br>
>> > > Step2) Send cib after a DC node was decided.<br>
>> > ><br>
>> > > An error occurs by the update of the attribute of pingd after Probe<br>
>> > > processing was over.<br>
>> > ><br>
>> > ><br>
>> ><br>
>><br>
>> ----------------------------------------------------------------------------------------------------------------------------------------<br>
>> > > Jun 14 10:58:03 hb0102 pingd: [2465]: info: ping_read: Retrying...<br>
>> > > Jun 14 10:58:13 hb0102 attrd: [2155]: WARN: attrd_cib_callback: Update<br>
>> > > 337 for<br>
>> > default_ping_set=1600<br>
>> > > failed: Remote node did not respond<br>
>> > > Jun 14 10:58:13 hb0102 attrd: [2155]: WARN: attrd_cib_callback: Update<br>
>> > > 340 for<br>
>> > default_ping_set=1600<br>
>> > > failed: Remote node did not respond<br>
>> > > Jun 14 10:58:13 hb0102 attrd: [2155]: WARN: attrd_cib_callback: Update<br>
>> > > 343 for<br>
>> > default_ping_set=1600<br>
>> > > failed: Remote node did not respond<br>
>> > > Jun 14 10:58:13 hb0102 attrd: [2155]: WARN: attrd_cib_callback: Update<br>
>> > > 346 for<br>
>> > default_ping_set=1600<br>
>> > > failed: Remote node did not respond<br>
>> > > Jun 14 10:58:13 hb0102 attrd: [2155]: WARN: attrd_cib_callback: Update<br>
>> > > 349 for<br>
>> > default_ping_set=1600<br>
>> > > failed: Remote node did not respond<br>
>> > ><br>
>> ><br>
>><br>
>> ----------------------------------------------------------------------------------------------------------------------------------------<br>
>> > ><br>
>> > > In the middle of this error, I carried out a cibadmin(-Q optin)<br>
>> > > command, but time-out<br>
>> > occurred.<br>
>> > > In addition, cib of the DC node seemed to move by the top command very<br>
>> > > busily.<br>
>> > ><br>
>> > ><br>
>> > > In addition, a communication error with cib occurs in the DC node, and<br>
>> > > crmd reboots.<br>
>> > ><br>
>> > ><br>
>> ><br>
>><br>
>> ----------------------------------------------------------------------------------------------------------------------------------------<br>
>> > > Jun 14 10:58:09 hb0101 attrd: [2278]: WARN: xmlfromIPC: No message<br>
>> > > received in the required<br>
>> > interval<br>
>> > > (120s)<br>
>> > > Jun 14 10:58:09 hb0101 attrd: [2278]: info: attrd_perform_update: Sent<br>
>> > > update -41:<br>
>> > > default_ping_set=1600<br>
>> > > (snip)<br>
>> > > Jun 14 10:59:07 hb0101 crmd: [2280]: info: do_exit: [crmd] stopped (2)<br>
>> > > Jun 14 10:59:07 hb0101 corosync[2269]: &#65533; [pcmk &#65533;]<br>
>> > > plugin.c:858 info: pcmk_ipc_exit:<br>
>> Client<br>
>> > crmd<br>
>> > > (conn=0x106a2bf0, async-conn=0x106a2bf0) left<br>
>> > > Jun 14 10:59:08 hb0101 corosync[2269]: &#65533; [pcmk &#65533;]<br>
>> > > plugin.c:481 ERROR:<br>
>> pcmk_wait_dispatch:<br>
>> > Child<br>
>> > > process crmd exited (pid=2280, rc=2)<br>
>> > > Jun 14 10:59:08 hb0101 corosync[2269]: &#65533; [pcmk &#65533;]<br>
>> > > plugin.c:498 notice:<br>
>> pcmk_wait_dispatch:<br>
>> > Respawning<br>
>> > > failed child process: crmd<br>
>> > > Jun 14 10:59:08 hb0101 corosync[2269]: &#65533; [pcmk &#65533;]<br>
>> > > utils.c:131 info: spawn_child:<br>
>> Forked child<br>
>> > 2680 for<br>
>> > > process crmd<br>
>> > > Jun 14 10:59:08 hb0101 crmd: [2680]: info: Invoked:<br>
>> > > /usr/lib64/heartbeat/crmd<br>
>> > > Jun 14 10:59:08 hb0101 crmd: [2680]: info: main: CRM Hg Version:<br>
>> > > 9f04fa88cfd3da553e977cc79983d1c494c8b502<br>
>> > > Jun 14 10:59:08 hb0101 crmd: [2680]: info: crmd_init: Starting crmd<br>
>> > > Jun 14 10:59:08 hb0101 crmd: [2680]: info: G_main_add_SignalHandler:<br>
>> > > Added signal handler for<br>
>> > signal<br>
>> > > 17<br>
>> > ><br>
>> ><br>
>><br>
>> ----------------------------------------------------------------------------------------------------------------------------------------<br>
>> > ><br>
>> > > There seems to be a problem in cib of the DC node somehow or other.<br>
>> > > We hope that an attribute change is completed in 16 nodes definitely.<br>
>> > > &#65533;* Is this phenomenon a limit of the current cib process?<br>
>> ><br>
>> > More likely of the underlying messaging infrastructure, but I'll take a<br>
>> > look.<br>
>> > Perhaps the default cib operation timeouts are too low for larger<br>
>> > clusters.<br>
>> ><br>
>> > ><br>
>> > > The log attached it to next Bugzilla.<br>
>> > > &#65533;*<br>
>> > > <a href="http://developerbugs.linux-foundation.org/show_bug.cgi?id=2443" target="_blank">http://developerbugs.linux-foundation.org/show_bug.cgi?id=2443</a><br>
>> ><br>
>> > Ok, I'll follow up there.<br>
>> ><br>
>> > ><br>
>> > > Best Regards,<br>
>> > > Hideo Yamauchi.<br>
>> > ><br>
>> > ><br>
>> > ><br>
>> > > _______________________________________________<br>
>> > > Pacemaker mailing list: <a href="mailto:Pacemaker@oss.clusterlabs.org" target="_blank">Pacemaker@oss.clusterlabs.org</a><br>
>> > > <a href="http://oss.clusterlabs.org/mailman/listinfo/pacemaker" target="_blank">http://oss.clusterlabs.org/mailman/listinfo/pacemaker</a><br>
>> > ><br>
>> > > Project Home: <a href="http://www.clusterlabs.org" target="_blank">http://www.clusterlabs.org</a><br>
>> > > Getting started:<br>
>> > > <a href="http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf" target="_blank">http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf</a><br>
>> > > Bugs:<br>
>> > > <a href="http://developerbugs.linux-foundation.org/enter_bug.cgi?product=Pacemaker" target="_blank">http://developerbugs.linux-foundation.org/enter_bug.cgi?product=Pacemaker</a><br>
>> > ><br>
>> ><br>
>> > _______________________________________________<br>
>> > Pacemaker mailing list: <a href="mailto:Pacemaker@oss.clusterlabs.org" target="_blank">Pacemaker@oss.clusterlabs.org</a><br>
>> > <a href="http://oss.clusterlabs.org/mailman/listinfo/pacemaker" target="_blank">http://oss.clusterlabs.org/mailman/listinfo/pacemaker</a><br>
>> ><br>
>> > Project Home: <a href="http://www.clusterlabs.org" target="_blank">http://www.clusterlabs.org</a><br>
>> > Getting started: <a href="http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf" target="_blank">http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf</a><br>
>> > Bugs:<br>
>> > <a href="http://developerbugs.linux-foundation.org/enter_bug.cgi?product=Pacemaker" target="_blank">http://developerbugs.linux-foundation.org/enter_bug.cgi?product=Pacemaker</a><br>
>> ><br>
>><br>
>><br>
>> _______________________________________________<br>
>> Pacemaker mailing list: <a href="mailto:Pacemaker@oss.clusterlabs.org" target="_blank">Pacemaker@oss.clusterlabs.org</a><br>
>> <a href="http://oss.clusterlabs.org/mailman/listinfo/pacemaker" target="_blank">http://oss.clusterlabs.org/mailman/listinfo/pacemaker</a><br>
>><br>
>> Project Home: <a href="http://www.clusterlabs.org" target="_blank">http://www.clusterlabs.org</a><br>
>> Getting started: <a href="http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf" target="_blank">http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf</a><br>
>> Bugs:<br>
>> <a href="http://developerbugs.linux-foundation.org/enter_bug.cgi?product=Pacemaker" target="_blank">http://developerbugs.linux-foundation.org/enter_bug.cgi?product=Pacemaker</a><br>
><br>
><br>
> _______________________________________________<br>
> Pacemaker mailing list: <a href="mailto:Pacemaker@oss.clusterlabs.org" target="_blank">Pacemaker@oss.clusterlabs.org</a><br>
> <a href="http://oss.clusterlabs.org/mailman/listinfo/pacemaker" target="_blank">http://oss.clusterlabs.org/mailman/listinfo/pacemaker</a><br>
><br>
> Project Home: <a href="http://www.clusterlabs.org" target="_blank">http://www.clusterlabs.org</a><br>
> Getting started: <a href="http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf" target="_blank">http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf</a><br>
> Bugs:<br>
> <a href="http://developerbugs.linux-foundation.org/enter_bug.cgi?product=Pacemaker" target="_blank">http://developerbugs.linux-foundation.org/enter_bug.cgi?product=Pacemaker</a><br>
><br>
><br>
<br>
_______________________________________________<br>
Pacemaker mailing list: <a href="mailto:Pacemaker@oss.clusterlabs.org" target="_blank">Pacemaker@oss.clusterlabs.org</a><br>
<a href="http://oss.clusterlabs.org/mailman/listinfo/pacemaker" target="_blank">http://oss.clusterlabs.org/mailman/listinfo/pacemaker</a><br>
<br>
Project Home: <a href="http://www.clusterlabs.org" target="_blank">http://www.clusterlabs.org</a><br>
Getting started: <a href="http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf" target="_blank">http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf</a><br>
Bugs: <a href="http://developerbugs.linux-foundation.org/enter_bug.cgi?product=Pacemaker" target="_blank">http://developerbugs.linux-foundation.org/enter_bug.cgi?product=Pacemaker</a><br>
</div></div></blockquote></div></div></div><font color="#888888"><br><br clear="all"><br>-- <br>Regards,<br>Tomo<br><br>
</font></blockquote></div><br><br clear="all"><br>-- <br>Regards,<br>Tomo<br><br>