help isolating alsa driver issue : recording at 10x speed and breaking other software

[fenugrec]

Hi,

Describe the bug
Starting audacity puts my builtin audio card into a (so far unrecoverable) state where it records at roughly 1/10 normal speed, i.e. playing back the audio sounds 10x too fast. This happens regardless of sample rate & format I select.

I currently believe this is an alsa-lib bug , but I'm looking for ideas here to isolate the problem since I haven't found a way to reproduce the problem outside audacity, and unsure what it does differently than, say, arecord .

To Reproduce

1. reboot
2. Recording with arecord, parecord, or obs-studio works fine
3. start audacity
4. recording, in any software, is now broken. Even after exiting audacity.

Additional information (please complete the following information):

• most info is in a ticket I opened initially think the issue was with pulseaudio: https://gitlab.freedesktop.org/pulseaudio/pulseaudio/-/issues/1344
• arch linux + audacity 2.4.1
• alsa + pulseaudio , all defaults, no custom config; other software works fine
• soundcard : mobo builtin, card 1: Generic [HD-Audio Generic], device 0: ALC1220 Analog [ALC1220 Analog]

So, specifically, I'm looking for some or all of this info :

• how / where in the code does Audacity initialize sound hardware when the program is first started ?
• is there a way to reproduce that same initialization with e.g. arecord or some other simple method ?
• to get a debug trace, what should I be looking at ? A simple strace is not very helpful because of the tons of data it produces, since I don't know what to look for.

[LudoOSGS]

Hello everyone,

I have exactly the same problem (recording at one tenth of speed and replay at ten times the speed) here with audacity 2.4.2 on a Debian 11 machine ;
hardware: amd ryzen 3900x on an asus prime x570 pro, and apart from that:
~$ pacmd list cards | nc termbin.com 9999 https://termbin.com/7zk3
~$ pactl list sinks | nc termbin.com 9999 https://termbin.com/3sm8
~$ sudo dmidecode | nc termbin.com 9999 https://termbin.com/3inh
~$ cat /proc/asound/{devices,cards,modules,pcm} | nc termbin.com 9999 https://termbin.com/cekd
~$ sudo dmesg | grep snd | nc termbin.com 9999 https://termbin.com/l68t

I don't have arecord here but I could reproduce exactly the same behaviour with gnome-sound-record :
if I start this programme alone I can record normally; if I start audacity, it messes up everything, I can't record normally with audacity, and a subsequent start of gnome-sound-record has it affected by the same problem as audacity.

The help that I got directed me towards settings in pulseaudio: those demanded by audacity were said to be incompatible with those demanded by other programmes like gnome-sound-record. I'm still loking where I should start changing settings.

I'm ready to give any help in testing as required.

Cheers.

Ludo

[LudoOSGS]

Hi again,

I was looking as I previously wrote - and I seem to have found something:
I started audacity from inside a console with the command:
~$ pasuspender audacity
audacity opened after the console gave a series of information;
in audacity I chose new recording hardware and new playback hardware

(that previously didn't seem to help).
And there it went: I was able to record sound very normally.
I must soon try reproduce the whole procedure.

Cheers.

Ludo

[LudoOSGS]

Hello eveyone,

I found a solution:
I turn the computer on.
Running audacity from the command line, even without the "pasuspender" pre-command, everything goes perfectly well, I can record, after selecting my two recording and playback devices

(or they have remained selected since the previous run), at normal speed, and then play back at normal speed as well.
After that, with audacity still open, I can also play other sound files; I can also record with gnome-sound-recording.

However, if pavuctrl (Pulseaudio's volume control) is opened and running/pending, I find when I go back to audacity (still open), that I cannot make any microphone recordings; I get an error message from audacity: "Error opening recording device. Error code: -9985 Device unavailable."

As soon as I close pavuctrl, after some 5 seconds, it is possible to record on microphone again.

Launching audacity in graphic mode after this first command line manipulation, seems to bring a functional instance of the program, with which I can record.

It seems that I should not launch audacity in graphic mode for the first time with the shortcut in the application menu. The numbering of the devices turns out to be incompatible with the rest of the environment and recording does not work.

On the contrary, when audacity is launched in the command line console with the command "audacity", the numbering of the devices is correct (see futher above, 1st picture) and recording is possible.

This procedure was carried out twice in a row at two different moments today (i.e. four times) - I hope I didn't disregard any unfavorable outcomes... ;-) ...
(Edit : I don't think I did: I repeated today, 4/4/22, this same procedure, and it worked perfectly well.)

Next step: check the procedure for launching audacity in graphic mode and try to correct it if possible.

Best regards.

Ludo

[LudoOSGS]

Hi everyone,

Final word?
Well before I say it, perhaps I ought to have given more details about my machine...
A Debian 11 Bullseye with LXDE, on an Asus Prime X570 Pro with an AMD Ryzen 3900X CPU - I hope this is enough...

I found something unexpectedly ... weird? in the applications menu, sub-section "Sound and Video" where audacity's shortcut is placed, when I right-clicked on the audacity shortcut, and selected "Properties" and in the properties window, then "desktop entry": there stood a very surprising entry line: env UBUNTU_MENUPROXY=0 GDK_BACKEND=x11 audacity %F
I don't know what that ubuntu thingy is doing here, but I tend to believe there should be nothing else than just the plain word audacity, just as when I start the programme from the command line...

I hope this could help...

Cheers.

Ludo

[LWinterberg]

UBUNTU_MENUPROXY=0 means "don't use the Unity DE global menu but keep the menu in the window instead"
GDK_BACKEND=x11 means "when on wayland, use x11 for audacity"

(that said, I have no idea what's causing this bug or how to fix it)

[LudoOSGS]

Hi everyone,

After testing for a few days, I can confirm what I suspected and wrote in my previous message: a plain "audacity" command in the --> applications menu --> sub-section "Sound and Video" --> audacity shortcut (--> right click) --> "Properties" --> "desktop entry" instead of the "original" entry (see above) definitely does the job.
No need to complain anymore, all reasons to be satisfied: audacity just records the way you want it to do.

Best regards to all of you.

Ludo

[fenugrec]

No need to complain anymore, all reasons to be satisfied: audacity just records the way you want it to do.

Hi Ludo, I'm happy you found a workaround ( I haven't had time to try yet), but I disagree that this is "solved" . The fact that Audacity, with default settings, can put our audio devices in a broken (unrecoverable) state, should be investigated...

[LudoOSGS]

Hi fenugrec,

As far as I'm concerned:
A - the original entry line in the --> applications menu --> sub-section "Sound and Video" --> audacity shortcut (--> right click) --> "Properties" --> "desktop entry" was very much non-standard; if I check all other programmes in the sub-section "Sound and Video", none of them has such a weird formulation (I repeat: env UBUNTU_MENUPROXY=0 GDK_BACKEND=x11 audacity %F), they have at the most a "%F" or "%U" added to the name of the programme; but often the name of the programme alone is sufficient, sometimes the whole path is added... This simply looks like a ... not completely finished job!? Why, or because of what, this weird wording landed this way in my computer, I don't know. I even suspect this "env ... " prefix could simply be removed to leave the "audacity %F" remaining.
B- Nothing is broken on my system, since everything I previously used is now still working properly (including gnome-sound-recorder).

But I trust developers will know what to do there.

I hope you get the same satisfaction as I did by using this knowledge.

Cheers

Ludo

[MarcelHB]

Hi there,

So I have the same hardware, a Realtek ALC1220, and also observe that the volume indicator of the microphone in both pavucontrol and Audacity completely slows down and leads to some factor 10 of over-sampling: It takes 10 seconds of polling input to complete one second in Audacity.

And yes, even something as arecord is broken afterwards. What works is doing $ pasuspender audacity to both recover the audio state and to see how one can record something normally. The env settings are doing nothing here.

Interestingly, Firefox is unaffected even while the audio appears broken through ALSA. Not sure why, maybe because of JACK?. On the other hand, if pasuspender helps here, there trigger is probably on the way through Pulseaudio?

Next time I'm trying pipewire, I'll have a look at this again.

[fenugrec]

PS this is probably related to #659 which I hadn't noticied initially.

There's something about how Audacity opens / configures its sound layer that puts the device into an unrecoverable state, and this should really be investigated. It's been going on for years and isn't disappearing on its own.
In my case, once the driver is borked, running pasuspender audacity doesn't repair anything - it does allow me to record succesfully , bypassing pulse entirely, but all other software is still unusable until I reboot. Extremely annoying, needless to say.

So I would ask again - is there a way to log/record/trace whatever API calls audacity makes on startup ?
Seems like a necessary first step to get this fixed, regardless of who is "responsible" whether Audacity,ALSA,Pulse, or kernel driver. None of these projects will budge without an easily reproducible test. Otherwise we're stuck between Pulse devs saying "only happens with audacity ? it's their fault" and Audacity saying "nah that's a pulse / alsa bug, sorry good luck"

Between #2724, #659 and the comments here, I think we have enough independent reports to rule out user error, bad builds, and the usual low-hanging fruit.

[iam-TJ]

Relieved I found this report! I'm seeing the exact same issue as @LudoOSGS reports with almost the exact same hardware (Asus PRIME X370/PRO) and OS release (Debian 11 Bullseye).

And as various reports have mentioned, it also seems to affect arecord and aplay - I eventually figure out the 10x by using arecord and then using audacity to change the playback speed to 0.1x and found the result was almost correct.

I find interesting the suggestion that some configuration gets set incorrectly - that makes sense. With these pointers I'll dig in to the code and see what I can discover.

Seems like the first thing to try is a fresh start from power-off, no GUI, and just using arecord to determine if this is related to audacity or in the ALSA libraries.

[iam-TJ]

Cold power-off reboot with systemd.unit=multi-user.target then log-in as my regular user, tmux and then immediately use arecord and aplay several times. Successful recordings of 5 seconds duration from the line-in of the motherboard.

arecord -D default -v --duration=5 -V stereo -f dat /tmp/test.03.wav
aplay -v /tmp/test.03.wav

Start the display-manager and open the terminal emulator, tmux attach and then retest playback with aplay, and then do another recording with arecord -- all good.
Try a clean configuration of audacity:

mv .audacity-data{,.backup}
audacity /tmp/test.03.wav

Audacity plays the file correctly. Close. Re-open. Play. All good.
Close then:

arecord -D default -v --duration=5 -V stereo -f dat /tmp/test.04.wav

And instead of stopping after 5 seconds it takes approximately 50 seconds. The resulting recording plays for approximately 5 seconds but sounds to be speeded up massively.

Load it into audacity and it needs playing at 0.08x speed to get anything like the original - albeit sounds like its gone through a low-pass filter (muffled and head-in-bucket effect).

I tested logging out from GUI and using aplay in a virtual console but that still had the problem. I then tried removing and re-adding the PCI Audio device and that reset to the expected working behaviour for arecord and aplay:

echo 1 | sudo dd of=/sys/bus/pci/devices/0000\:0c\:00.4/remove
echo 1 | sudo dd of=/sys/bus/pci/devices/0000\:00\:08.1/rescan
lspci -nn -d ::0403                                                                                                                                                                        
0a:00.1 Audio device [0403]: Advanced Micro Devices, Inc. [AMD/ATI] Oland/Hainan/Cape Verde/Pitcairn HDMI Audio [Radeon HD 7000 Series] [1002:aab0]
0c:00.4 Audio device [0403]: Advanced Micro Devices, Inc. [AMD] Starship/Matisse HD Audio Controller [1022:1487]

So, this seems to happen just due to playing the file, not even accessing the input source, from audacity. The next test is to see if it happens without even loading a file or using sources or sinks. Yes, it does. Simply starting and then exiting audacity is enough to cause the next arecord to suffer the problem.

After that I can instrument audacity to determine what is going on.

[iam-TJ]

Working on the source-code now. First step is to examine any effect the Debian specific patches might have:

audacity/audacity-2.4.2~dfsg0$ cat debian/patches/series 
0001-Add-keywords-to-desktop-file.patch
0002-PATCH-Fix-building-against-the-system-portaudio-libr.patch
0003-cmake-relax-versions-for-mad-and-libid3tag.patch
0004-cmake-use-system-portaudio.patch
0005-Install-plugins-in-usr-lib.patch
0006-Fix_CVE-2020-11867.patch
0007-Playback_cursor_workaround.patch

Of those 0002-PATCH-Fix-building-against-the-system-portaudio-libr.patch looks most likely since it messes with a PortAudio time function:

From: Antonio Ospite <[email protected]>
Date: Tue, 7 Nov 2017 13:06:33 +0100
Subject: [PATCH] Fix building against the system portaudio library

Building against the system portaudio results in this error:

./src/AudioIO.cpp:983: undefined reference to `PaUtil_GetTime'
audacity-AudioIO.o: In function `audacityAudioCallback(void const*, void*,
unsigned long, PaStreamCallbackTimeInfo const*, unsigned long, void*)':
./src/AudioIO.cpp:4630: undefined reference to `PaUtil_GetTime'
collect2: error: ld returned 1 exit status
Makefile:2349: recipe for target 'audacity' failed
make[3]: *** [audacity] Error 1

This is because PaUtil_GetTime is declared as a C symbol in pa_util.h
but is resolved as a C++ symbol at link time.

Audacity fixes this in the local tree with this change:
https://github.com/audacity/audacity/commit/38fd97b8e26060332ab3e9e000a8882326a70ba7

However this is not general enough for the portaudio debian package.

Since PaUtil_GetTime() is the only function causing problems, just copy
over the code where it's used.

[Sebastian Ramacher]: Call clock_gettime directly.
---
 src/AudioIO.cpp | 10 +++++++++-
 1 file changed, 9 insertions(+), 1 deletion(-)

diff --git a/src/AudioIO.cpp b/src/AudioIO.cpp
index 0187e39..bfb0848 100644
--- a/src/AudioIO.cpp
+++ b/src/AudioIO.cpp
@@ -491,8 +491,16 @@ time warp info and AudioIOListener and whether the playback is looped.
    #define ROUND(x) (int) ((x)+0.5)
    //#include <string.h>
 //   #include "../lib-src/portmidi/pm_common/portmidi.h"
-   #include "../lib-src/portaudio-v19/src/common/pa_util.h"
    #include "NoteTrack.h"
+#include <time.h>
+
+PaTime PaUtil_GetTime( void )
+{
+    struct timespec tp;
+    clock_gettime(CLOCK_REALTIME, &tp);
+    return (PaTime)(tp.tv_sec + tp.tv_nsec * 1e-9);
+}
+
 #endif
 
 #ifdef EXPERIMENTAL_AUTOMATED_INPUT_LEVEL_ADJUSTMENT

So my next step is to try to build without this and the other PortAudio patch on Debian!

[iam-TJ]

Uploading audacity-debug.log…
Just tested building from HEAD (commit a4101ba 2023-04-12), removed and re-added the PCI audio device, did a test arecord that was good, started and terminated audacity builds/audacity/Debug/bin$ ./audacity |& tee /tmp/audacity-debug.log and then retested arecord and the problem recurs.

[iam-TJ]

Currently awaiting a reply to #4538

[iam-TJ]

PortAudio project has a recent discussion around using PaUtil_GetTime() that may be relevant -although usages of it seem to only be in MIDIPlay.cpp:

review PaUtil_GetTime usage #807

WaitCondition in JACK backend mixes up two clocks #795

[iam-TJ]

In trying to rule in or out PortAudio I looked for other applications that use it. In Debian I found sonic-visualiser which I used to view and play two of the recorded files - one bad, one good - then terminated it and tried arecord - the resulting recording was good. This tends to suggest PortAudio itself may not be the problem and we need to dig further.

[iam-TJ]

I disabled PulseAudio (systemctl --user stop pulseaudio.service pulseaudio.socket) and then started Audacity, configured the Audio devices with host ALSA, HDMI output, analogue line-in, and was able to record correctly. Then after terminating it I ran arecord and it worked correctly, using arecord -D hw:1,0 -v --duration=5 -V stereo -f dat /tmp/test.14.wav and played back using aplay -D hdmi:CARD=HDMI,DEV=0 -v /tmp/test.14.wav. Does this point to PulseAudio or possibly its interaction with PipeWire - which I notice is lurking in the background as well?

[iam-TJ]

Disabling pipewire with pulseaudio enabled the problem still occurs, both affecting arecord still using the direct hardware device (-D hw:1,0 ) and for audacity recording from pulse. This tends to point to some timebase within ALSA being affected, possibly at the kernel driver level.

[iam-TJ]

Separate note on how to edit and rebuild conan package source-code. For this example I'm adding a debug line to PortAudio's hostapi/alsa/pa_linux_alsa.c::PaAlsaStreamComponent_DetermineFramesPerBuffer().
There will always be 2 copies of the source code for each package conan is managing - the original, and a copy in the build directory. Here's a diff showing a new debug statement in the build directory:

builds/audacity/.conan/data/portaudio/19.7.0/_/_$ diff -u ./source/sources/src/hostapi/alsa/pa_linux_alsa.c ./build/3875a9b012c712dc0fb6aa2e879463bdf32ef4bd/sources/src/hostapi/alsa/pa_linux_alsa.c
--- ./source/sources/src/hostapi/alsa/pa_linux_alsa.c   2023-04-13 16:37:16.550103309 +0100
+++ ./build/3875a9b012c712dc0fb6aa2e879463bdf32ef4bd/sources/src/hostapi/alsa/pa_linux_alsa.c   2023-04-13 16:38:34.943364020 +0100
@@ -2275,6 +2275,7 @@
     bufferSize = PaAlsa_GetFramesPerHostBuffer(framesPerUserBuffer, params->suggestedLatency, sampleRate);
 
     /* Log */
+    PA_DEBUG(( "%s: sample-rate                    = %f\n",  __FUNCTION__, sampleRate ));
     PA_DEBUG(( "%s: user-buffer (frames)           = %lu\n", __FUNCTION__, framesPerUserBuffer ));
     PA_DEBUG(( "%s: user-buffer (sec)              = %f\n",  __FUNCTION__, (double)(framesPerUserBuffer / sampleRate) ));
     PA_DEBUG(( "%s: suggested latency (sec)        = %f\n",  __FUNCTION__, params->suggestedLatency ));

With that in place conan can do a rebuild. It has to be given both the source and build directories:

builds/audacity$ conan_venv/bin/conan build -bf ./.conan/data/portaudio/19.7.0/_/_/build/3875a9b012c712dc0fb6aa2e879463bdf32ef4bd/ -sf ./.conan/data/portaudio/19.7.0/_/_/build/3875a9b012c712dc0fb6aa2e879463bdf32ef4bd/   ./.conan/data/portaudio/19.7.0/_/_/export/conanfile.py

conanfile.py (portaudio/None): Calling build()
-- Conan: called by CMake conan helper               
-- Conan: Adjusting output directories
-- Conan: Using cmake global configuration          
-- Conan: Adjusting default RPATHs Conan policies
-- Conan: Adjusting language standard
-- Conan: Adjusting fPIC flag (ON)
-- Conan: Compiler GCC>=5, checking major version 10
-- Conan: Checking correct version: 10
-- Found OSS: 
        OSS_INCLUDE_DIR: /usr/include
-- Configuring done
-- Generating done
-- Build files have been written to: /srv/NAS/Sunny/SourceCode/builds/audacity/.conan/data/portaudio/19.7.0/_/_/build/3875a9b012c712dc0fb6aa2e87
9463bdf32ef4bd/build_folder
Consolidate compiler generated dependencies of target portaudio_static
[  5%] Building C object sources/CMakeFiles/portaudio_static.dir/src/hostapi/alsa/pa_linux_alsa.c.o
...
[ 11%] Linking C static library ../lib/libportaudio.a
[100%] Built target portaudio_static

TO BE CONTINUED (once I've solve it not rebuilding the shared library!)

[iam-TJ]

And here is the smoking gun! Using the pulse device sampleRate is 384000:

OpenStream: Stream: framesPerBuffer = 0, maxFramesPerHostBuffer = 1024, latency i=0.008000, o=0.008000                                [138/4839]
PaAlsaStreamComponent_Initialize: Host Chans C 1                                                                                                
AlsaOpen: Opening device pulse                                                                                                                  
PaAlsaStreamComponent_InitialConfigure: device MMAP SND_PCM_ACCESS_MMAP_INTERLEAVED: NO                                                         
PaAlsaStreamComponent_InitialConfigure: device MMAP SND_PCM_ACCESS_MMAP_NONINTERLEAVED: NO                                                      
PaAlsaStreamComponent_InitialConfigure: device can MMAP: NO                                                                                     
PaAlsaStreamComponent_DetermineFramesPerBuffer: sample-rate                    = 384000.000000                                                  
PaAlsaStreamComponent_DetermineFramesPerBuffer: user-buffer (frames)           = 0                                                              
PaAlsaStreamComponent_DetermineFramesPerBuffer: user-buffer (sec)              = 0.000000                                                       
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested latency (sec)        = 0.008707                                                       
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested host buffer (frames) = 3343                                                           
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested host buffer (sec)    = 0.008706                                                       
PaAlsaStreamComponent_DetermineFramesPerBuffer: periods min = 3, max = 1024, req = 4                                                            
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested host buffer period   = 835                                                            
PaAlsaStreamComponent_DetermineFramesPerBuffer: device period minimum          = 32                                                             
PaAlsaStreamComponent_DetermineFramesPerBuffer: device period maximum          = 349526                                                         
PaAlsaStreamComponent_DetermineFramesPerBuffer: host buffer period             = 835                                                            
PaAlsaStreamComponent_DetermineFramesPerBuffer: host buffer period latency     = 0.002174                                                       
PaAlsaStream_Configure: Capture period size: 835, latency: 0.008698                                                                             
OpenStream: Stream: framesPerBuffer = 0, maxFramesPerHostBuffer = 835, latency i=0.008698, o=0.000000                                           
PaAlsaStreamComponent_Initialize: Host Chans P 1                                                                                                
AlsaOpen: Opening device pulse                                                                                                                  
PaAlsaStreamComponent_InitialConfigure: device MMAP SND_PCM_ACCESS_MMAP_INTERLEAVED: NO                                                         
PaAlsaStreamComponent_InitialConfigure: device MMAP SND_PCM_ACCESS_MMAP_NONINTERLEAVED: NO                                                      
PaAlsaStreamComponent_InitialConfigure: device can MMAP: NO                                                                                     
PaAlsaStreamComponent_DetermineFramesPerBuffer: sample-rate                    = 384000.000000                                                  
PaAlsaStreamComponent_De384000.000000termineFramesPerBuffer: user-buffer (frames)           = 0
PaAlsaStreamComponent_DetermineFramesPerBuffer: user-buffer (sec)              = 0.000000
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested latency (sec)        = 0.008707
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested host buffer (frames) = 3343
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested host buffer (sec)    = 0.008706
PaAlsaStreamComponent_DetermineFramesPerBuffer: periods min = 3, max = 1024, req = 4 
PaAlsaStreamComponent_DetermineFramesPerBuffer: suggested host buffer period   = 835 
PaAlsaStreamComponent_DetermineFramesPerBuffer: device period minimum          = 32
PaAlsaStreamComponent_DetermineFramesPerBuffer: device period maximum          = 349526
PaAlsaStreamComponent_DetermineFramesPerBuffer: host buffer period             = 835
PaAlsaStreamComponent_DetermineFramesPerBuffer: host buffer period latency     = 0.002174
PaAlsaStream_Configure: Playback period size: 835, latency: 0.008698

[iam-TJ]

I don't want to get too focused on this since there is some additional scenario. Even with PulseAudio sampleRate 384000 arecord will behave correctly - which confused me until I realised that due to all the experiments the PulseAudio profile for the HD Audio device no longer had an input since it thought all the input jacks were unplugged and therefore unavailable.
For the HD Audio Controller the profile only had the output "Digital Stereo (IEC958) Output" so when arecord ran (selecting the 'default' device which is PulseAudio) it captured from a monitor input of one of the existing outputs.
When arecord terminated in around 4 seconds after Audacity had been started and the bug should be triggered, I realised that due to removing and readding the PCI device the jack sense hadn't detected the line-in was connected.
After an unplug/re-plug of the jack and ensuring PulseAudio's profile was "Digital Stereo (IEC958) Output + Analogue Stereo Input", and that the Input Device port is "Line In (plugged in)" I re-ran the tests and after Audacity started the bug is triggered with arecord taking 24 seconds to complete.

What this appears to tell us is that this is specific to using sampleRate or self->framesPerPeriod inadvertently somewhere else with real hardware.

I guess when the input (capture source) was a monitor which is created and provided by PulseAudio itself the 384000 value was not a problem.

With a little lateral thinking I finally found the culprit!

$ pacmd info | grep 384
                device.buffering.buffer_size = "384000"
                device.buffering.buffer_size = "384000"
                device.buffering.buffer_size = "384000"

Looking at the info output in its entirety I found that the buffer_size is attached to any of the sink outputs - the HD Audio, HDMI, and a Simultaneous virtual output I have enabled.

So it seems in PortAudio in hostapi/alsa/pa_linux_alsa.c::PaError PaAlsaStream_Configure() there is some munging of the passed-in sampleRate via realSr which is the actual value passed in the subsequent calls to PaStream_DetermineFramesPerBuffer() which in turn calls PaStreamComponent_DetermineFramesPerBuffer() but this isn't the source of the bug.

Right back in Audacity I think this happens due to libraries/lib-audio-io/AudioIO.cpp:

bool AudioIO::StartPortAudioStream(const AudioIOStartStreamOptions &options,
                                   unsigned int numPlaybackChannels,
                                   unsigned int numCaptureChannels,
                                   sampleFormat captureFormat)
{
   auto sampleRate = options.rate;
...
   // pick a rate to do the audio I/O at, from those available. The project
   // rate is suggested, but we may get something else if it isn't supported
   mRate = GetBestRate(numCaptureChannels > 0, numPlaybackChannels > 0, sampleRate);

...
      mLastPaError = Pa_OpenStream( &mPortStreamV19,
                                    useCapture ? &captureParameters : NULL,
                                    usePlayback ? &playbackParameters : NULL,
                                    mRate, paFramesPerBufferUnspecified,
                                    paNoFlag,
                                    audacityAudioCallback, lpUserData );

So mRate is a result of a call to ``GetBestRate()` :

double AudioIO::GetBestRate(bool capturing, bool playing, double sampleRate)
{
   // Check if we can use the cached value
   if (mCachedBestRateIn != 0.0 && mCachedBestRateIn == sampleRate
      && mCachedBestRatePlaying == playing && mCachedBestRateCapturing == capturing) {
      return mCachedBestRateOut;
   }

   // In order to cache the value, all early returns should instead set retval
   // and jump to finished
   double retval;

   std::vector<long> rates;
   if (capturing) wxLogDebug(wxT("AudioIO::GetBestRate() for capture"));
   if (playing) wxLogDebug(wxT("AudioIO::GetBestRate() for playback"));
   wxLogDebug(wxT("GetBestRate() suggested rate %.0lf Hz"), sampleRate);

   if (capturing && !playing) {
      rates = GetSupportedCaptureRates(-1, sampleRate);
   }
   else if (playing && !capturing) {
      rates = GetSupportedPlaybackRates(-1, sampleRate);
   }
   else {   // we assume capturing and playing - the alternative would be a
            // bit odd
      rates = GetSupportedSampleRates(-1, -1, sampleRate);
   }

So when both capturing and playing it calls libraries/lib-audio-devices/AudioIOBase.cpp::AudioIOBase::GetSupportedSampleRates()

std::vector<long> AudioIOBase::GetSupportedSampleRates(
   int playDevice, int recDevice, double rate)
{
...
   // Check if we can use the cached rates
   if (mCachedPlaybackIndex != -1 && mCachedCaptureIndex != -1 &&
         playDevice == mCachedPlaybackIndex &&
         recDevice == mCachedCaptureIndex &&
         (rate == 0.0 || make_iterator_range(mCachedSampleRates).contains(rate)))
   {
      return mCachedSampleRates;
   }

   auto playback = GetSupportedPlaybackRates(playDevice, rate);
   auto capture = GetSupportedCaptureRates(recDevice, rate);
   int i;

   // Return only sample rates which are in both arrays
   std::vector<long> result;

   for (i = 0; i < (int)playback.size(); i++)
      if (make_iterator_range(capture).contains(playback[i]))
         result.push_back(playback[i]);
...
   return result;
}

But since PulseAudio told PortAudio that both output and input device do 384000 that value will be selected even though we know the hardware's maxium is 48000:

$ cat /proc/asound/card1/pcm0c/sub0/hw_params 
access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 48000 (48000/1)
period_size: 48000
buffer_size: 96000

[iam-TJ]

After a day of diversions trying to master conan I've done some further debug logging; this time from libraries/lib-audio-io/ and lib-audio-devices/ to ensure we know the devices and sample rates Audacity gets to see. The listed rates are reported from AudioIOBase::GetSupportedSampleRates() which reports rates that exist both for playback and capture:

18:34:04: Debug: PlayDev 'pulse' index: 9
18:34:04: Debug: RecDev 'pulse' index: 9
18:34:05: Debug: Supported sample rate: 8000
18:34:05: Debug: Supported sample rate: 9600
18:34:05: Debug: Supported sample rate: 11025
18:34:05: Debug: Supported sample rate: 12000
18:34:05: Debug: Supported sample rate: 15000
18:34:05: Debug: Supported sample rate: 16000
18:34:05: Debug: Supported sample rate: 22050
18:34:05: Debug: Supported sample rate: 24000
18:34:05: Debug: Supported sample rate: 32000
18:34:05: Debug: Supported sample rate: 44100
18:34:05: Debug: Supported sample rate: 48000
18:34:05: Debug: Supported sample rate: 88200
18:34:05: Debug: Supported sample rate: 96000
18:34:05: Debug: Supported sample rate: 176400
18:34:05: Debug: Supported sample rate: 192000
18:34:05: Debug: Supported sample rate: 352800
18:34:05: Debug: Supported sample rate: 384000
18:34:07: Debug: PlayDev 'pulse' index: 9
18:34:07: Debug: RecDev 'pulse' index: 9
18:34:08: Debug: PortAudio stream error creating device list: ALSA:HD-Audio Generic: ALC1220 Analog (hw:1,0): Device unavailable

So that confirms my hypothesis that when using PulseAudio backend PortAudio gets synthesised sample rates, not device specific.

What I do not understand is how this appeared to work correctly when run under gdb! I need to retry that several times to convince myself.

I'm not really sure how you'd cope with this when 'pulse' is the default. Maybe PortAudio has a way to coerce digging for the underlying hardware rates, but that doesn't help in preventing PortAudio seemingly affecting the hardware device sample rate.

I'm wondering if this a subtle bug in PortAudio whereby when the client (in this case Audacity) requests a specific sample rate (in this case 384000) PortAudio probes all devices, not just the default ("pulse") and uses the requested sample rate (384000) in the probe of the hardware regardless of what the hardware's maximum supported rate might be.

[iam-TJ]

Just noticed PortAudio has a pull request for implementing a PulseAudio Host API! PortAudio/portaudio#336

There are also several issues that might be relevant but from the look of things development progress in PortAudio is extremely slow - like years!

PortAudio/portaudio#677
PortAudio/portaudio#272
PortAudio/portaudio#225

[iam-TJ]

Back to analysing the PortAudio code, and I think I see where the issue is. From an earlier log with PA_ENABLE_DEBUG_OUTPUT I see:

GropeDevice: collecting info ..
Default output device: HDA ATI HDMI: 1 (hw:0,7)
FillInDevInfo: Adding device HDA ATI HDMI: 1 (hw:0,7): 0
FillInDevInfo: Filling device info for: HDA ATI HDMI: 2 (hw:0,8)
GropeDevice: collecting info ..
FillInDevInfo: Adding device HDA ATI HDMI: 2 (hw:0,8): 1
FillInDevInfo: Filling device info for: HDA ATI HDMI: 3 (hw:0,9)
GropeDevice: collecting info ..
FillInDevInfo: Adding device HDA ATI HDMI: 3 (hw:0,9): 2
FillInDevInfo: Filling device info for: HDA ATI HDMI: 4 (hw:0,10)
GropeDevice: collecting info ..
FillInDevInfo: Adding device HDA ATI HDMI: 4 (hw:0,10): 3
FillInDevInfo: Filling device info for: HDA ATI HDMI: 5 (hw:0,11)
GropeDevice: collecting info ..
FillInDevInfo: Adding device HDA ATI HDMI: 5 (hw:0,11): 4
FillInDevInfo: Filling device info for: HD-Audio Generic: ALC1220 Analog (hw:1,0)
OpenPcm: Failed to open busy device 'hw:1,0'
GropeDevice: collecting info ..
FillInDevInfo: Adding device HD-Audio Generic: ALC1220 Analog (hw:1,0): 5
FillInDevInfo: Filling device info for: HD-Audio Generic: ALC1220 Digital (hw:1,1)
OpenPcm: Failed to open busy device 'hw:1,1'
FillInDevInfo: Skipped device: HD-Audio Generic: ALC1220 Digital (hw:1,1), all channels == 0
FillInDevInfo: Filling device info for: HD-Audio Generic: ALC1220 Alt Analog (hw:1,2)
GropeDevice: collecting info ..
Default input device: HD-Audio Generic: ALC1220 Alt Analog (hw:1,2)
FillInDevInfo: Adding device HD-Audio Generic: ALC1220 Alt Analog (hw:1,2): 6
FillInDevInfo: Filling device info for: sysdefault

This is reported from hostapi/alsa/pa_linux_alsa.c:

/** Determine max channels and default latencies.
 *
 * This function provides functionality to grope an opened (might be opened for capture or playback) pcm device for
 * traits like max channels, suitable default latencies and default sample rate. Upon error, max channels is set to zero,
 * and a suitable result returned. The device is closed before returning.
 */
static PaError GropeDevice( snd_pcm_t* pcm, int isPlug, StreamDirection mode, int openBlocking,
        PaAlsaDeviceInfo* devInfo )
{
    PaError result = paNoError;
    snd_pcm_hw_params_t *hwParams;
    snd_pcm_uframes_t alsaBufferFrames, alsaPeriodFrames;
    unsigned int minChans, maxChans;
    int* minChannels, * maxChannels;
    double * defaultLowLatency, * defaultHighLatency, * defaultSampleRate =
        &devInfo->baseDeviceInfo.defaultSampleRate;
    double defaultSr = *defaultSampleRate;

    assert( pcm );

    PA_DEBUG(( "%s: collecting info ..\n", __FUNCTION__ ));
...
    if( defaultSr >= 0 )
    {
        /* Could be that the device opened in one mode supports samplerates that the other mode wont have,
         * so try again .. */
        if( SetApproximateSampleRate( pcm, hwParams, defaultSr ) < 0 )

And then we have:

/* Set the stream sample rate to a nominal value requested; allow only a defined tolerance range */
static int SetApproximateSampleRate( snd_pcm_t *pcm, snd_pcm_hw_params_t *hwParams, double sampleRate )
{
    PaError result = paNoError;
    unsigned int reqRate, setRate, deviation;

    assert( pcm && hwParams );

    /* The Alsa sample rate is set by integer value; also the actual rate may differ */
    reqRate = setRate = (unsigned int) sampleRate;

    ENSURE_( alsa_snd_pcm_hw_params_set_rate_near( pcm, hwParams, &setRate, NULL ), paUnanticipatedHostError );
    /* The value actually set will be put in 'setRate' (may be way off); check the deviation as a proportion
     * of the requested-rate with reference to the max-deviate-ratio (larger values allow less deviation) */
    deviation = abs( (int)setRate - (int)reqRate );
    if( deviation > 0 && deviation * RATE_MAX_DEVIATE_RATIO > reqRate )
        result = paInvalidSampleRate;

end:
    return result;

error:
    /* Log */
    {
        unsigned int _min = 0, _max = 0;
        int _dir = 0;
        ENSURE_( alsa_snd_pcm_hw_params_get_rate_min( hwParams, &_min, &_dir ), paUnanticipatedHostError );
        _dir = 0;
        ENSURE_( alsa_snd_pcm_hw_params_get_rate_max( hwParams, &_max, &_dir ), paUnanticipatedHostError );
        PA_DEBUG(( "%s: SR min = %u, max = %u, req = %u\n", __FUNCTION__, _min, _max, reqRate ));
    }
    goto end;
}

So it seems to do what I thought ... iterates over all the devices and writes the requested rate to the device using alsa_snd_pcm_hw_params_set_rate_near( pcm, hwParams, &setRate, NULL ) without checking what that device can support. This would seem to be the bug.

Thoughts?

[iam-TJ]

I should note here that this is triggered by something that Audacity does that most other applications that use PortAudio don't do - I'm trying to find other such packages on Debian that might trigger the same issues but failed so far. That would indicate that something Audacity does after the call to Pa_Initialize() is triggering this. Add that to the apparent timing/race-condition possibility and identifying the trigger becomes challenging.

[crsib]

I think you have observed that Audacity has very few interactions with PortAudio. As I have mentioned previously in this discussion and in the comment in the source code - fewer than we need to fix some stuttering issues on Linux. We only call PA from the UI thread.

We only request the supported sample rates and open the device with one of the rates and a user configured latency. There could be bugs in getting sample rates on our side, as well as in PortAudio, but I expect that ALSA should reject unsupported configurations, rather than breaking the user environment. This bugs should be fixed for sure if they are present. I don't see a reason to resample project to 384k if the native project rate is supported by the hardware.

This bug seems to be very distro and hardware specific, I was never able to reproduce it locally. Likely it is a bug with ALSA, or PulseAudio, or the drivers themselves. Figuring the pitfall is still important, so when we reduce our reliance on PortAudio we can avoid it in the implementation. Probably even using native implementations for PulseAudio and PipeWire would solve a lot of issues for us.

[iam-TJ]

I thought to try and reproduce the bug manually using arecord to force the wrong sample rate but ALSA behaves properly and selects the best rate available - so there is something very strange going on with Audacity/PortAudio!

$ time arecord -D pulse -d 2 -c 2 -f S16_LE -r 384000 --dump-hw-params /dev/null                                                                                                                          
Recording WAVE '/dev/null' : Signed 16 bit Little Endian, Rate 384000 Hz, Stereo                                               
HW Params of device "pulse":                                                                                                   
--------------------                                                                                                           
ACCESS:  RW_INTERLEAVED                                                                                                        
FORMAT:  U8 S16_LE S16_BE S24_LE S24_BE S32_LE S32_BE FLOAT_LE FLOAT_BE MU_LAW A_LAW S24_3LE S24_3BE                           
SUBFORMAT:  STD                                                                                                                
SAMPLE_BITS: [8 32]                                                                                                            
FRAME_BITS: [8 1024]                                                                                                           
CHANNELS: [1 32]                                                                                                               
RATE: [1 384000]                                                                                                               
PERIOD_TIME: (2 4294967295)                                                                                                    
PERIOD_SIZE: [1 1398102)
PERIOD_BYTES: [128 1398102)
PERIODS: [3 1024]
BUFFER_TIME: (7 4294967295]
BUFFER_SIZE: [3 4194304]
BUFFER_BYTES: [384 4194304]
TICK_TIME: ALL
--------------------

real    0m2.120s
user    0m0.004s
sys     0m0.008s

$ time arecord -D hw:1,0 -d 2 -c 2 -f S16_LE -r 384000 --dump-hw-params /dev/null
Recording WAVE '/dev/null' : Signed 16 bit Little Endian, Rate 384000 Hz, Stereo
HW Params of device "hw:1,0":
--------------------
ACCESS:  MMAP_INTERLEAVED RW_INTERLEAVED
FORMAT:  S16_LE S32_LE
SUBFORMAT:  STD
SAMPLE_BITS: [16 32]
FRAME_BITS: [32 64]
CHANNELS: 2
RATE: [44100 192000]
PERIOD_TIME: (83 11888617)
PERIOD_SIZE: [16 524288]
PERIOD_BYTES: [128 2097152]
PERIODS: [2 32]
BUFFER_TIME: (166 23777234)
BUFFER_SIZE: [32 1048576]
BUFFER_BYTES: [128 4194304]
TICK_TIME: ALL
--------------------
Warning: rate is not accurate (requested = 384000Hz, got = 192000Hz)
         please, try the plug plugin 

real    0m4.010s
user    0m0.003s
sys     0m0.006s

HOWEVER, notice how long the last recording took - twice as long as requested (4 seconds instead of 2) presumably because the sample rate actually used was half of what was requested. Indirectly that tells us there's a subtle bug in arecord too - it calculates duration in terms of a sample count and does not take account of the real sample rate used!

[iam-TJ]

I've published a PR for the arecord bug alsa-project/alsa-utils#200 - note this is NOT the cause of the Audacity issue.

[iam-TJ]

I've confirmed that when stepping into the process with gdb I cannot trigger the bug. In these circumstances it really needs some insight from an Audacity developer that understands the audio threading model especially during init, before entering the main loop.
It triggers even if I use tasksel 0x01 ./Debug/bin/audacity which seems to rule out this being SMP/SMT related.

[fenugrec]

@iam-TJ , I've been reading your progress with much interest. Great work and thanks for the updates !

when stepping into the process with gdb I cannot trigger the bug.

Have you looked at rr (https://rr-project.org/) ? I think it could help trace the possible race condition, now that you have a very good idea of what to look at.

[iam-TJ]

Bah! just realised rr won't work since there is no internal program state to debug - the effect is external.

And also, just realised I can no longer reproduce the bug at all!! (Not even executing Audacity on its own)

[fenugrec]

Bah! just realised rr won't work since there is no internal program state to debug - the effect is external.

Weren't you able to singlestep into portaudio code already ? What would prevent you from stepping into library calls etc ?

I think it would be worth a try - just replay a trace and if the bug is reproducible, then you can eventually converge on when it happens exactly. Unless I'm misunderstanding something.

[iam-TJ]

Did a complete power-off restart. Tried rr again, cannot trigger the bug. Can trigger the bug executing ./Debug/bin/audacity on its own. This makes sense if this is a thread sync issue since rr slows things down considerably whilst recording.

[fenugrec]

ah, too bad...

[iam-TJ]

Also cannot rr replay - it hits an internal rr crash at some point.

{
  real_time:144.717289 global_time:8970, event:`SYSCALL: brk' (state:ENTERING_SYSCALL) tid:4903, ticks:289728555
rax:0xffffffffffffffda rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x1030 rsi:0x21000 rdi:0x564a4e664000 rbp:0xc rsp:0x681ffe20 r8:0x3 r9:0x7f2a0dd37be0 r10:0x1030 r11:0x246 r12:0x564a4e643000 r13:0xfffffffffffff000 r14:0x564a4e642670 r15:0x1030 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xc fs_base:0x7f2a0c541ec0 gs_base:0x0
}
{
  real_time:144.717293 global_time:8971, event:`SYSCALLBUF_RESET' tid:4903, ticks:289728555
}
=== Start rr backtrace:
rr(_ZN2rr13dump_rr_stackEv+0x41)[0x557f6e937c91]
rr(_ZN2rr9GdbServer15emergency_debugEPNS_4TaskE+0x265)[0x557f6e829705]
rr(_ZN2rr21EmergencyDebugOstreamD2Ev+0x292)[0x557f6e837e32]
rr(_ZN2rr13ReplaySession23check_ticks_consistencyEPNS_10ReplayTaskERKNS_5EventE+0xae)[0x557f6e8c2fee]
rr(_ZN2rr13ReplaySession11replay_stepERKNS0_15StepConstraintsE+0xb42)[0x557f6e8cae02]
rr(_ZN2rr14ReplayTimeline19replay_step_forwardENS_10RunCommandEl+0xdc)[0x557f6e8e386c]
rr(_ZN2rr9GdbServer14debug_one_stepERNS_10GdbRequestE+0x68d)[0x557f6e8281ed]
rr(_ZN2rr9GdbServer12serve_replayERKNS0_15ConnectionFlagsE+0x7b3)[0x557f6e8291e3]
rr(+0x14a3cf)[0x557f6e8bf3cf]
rr(_ZN2rr13ReplayCommand3runERSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS7_EE+0x4c5)[0x557f6e8c04c5]
rr(main+0x166)[0x557f6e7cdf86]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xea)[0x7f856bc7bd0a]
rr(_start+0x2a)[0x557f6e7ce0da]
=== End rr backtrace

[iam-TJ]

Suddenly recalled that valgrind has thread race detectors. Logs show several potential problems. I used Helgrind and DRD. Logs attached.
audacity-helgrind.03.log
audacity-drd.03.log

[iam-TJ]

Here's a much more comprehensive Helgrind. These files get large so this is compressed with gzip (2.2MB > 61KB). There's a summary at the end of the file of all the errors in the form of the stack-traces each titled "X errors in context Y of Z:". The summary reports ERROR SUMMARY: 1568 errors from 136 contexts (suppressed: 14702 from 266)

I've also got the xtree callgrind dump (22MB) that can be viewed with the GUI tool kcachegrind. which I can provide via my server on request.

Dumps were generated with this command line:

valgrind --tool=helgrind \
         --trace-children=yes \
         --read-var-info=yes \
         --fullpath-after=audacity/ \
         --read-inline-info=yes \
         --sim-hints=no-nptl-pthread-stackcache \
         --progress-interval=2 \
         --free-is-write=yes \
         --xtree-memory=full \
         --show-error-list=yes \
         --log-file=/tmp/audacity-helgrind.07.log \
       Debug/bin/audacity

audacity-helgrind.07.log.gz

[iam-TJ]

The Helgrind logs seem to indicate that all the early rush of ~ 70 threads is triggered by PortAudio or ALSA when probing devices. PortAudio probes for Jack and ALSA, and we know that PortAudio's hostapi ALSA probes both the direct hardware and pulse device and Pulseaudio presumably probes the underlying hardware devices itself via ALSA.

In that case when running at full speed I wonder if both ALSA and Pulseaudio are both using the same ALSA functions at the same time to access the same hardware device - neither would be aware of the other and those functions may not be thread-safe.

If they try to determine supported sample rates by actually setting it and trying to open the stream then overlap between them might explain the symptoms we see. After all, we have shown that if Pulseaudio is disabled the issue doesn't happen.

In my next session I'm going to look at PortAudio to see if it is responsible for creation of those ~ 70 threads during initialisation. If it is, then an obvious fix would be to serialise the ALSA and pulse devices so no overlap can occur.

And PortAudio seems to confirm this could be it:

https://github.com/PortAudio/portaudio/wiki/Tips_Threading

PortAudio/portaudio#808

PortAudio/portaudio#809

[iam-TJ]

I take that back - it is PulseAudio creating all those threads as far as I can tell from doing another Helgrind run with Pulseaudio disabled.

With Pulse: ERROR SUMMARY: 1568 errors from 136 contexts (suppressed: 14702 from 266)
Without: ERROR SUMMARY: 38 errors from 16 contexts (suppressed: 520 from 253)

Many of those 38 errors are related to libjack and libsqlite

This will save me doing a fruitless search in PortAudio. My hypothesis that ALSA-native and Pulse device probing are clashing due to not being serialised still holds.

However, this evidence gives me confidence to build Pulseaudio with additional debugging and code as well as exploring how to get PortAudio to serialise device probing.

audacity-helgrind.08.log.gz

[iam-TJ]

Enabling verbose debugging for Pulseaudio's user service:

systemctl --user edit pulseaudio.service

Now add the following overrides. When saved it will be written as a "drop-in" (fragment) to the path shown:

# /home/$USER/.config/systemd/user/pulseaudio.service.d/override.conf
[Service]
Environment=LIBASOUND_DEBUG=2
ExecStart=
ExecStart=/usr/bin/pulseaudio --daemonize=no --log-target=journal --log-level=4 --log-meta=1 --log-time=1

Then to restart and monitor the logging:

systemctl --user restart pulseaudio.service
journalctl --user --follow  --unit=pulseaudio.service

[fenugrec]

I tried for myself here with rr-5.6 , also did a few runs with "chaos mode" enabled (randomizes some scheduling), with the same results as you : can't reproduce when running under rr.
And, also having trouble replaying an rr trace, this one rr-debugger/rr#3457 , not sure if you had the same.

Thanks for your earlier explanation of how to remove + rescan the device , I'm never sure how to do that. It succesfully restores function without a reboot. Good to know !

[iam-TJ]

For some reason after so much messing about, including playing with ALSA and PulseAudio configuration, I could no longer reproduce the issue last time I tried, even after reverting the configuration changes.

I've put my investigation on suspend for now - it ate up far too much time and needs someone much more familiar with the inner workings and interactions. The one thing that does seem to be clear is that Audacity is doing something weird (or its use of PortAudio is) but without other similar applications that also use Portaudio it is difficult to compare 'good' from 'bad'.

I suspect the debuggers affect the parallelisation of threads to the extent they become serialised and therefore avoid the race. As to what is able to lock the hardware device itself into a sample rate (as seems to be the effect of this issue) - I struggle to imagine how the userspace libraries above libasound2 could cause it! Something somewhere is missing some locking construct.

[fenugrec]

The one thing that does seem to be clear is that Audacity is doing something weird (or its use of PortAudio is)

Agreed.
Out of curiosity I booted into a live-USB distro, "ubuntu studio 16.04" : this has kernel 4.5, portaudio v19 from 2015, and audacity 2.1.2 : exact same bug.

[iam-TJ]

I've just revisited this after reading latest kernel ALSA commits, and that made me look at latest alsa-lib commits. That led to me wanting to try the latest alsa-lib. Debian testing (bookworm) has v1.2.8 but it is built against a more recent version of libc6 so won't work.
Therefore I built latest alsa-lib from its source repository and tested using it. So far I've not been able to reproduce the issue using the arecord test case.

Note: this does require patching the gitcompile script to use the correct system library paths. Attached is the patch. Download it then:

git clone https://github.com/alsa-project/alsa-lib.git
cd alsa-lib
patch -p1 < ../gitcompile.patch.txt
# check file INSTALL for required build dependencies
./gitcompile
# ... configure and make messages
# shared library in ./src/.libs/

# test
LD_PRELOAD=$PWD/src/.libs/libasound.so.2.0.0  /usr/bin/audacity

And in another shell:

$ time arecord -D default -v --duration=2 -V stereo -f dat /tmp/test.03.wav
Recording WAVE '/tmp/test.03.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
ALSA <-> PulseAudio PCM I/O Plugin
Its setup is:
  stream       : CAPTURE
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 48000
  exact rate   : 48000 (48000/1)
  msbits       : 16
  buffer_size  : 24000
  period_size  : 6000
  period_time  : 125000
  tstamp_mode  : NONE
  tstamp_type  : GETTIMEOFDAY
  period_step  : 1
  avail_min    : 6000
  period_event : 0
  start_threshold  : 1
  stop_threshold   : 24000
  silence_threshold: 0
  silence_size : 0
  boundary     : 6755399441055744000
                                  +00%|00%+                                   
real    0m2.220s
user    0m0.005s
sys     0m0.006s

gitcompile.patch.txt

[iam-TJ]

Using this upstream code I did a git bisect from v1.2.4 (the version in Debian Bullseye) to current master/HEAD. It used 8 steps to work back to v1.2.4 and I was unable to reproduce the issue. I then checked what patches Debian applied on top of v1.2.4 and there is only one code patch cherry-picked from alsa-lib which is afe6ff3b33ee "pcm: plugin status - fix the return value (regression)".

Before I started this series of tests with 'upstream' builds the issue occurred and I had to reset the hardware. Now I cannot trigger it using system libraries again after these tests. I wonder if this is yet another vague hint that something is being set (badly) once but once set correctly will remain that way? Current kernel is v6.2.11.

[LudoOSGS]

Hello eveyone,

A problem without an end?

But with evolution... as time and OSes go by...

Still sporting the same hardware as almost two years ago (#3269 (comment)) : Asus Prime X570 Pro with an AMD Ryzen 3900X CPU .

~$ pacmd list cards | nc termbin.com 9999 https://termbin.com/5zo3
~$ cat /proc/asound/{devices,cards,modules,pcm} | nc termbin.com 9999 https://termbin.com/9xb5
~$ sudo dmesg | grep snd | nc termbin.com 9999 https://termbin.com/vqo4
(More info available on request)

This time round with GNU-Linux Debian 12 Bookworm and Linux kernel 6.1.0-18-amd64, PulseAudio 16.1+dfsg1-2+b1, PortAudio 19.6.0-1.2, (only alsa-utils 1.2.8-1) and Audacity 3.2.4+dfsg-1.
(Plus : VLC, gnome-sound-record, Audacious, SMPlayer and mpv).

The evolution is that, to avoid running one more time against the wall, and in order to try and get Audacity to record anything at all from the microphone (and not just donaldducks), I decided to follow the same procedure as at that time (#3269 (comment)) , but apparently the procedure had to be overhauled:

1. • I turn the computer on.
2. • A first start of Audacity has to happen with the shell command line: "~$ pasuspender audacity", launch goes well, I must then change the standard choice of recording device and playback device to select (Generic ALC1220 Analog (hw:2,0) or (hw:1,0)) for both, and I can record from the mike. However, no other program can playback any other sound nor video file, nor can gnome-sound-record record anything (the effect of the pasuspender command, probably). (As soon as I close Audacity other playbacks, e.g. by VLC, launched but muted or motionless, immediately start).
3. • After closing ALL these programmes, a later start of Audacity can happen with a plain "~$ audacity" shell command line (without pasuspender), or even from the Start Menu; I must then check that my recording device (Generic ALC1220 Analog (hw:2,0) or (hw:1,0)) is still existent and selected in Audacity (but the playback device (Generic ALC1220 Analog (hw:2,0) or (hw:1,0)) sometimes disappears, in this case "default" is now selected, and I can leave it at that); either way the fact is then that ALL (above named) programmes co-exist and co-work perfectly: I can record from the microphone with both audacity and gnome-sound-record, and hear music with any programme while the latter two are open.

I still haven't checked what happens when pavucontrol is launched...
This will be the goal of my next tests...

Cheers and thanks for the support... hoping that, one day, this problem will be taken care of...

Best regards.

ludo

[LudoOSGS]

Hello everyone,

Well, this is the second part of the test: checking the role of pavucontrol in this precarious environment.

As it was to be expected, having pavucontrol launched and running, when you launch Audacity, you literally see the collision happen: immediately pavucontrol reacts to the start of Audacity as if it were recording an explosion - a burst in tone is displayed, and then the level of recording is always very high: middle to two thirds, even at "base" level (10%, -60 dB) athough nothing is recorded, reactions to sounds and silence is displayed to be very sluggish.
Then the sound system is no longer fully functional: no recording with the mike is possible, neither with audacity nor gnome-sound-record; but playback still works alright.

The only way I can get things back to fully functional (see the comment just above) is with a reboot.

Hope this can help.

Cheers and keep it up!

ludo