Several times in the last 4 days, we have been getting late heartbeat warnings that occur during the daily informational statistics run (approx 2:06 AM).
On one occasion, the heartbeat was late enough to cause a fail-over. It appears to me that heartbeat is not able to process anything at all while the daily stats are running - e.g. if the daily stats take 5 seconds to run, then I will get a couple of late heartbeat notices that are 5 seconds long. Also, it seems that the memory stats should run in less than 100 ms, but in some cases it's taking like 12 seconds to run? Please see attached last few days logs.
heartbeat[11160]: 2008/07/05_02:06:05 info: Daily informational memory statistics heartbeat[11160]: 2008/07/05_02:06:05 info: MSG stats: 4/10711325 ms age 0 [pid11160/MST_CONTROL] heartbeat[11160]: 2008/07/05_02:06:05 info: cl_malloc stats: 626/331598983 181240/91196 [pid11160/MST_CONTROL] heartbeat[11160]: 2008/07/05_02:06:05 info: RealMalloc stats: 654292 total malloc bytes. pid [11160/MST_CONTROL] heartbeat[11160]: 2008/07/05_02:06:05 info: Current arena value: 0 heartbeat[11160]: 2008/07/05_02:06:05 info: MSG stats: 0/0 ms age 6475160640 [pid11162/HBFIFO] heartbeat[11160]: 2008/07/05_02:06:05 info: cl_malloc stats: 360/415 32416/14005 [pid11162/HBFIFO] heartbeat[11160]: 2008/07/05_02:06:05 info: RealMalloc stats: 32416 total malloc bytes. pid [11162/HBFIFO] heartbeat[11160]: 2008/07/05_02:06:05 info: Current arena value: 0 heartbeat[11160]: 2008/07/05_02:06:05 info: MSG stats: 0/0 ms age 6475160650 [pid11163/HBWRITE] heartbeat[11160]: 2008/07/05_02:06:05 info: cl_malloc stats: 380/2365666 44048/20302 [pid11163/HBWRITE] heartbeat[11160]: 2008/07/05_02:06:05 info: RealMalloc stats: 53132 total malloc bytes. pid [11163/HBWRITE] heartbeat[11160]: 2008/07/05_02:06:12 info: Current arena value: 0 heartbeat[11160]: 2008/07/05_02:06:15 info: MSG stats: 0/0 ms age 6475167510 [pid11164/HBREAD] heartbeat[11160]: 2008/07/05_02:06:15 info: cl_malloc stats: 381/4448832 44140/20366 [pid11164/HBREAD] heartbeat[11160]: 2008/07/05_02:06:15 info: RealMalloc stats: 60840 total malloc bytes. pid [11164/HBREAD] heartbeat[11160]: 2008/07/05_02:06:15 info: Current arena value: 0 heartbeat[11160]: 2008/07/05_02:06:15 info: MSG stats: 0/0 ms age 6475169980 [pid11165/HBWRITE] heartbeat[11160]: 2008/07/05_02:06:15 info: cl_malloc stats: 392/2365690 46176/21694 [pid11165/HBWRITE] heartbeat[11160]: 2008/07/05_02:06:15 info: RealMalloc stats: 63480 total malloc bytes. pid [11165/HBWRITE] heartbeat[11160]: 2008/07/05_02:06:15 info: Current arena value: 0 heartbeat[11160]: 2008/07/05_02:06:15 info: MSG stats: 0/0 ms age 6475169980 [pid11166/HBREAD] heartbeat[11160]: 2008/07/05_02:06:15 info: cl_malloc stats: 393/8897408 46268/21758 [pid11166/HBREAD] heartbeat[11160]: 2008/07/05_02:06:15 info: RealMalloc stats: 62968 total malloc bytes. pid [11166/HBREAD] heartbeat[11160]: 2008/07/05_02:06:15 info: Current arena value: 0 heartbeat[11160]: 2008/07/05_02:06:15 info: MSG stats: 0/4038565 ms age 9340 [pid11167/HBWRITE] heartbeat[11160]: 2008/07/05_02:06:15 info: cl_malloc stats: 404/108650879 48304/23086 [pid11167/HBWRITE] heartbeat[11160]: 2008/07/05_02:06:15 info: RealMalloc stats: 81108 total malloc bytes. pid [11167/HBWRITE] heartbeat[11160]: 2008/07/05_02:06:15 info: Current arena value: 0 heartbeat[11160]: 2008/07/05_02:06:15 info: MSG stats: 0/1814211 ms age 9340 [pid11168/HBREAD] heartbeat[11160]: 2008/07/05_02:06:15 info: cl_malloc stats: 405/38098919 48396/23150 [pid11168/HBREAD] heartbeat[11160]: 2008/07/05_02:06:15 info: RealMalloc stats: 50748 total malloc bytes. pid [11168/HBREAD] heartbeat[11160]: 2008/07/05_02:06:15 info: Current arena value: 0 heartbeat[11160]: 2008/07/05_02:06:15 WARN: Late heartbeat: Node node1.mydomain.com: interval 9350 ms heartbeat[11160]: 2008/07/05_02:06:15 info: These are nothing to worry about. heartbeat[11160]: 2008/07/05_02:06:15 WARN: Gmain_timeout_dispatch: Dispatch function for memory stats took too long to execute: 12170 ms (> 100 ms) (GSource: 0x1176a208) heartbeat[11160]: 2008/07/05_02:06:15 WARN: Gmain_timeout_dispatch: Dispatch function for send local status was delayed 11530 ms (> 510 ms) before being called (GSource: 0x11769de8) heartbeat[11160]: 2008/07/05_02:06:15 info: Gmain_timeout_dispatch: started at 647517000 should have started at 647515847 heartbeat[11160]: 2008/07/05_02:06:15 WARN: Late heartbeat: Node node2.mydomain.com: interval 12530 ms heartbeat[11160]: 2008/07/05_02:06:15 WARN: Late heartbeat: Node gateway.mydomain.com: interval 12180 ms heartbeat[11160]: 2008/07/05_02:06:15 WARN: Gmain_timeout_dispatch: Dispatch function for check for signals was delayed 11890 ms (> 510 ms) before being called (GSource: 0x1176a508) heartbeat[11160]: 2008/07/05_02:06:15 info: Gmain_timeout_dispatch: started at 647517000 should have started at 647515811 heartbeat[11160]: 2008/07/05_02:06:15 WARN: Gmain_timeout_dispatch: Dispatch function for update msgfree count was delayed 12150 ms (> 10000 ms) before being called (GSource: 0x1176a688) heartbeat[11160]: 2008/07/05_02:06:15 info: Gmain_timeout_dispatch: started at 647517000 should have started at 647515785 heartbeat[11160]: 2008/07/05_02:06:15 WARN: Gmain_timeout_dispatch: Dispatch function for client audit was delayed 8150 ms (> 5000 ms) before being called (GSource: 0x1176a388) heartbeat[11160]: 2008/07/05_02:06:15 info: Gmain_timeout_dispatch: started at 647517000 should have started at 647516185 lrmd[11173]: 2008/07/05_03:30:48 WARN: G_SIG_dispatch: Dispatch function for SIGCHLD was delayed 1000 ms (> 100 ms) before being called (GSource: 0xc50e9b8) lrmd[11173]: 2008/07/05_03:30:48 info: G_SIG_dispatch: started at 648024297 should have started at 648024197 lrmd[11173]: 2008/07/05_11:29:00 WARN: G_SIG_dispatch: Dispatch function for SIGCHLD was delayed 1000 ms (> 100 ms) before being called (GSource: 0xc50e9b8) lrmd[11173]: 2008/07/05_11:29:00 info: G_SIG_dispatch: started at 650892901 should have started at 650892801 lrmd[11173]: 2008/07/05_15:01:52 WARN: G_SIG_dispatch: Dispatch function for SIGCHLD was delayed 1000 ms (> 100 ms) before being called (GSource: 0xc50e9b8) lrmd[11173]: 2008/07/05_15:01:52 info: G_SIG_dispatch: started at 652169937 should have started at 652169837 lrmd[11173]: 2008/07/06_01:41:08 WARN: G_SIG_dispatch: Dispatch function for SIGCHLD was delayed 1000 ms (> 100 ms) before being called (GSource: 0xc50e9b8) lrmd[11173]: 2008/07/06_01:41:08 info: G_SIG_dispatch: started at 656004844 should have started at 656004744 heartbeat[11160]: 2008/07/06_02:06:18 info: Daily informational memory statistics heartbeat[11160]: 2008/07/06_02:06:18 info: MSG stats: 9/11212383 ms age 0 [pid11160/MST_CONTROL] heartbeat[11160]: 2008/07/06_02:06:18 info: cl_malloc stats: 776/346946608 195520/97886 [pid11160/MST_CONTROL] heartbeat[11160]: 2008/07/06_02:06:18 info: RealMalloc stats: 654292 total malloc bytes. pid [11160/MST_CONTROL] heartbeat[11160]: 2008/07/06_02:06:18 info: Current arena value: 0 heartbeat[11160]: 2008/07/06_02:06:18 info: MSG stats: 0/0 ms age 6561557870 [pid11162/HBFIFO] heartbeat[11160]: 2008/07/06_02:06:18 info: cl_malloc stats: 360/415 32416/14005 [pid11162/HBFIFO] heartbeat[11160]: 2008/07/06_02:06:18 info: RealMalloc stats: 32416 total malloc bytes. pid [11162/HBFIFO] heartbeat[11160]: 2008/07/06_02:06:18 info: Current arena value: 0 heartbeat[11160]: 2008/07/06_02:06:18 info: MSG stats: 0/0 ms age 6561557870 [pid11163/HBWRITE] heartbeat[11160]: 2008/07/06_02:06:18 info: cl_malloc stats: 380/2475808 44048/20302 [pid11163/HBWRITE] heartbeat[11160]: 2008/07/06_02:06:18 info: RealMalloc stats: 53132 total malloc bytes. pid [11163/HBWRITE] heartbeat[11160]: 2008/07/06_02:06:19 info: Current arena value: 0 heartbeat[11160]: 2008/07/06_02:06:21 info: MSG stats: 0/0 ms age 6561559310 [pid11164/HBREAD] heartbeat[11160]: 2008/07/06_02:06:23 info: cl_malloc stats: 381/4656164 44140/20366 [pid11164/HBREAD] heartbeat[11160]: 2008/07/06_02:06:23 info: RealMalloc stats: 60840 total malloc bytes. pid [11164/HBREAD] heartbeat[11160]: 2008/07/06_02:06:23 info: Current arena value: 0 heartbeat[11160]: 2008/07/06_02:06:23 info: MSG stats: 0/0 ms age 6561563130 [pid11165/HBWRITE] heartbeat[11160]: 2008/07/06_02:06:23 info: cl_malloc stats: 392/2475832 46176/21694 [pid11165/HBWRITE] heartbeat[11160]: 2008/07/06_02:06:23 info: RealMalloc stats: 63480 total malloc bytes. pid [11165/HBWRITE] heartbeat[11160]: 2008/07/06_02:06:23 info: Current arena value: 0 heartbeat[11160]: 2008/07/06_02:06:23 info: MSG stats: 0/0 ms age 6561563140 [pid11166/HBREAD] heartbeat[11160]: 2008/07/06_02:06:23 info: cl_malloc stats: 393/9312070 46268/21758 [pid11166/HBREAD] heartbeat[11160]: 2008/07/06_02:06:23 info: RealMalloc stats: 62968 total malloc bytes. pid [11166/HBREAD] heartbeat[11160]: 2008/07/06_02:06:23 info: Current arena value: 0 heartbeat[11160]: 2008/07/06_02:06:23 info: MSG stats: 0/4228613 ms age 5270 [pid11167/HBWRITE] heartbeat[11160]: 2008/07/06_02:06:23 info: cl_malloc stats: 404/113719547 48304/23086 [pid11167/HBWRITE] heartbeat[11160]: 2008/07/06_02:06:23 info: RealMalloc stats: 81108 total malloc bytes. pid [11167/HBWRITE] heartbeat[11160]: 2008/07/06_02:06:23 info: Current arena value: 0 heartbeat[11160]: 2008/07/06_02:06:23 info: MSG stats: 0/1900591 ms age 5270 [pid11168/HBREAD] heartbeat[11160]: 2008/07/06_02:06:23 info: cl_malloc stats: 405/39912899 48396/23150 [pid11168/HBREAD] heartbeat[11160]: 2008/07/06_02:06:23 info: RealMalloc stats: 50748 total malloc bytes. pid [11168/HBREAD] heartbeat[11160]: 2008/07/06_02:06:23 info: Current arena value: 0 heartbeat[11160]: 2008/07/06_02:06:23 WARN: Late heartbeat: Node node1.mydomain.com: interval 5280 ms heartbeat[11160]: 2008/07/06_02:06:23 info: These are nothing to worry about. heartbeat[11160]: 2008/07/06_02:06:23 WARN: Gmain_timeout_dispatch: Dispatch function for memory stats took too long to execute: 5340 ms (> 100 ms) (GSource: 0x1176a208) heartbeat[11160]: 2008/07/06_02:06:23 WARN: Gmain_timeout_dispatch: Dispatch function for send local status was delayed 4670 ms (> 510 ms) before being called (GSource: 0x11769de8) heartbeat[11160]: 2008/07/06_02:06:23 info: Gmain_timeout_dispatch: started at 656156316 should have started at 656155849 heartbeat[11160]: 2008/07/06_02:06:23 WARN: Late heartbeat: Node node2.mydomain.com: interval 5340 ms heartbeat[11160]: 2008/07/06_02:06:23 WARN: Late heartbeat: Node gateway.mydomain.com: interval 5600 ms heartbeat[11160]: 2008/07/06_02:06:23 WARN: Gmain_timeout_dispatch: Dispatch function for check for signals was delayed 5120 ms (> 510 ms) before being called (GSource: 0x1176a508) heartbeat[11160]: 2008/07/06_02:06:23 info: Gmain_timeout_dispatch: started at 656156316 should have started at 656155804 lrmd[11173]: 2008/07/06_11:44:40 WARN: G_SIG_dispatch: Dispatch function for SIGCHLD was delayed 1000 ms (> 100 ms) before being called (GSource: 0xc50e9b8) lrmd[11173]: 2008/07/06_11:44:40 info: G_SIG_dispatch: started at 659625374 should have started at 659625274 lrmd[11173]: 2008/07/06_12:07:41 WARN: G_SIG_dispatch: Dispatch function for SIGCHLD was delayed 1000 ms (> 100 ms) before being called (GSource: 0xc50e9b8) lrmd[11173]: 2008/07/06_12:07:41 info: G_SIG_dispatch: started at 659763501 should have started at 659763401 lrmd[11173]: 2008/07/06_18:29:49 WARN: G_SIG_dispatch: Dispatch function for SIGCHLD was delayed 1000 ms (> 100 ms) before being called (GSource: 0xc50e9b8) lrmd[11173]: 2008/07/06_18:29:49 info: G_SIG_dispatch: started at 662055843 should have started at 662055743 lrmd[11173]: 2008/07/06_23:13:05 WARN: G_SIG_dispatch: Dispatch function for SIGCHLD was delayed 420 ms (> 100 ms) before being called (GSource: 0xc50e9b8) lrmd[11173]: 2008/07/06_23:13:05 info: G_SIG_dispatch: started at 663755144 should have started at 663755102 heartbeat[11160]: 2008/07/07_02:06:33 info: Daily informational memory statistics heartbeat[11160]: 2008/07/07_02:06:33 info: MSG stats: 11/11713473 ms age 0 [pid11160/MST_CONTROL] heartbeat[11160]: 2008/07/07_02:06:33 info: cl_malloc stats: 836/362295131 201232/100551 [pid11160/MST_CONTROL] heartbeat[11160]: 2008/07/07_02:06:33 info: RealMalloc stats: 654292 total malloc bytes. pid [11160/MST_CONTROL] heartbeat[11160]: 2008/07/07_02:06:33 info: Current arena value: 0 heartbeat[11160]: 2008/07/07_02:06:33 info: MSG stats: 0/0 ms age 6647957870 [pid11162/HBFIFO] heartbeat[11160]: 2008/07/07_02:06:33 info: cl_malloc stats: 360/415 32416/14005 [pid11162/HBFIFO] heartbeat[11160]: 2008/07/07_02:06:33 info: RealMalloc stats: 32416 total malloc bytes. pid [11162/HBFIFO] heartbeat[11160]: 2008/07/07_02:06:33 info: Current arena value: 0 heartbeat[11160]: 2008/07/07_02:06:33 info: MSG stats: 0/0 ms age 6647957870 [pid11163/HBWRITE] heartbeat[11160]: 2008/07/07_02:06:33 info: cl_malloc stats: 380/2585957 44048/20302 [pid11163/HBWRITE] heartbeat[11160]: 2008/07/07_02:06:33 info: RealMalloc stats: 53132 total malloc bytes. pid [11163/HBWRITE] heartbeat[11160]: 2008/07/07_02:06:33 info: Current arena value: 0 heartbeat[11160]: 2008/07/07_02:06:33 info: MSG stats: 0/0 ms age 6647957920 [pid11164/HBREAD] heartbeat[11160]: 2008/07/07_02:06:33 info: cl_malloc stats: 381/4863512 44140/20366 [pid11164/HBREAD] heartbeat[11160]: 2008/07/07_02:06:33 info: RealMalloc stats: 60840 total malloc bytes. pid [11164/HBREAD] heartbeat[11160]: 2008/07/07_02:06:33 info: Current arena value: 0 heartbeat[11160]: 2008/07/07_02:06:33 info: MSG stats: 0/0 ms age 6647957920 [pid11165/HBWRITE] heartbeat[11160]: 2008/07/07_02:06:33 info: cl_malloc stats: 392/2585981 46176/21694 [pid11165/HBWRITE] heartbeat[11160]: 2008/07/07_02:06:33 info: RealMalloc stats: 63480 total malloc bytes. pid [11165/HBWRITE] heartbeat[11160]: 2008/07/07_02:06:33 info: Current arena value: 0 heartbeat[11160]: 2008/07/07_02:06:33 info: MSG stats: 0/0 ms age 6647957980 [pid11166/HBREAD] heartbeat[11160]: 2008/07/07_02:06:33 info: cl_malloc stats: 393/9726758 46268/21758 [pid11166/HBREAD] heartbeat[11160]: 2008/07/07_02:06:33 info: RealMalloc stats: 62968 total malloc bytes. pid [11166/HBREAD] heartbeat[11160]: 2008/07/07_02:06:33 info: Current arena value: 0 heartbeat[11160]: 2008/07/07_02:06:33 info: MSG stats: 0/4418677 ms age 140 [pid11167/HBWRITE] heartbeat[11160]: 2008/07/07_02:06:33 info: cl_malloc stats: 404/118788640 48304/23086 [pid11167/HBWRITE] heartbeat[11160]: 2008/07/07_02:06:33 info: RealMalloc stats: 81108 total malloc bytes. pid [11167/HBWRITE] heartbeat[11160]: 2008/07/07_02:06:33 info: Current arena value: 0 heartbeat[11160]: 2008/07/07_02:06:33 info: MSG stats: 0/1986983 ms age 130 [pid11168/HBREAD] heartbeat[11160]: 2008/07/07_02:06:33 info: cl_malloc stats: 405/41727131 48396/23150 [pid11168/HBREAD] heartbeat[11160]: 2008/07/07_02:06:33 info: RealMalloc stats: 50748 total malloc bytes. pid [11168/HBREAD] heartbeat[11160]: 2008/07/07_02:06:33 info: Current arena value: 0 heartbeat[11160]: 2008/07/07_02:06:33 info: These are nothing to worry about. heartbeat[11160]: 2008/07/07_02:06:33 WARN: Gmain_timeout_dispatch: Dispatch function for memory stats took too long to execute: 170 ms (> 100 ms) (GSource: 0x1176a208)
_______________________________________________ Linux-HA mailing list [email protected] http://lists.linux-ha.org/mailman/listinfo/linux-ha See also: http://linux-ha.org/ReportingProblems
