Hi, On Tue, Jun 10, 2008 at 07:33:50AM +0200, Andrew Beekhof wrote: > On Tue, Jun 10, 2008 at 03:33, Greg Haase <[EMAIL PROTECTED]> wrote: > > If I look through my logs, every few days or so I see a few messages > > that look like: > > > > lrmd[4144]: 2008/06/07_01:27:03 WARN: G_SIG_dispatch: Dispatch function > > for SIGCHLD was delayed 1000 ms (> 100 ms) before being called (GSource: > > 0x16e2e9b8 > > ) > > lrmd[4144]: 2008/06/07_01:27:03 info: G_SIG_dispatch: started at > > 465607845 should have started at 465607745 > > lrmd[4144]: 2008/06/07_12:44:01 WARN: G_SIG_dispatch: Dispatch function > > for SIGCHLD was delayed 1000 ms (> 100 ms) before being called (GSource: > > 0x16e2e9b8 > > ) > > lrmd[4144]: 2008/06/07_12:44:01 info: G_SIG_dispatch: started at > > 469668996 should have started at 469668896 > > > > > > I asked on the irc channel, and someone commented that they are probably > > nothing to worry about. > > > > However, today I had a node failure on or about the same time as these > > dispatch messages. The timeout for the IP Address is 5 seconds, and > > actually I and another guy were working in the database at the time of > > failure - using the VIP. > > > > lrmd[4144]: 2008/06/09_19:03:25 WARN: G_SIG_dispatch: Dispatch function > > for SIGCHLD was delayed 1000 ms (> 100 ms) before being called (GSource: > > 0x16e2e9b8 > > ) > > lrmd[4144]: 2008/06/09_19:03:25 info: G_SIG_dispatch: started at > > 489221947 should have started at 489221847 > > lrmd[4144]: 2008/06/09_19:38:21 WARN: ip_mysql:monitor process (PID > > 27595) timed out (try 1). Killing with signal SIGTERM (15). > > lrmd[4144]: 2008/06/09_19:38:21 WARN: operation monitor[24] on > > ocf::IPaddr::ip_mysql for client 4147, its parameters: > > CRM_meta_interval=[15000] ip=[192.168. > > 0.20] netmask=[23] CRM_meta_id=[ip_mysql_mon] CRM_meta_timeout=[5000] > > crm_feature_set=[2.1] CRM_meta_name=[monitor] : pid [27595] timed out > > lrmd[4144]: 2008/06/09_19:38:23 WARN: G_SIG_dispatch: Dispatch function > > for SIGCHLD took too long to execute: 1850 ms (> 300 ms) (GSource: > > 0x16e2e9b8) > > lrmd[4144]: 2008/06/09_19:38:23 WARN: G_SIG_dispatch: Dispatch function > > for SIGCHLD was delayed 1530 ms (> 100 ms) before being called (GSource: > > 0x16e2e9b8 > > ) > > lrmd[4144]: 2008/06/09_19:38:23 info: G_SIG_dispatch: started at > > 489431682 should have started at 489431529 > > crmd[4147]: 2008/06/09_19:38:28 ERROR: process_lrm_event: LRM operation > > ip_mysql_monitor_15000 (24) Timed Out (timeout=5000ms) > > tengine[32033]: 2008/06/09_19:38:31 info: process_graph_event: Detected > > action ip_mysql_monitor_15000 from a different transition: 6 vs. 7 > > tengine[32033]: 2008/06/09_19:38:31 info: update_abort_priority: Abort > > priority upgraded to 1000000 > > > > Can anyone shed some light as to what might be going on here? Are the > > events related, or is the dispatch error a complete red herring in this > > case? > > Its possible they're related. > I'd guess that the delays are due to system load, which could also > have caused the monitor op to time out.
Most probably. Please increase the timeouts. Five seconds is definitely way too low. The warnings about delayed dispatch functions and similar are definitely due to high load. > Another (less likely) alternative is that the lrmd may not be > accounting for the delays when it times out the action. > Ie. the monitor might only be getting 4s to complete instead of 5s Not likely. The timeouts are triggered asynchronously (using glib2). Thanks, Dejan > > My money would be on the first one though > _______________________________________________ > Linux-HA mailing list > [email protected] > http://lists.linux-ha.org/mailman/listinfo/linux-ha > See also: http://linux-ha.org/ReportingProblems _______________________________________________ Linux-HA mailing list [email protected] http://lists.linux-ha.org/mailman/listinfo/linux-ha See also: http://linux-ha.org/ReportingProblems
