delay of nnn exceeds... and weird behavior

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

delay of nnn exceeds... and weird behavior

Fernando Lopez-Lezcano
Hi all, I'm trying to start to debug some latency problems I'm having
with recent 2.6.x kernels that include Ingo's realtime preemption patch
(this is related to a still unfinished thread I started in the jack and
kernel mailing lists).

I have observed some strange behavior that may be related to just jack.

I reboot the computer, login, start up jack through qjackctl. This is
with a freshly built current cvs (0.100.6) copy of jack.

Start some clients, everything's fine.
Pretty soon I get one "delay of xxx exceeds" message:

12:47:35.205 Server configuration saved to "/user/n/nando/.jackdrc".
12:47:35.205 Statistics reset.
12:47:35.484 Client activated.
12:47:35.486 Audio connection change.
12:47:35.490 Audio connection graph change.
12:47:59.292 Audio connection graph change.
12:47:59.354 Audio connection change.
12:47:59.469 MIDI connection graph change.
12:47:59.472 Audio connection graph change.
12:47:59.563 MIDI connection change.
12:47:59.765 MIDI connection change.
delay of 31993.000 usecs exceeds estimated spare time of 2460.000;
restart ...

Big one. But just the first one after a reboot?
Eventually the floodgates open:

12:48:52.930 XRUN callback (1).
12:49:42.432 XRUN callback (2).
delay of 1243.000 usecs exceeds estimated spare time of 1232.000;
restart ...delay of 1249.000 usecs exceeds estimated spare time of
1232.000; restart ...
delay of 1258.000 usecs exceeds estimated spare time of 1232.000;
restart ...
delay of 1253.000 usecs exceeds estimated spare time of 1207.000;
restart ...
delay of 1264.000 usecs exceeds estimated spare time of 1207.000;
restart ...
delay of 1278.000 usecs exceeds estimated spare time of 1207.000;
restart ...
delay of 1284.000 usecs exceeds estimated spare time of 1207.000;
restart ...
delay of 1285.000 usecs exceeds estimated spare time of 1207.000;
restart ...
delay of 1295.000 usecs exceeds estimated spare time of 1207.000;
restart ...
12:49:44.160 XRUN callback (8 skipped).
12:49:44.956 XRUN callback (11).
delay of 1322.000 usecs exceeds estimated spare time of 1170.000;
restart ...
delay of 1320.000 usecs exceeds estimated spare time of 1170.000;
restart ...
delay of 1326.000 usecs exceeds estimated spare time of 1170.000;
restart ...
delay of 1323.000 usecs exceeds estimated spare time of 1170.000;
restart ...
delay of 1335.000 usecs exceeds estimated spare time of 1170.000;
restart ...
12:49:46.183 XRUN callback (4 skipped).

and so on and so forth.
After a while:

12:54:35.702 XRUN callback (1 skipped).
delay of 3589.000 usecs exceeds estimated spare time of 2482.000;
restart ...
12:54:36.680 XRUN callback (257).
delay of 3600.000 usecs exceeds estimated spare time of 2459.000;
restart ...
12:54:39.237 XRUN callback (258).
delay of 3608.000 usecs exceeds estimated spare time of 2468.000;
restart ...

The thing I noticed is that the delay time keeps increasing
monotonically. All the time.

...

Now I _STOP_ jack and qjackctl. And start it again.

12:55:35.721 Server configuration saved to "/user/n/nando/.jackdrc".
12:55:35.722 Statistics reset.
12:55:35.765 Client activated.
12:55:35.767 Audio connection change.
12:55:35.771 Audio connection graph change.
delay of 3788.000 usecs exceeds estimated spare time of 2624.000;
restart ...
12:55:37.296 XRUN callback (1).
delay of 3782.000 usecs exceeds estimated spare time of 2622.000;
restart ...
12:55:38.350 XRUN callback (2).
delay of 3792.000 usecs exceeds estimated spare time of 2622.000;
restart ...
12:55:39.461 XRUN callback (4).
delay of 3797.000 usecs exceeds estimated spare time of 2599.000;
restart ...
delay of 3793.000 usecs exceeds estimated spare time of 2599.000;
restart ...

The delay keeps increasing!
If I start and stop jack it keeps going up (up to, for example, 80000+
after one day of chugging along - whether I'm logged in or not). No
matter what I do. If I reboot the machine it goes back down.

Am I the only one to find this strange?

Most probably there is a perfectly logical explanation... obviously I
have only a very fuzzy idea of the code behind all this.

-- Fernando

PS: while I wrote this email:

13:00:00.912 XRUN callback (203).
delay of 4232.000 usecs exceeds estimated spare time of 2594.000;
restart ...
delay of 4095.000 usecs exceeds estimated spare time of 2594.000;
restart ...
13:00:01.216 XRUN callback (1 skipped).
delay of 4240.000 usecs exceeds estimated spare time of 2609.000;
restart ...
13:00:01.997 XRUN callback (205).
delay of 4055.000 usecs exceeds estimated spare time of 2585.000;
restart ...




-------------------------------------------------------
This SF.Net email is sponsored by:
Power Architecture Resource Center: Free content, downloads, discussions,
and more. http://solutions.newsforge.com/ibmarch.tmpl
_______________________________________________
Jackit-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/jackit-devel
Reply | Threaded
Open this post in threaded view
|

Re: delay of nnn exceeds... and weird behavior

Fernando Lopez-Lezcano
On Tue, 2005-09-27 at 13:02 -0700, Fernando Lopez-Lezcano wrote:
> Hi all, I'm trying to start to debug some latency problems I'm having
> with recent 2.6.x kernels that include Ingo's realtime preemption patch
> (this is related to a still unfinished thread I started in the jack and
> kernel mailing lists).
>
> I have observed some strange behavior that may be related to just jack.

BTW, one more detail, as I outlined to Stephane off list I'm not hearing
any dropouts in Jack's output. Plenty of warnings of excessive delay but
no audible stuff (and the "delay" keeps going up and up and up).

-- Fernando

> I reboot the computer, login, start up jack through qjackctl. This is
> with a freshly built current cvs (0.100.6) copy of jack.
>
> Start some clients, everything's fine.
> Pretty soon I get one "delay of xxx exceeds" message:
>
> 12:47:35.205 Server configuration saved to "/user/n/nando/.jackdrc".
> 12:47:35.205 Statistics reset.
> 12:47:35.484 Client activated.
> 12:47:35.486 Audio connection change.
> 12:47:35.490 Audio connection graph change.
> 12:47:59.292 Audio connection graph change.
> 12:47:59.354 Audio connection change.
> 12:47:59.469 MIDI connection graph change.
> 12:47:59.472 Audio connection graph change.
> 12:47:59.563 MIDI connection change.
> 12:47:59.765 MIDI connection change.
> delay of 31993.000 usecs exceeds estimated spare time of 2460.000;
> restart ...
>
> Big one. But just the first one after a reboot?
> Eventually the floodgates open:
>
> 12:48:52.930 XRUN callback (1).
> 12:49:42.432 XRUN callback (2).
> delay of 1243.000 usecs exceeds estimated spare time of 1232.000;
> restart ...delay of 1249.000 usecs exceeds estimated spare time of
> 1232.000; restart ...
> delay of 1258.000 usecs exceeds estimated spare time of 1232.000;
> restart ...
> delay of 1253.000 usecs exceeds estimated spare time of 1207.000;
> restart ...
> delay of 1264.000 usecs exceeds estimated spare time of 1207.000;
> restart ...
> delay of 1278.000 usecs exceeds estimated spare time of 1207.000;
> restart ...
> delay of 1284.000 usecs exceeds estimated spare time of 1207.000;
> restart ...
> delay of 1285.000 usecs exceeds estimated spare time of 1207.000;
> restart ...
> delay of 1295.000 usecs exceeds estimated spare time of 1207.000;
> restart ...
> 12:49:44.160 XRUN callback (8 skipped).
> 12:49:44.956 XRUN callback (11).
> delay of 1322.000 usecs exceeds estimated spare time of 1170.000;
> restart ...
> delay of 1320.000 usecs exceeds estimated spare time of 1170.000;
> restart ...
> delay of 1326.000 usecs exceeds estimated spare time of 1170.000;
> restart ...
> delay of 1323.000 usecs exceeds estimated spare time of 1170.000;
> restart ...
> delay of 1335.000 usecs exceeds estimated spare time of 1170.000;
> restart ...
> 12:49:46.183 XRUN callback (4 skipped).
> [MUNCH]




-------------------------------------------------------
This SF.Net email is sponsored by:
Power Architecture Resource Center: Free content, downloads, discussions,
and more. http://solutions.newsforge.com/ibmarch.tmpl
_______________________________________________
Jackit-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/jackit-devel
Reply | Threaded
Open this post in threaded view
|

Re: delay of nnn exceeds... and weird behavior

LGTrader
On 9/28/05, Fernando Lopez-Lezcano <[hidden email]> wrote:

> On Tue, 2005-09-27 at 13:02 -0700, Fernando Lopez-Lezcano wrote:
> > Hi all, I'm trying to start to debug some latency problems I'm having
> > with recent 2.6.x kernels that include Ingo's realtime preemption patch
> > (this is related to a still unfinished thread I started in the jack and
> > kernel mailing lists).
> >
> > I have observed some strange behavior that may be related to just jack.
>
> BTW, one more detail, as I outlined to Stephane off list I'm not hearing
> any dropouts in Jack's output. Plenty of warnings of excessive delay but
> no audible stuff (and the "delay" keeps going up and up and up).
>
> -- Fernando

Fernando,
   I wonder if possibly you have any of this 'experimental' timer
stuff turned on. I was thinking that maybe a timer is not being reset
and then each time this event occurs the time is read out getting
greater and greater.

   Lee Revell suggested I disable that stuff. I'm working on xrun
problems on my AMD64 machine.

Take care,
Mark


-------------------------------------------------------
This SF.Net email is sponsored by:
Power Architecture Resource Center: Free content, downloads, discussions,
and more. http://solutions.newsforge.com/ibmarch.tmpl
_______________________________________________
Jackit-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/jackit-devel
Reply | Threaded
Open this post in threaded view
|

Re: delay of nnn exceeds... and weird behavior

Fernando Lopez-Lezcano
On Wed, 2005-09-28 at 19:51 -0700, Mark Knecht wrote:

> On 9/28/05, Fernando Lopez-Lezcano <[hidden email]> wrote:
> > On Tue, 2005-09-27 at 13:02 -0700, Fernando Lopez-Lezcano wrote:
> > > Hi all, I'm trying to start to debug some latency problems I'm having
> > > with recent 2.6.x kernels that include Ingo's realtime preemption patch
> > > (this is related to a still unfinished thread I started in the jack and
> > > kernel mailing lists).
> > >
> > > I have observed some strange behavior that may be related to just jack.
> >
> > BTW, one more detail, as I outlined to Stephane off list I'm not hearing
> > any dropouts in Jack's output. Plenty of warnings of excessive delay but
> > no audible stuff (and the "delay" keeps going up and up and up).
>
>    I wonder if possibly you have any of this 'experimental' timer
> stuff turned on.

You mean the "High Resolution Timers"? I don't have that on.

> I was thinking that maybe a timer is not being reset
> and then each time this event occurs the time is read out getting
> greater and greater.

It sort of looks like that. I'll see what I can do to try to debug
this.

-- Fernando




-------------------------------------------------------
This SF.Net email is sponsored by:
Power Architecture Resource Center: Free content, downloads, discussions,
and more. http://solutions.newsforge.com/ibmarch.tmpl
_______________________________________________
Jackit-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/jackit-devel
Reply | Threaded
Open this post in threaded view
|

Re: delay of nnn exceeds... and weird behavior

LGTrader
On 9/29/05, Fernando Lopez-Lezcano <[hidden email]> wrote:

> On Wed, 2005-09-28 at 19:51 -0700, Mark Knecht wrote:
> > On 9/28/05, Fernando Lopez-Lezcano <[hidden email]> wrote:
> > > On Tue, 2005-09-27 at 13:02 -0700, Fernando Lopez-Lezcano wrote:
> > > > Hi all, I'm trying to start to debug some latency problems I'm having
> > > > with recent 2.6.x kernels that include Ingo's realtime preemption patch
> > > > (this is related to a still unfinished thread I started in the jack and
> > > > kernel mailing lists).
> > > >
> > > > I have observed some strange behavior that may be related to just jack.
> > >
> > > BTW, one more detail, as I outlined to Stephane off list I'm not hearing
> > > any dropouts in Jack's output. Plenty of warnings of excessive delay but
> > > no audible stuff (and the "delay" keeps going up and up and up).
> >
> >    I wonder if possibly you have any of this 'experimental' timer
> > stuff turned on.
>
> You mean the "High Resolution Timers"? I don't have that on.

Yes, I think that was what Lee was talking about.

>
> > I was thinking that maybe a timer is not being reset
> > and then each time this event occurs the time is read out getting
> > greater and greater.
>
> It sort of looks like that. I'll see what I can do to try to debug
> this.
>
> -- Fernando

Good luck.

Cheers,
Mark


-------------------------------------------------------
This SF.Net email is sponsored by:
Power Architecture Resource Center: Free content, downloads, discussions,
and more. http://solutions.newsforge.com/ibmarch.tmpl
_______________________________________________
Jackit-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/jackit-devel