Your log file almost looks like a bug in Asterisk doesn't it?
Why call poll() with a zero timeout while passing only one FD?
and then why do the read when there is no data?
Read the man pages for all the system calls
Take a look at the source chan_sip.c
/* Wait for sched or io */
res = ast_sched_wait(sched);
if ((res < 0) || (res > 1000))
res = 1000;
res = ast_io_wait(io, res);
ast_pthread_mutex_lock(&monlock);
if (res >= 0)
ast_sched_runq(sched);
ast_pthread_mutex_unlock(&monlock);
OK so it looks like ast_sched_wait(sched) is returning
zeroes Take a look....
{
/*
* Return the number of milliseconds
* until the next scheduled event
*/
struct timeval tv;
int ms;
DEBUG(ast_log(LOG_DEBUG, "ast_sched_wait()\n"));
if (!con->schedq)
return -1;
if (gettimeofday(&tv, NULL) < 0) {
/* This should never happen */
return 0;
};
ms = (con->schedq->when.tv_sec - tv.tv_sec) * 1000;
ms += (con->schedq->when.tv_usec - tv.tv_usec) / 1000;
if (ms < 0)
ms = 0;
return ms;
gettimeofday might be failing!! Why?
I'd add a call to perror() after "his should never happen"
I'll bet it has to do with time zones
But then maybe ms is beingset to zero...
Good luck
--- "Olle E. Johansson" <oej@edvina.net>
wrote:> From: "Olle E. Johansson" <oej@edvina.net>
> To: asterisk-users@lists.digium.com
> Subject: Re: [Asterisk-Users] Asterisk on FreeBSD
> Date: Mon, 27 Oct 2003 21:25:04 +0100
>
> Perry E. Metzger wrote:
>
> > "Olle E. Johansson" <oej@edvina.net> writes:
> >
> >>My Asterisk (fresh CVS) takes 98% of the system load on my FreeBSD
> >>server. On a slower CPU linux system, Asterisk runs at 0.1% - both
> >>without any active channels...
> >>
> >>Any ideas, anyone recognizing the problem?
> >
> >
> > On the BSDs, your friend is ktrace (or ktruss, depending on
> > flavor). It will tell you what system calls your process is
> executing
> > while it is doing this.
> ktrace on FreeBSD generates a file filled with this:
> And some signals caught here and there.
> Doesn't make me wiser.
>
> /Olle
> ---------------------------------------------------------------
> 74987 asterisk RET read 0
> 74987 asterisk CALL poll(0x851e400,0x1,0)
> 74987 asterisk RET poll 1
> 74987 asterisk CALL read(0x15,0x2845e060,0x100)
> 74987 asterisk GIO fd 21 read 0 bytes
> ""
> 74987 asterisk RET read 0
> 74987 asterisk CALL poll(0x851e400,0x1,0)
> 74987 asterisk RET poll 1
> 74987 asterisk CALL read(0x15,0x2845e060,0x100)
> 74987 asterisk GIO fd 21 read 0 bytes
> ""
> 74987 asterisk RET read 0
> 74987 asterisk CALL poll(0x851e400,0x1,0)
> 74987 asterisk RET poll 1
> 74987 asterisk CALL read(0x15,0x2845e060,0x100)
> 74987 asterisk GIO fd 21 read 0 bytes
> ""
> 74987 asterisk RET read 0
> 74987 asterisk CALL poll(0x851e400,0x1,0)
> 74987 asterisk RET poll 1
> 74987 asterisk CALL read(0x15,0x2845e060,0x100)
> 74987 asterisk GIO fd 21 read 0 bytes
> ""
> 74987 asterisk RET read 0
> 74987 asterisk CALL poll(0x851e400,0x1,0)
> 74987 asterisk RET poll 1
> 74987 asterisk CALL read(0x15,0x2845e060,0x100)
> 74987 asterisk GIO fd 21 read 0 bytes
> ""
> 74987 asterisk RET read 0
> 74987 asterisk CALL poll(0x851e400,0x1,0)
> 74987 asterisk RET poll 1
> 74987 asterisk CALL read(0x15,0x2845e060,0x100)
> 74987 asterisk GIO fd 21 read 0 bytes
> ""
> 74987 asterisk RET read 0
> 74987 asterisk CALL poll(0x851e400,0x1,0)
> 74987 asterisk RET poll 1
> 74987 asterisk CALL read(0x15,0x2845e060,0x100)
> 74987 asterisk GIO fd 21 read 0 bytes
> ""
> 74987 asterisk RET read 0
> 74987 asterisk CALL poll(0x851e400,0x1,0)
> 74987 asterisk RET poll 1
> 74987 asterisk CALL read(0x15,0x2845e060,0x100)
> 74987 asterisk GIO fd 21 read 0 bytes
> ""
> 74987 asterisk RET read 0
> 74987 asterisk CALL poll(0x851e400,0x1,0)
> 74987 asterisk RET poll 1
> 74987 asterisk CALL read(0x15,0x2845e060,0x100)
> 74987 asterisk GIO fd 21 read 0 bytes
> ""
> 74987 asterisk RET read 0
> 74987 asterisk CALL poll(0x851e400,0x1,0)
> 74987 asterisk RET poll 1
> 74987 asterisk CALL read(0x15,0x2845e060,0x100)
> 74987 asterisk GIO fd 21 read 0 bytes
>
> ----------
> And sometimes this - repeated many times:
>
> ""
> 74987 asterisk PSIG SIGPROF caught handler=0x28180260 mask=0x0
> code=0x0
> 74987 asterisk RET read 0
> 74987 asterisk CALL gettimeofday(0x281c8e88,0)
> 74987 asterisk RET gettimeofday 0
> 74987 asterisk CALL sigprocmask(0x3,0x281c8ef8,0)
> 74987 asterisk RET sigprocmask 0
> 74987 asterisk CALL poll(0x80cf000,0x4,0)
> 74987 asterisk RET poll 0
> 74987 asterisk CALL sigreturn(0xbfa87cec)
> 74987 asterisk RET sigreturn JUSTRETURN
> 74987 asterisk CALL poll(0x851e400,0x1,0)
> 74987 asterisk RET poll 1
> 74987 asterisk CALL read(0x15,0x2845e060,0x100)
> 74987 asterisk GIO fd 21 read 0 bytes
>
>
> -----------------
>
> _______________________________________________
> Asterisk-Users mailing list
> Asterisk-Users@lists.digium.com
> http://lists.digium.com/mailman/listinfo/asterisk-users
====Chris Albertson
Home: 310-376-1029 chrisalbertson90278@yahoo.com
Cell: 310-990-7550
Office: 310-336-5189 Christopher.J.Albertson@aero.org
KG6OMK
__________________________________
Do you Yahoo!?
Exclusive Video Premiere - Britney Spears
http://launch.yahoo.com/promos/britneyspears/
Chris Albertson wrote:> Your log file almost looks like a bug in Asterisk doesn't it? > Why call poll() with a zero timeout while passing only one FD? > and then why do the read when there is no data? > > Read the man pages for all the system calls > > Take a look at the source chan_sip.c > > /* Wait for sched or io */ > res = ast_sched_wait(sched); > if ((res < 0) || (res > 1000)) > res = 1000; > res = ast_io_wait(io, res); > ast_pthread_mutex_lock(&monlock); > if (res >= 0) > ast_sched_runq(sched); > ast_pthread_mutex_unlock(&monlock); > > > OK so it looks like ast_sched_wait(sched) is returning > zeroes Take a look.... > > { > /* > * Return the number of milliseconds > * until the next scheduled event > */ > struct timeval tv; > int ms; > DEBUG(ast_log(LOG_DEBUG, "ast_sched_wait()\n")); > if (!con->schedq) > return -1; > if (gettimeofday(&tv, NULL) < 0) { > /* This should never happen */ > return 0; > }; > ms = (con->schedq->when.tv_sec - tv.tv_sec) * 1000; > ms += (con->schedq->when.tv_usec - tv.tv_usec) / 1000; > if (ms < 0) > ms = 0; > return ms; > > gettimeofday might be failing!! Why? > I'd add a call to perror() after "his should never happen" > I'll bet it has to do with time zones > > But then maybe ms is beingset to zero...Aha. It may be connected to this error message, then: messages:Oct 26 21:18:15 NOTICE[137382912]: File sched.c, Line 209 (sched_settime): Request to schedule in the past?!?! I read somewhere that I could ignore this message, therefore I just didn't include it in my earlier report. Seems like I can't ignore it any more :-( However, I'm not a fluent C programmer, so I don't now where to fix this. I just wish there are others on the list that works with FreeBSD and are programmers... Hello, out there! List: Sorry for filling this list with dev- related information, it started as a general problem and slided into development, such things happens. /Olle> > > Good luck > > > --- "Olle E. Johansson" <oej@edvina.net> wrote: > >>From: "Olle E. Johansson" <oej@edvina.net> >>To: asterisk-users@lists.digium.com >>Subject: Re: [Asterisk-Users] Asterisk on FreeBSD >>Date: Mon, 27 Oct 2003 21:25:04 +0100 >> >>Perry E. Metzger wrote: >> >> >>>"Olle E. Johansson" <oej@edvina.net> writes: >>> >>> >>>>My Asterisk (fresh CVS) takes 98% of the system load on my FreeBSD >>>>server. On a slower CPU linux system, Asterisk runs at 0.1% - both >>>>without any active channels... >>>> >>>>Any ideas, anyone recognizing the problem? >>> >>> >>>On the BSDs, your friend is ktrace (or ktruss, depending on >>>flavor). It will tell you what system calls your process is >> >>executing >> >>>while it is doing this. >> >>ktrace on FreeBSD generates a file filled with this: >>And some signals caught here and there. >>Doesn't make me wiser. >> >>/Olle >>--------------------------------------------------------------- >>74987 asterisk RET read 0 >> 74987 asterisk CALL poll(0x851e400,0x1,0) >> 74987 asterisk RET poll 1 >> 74987 asterisk CALL read(0x15,0x2845e060,0x100) >> 74987 asterisk GIO fd 21 read 0 bytes >> "" >> 74987 asterisk RET read 0 >> 74987 asterisk CALL poll(0x851e400,0x1,0) >> 74987 asterisk RET poll 1 >> 74987 asterisk CALL read(0x15,0x2845e060,0x100) >> 74987 asterisk GIO fd 21 read 0 bytes >> "" >> 74987 asterisk RET read 0 >> 74987 asterisk CALL poll(0x851e400,0x1,0) >> 74987 asterisk RET poll 1 >> 74987 asterisk CALL read(0x15,0x2845e060,0x100) >> 74987 asterisk GIO fd 21 read 0 bytes >> "" >> 74987 asterisk RET read 0 >> 74987 asterisk CALL poll(0x851e400,0x1,0) >> 74987 asterisk RET poll 1 >> 74987 asterisk CALL read(0x15,0x2845e060,0x100) >> 74987 asterisk GIO fd 21 read 0 bytes >> "" >> 74987 asterisk RET read 0 >> 74987 asterisk CALL poll(0x851e400,0x1,0) >> 74987 asterisk RET poll 1 >> 74987 asterisk CALL read(0x15,0x2845e060,0x100) >> 74987 asterisk GIO fd 21 read 0 bytes >> "" >> 74987 asterisk RET read 0 >> 74987 asterisk CALL poll(0x851e400,0x1,0) >> 74987 asterisk RET poll 1 >> 74987 asterisk CALL read(0x15,0x2845e060,0x100) >> 74987 asterisk GIO fd 21 read 0 bytes >> "" >> 74987 asterisk RET read 0 >> 74987 asterisk CALL poll(0x851e400,0x1,0) >> 74987 asterisk RET poll 1 >> 74987 asterisk CALL read(0x15,0x2845e060,0x100) >> 74987 asterisk GIO fd 21 read 0 bytes >> "" >> 74987 asterisk RET read 0 >> 74987 asterisk CALL poll(0x851e400,0x1,0) >> 74987 asterisk RET poll 1 >> 74987 asterisk CALL read(0x15,0x2845e060,0x100) >> 74987 asterisk GIO fd 21 read 0 bytes >> "" >> 74987 asterisk RET read 0 >> 74987 asterisk CALL poll(0x851e400,0x1,0) >> 74987 asterisk RET poll 1 >> 74987 asterisk CALL read(0x15,0x2845e060,0x100) >> 74987 asterisk GIO fd 21 read 0 bytes >> "" >> 74987 asterisk RET read 0 >> 74987 asterisk CALL poll(0x851e400,0x1,0) >> 74987 asterisk RET poll 1 >> 74987 asterisk CALL read(0x15,0x2845e060,0x100) >> 74987 asterisk GIO fd 21 read 0 bytes >> >>---------- >>And sometimes this - repeated many times: >> >> "" >> 74987 asterisk PSIG SIGPROF caught handler=0x28180260 mask=0x0 >>code=0x0 >> 74987 asterisk RET read 0 >> 74987 asterisk CALL gettimeofday(0x281c8e88,0) >> 74987 asterisk RET gettimeofday 0 >> 74987 asterisk CALL sigprocmask(0x3,0x281c8ef8,0) >> 74987 asterisk RET sigprocmask 0 >> 74987 asterisk CALL poll(0x80cf000,0x4,0) >> 74987 asterisk RET poll 0 >> 74987 asterisk CALL sigreturn(0xbfa87cec) >> 74987 asterisk RET sigreturn JUSTRETURN >> 74987 asterisk CALL poll(0x851e400,0x1,0) >> 74987 asterisk RET poll 1 >> 74987 asterisk CALL read(0x15,0x2845e060,0x100) >> 74987 asterisk GIO fd 21 read 0 bytes >> >