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

[Sean M. Pappalardo]

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.

[RJ Skerry-Ryan (rryan)]

Bill can you take a look?

[RJ Skerry-Ryan (rryan)]

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

[RJ Skerry-Ryan (rryan)]

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

[RJ Skerry-Ryan (rryan)]

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

[Sean M. Pappalardo (pegasus-renegadetech)]

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?

[RJ Skerry-Ryan (rryan)]

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
>

[William Good (bkgood)]

> "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?

[William Good (bkgood)]

*do those lines... ugh

[Daniel Schürmann (daschuer)]

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?

[Sean M. Pappalardo (pegasus-renegadetech)]

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.

[Daniel Schürmann (daschuer)]

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?

[Daniel Schürmann (daschuer)]

here it is:

[William Good (bkgood)]

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).

[Daniel Schürmann (daschuer)]

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?

[William Good (bkgood)]

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.

[Daniel Schürmann (daschuer)]

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.

[Sean M. Pappalardo (pegasus-renegadetech)]

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.

[Daniel Schürmann (daschuer)]

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

[Daniel Schürmann (daschuer)]

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?

[Daniel Schürmann (daschuer)]

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

[Daniel Schürmann (daschuer)]

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)

[Daniel Schürmann (daschuer)]

Is this a candidate for 1.11?

[Daniel Schürmann (daschuer)]

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.

[Swiftb0y (swiftb0y)]

Mixxx now uses GitHub for bug tracking. This bug has been migrated to:
https://github.com/mixxxdj/mixxx/issues/6065