Actual latency is double what is requested (off by one in the prefs)

[mixxxbot]

Reported by: Pegasus-RPG
Date: 2011-11-01T11:25:04Z
Status: Fix Released
Importance: High
Launchpad Issue: lp884705
Tags: latency
Attachments: pa_alsa.patch, AudioBufferSize.patch

---

This only happens on my Linux system: Debian Squeeze AMD64, qt 4.6.3 as of 1.10 branch r2870.

When I choose a latency in the prefs, the actual latency PA reports is the next one up from what is selected, preventing me from choosing the lowest option. If I add at line 107 in sounddeviceportaudio.cpp:
m_framesPerBuffer = m_framesPerBuffer/2;
...then it works as expected.

Since that's obviously a hack, and I don't see the problem on my Windows machine, I leave it to those that know more to investigate further.

[mixxxbot]

Commented by: rryan
Date: 2011-11-01T12:29:59Z

---

Bill can you take a look?

[mixxxbot]

Commented by: rryan
Date: 2011-11-01T12:48:58Z

---

I think this is not a bug but more of a logging error. I just checked and at 1ms latency, 44.1kHz, the engine is receiving requests for 128 stereo samples at a time. 128 stereo samples = 64 frames = 64 frames / 44.1kHz = 1.45ms

[mixxxbot]

Commented by: rryan
Date: 2011-11-01T12:53:01Z

---

And here is a section from my log file. I build PortAudio with debug info on, so it spits out those extra lines in between. I'm not sure what is going on. I think that maybe our user buffer is set to 1.45 ms but maybe my soundcard is requiring at least 128 frames so the host buffer is 128 frames while my user buffer is 64.

Debug: [Main]: SoundDevicePortAudio::open() "0, HDA Intel: CONEXANT Analog (hw:0,0)" 
Debug: [Main]: Requested sample rate: 44100 
Debug: [Main]: framesPerBuffer: 64 
Debug: [Main]: Mixxx latency in milliseconds: 1.45125 
Debug: [Main]: output channels: 2 | input channels: 0 
Debug: [Main]: Opening stream with id 0 
AlsaOpen: Opening device hw:0,0
PaAlsaStreamComponent_InitialConfigure: device MMAP SND_PCM_ACCESS_MMAP_INTERLEAVED: YES
PaAlsaStreamComponent_InitialConfigure: device MMAP SND_PCM_ACCESS_MMAP_NONINTERLEAVED: NO
PaAlsaStreamComponent_InitialConfigure: device can MMAP: YES
PaAlsaStreamComponent_DetermineFramesPerBuffer: user-buffer (frames)           = 64
PaAlsaStreamComponent_DetermineFramesPerBuffer: user-buffer (sec)              = 0.001451
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested latency (sec)        = 0.001451
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested host buffer (frames) = 128
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested host buffer (sec)    = 0.002902
PaAlsaStreamComponent_DetermineFramesPerBuffer: periods min = 2, max = 32, req = 4 
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested host buffer period   = 64 
PaAlsaStreamComponent_DetermineFramesPerBuffer: device period minimum          = 16
PaAlsaStreamComponent_DetermineFramesPerBuffer: device period maximum          = 262144
PaAlsaStreamComponent_DetermineFramesPerBuffer: host buffer period             = 64
PaAlsaStreamComponent_DetermineFramesPerBuffer: host buffer period latency     = 0.001451
PaAlsaStream_Configure: Playback period size: 64, latency: 0.002902
OpenStream: Stream: framesPerBuffer = 64, maxFramesPerHostBuffer = 64, latency = i(0.000000)/o(0.002902), 
Debug: [Main]: Opened PortAudio stream successfully... starting 
Debug: [Main]: Dynamically loaded PortAudio library! 
PaUnixThread_New: Waited for 5.00679e-06 seconds for stream to start
Debug: [Main]: PortAudio: Started stream successfully 
Debug: [Main]: Actual sample rate:  44100 Hz, latency: 2.90249 ms 
Debug: [Main]: Using "HDA Intel: CONEXANT Analog (hw:0,0)" as output sound device clock reference 
Debug: [Main]: 1 output sound devices opened 
Debug: [Main]: 0 input sound devices opened 

[mixxxbot]

Commented by: rryan
Date: 2011-11-01T12:55:43Z

---

And here it is for 11ms selected in preferences.

Debug: [Main]: SoundDevicePortAudio::open() "0, HDA Intel: CONEXANT Analog (hw:0,0)" 
Debug: [Main]: Requested sample rate: 44100 
Debug: [Main]: framesPerBuffer: 512 
Debug: [Main]: Mixxx latency in milliseconds: 11.61 
Debug: [Main]: output channels: 2 | input channels: 0 
Debug: [Main]: Opening stream with id 0 
AlsaOpen: Opening device hw:0,0
PaAlsaStreamComponent_InitialConfigure: device MMAP SND_PCM_ACCESS_MMAP_INTERLEAVED: YES
PaAlsaStreamComponent_InitialConfigure: device MMAP SND_PCM_ACCESS_MMAP_NONINTERLEAVED: NO
PaAlsaStreamComponent_InitialConfigure: device can MMAP: YES
PaAlsaStreamComponent_DetermineFramesPerBuffer: user-buffer (frames)           = 512
PaAlsaStreamComponent_DetermineFramesPerBuffer: user-buffer (sec)              = 0.011610
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested latency (sec)        = 0.011610
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested host buffer (frames) = 1024
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested host buffer (sec)    = 0.023220
PaAlsaStreamComponent_DetermineFramesPerBuffer: periods min = 2, max = 32, req = 4 
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested host buffer period   = 512 
PaAlsaStreamComponent_DetermineFramesPerBuffer: device period minimum          = 16
PaAlsaStreamComponent_DetermineFramesPerBuffer: device period maximum          = 262144
PaAlsaStreamComponent_DetermineFramesPerBuffer: host buffer period             = 512
PaAlsaStreamComponent_DetermineFramesPerBuffer: host buffer period latency     = 0.011610
PaAlsaStream_Configure: Playback period size: 512, latency: 0.023220
OpenStream: Stream: framesPerBuffer = 512, maxFramesPerHostBuffer = 512, latency = i(0.000000)/o(0.023220), 
Debug: [Main]: Opened PortAudio stream successfully... starting 
Debug: [Main]: Dynamically loaded PortAudio library! 
PaUnixThread_New: Waited for 1.90735e-06 seconds for stream to start
Debug: [Main]: PortAudio: Started stream successfully 
Debug: [Main]: Actual sample rate:  44100 Hz, latency: 23.22 ms 
Debug: [Main]: Using "HDA Intel: CONEXANT Analog (hw:0,0)" as output sound device clock reference 
Debug: [Main]: 1 output sound devices opened 
Debug: [Main]: 0 input sound devices opened 

[mixxxbot]

Commented by: Pegasus-RPG
Date: 2011-11-01T14:43:39Z

---

Right:
"Debug: [Main]: framesPerBuffer: 64" but "PaAlsaStream_Configure: Playback period size: 64, latency: 0.002902"
and:
"Debug: [Main]: framesPerBuffer: 512" but "PaAlsaStream_Configure: Playback period size: 512, latency: 0.023220"

Are we getting our stereo and mono frame counts mixed up or is there something wrong with PortAudio?

[mixxxbot]

Commented by: rryan
Date: 2011-11-01T18:26:23Z

---

Sean reports that in Windows this behavior does not happen. Can somebody
confirm whether this happens in OSX?

On Tue, Nov 1, 2011 at 10:43 AM, Sean M. Pappalardo <
<email address hidden>> wrote:

Right:
"Debug: [Main]: framesPerBuffer: 64" but "PaAlsaStream_Configure: Playback
period size: 64, latency: 0.002902"
and:
"Debug: [Main]: framesPerBuffer: 512" but "PaAlsaStream_Configure:
Playback period size: 512, latency: 0.023220"

Are we getting our stereo and mono frame counts mixed up or is there
something wrong with PortAudio?

--
You received this bug notification because you are a member of Mixxx
Development Team, which is subscribed to Mixxx.
https://bugs.launchpad.net/bugs/884705

Title:
Actual latency is double what is requested (off by one in the prefs)

To manage notifications about this bug go to:
https://bugs.launchpad.net/mixxx/+bug/884705/+subscriptions

[mixxxbot]

Commented by: bkgood
Date: 2011-11-05T02:09:45Z

---

> "Debug: [Main]: framesPerBuffer: 64" but "PaAlsaStream_Configure: Playback period size: 64, latency: 0.002902"
and:
"Debug: [Main]: framesPerBuffer: 512" but "PaAlsaStream_Configure: Playback period size: 512, latency: 0.023220"

I'm not understanding the problem at this point. Does those lines not correspond to a selection of 2ms and 23ms (respectively) in the preferences?

[mixxxbot]

Commented by: bkgood
Date: 2011-11-05T02:10:00Z

---

*do those lines... ugh

[mixxxbot]

Commented by: daschuer
Date: 2012-08-01T07:15:43Z

---

I can find this in the log:

Requested sample rate: 44100 Hz, latency: 92.8798 ms
Actual sample rate: 44100 Hz, latency: 185.76 ms

"[Master], latency" is set to 185.76 ms

Latency in preferences is 92.9 ms

    const PaStreamInfo* streamDetails = Pa_GetStreamInfo(m_pStream);
streamDetails->outputLatency = 185.76 ms 
streamDetails->inputLatency = 0 ms;

Actual, Mixxx uses a buffer of 92.9 ms

The other latency values are also effected.

Currently "[Master], latency" is currently unused.
But I want to use it for calculate the current play position.
It looks like there is different behaviour in Linux and Windows.
Any Idea how to solve this issue?

[mixxxbot]

Commented by: Pegasus-RPG
Date: 2012-08-01T21:08:22Z

---

Bill: Yes, those values do not correspond:
64 frames at 44100kHz is 0.00145s latency (64/44100,) but PA reports double that in RJ's log. Same situation with 512 fames where it should be 0.01161s. So this looks like a PA problem to me, especially since it doesn't happen on Windows and we do nothing different in Mixxx code.

[mixxxbot]

Commented by: daschuer
Date: 2012-08-02T09:31:28Z

---

It looks like there is an PA bug somewhere in scr/hostapi/alsa/pa_linux_alsa.c line 1994 ff
Only the setting "Sound API" = ALSA is effected, OSS works as desired.

I will prepare a patch which solves the problem within Mixxx.
Solving it in PA will make things worth because we, don't know if it is solved in the user setup.

Has one connection to the PA team for clarification?

[mixxxbot]

Commented by: daschuer
Date: 2012-08-02T10:17:59Z
Attachments: pa_alsa.patch

---

here it is:

[mixxxbot]

Commented by: bkgood
Date: 2012-08-02T12:24:56Z

---

Line 1994 in PA trunk is a closing brace http://www.assembla.com/code/portaudio/subversion/nodes/portaudio/trunk/src/hostapi/alsa/pa_linux_alsa.c?rev=1858#ln1994 , can you find this issue in the current code?

I don't recall seeing this with ALSA on my Linux machine so doing a blanket division by 2 for all ALSA-users has a lot of collateral damage as presumably I'm not the only one. I've seen PortAudio do things similar to this in the past because it doesn't think it can open the device with those parameters, so it tries with less demanding values (iirc the pa docs say the latency parameters are only suggested values, with PA doing the best it can to match them).

[mixxxbot]

Commented by: daschuer
Date: 2012-08-02T13:34:48Z

---

Hi Bill,

I had a look in "portaudio19-19+svn20111121"
fetched by
apt-get source libportaudio2
on ubuntu precise 32bit.
I think the issue is somewhere in PaAlsaStreamComponent_FinishConfigure
http://www.assembla.com/code/portaudio/subversion/nodes/portaudio/trunk/src/hostapi/alsa/pa_linux_alsa.c?rev=1858#ln2038

To clarify the issue again:
PA manages to use exactly the "suggestedLatency" but simply reports the double value back.
With the current Mixxx nothing happens due to this issue because no one listens to "[Master], latency", except the wrong log entry: " Actual sample rate: 44100 Hz, latency: 185.76 ms"

My Ubuntu Lucid and my Ubuntu Precise are effected. Which ALSA Systems are not effected?

[mixxxbot]

Commented by: bkgood
Date: 2012-08-02T15:24:33Z

---

I use Arch with portaudio built from svn, and I don' t remember being able to reproduce this. But I misunderstood, I thought the stream was being opened with a higher-than-requested latency, which can be normal PA behaviour. If it's just a reporting error, I'm not that worried about it, so I withdraw my objection -- sorry for the confusion.

[mixxxbot]

Commented by: daschuer
Date: 2012-08-02T17:15:07Z

---

Bill, can you please have a look to your latest log file and report if Arch linux is affected as well?
If so, I think its safe to commit this patch.

[mixxxbot]

Commented by: Pegasus-RPG
Date: 2012-08-03T07:17:28Z

---

Please talk to the PA team (developers mailing list) as they are usually good about fixing things. Since this is just a reporting issue, I would also rather not blindly divide by two. Either leave it as-is or only divide by two if the PA version number is less than whatever one in which this gets fixed.
Make sure to link this bug to the one in PA's bug tracker.

[mixxxbot]

Commented by: daschuer
Date: 2012-08-05T22:02:25Z

---

Here is the thread on the Portaudio mailing list:
http://music.columbia.edu/pipermail/portaudio/2012-August/014313.html

[mixxxbot]

Commented by: daschuer
Date: 2012-08-08T12:49:13Z

---

Reading.
http://www.assembla.com/wiki/show/portaudio/BufferingLatencyAndTimingImplementationGuidelines
clarifies some points.

In "streamDetails->outputLatency", PA tries to report all latencies that are known. Unfortunately it does not only depend on the Sound API but also on the selected device. On my hardware PA reports 42 ms for ALSA + Intel sound card and 64 ms for ALSA + pulse, with the suggested Latency of 21 ms. In fact, the output latency is currently controlled by the buffer provided by Mixxx in this case.

So the patch from #⁠12 is not a solution.

A flexible solution would be to allow the user to set the Buffer and the latency independent and report the current Latency in the GUI. This will offer optimum flexibility but will clutter the GUI and opens an other window for miss configuration.

The best solution for me, will be to set the buffer size in ms by user preferences and request a minimum latency. In this case PA will adopt this minimum possible Latency with this buffer. In fact, nothing will change compared to the current behavior except the wording.
"Latency" -> "Audio Buffer Size"

Additional we could report the current Latency in the preferences see Bug #⁠884688.

What do you think?

[mixxxbot]

Commented by: daschuer
Date: 2012-08-08T12:54:50Z

---

Bug #⁠884694 confirms that it is fine to set the buffer size in preferences.

[mixxxbot]

Commented by: daschuer
Date: 2012-09-11T18:53:49Z
Attachments: AudioBufferSize.patch

---

The attached patch changes the latency configuration to audio buffer size configuration (like it actually already is).
Additional the known latency reported by PortAudio is displayed. (Solved Bug #⁠884688)

[mixxxbot]

Commented by: daschuer
Date: 2012-12-04T20:44:33Z

---

Is this a candidate for 1.11?

[mixxxbot]

Commented by: daschuer
Date: 2013-03-21T22:31:44Z

---

IMHO Mixxx 1.11.1 will only include band aid fixes.
So this will be part of Mixxx 1.12.
Committed to lp:mixxx revision 3334.

[mixxxbot]

Issue closed with status Fix Released.