negative timestamps on pcm?!?

negative timestamps on pcm?!?

[Steve deRosier]

All,

We've noticed a problem with the newest version of Alsa while doing some 
stress testing of our devices.  Basically, the scenerio is we're playing 
through a large library of .ogg files over the weekend.  When we checked 
on the progress upon getting in on Monday, we discovered that the PCM 
had ceased playing, and our ogg player had started a ton of instances 
(one for each song it was supposed to play) and couldn't play on any of 
them.  Looking at /proc/asound/card0/pcm0p/sub0/status:
# cat status
state: OPEN
trigger_time: 642.000000000
tstamp      : -1071072720.-1071072332
delay       : 498
avail       : -1072507698
avail_max   : -1071072720
-----
hw_ptr      : 26942906
appl_ptr    : 26942906

It seems that our ogg player is set to blocking behavior and each one is 
blocked on the call to open the pcm.  The intrieging thing is the 
timestamp is negative.  It jumped out that this just looks wrong!

Hypothesis 1:  After a really long time playing, the timestamp on the 
pcm wraps to negative.  alsa can't handle this and blocks on the output. 
  It's no longer running, but is still in an OPEN state so nothing else 
can open it.  alsa should either use an unsigned value so large that it 
is impossable to overflow (???), use an unsigned and detect overflow and 
handle it gracefully, or use a signed value and detect the overflow/wrap 
and handle it.
Hypothesis 2:  We're barking up the wrong tree and the only thing wrong 
is that the proc entry is formmated poorly.  (but even if that is the 
case, the problem still happens where after prolonged time alsa stops us).

This didn't happen with earlier versions of alsa using the same playing 
software.

I hope this helps the developers in tracking down any bugs.

Thanks,
- Steve



-------------------------------------------------------
This SF.net email is sponsored by OSDN developer relations
Here's your chance to show off your extensive product knowledge
We want to know what you know. Tell us and you have a chance to win $100
http://www.zoomerang.com/survey.zgi?HRPT1X3RYQNC5V4MLNSV3E54

Re: negative timestamps on pcm?!?

[Takashi Iwai]

At Mon, 20 Oct 2003 11:05:29 -0700,
Steve deRosier wrote:
> 
> All,
> 
> We've noticed a problem with the newest version of Alsa while doing some 
> stress testing of our devices.  Basically, the scenerio is we're playing 
> through a large library of .ogg files over the weekend.  When we checked 
> on the progress upon getting in on Monday, we discovered that the PCM 
> had ceased playing, and our ogg player had started a ton of instances 
> (one for each song it was supposed to play) and couldn't play on any of 
> them.  Looking at /proc/asound/card0/pcm0p/sub0/status:
> # cat status
> state: OPEN
> trigger_time: 642.000000000
> tstamp      : -1071072720.-1071072332
> delay       : 498
> avail       : -1072507698
> avail_max   : -1071072720

when the state is OPEN, these values are bogus, since snd_pcm_status()
returns immediately without putting the values.


> -----
> hw_ptr      : 26942906
> appl_ptr    : 26942906

they are real values.


i can't remember any reason of the restriction above.
i think it's ok to remove it.


> It seems that our ogg player is set to blocking behavior and each one is 
> blocked on the call to open the pcm.  The intrieging thing is the 
> timestamp is negative.  It jumped out that this just looks wrong!
> 
> Hypothesis 1:  After a really long time playing, the timestamp on the 
> pcm wraps to negative.  alsa can't handle this and blocks on the output. 
>   It's no longer running, but is still in an OPEN state so nothing else 
> can open it.  alsa should either use an unsigned value so large that it 
> is impossable to overflow (???), use an unsigned and detect overflow and 
> handle it gracefully, or use a signed value and detect the overflow/wrap 
> and handle it.
> Hypothesis 2:  We're barking up the wrong tree and the only thing wrong 
> is that the proc entry is formmated poorly.  (but even if that is the 
> case, the problem still happens where after prolonged time alsa stops us).

at least, the values above make no sense.

which version of ALSA driver are you using?


Takashi


-------------------------------------------------------
This SF.net email is sponsored by OSDN developer relations
Here's your chance to show off your extensive product knowledge
We want to know what you know. Tell us and you have a chance to win $100
http://www.zoomerang.com/survey.zgi?HRPT1X3RYQNC5V4MLNSV3E54

Re: negative timestamps on pcm?!?

[Steve deRosier]

> 
> when the state is OPEN, these values are bogus, since snd_pcm_status()
> returns immediately without putting the values.
> 

So, alsa writes bogus data to the proc entries?  Maybe it shouldn't 
write bad data, just leave the spots blank, initilize with 0's or 
something else?

>>-----
>>hw_ptr      : 26942906
>>appl_ptr    : 26942906
> 
> 
> they are real values.
> 
> 
> i can't remember any reason of the restriction above.
> i think it's ok to remove it.
> 

What restriction is that?

>>It seems that our ogg player is set to blocking behavior and each one is 
>>blocked on the call to open the pcm.  The intrieging thing is the 
>>timestamp is negative.  It jumped out that this just looks wrong!
>>
>>Hypothesis 1:  After a really long time playing, the timestamp on the 
>>pcm wraps to negative.  alsa can't handle this and blocks on the output. 
>>  It's no longer running, but is still in an OPEN state so nothing else 
>>can open it.  alsa should either use an unsigned value so large that it 
>>is impossable to overflow (???), use an unsigned and detect overflow and 
>>handle it gracefully, or use a signed value and detect the overflow/wrap 
>>and handle it.
>>Hypothesis 2:  We're barking up the wrong tree and the only thing wrong 
>>is that the proc entry is formmated poorly.  (but even if that is the 
>>case, the problem still happens where after prolonged time alsa stops us).
> 
> 
> at least, the values above make no sense.

Right, the values make no sense, but I think we've explained that away 
now.  So, what is causing alsa to eventually stop playing right?  Yes, 
that's not exactly a fair question... where should we start looking? 
Maybe a mutex, race condition, or an off-by-one error somewhere?

> 
> which version of ALSA driver are you using?
> 

Driver: 0.9.7c
Library: 0.9.7
(retrieved from the website just a few days ago)

Thanks,
- Steve



-------------------------------------------------------
This SF.net email is sponsored by OSDN developer relations
Here's your chance to show off your extensive product knowledge
We want to know what you know. Tell us and you have a chance to win $100
http://www.zoomerang.com/survey.zgi?HRPT1X3RYQNC5V4MLNSV3E54

Re: negative timestamps on pcm?!?

[Takashi Iwai]

At Tue, 21 Oct 2003 10:05:26 -0700,
Steve deRosier wrote:
> 
> > 
> > when the state is OPEN, these values are bogus, since snd_pcm_status()
> > returns immediately without putting the values.
> > 
> 
> So, alsa writes bogus data to the proc entries?  Maybe it shouldn't 
> write bad data, just leave the spots blank, initilize with 0's or 
> something else?

yes, it should be.

> 
> >>-----
> >>hw_ptr      : 26942906
> >>appl_ptr    : 26942906
> > 
> > 
> > they are real values.
> > 
> > 
> > i can't remember any reason of the restriction above.
> > i think it's ok to remove it.
> > 
> 
> What restriction is that?
 
i meant the check of pcm state in the proc read function.
(i.e. to show the bogus values in the OPEN state)

> >>It seems that our ogg player is set to blocking behavior and each one is 
> >>blocked on the call to open the pcm.  The intrieging thing is the 
> >>timestamp is negative.  It jumped out that this just looks wrong!
> >>
> >>Hypothesis 1:  After a really long time playing, the timestamp on the 
> >>pcm wraps to negative.  alsa can't handle this and blocks on the output. 
> >>  It's no longer running, but is still in an OPEN state so nothing else 
> >>can open it.  alsa should either use an unsigned value so large that it 
> >>is impossable to overflow (???), use an unsigned and detect overflow and 
> >>handle it gracefully, or use a signed value and detect the overflow/wrap 
> >>and handle it.
> >>Hypothesis 2:  We're barking up the wrong tree and the only thing wrong 
> >>is that the proc entry is formmated poorly.  (but even if that is the 
> >>case, the problem still happens where after prolonged time alsa stops us).
> > 
> > 
> > at least, the values above make no sense.
> 
> Right, the values make no sense, but I think we've explained that away 
> now.  So, what is causing alsa to eventually stop playing right?  Yes, 
> that's not exactly a fair question... where should we start looking? 
> Maybe a mutex, race condition, or an off-by-one error somewhere?

i thought it might be a mutex deadlock which was fixed in the recent
version, but obviously you're using the enough new one.

the fact that it's in OPEN state implies that you can at least open
this pcm device but it's not raised to the PREPARE state by some
reason.  at first, check the application at which point it's blocked.


Takashi


-------------------------------------------------------
This SF.net email is sponsored by OSDN developer relations
Here's your chance to show off your extensive product knowledge
We want to know what you know. Tell us and you have a chance to win $100
http://www.zoomerang.com/survey.zgi?HRPT1X3RYQNC5V4MLNSV3E54