Latency and timestamps

Latency and timestamps

[Claudio Matsuoka]

Hi,

I'm adding latency control to an application and didn't find much
documentation about the pcm status functions aside from a very brief
description and the latency.c example. What exactly are the "trigger
timestamp" and "now timestamp" returned by
snd_pcm_status_get_trigger_tstamp() and snd_pcm_status_get_tstamp()? I
collected both from my output pcm handle to find values (in
tv_sec.tv_usec format) such as

1195518180.938427 938427.557702
1195518180.938441 938441.557702
1195518181.300395 300395.557702
1195518181.300441 300441.557702

where the "trigger" tv_sec matches the "now" tv_usec, and the
"trigger" tv_usec varies in large steps. Also the example latency.c
says:

00703                 showinmax(in_max);
00704                 if (p_tstamp.tv_sec == p_tstamp.tv_sec &&
00705                     p_tstamp.tv_usec == c_tstamp.tv_usec)
00706                         printf("Hardware sync\n");
00707                 snd_pcm_drop(chandle);

In line 704, shouldn't it be p_tstamp.tv_sec == c_tstamp.tv_sec?

My final goal is to sync on-screen events with the sound output. I'd
like to do something like storing output metadata associated with a
certain timestamp and collecting it back based on the timestamp of the
currently playing pcm data (like the OSS sequencer echoback events),
is that possible, or is there a better way to do this?

Re: Latency and timestamps

[Takashi Iwai]

At Mon, 19 Nov 2007 22:46:31 -0200,
Claudio Matsuoka wrote:
> 
> Hi,
> 
> I'm adding latency control to an application and didn't find much
> documentation about the pcm status functions aside from a very brief
> description and the latency.c example. What exactly are the "trigger
> timestamp" and "now timestamp" returned by
> snd_pcm_status_get_trigger_tstamp() and snd_pcm_status_get_tstamp()?

The trigger_tstamp is the time-stamp at the last time the PCM status
change occured.  For example, when the PCM is really triggered to
start, or stopped, or XRUN, etc.  It won't be changed as long as the 
PCM status is kept.

OTOH, the tstamp is the current timestamp (now).  But, this value has
a slightly different meaning when tstamp_mode is set to
SND_PCM_TSTAMP_MMAP.  Then it keeps the timestamp of the last period
update time instead of the now.


Takashi

Re: Latency and timestamps

[Takashi Iwai]

At Wed, 21 Nov 2007 13:33:59 +0200,
Heikki Lindholm wrote:
> 
> Takashi Iwai kirjoitti:
> > At Mon, 19 Nov 2007 22:46:31 -0200,
> > Claudio Matsuoka wrote:
> >> Hi,
> >>
> >> I'm adding latency control to an application and didn't find much
> >> documentation about the pcm status functions aside from a very brief
> >> description and the latency.c example. What exactly are the "trigger
> >> timestamp" and "now timestamp" returned by
> >> snd_pcm_status_get_trigger_tstamp() and snd_pcm_status_get_tstamp()?
> > 
> > The trigger_tstamp is the time-stamp at the last time the PCM status
> > change occured.  For example, when the PCM is really triggered to
> > start, or stopped, or XRUN, etc.  It won't be changed as long as the 
> > PCM status is kept.
> > 
> > OTOH, the tstamp is the current timestamp (now).  But, this value has
> > a slightly different meaning when tstamp_mode is set to
> > SND_PCM_TSTAMP_MMAP.  Then it keeps the timestamp of the last period
> > update time instead of the now.
> 
> Good explanation. How about adding this to the API documentation, too? 
> Even a copy-paste of the above would be much much better than what's in 
> there now (basically repetitions of the already quite verbose function 
> names.)

As usual, a patch is always welcome ;)


Takashi

Re: Latency and timestamps

[Heikki Lindholm]

Takashi Iwai kirjoitti:
> At Mon, 19 Nov 2007 22:46:31 -0200,
> Claudio Matsuoka wrote:
>> Hi,
>>
>> I'm adding latency control to an application and didn't find much
>> documentation about the pcm status functions aside from a very brief
>> description and the latency.c example. What exactly are the "trigger
>> timestamp" and "now timestamp" returned by
>> snd_pcm_status_get_trigger_tstamp() and snd_pcm_status_get_tstamp()?
> 
> The trigger_tstamp is the time-stamp at the last time the PCM status
> change occured.  For example, when the PCM is really triggered to
> start, or stopped, or XRUN, etc.  It won't be changed as long as the 
> PCM status is kept.
> 
> OTOH, the tstamp is the current timestamp (now).  But, this value has
> a slightly different meaning when tstamp_mode is set to
> SND_PCM_TSTAMP_MMAP.  Then it keeps the timestamp of the last period
> update time instead of the now.

Good explanation. How about adding this to the API documentation, too? 
Even a copy-paste of the above would be much much better than what's in 
there now (basically repetitions of the already quite verbose function 
names.)

-- Heikki Lindholm

Re: Latency and timestamps

[Takashi Iwai]

At Wed, 21 Nov 2007 15:26:05 +0200,
Heikki Lindholm wrote:
> 
> Takashi Iwai kirjoitti:
> > At Mon, 19 Nov 2007 22:46:31 -0200,
> > Claudio Matsuoka wrote:
> >> Hi,
> >>
> >> I'm adding latency control to an application and didn't find much
> >> documentation about the pcm status functions aside from a very brief
> >> description and the latency.c example. What exactly are the "trigger
> >> timestamp" and "now timestamp" returned by
> >> snd_pcm_status_get_trigger_tstamp() and snd_pcm_status_get_tstamp()?
> > 
> > The trigger_tstamp is the time-stamp at the last time the PCM status
> > change occured.  For example, when the PCM is really triggered to
> > start, or stopped, or XRUN, etc.  It won't be changed as long as the 
> > PCM status is kept.
> > 
> > OTOH, the tstamp is the current timestamp (now).  But, this value has
> > a slightly different meaning when tstamp_mode is set to
> > SND_PCM_TSTAMP_MMAP.  Then it keeps the timestamp of the last period
> > update time instead of the now.
> 
> I looked at the code and I'm not sure I understand the above "last 
> period update time" correctly. I'd like to think that MMAP timestamp is 
> updated by the driver interrupt handler when a new period arrives _and 
> only there_, but the code seems somewhat different:
> - the timestamp is generated in snd_pcm_update_hw_ptr_pos
> - snd_pcm_update_hw_ptr_pos is called by snd_pcm_update_hw_ptr_interrupt
> - the driver interrupt updates the timestamp in snd_pcm_period_elapsed
> BUT if the user calls snd_pcm_status
> - snd_pcm_status calls snd_pcm_update_hw_ptr
> - snd_pcm_update_hw_ptr calls snd_pcm_update_hw_ptr_pos
> and therefore it seems that the timestamp is updated when calling 
> snd_pcm_status also, effectively making the timestamp a "now" timestamp 
> anyway.

Oh, yeah, it's broken.  I think the original design was supposed to
update the mmap update.  Let's fix this.


thanks,

Takashi

Re: Latency and timestamps

[Heikki Lindholm]

Takashi Iwai kirjoitti:
> At Mon, 19 Nov 2007 22:46:31 -0200,
> Claudio Matsuoka wrote:
>> Hi,
>>
>> I'm adding latency control to an application and didn't find much
>> documentation about the pcm status functions aside from a very brief
>> description and the latency.c example. What exactly are the "trigger
>> timestamp" and "now timestamp" returned by
>> snd_pcm_status_get_trigger_tstamp() and snd_pcm_status_get_tstamp()?
> 
> The trigger_tstamp is the time-stamp at the last time the PCM status
> change occured.  For example, when the PCM is really triggered to
> start, or stopped, or XRUN, etc.  It won't be changed as long as the 
> PCM status is kept.
> 
> OTOH, the tstamp is the current timestamp (now).  But, this value has
> a slightly different meaning when tstamp_mode is set to
> SND_PCM_TSTAMP_MMAP.  Then it keeps the timestamp of the last period
> update time instead of the now.

I looked at the code and I'm not sure I understand the above "last 
period update time" correctly. I'd like to think that MMAP timestamp is 
updated by the driver interrupt handler when a new period arrives _and 
only there_, but the code seems somewhat different:
- the timestamp is generated in snd_pcm_update_hw_ptr_pos
- snd_pcm_update_hw_ptr_pos is called by snd_pcm_update_hw_ptr_interrupt
- the driver interrupt updates the timestamp in snd_pcm_period_elapsed
BUT if the user calls snd_pcm_status
- snd_pcm_status calls snd_pcm_update_hw_ptr
- snd_pcm_update_hw_ptr calls snd_pcm_update_hw_ptr_pos
and therefore it seems that the timestamp is updated when calling 
snd_pcm_status also, effectively making the timestamp a "now" timestamp 
anyway.

-- Heikki Lindholm

Re: Latency and timestamps

[Takashi Iwai]

At Wed, 21 Nov 2007 14:11:37 +0100,
I wrote:
> 
> At Wed, 21 Nov 2007 15:26:05 +0200,
> Heikki Lindholm wrote:
> > 
> > Takashi Iwai kirjoitti:
> > > At Mon, 19 Nov 2007 22:46:31 -0200,
> > > Claudio Matsuoka wrote:
> > >> Hi,
> > >>
> > >> I'm adding latency control to an application and didn't find much
> > >> documentation about the pcm status functions aside from a very brief
> > >> description and the latency.c example. What exactly are the "trigger
> > >> timestamp" and "now timestamp" returned by
> > >> snd_pcm_status_get_trigger_tstamp() and snd_pcm_status_get_tstamp()?
> > > 
> > > The trigger_tstamp is the time-stamp at the last time the PCM status
> > > change occured.  For example, when the PCM is really triggered to
> > > start, or stopped, or XRUN, etc.  It won't be changed as long as the 
> > > PCM status is kept.
> > > 
> > > OTOH, the tstamp is the current timestamp (now).  But, this value has
> > > a slightly different meaning when tstamp_mode is set to
> > > SND_PCM_TSTAMP_MMAP.  Then it keeps the timestamp of the last period
> > > update time instead of the now.
> > 
> > I looked at the code and I'm not sure I understand the above "last 
> > period update time" correctly. I'd like to think that MMAP timestamp is 
> > updated by the driver interrupt handler when a new period arrives _and 
> > only there_, but the code seems somewhat different:
> > - the timestamp is generated in snd_pcm_update_hw_ptr_pos
> > - snd_pcm_update_hw_ptr_pos is called by snd_pcm_update_hw_ptr_interrupt
> > - the driver interrupt updates the timestamp in snd_pcm_period_elapsed
> > BUT if the user calls snd_pcm_status
> > - snd_pcm_status calls snd_pcm_update_hw_ptr
> > - snd_pcm_update_hw_ptr calls snd_pcm_update_hw_ptr_pos
> > and therefore it seems that the timestamp is updated when calling 
> > snd_pcm_status also, effectively making the timestamp a "now" timestamp 
> > anyway.
> 
> Oh, yeah, it's broken.  I think the original design was supposed to
> update the mmap update.  Let's fix this.

And here is the patch.


Takashi

diff -r a37346b0c0be core/pcm_lib.c
--- a/core/pcm_lib.c	Tue Nov 20 18:32:08 2007 +0100
+++ b/core/pcm_lib.c	Wed Nov 21 16:00:41 2007 +0100
@@ -148,8 +148,6 @@ static inline snd_pcm_uframes_t snd_pcm_
 	pos = substream->ops->pointer(substream);
 	if (pos == SNDRV_PCM_POS_XRUN)
 		return pos; /* XRUN */
-	if (runtime->tstamp_mode & SNDRV_PCM_TSTAMP_MMAP)
-		getnstimeofday((struct timespec *)&runtime->status->tstamp);
 #ifdef CONFIG_SND_DEBUG
 	if (pos >= runtime->buffer_size) {
 		snd_printk(KERN_ERR  "BUG: stream = %i, pos = 0x%lx, buffer size = 0x%lx, period size = 0x%lx\n", substream->stream, pos, runtime->buffer_size, runtime->period_size);
@@ -189,6 +187,8 @@ static inline int snd_pcm_update_hw_ptr_
 	snd_pcm_uframes_t new_hw_ptr, hw_ptr_interrupt;
 	snd_pcm_sframes_t delta;
 
+	if (runtime->tstamp_mode == SNDRV_PCM_TSTAMP_MMAP)
+		getnstimeofday((struct timespec *)&runtime->status->tstamp);
 	pos = snd_pcm_update_hw_ptr_pos(substream, runtime);
 	if (pos == SNDRV_PCM_POS_XRUN) {
 		xrun(substream);
diff -r a37346b0c0be core/pcm_native.c
--- a/core/pcm_native.c	Tue Nov 20 18:32:08 2007 +0100
+++ b/core/pcm_native.c	Wed Nov 21 16:00:41 2007 +0100
@@ -595,7 +595,7 @@ int snd_pcm_status(struct snd_pcm_substr
 	status->trigger_tstamp = runtime->trigger_tstamp;
 	if (snd_pcm_running(substream)) {
 		snd_pcm_update_hw_ptr(substream);
-		if (runtime->tstamp_mode & SNDRV_PCM_TSTAMP_MMAP)
+		if (runtime->tstamp_mode == SNDRV_PCM_TSTAMP_MMAP)
 			status->tstamp = runtime->status->tstamp;
 		else
 			getnstimeofday(&status->tstamp);