Re: [Freeswitch-users] Reliability of HEARTBEAT events every 20 seconds? (in mod_event_socket)
No, and all timing seems ok (both good audio and timer_test returns with good results). And we're actually talking about 10 seconds here :) This is on Windows, and I'm starting with -hp, I wonder if I might have some kind of thread priority issue - I can't remember seeing this before adding -hp.. hmm, I will check that out. Peter Olsson ----- Reply message ----- Från: "DJB International" <djbinter@gmail.com> Datum: tors, dec 9, 2010 17:25 Rubrik: [Freeswitch-users] Reliability of HEARTBEAT events every 20 seconds? (in mod_event_socket) Till: "FreeSWITCH Users Help" <freeswitch-users@lists.freeswitch.org> Are you running FS with -nocal? -djbinter On Thu, Dec 9, 2010 at 5:12 AM, Peter Olsson <peter.olsson@visionutveckling.se<mailto:peter.olsson@visionutveckling.se>> wrote: Ok - I trapped the problem with full event info. The up-time also reports a difference, in this case 32 seconds. As you can see there is no load on the server at all by this time, no calls etc. Hmm, this is really strange I must say. [2010-12-09 13:53:49] Received HEARTBEAT event - we're alive content-length == 629 content-type == text/event-plain core-uuid == 1550f368-b577-4304-bacd-2681d4067036 event-calling-file == switch_core.c event-calling-function == send_heartbeat event-calling-line-number == 65 event-date-gmt == Thu, 09 Dec 2010 12:53:53 GMT event-date-local == 2010-12-09 13:53:53 event-date-timestamp == 1291899233256303 event-info == System Ready event-name == HEARTBEAT freeswitch-hostname == 79w3sipt4 freeswitch-ipv4 == 10.66.195.14 freeswitch-ipv6 == ::1 idle-cpu == 98.437500 session-count == 0 session-per-sec == 30 session-since-startup == 277 up-time == 0 years, 7 days, 1 hour, 1 minute, 1 second, 680 milliseconds, 750 microseconds [2010-12-09 13:54:21] Received HEARTBEAT event - we're alive content-length == 631 content-type == text/event-plain core-uuid == 1550f368-b577-4304-bacd-2681d4067036 event-calling-file == switch_core.c event-calling-function == send_heartbeat event-calling-line-number == 65 event-date-gmt == Thu, 09 Dec 2010 12:54:25 GMT event-date-local == 2010-12-09 13:54:25 event-date-timestamp == 1291899265259303 event-info == System Ready event-name == HEARTBEAT freeswitch-hostname == 79w3sipt4 freeswitch-ipv4 == 10.66.195.14 freeswitch-ipv6 == ::1 idle-cpu == 97.656250 session-count == 0 session-per-sec == 30 session-since-startup == 277 up-time == 0 years, 7 days, 1 hour, 1 minute, 33 seconds, 683 milliseconds, 750 microseconds Mvh Peter Olsson -----Ursprungligt meddelande----- Från: freeswitch-users-bounces@lists.freeswitch.org<mailto:freeswitch-users-bounces@lists.freeswitch.org> [mailto:freeswitch-users-bounces@lists.freeswitch.org<mailto:freeswitch-users-bounces@lists.freeswitch.org>] För Steven Ayre Skickat: den 9 december 2010 12:42 Till: FreeSWITCH Users Help Ämne: Re: [Freeswitch-users] Reliability of HEARTBEAT events every 20 seconds? (in mod_event_socket) Also do you have any warning messages like this in the fs log? Task was executed late by %d seconds (That should show up if the delay is in the scheduler, if the task runs >1s late). -Steve On 9 December 2010 11:27, Peter Olsson <peter.olsson@visionutveckling.se<mailto:peter.olsson@visionutveckling.se>> wrote:
Hello everyone,
I have a question about the reliability of heartbeat events, it should be sent from FreeSWITCH every 20 seconds - right? If you look below in my log sample (from my own process), you can see that it comes 12:07:01, then 21, then 41, but after this it suddenly takes 31 seconds for it to show up (12:08:12). I've also done a Wireshark trace, and it shows the same thing - so it is really delayed from FS. The load at the time was zero calls, and the server itself was using maybe 5% CPU. After the delayed event it continues to show up every 20 seconds.
[2010-12-09 12:07:01] Received HEARTBEAT event - we're alive.
[2010-12-09 12:07:21] Received HEARTBEAT event - we're alive.
[2010-12-09 12:07:41] Received HEARTBEAT event - we're alive.
[2010-12-09 12:08:12] Received HEARTBEAT event - we're alive.
[2010-12-09 12:08:32] Received HEARTBEAT event - we're alive.
[2010-12-09 12:08:52] Received HEARTBEAT event - we're alive.
[2010-12-09 12:09:12] Received HEARTBEAT event - we're alive.
Should the HEARTBEAT event be 100% reliable, or could something cause a delay like this? This server is not on latest GIT, but it's not more then one month old. I can debug this further myself, but I just want to know if it always should be triggered every 20 seconds, or if these events for some reasons might be delayed.
By the way - no clock skew or anything is detected on the machine, so that's not causing it.
Thanks,
Peter
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto:FreeSWITCH-users@lists.freeswitch.org> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto:FreeSWITCH-users@lists.freeswitch.org> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org _______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto:FreeSWITCH-users@lists.freeswitch.org> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org !DSPAM:4d0102cf32763135019700!
That didn't make a difference either.. I will have to look into this deeper, and add some more debug logging for when the event fires within FS. No more suggestions anyone? :) /Peter ________________________________________ Från: freeswitch-users-bounces@lists.freeswitch.org [freeswitch-users-bounces@lists.freeswitch.org] för Peter Olsson [peter.olsson@visionutveckling.se] Skickat: den 9 december 2010 17:44 Till: freeswitch-users@lists.freeswitch.org Ämne: Re: [Freeswitch-users] Reliability of HEARTBEAT events every 20 seconds? (in mod_event_socket) No, and all timing seems ok (both good audio and timer_test returns with good results). And we're actually talking about 10 seconds here :) This is on Windows, and I'm starting with -hp, I wonder if I might have some kind of thread priority issue - I can't remember seeing this before adding -hp.. hmm, I will check that out. Peter Olsson ----- Reply message ----- Från: "DJB International" <djbinter@gmail.com> Datum: tors, dec 9, 2010 17:25 Rubrik: [Freeswitch-users] Reliability of HEARTBEAT events every 20 seconds? (in mod_event_socket) Till: "FreeSWITCH Users Help" <freeswitch-users@lists.freeswitch.org> Are you running FS with -nocal? -djbinter On Thu, Dec 9, 2010 at 5:12 AM, Peter Olsson <peter.olsson@visionutveckling.se<mailto:peter.olsson@visionutveckling.se>> wrote: Ok - I trapped the problem with full event info. The up-time also reports a difference, in this case 32 seconds. As you can see there is no load on the server at all by this time, no calls etc. Hmm, this is really strange I must say. [2010-12-09 13:53:49] Received HEARTBEAT event - we're alive content-length == 629 content-type == text/event-plain core-uuid == 1550f368-b577-4304-bacd-2681d4067036 event-calling-file == switch_core.c event-calling-function == send_heartbeat event-calling-line-number == 65 event-date-gmt == Thu, 09 Dec 2010 12:53:53 GMT event-date-local == 2010-12-09 13:53:53 event-date-timestamp == 1291899233256303 event-info == System Ready event-name == HEARTBEAT freeswitch-hostname == 79w3sipt4 freeswitch-ipv4 == 10.66.195.14 freeswitch-ipv6 == ::1 idle-cpu == 98.437500 session-count == 0 session-per-sec == 30 session-since-startup == 277 up-time == 0 years, 7 days, 1 hour, 1 minute, 1 second, 680 milliseconds, 750 microseconds [2010-12-09 13:54:21] Received HEARTBEAT event - we're alive content-length == 631 content-type == text/event-plain core-uuid == 1550f368-b577-4304-bacd-2681d4067036 event-calling-file == switch_core.c event-calling-function == send_heartbeat event-calling-line-number == 65 event-date-gmt == Thu, 09 Dec 2010 12:54:25 GMT event-date-local == 2010-12-09 13:54:25 event-date-timestamp == 1291899265259303 event-info == System Ready event-name == HEARTBEAT freeswitch-hostname == 79w3sipt4 freeswitch-ipv4 == 10.66.195.14 freeswitch-ipv6 == ::1 idle-cpu == 97.656250 session-count == 0 session-per-sec == 30 session-since-startup == 277 up-time == 0 years, 7 days, 1 hour, 1 minute, 33 seconds, 683 milliseconds, 750 microseconds Mvh Peter Olsson -----Ursprungligt meddelande----- Från: freeswitch-users-bounces@lists.freeswitch.org<mailto:freeswitch-users-bounces@lists.freeswitch.org> [mailto:freeswitch-users-bounces@lists.freeswitch.org<mailto:freeswitch-users-bounces@lists.freeswitch.org>] För Steven Ayre Skickat: den 9 december 2010 12:42 Till: FreeSWITCH Users Help Ämne: Re: [Freeswitch-users] Reliability of HEARTBEAT events every 20 seconds? (in mod_event_socket) Also do you have any warning messages like this in the fs log? Task was executed late by %d seconds (That should show up if the delay is in the scheduler, if the task runs >1s late). -Steve On 9 December 2010 11:27, Peter Olsson <peter.olsson@visionutveckling.se<mailto:peter.olsson@visionutveckling.se>> wrote:
Hello everyone,
I have a question about the reliability of heartbeat events, it should be sent from FreeSWITCH every 20 seconds - right? If you look below in my log sample (from my own process), you can see that it comes 12:07:01, then 21, then 41, but after this it suddenly takes 31 seconds for it to show up (12:08:12). I've also done a Wireshark trace, and it shows the same thing - so it is really delayed from FS. The load at the time was zero calls, and the server itself was using maybe 5% CPU. After the delayed event it continues to show up every 20 seconds.
[2010-12-09 12:07:01] Received HEARTBEAT event - we're alive.
[2010-12-09 12:07:21] Received HEARTBEAT event - we're alive.
[2010-12-09 12:07:41] Received HEARTBEAT event - we're alive.
[2010-12-09 12:08:12] Received HEARTBEAT event - we're alive.
[2010-12-09 12:08:32] Received HEARTBEAT event - we're alive.
[2010-12-09 12:08:52] Received HEARTBEAT event - we're alive.
[2010-12-09 12:09:12] Received HEARTBEAT event - we're alive.
Should the HEARTBEAT event be 100% reliable, or could something cause a delay like this? This server is not on latest GIT, but it's not more then one month old. I can debug this further myself, but I just want to know if it always should be triggered every 20 seconds, or if these events for some reasons might be delayed.
By the way - no clock skew or anything is detected on the machine, so that's not causing it.
Thanks,
Peter
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto:FreeSWITCH-users@lists.freeswitch.org> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto:FreeSWITCH-users@lists.freeswitch.org> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org _______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto:FreeSWITCH-users@lists.freeswitch.org> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org _______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org !DSPAM:4d01088c32762074620997!
You do realize the time in the log is when its submitted. And you have some time between then the task is run then rescheduled... Are we really going to be that picky? /b On Dec 9, 2010, at 12:25 PM, Peter Olsson wrote:
That didn't make a difference either.. I will have to look into this deeper, and add some more debug logging for when the event fires within FS.
No more suggestions anyone? :)
/Peter
Yes I realize this, but I just think 10-12 seconds (30-32 instead of 20) seems like a little too much to be correct - or should I consider this as normal? /Peter ________________________________________ Från: freeswitch-users-bounces@lists.freeswitch.org [freeswitch-users-bounces@lists.freeswitch.org] för Brian West [brian@freeswitch.org] Skickat: den 9 december 2010 19:35 Till: FreeSWITCH Users Help Ämne: Re: [Freeswitch-users] Reliability of HEARTBEAT events every 20 seconds? (in mod_event_socket) You do realize the time in the log is when its submitted. And you have some time between then the task is run then rescheduled... Are we really going to be that picky? /b On Dec 9, 2010, at 12:25 PM, Peter Olsson wrote:
That didn't make a difference either.. I will have to look into this deeper, and add some more debug logging for when the event fires within FS.
No more suggestions anyone? :)
/Peter
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org !DSPAM:4d0122b032761938095686!
Ok, I found the reason for the delays. check_ip() (which is called after heartbeat has been sent) sometimes took up to 12 seconds to complete. This seems to be related with some slow/semi-working DNS-servers in my lab network. I've created a patch that adds a setting that makes it possible to deactivate detection of IP address change (default behaviour will be the way it works now). I know this is kind of a special case, but still, the check_ip() is not needed on most servers I would say. I will create a jira and post the patch there (later on today). Thanks for all suggestions about this. /Peter ________________________________________ Från: freeswitch-users-bounces@lists.freeswitch.org [freeswitch-users-bounces@lists.freeswitch.org] för Peter Olsson [peter.olsson@visionutveckling.se] Skickat: den 9 december 2010 19:42 Till: FreeSWITCH Users Help Ämne: Re: [Freeswitch-users] Reliability of HEARTBEAT events every 20 seconds? (in mod_event_socket) Yes I realize this, but I just think 10-12 seconds (30-32 instead of 20) seems like a little too much to be correct - or should I consider this as normal? /Peter ________________________________________ Från: freeswitch-users-bounces@lists.freeswitch.org [freeswitch-users-bounces@lists.freeswitch.org] för Brian West [brian@freeswitch.org] Skickat: den 9 december 2010 19:35 Till: FreeSWITCH Users Help Ämne: Re: [Freeswitch-users] Reliability of HEARTBEAT events every 20 seconds? (in mod_event_socket) You do realize the time in the log is when its submitted. And you have some time between then the task is run then rescheduled... Are we really going to be that picky? /b On Dec 9, 2010, at 12:25 PM, Peter Olsson wrote:
That didn't make a difference either.. I will have to look into this deeper, and add some more debug logging for when the event fires within FS.
No more suggestions anyone? :)
/Peter
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org _______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org !DSPAM:4d0124e632764708731795!
participants (2)
-
Brian West
-
Peter Olsson