search

raspberrypi / linux

Kernel source tree for Raspberry Pi-provided kernel builds. Issues unrelated to the linux kernel should be posted on the community forum at https://forums.raspberrypi.com/
Other
11.2k stars 5.02k forks source link

Inconsistent AL_SAMPLE_OFFSET updates on Raspberry Pi OS leading to audio synchronization issues (too slow playing position update with too large sample steps) #6422

Open qrp73 opened 1 month ago

qrp73 commented 1 month ago

Describe the bug

I am debugging my code, which is designed to synchronize precisely with the sound card to maintain a continuous audio stream without interruptions and with minimal latency. However, I have encountered an issue where my code fails to maintain stream synchronization with the sound card on Raspberry Pi OS, while it works fine on other systems (Windows, Linux Arch).

A detailed investigation revealed that on Raspberry Pi OS, the AL_SAMPLE_OFFSET position updates occur in excessively large steps with a long interval, and the update step is quite unusual (not a power of two).

For example, at a sample rate of 48 kHz, the step is typically 1114 samples with an update interval of 30 ms, which is too much to maintain synchronization with a buffer length of 1/50 or 1/60 seconds (to match the display refresh rate). In contrast, on Linux Arch with the same USB sound card, I see a stable update step of 512 samples and an update interval of 10 ms, which is sufficient for most use cases.

Could you please fix it to get 10 ms update and 512 sample steps at 48 kHz sample rate as it works on other OS?

Steps to reproduce the behaviour

1) sudo apt install libopenal-dev 2) create test-al.cpp with the following test code:

// g++ -o test-al test-al.cpp -lopenal
#include <AL/al.h>
#include <AL/alc.h>
#include <iostream>
#include <thread>
#include <vector>
#include <cmath>
#include <algorithm>
#include <chrono>
#include <numeric>
#include <iomanip>

const int SampleRate = 48000;
const int BufferSize = SampleRate / 50;
int BufferCount = 8;
bool isFinished = false;

double phase = 0;
double phaseStep = 2 * M_PI * 700 / SampleRate;

// 700 Hz sine generator
void RequestData(uint32_t* buffer) {
    for (int i = 0; i < BufferSize; i++) {
        auto sample = static_cast<uint16_t>(32760 * sin(phase));
        buffer[i] = static_cast<uint32_t>(sample | (sample << 16));
        phase += phaseStep;
        if (phase >= 2 * M_PI)
            phase -= 2 * M_PI;
    }
}

void BufferStreamingThread() {
    ALuint source = 0;
    ALuint buffers[BufferCount] = {0};

    try {
        alGenSources(1, &source);
        alGenBuffers(BufferCount, buffers);

        uint32_t data[BufferSize];
        for (int i = 0; i < BufferCount; i++) {
            RequestData(data);
            alBufferData(buffers[i], AL_FORMAT_STEREO16, data, sizeof(data), SampleRate);
            alSourceQueueBuffers(source, 1, &buffers[i]);
        }

        printf("SampleRate:  %d\n", SampleRate);
        printf("BufferSize:  %d\n", BufferSize);
        printf("BufferCount: %d\n", BufferCount);

        alSourcePlay(source);
        std::vector<std::tuple<long long, int, int>> records;

        while (!isFinished) {
            ALint processedBuffers = 0, sampleOffset = 0;
            alGetSourcei(source, AL_BUFFERS_PROCESSED, &processedBuffers);
            alGetSourcei(source, AL_SAMPLE_OFFSET, &sampleOffset);

            auto now = std::chrono::high_resolution_clock::now();
            auto timestamp = std::chrono::duration_cast<std::chrono::microseconds>(now.time_since_epoch()).count();
            records.emplace_back(timestamp, sampleOffset, processedBuffers);

            if (records.size() > 1 && std::get<1>(records[records.size() - 2]) > sampleOffset) {
                std::vector<double> stat_offdt;
                std::vector<int> stat_offds;
                std::vector<double> stat_bufdt;
                auto t0 = std::get<0>(records.front());
                int prevOffset = -1;
                long long prevOfTime = 0;
                int prevBuffer = -1;
                long long prevBuTime = 0;

                for (size_t i = 0; i < records.size(); ++i) {
                    auto t1 = std::get<0>(records[i]);
                    int offset = std::get<1>(records[i]);
                    int buffer = std::get<2>(records[i]);

                    double timef = (t1 - t0) / 1000.0;
                    double offdt = NAN;
                    double bufdt = NAN; 
                    int offds = 0;
                    if (prevOffset != offset) {
                        if (prevOffset != -1) {
                            offdt = (t1 - prevOfTime) / 1000.0;
                            stat_offdt.push_back(offdt);

                            offds = offset - prevOffset;                            
                            if (i != records.size()-1)  // do not include last record into statistics
                            {
                                stat_offds.push_back(offds);
                            }
                        }
                        prevOffset = offset;
                        prevOfTime = t1;
                    }
                    if (prevBuffer != buffer) {
                        if (prevBuffer != -1) {
                            bufdt = (t1 - prevBuTime) / 1000.0;
                            stat_bufdt.push_back(bufdt);
                        }
                        prevBuffer = buffer;
                        prevBuTime = t1;
                    }

                    printf("%zu: time=%.1f ms, offset=%d, buffers=%d", i, timef, offset, buffer);
                    if (!std::isnan(offdt))
                        printf(" => offset_dt=%.2f ms, delta=%d", offdt, offds);
                    if (!std::isnan(bufdt))
                        printf(" => buffer_dt=%.2f ms", bufdt);
                    printf("\n");
                }

                printf("Statistics: [sampleOffset] | [processedBuffers]\n");
                printf("min dt [ms]: %6.2f | %6.2f\n",
                    *std::min_element(stat_offdt.begin(), stat_offdt.end()),
                    *std::min_element(stat_bufdt.begin(), stat_bufdt.end()));
                printf("max dt [ms]: %6.2f | %6.2f\n",
                    *std::max_element(stat_offdt.begin(), stat_offdt.end()),
                    *std::max_element(stat_bufdt.begin(), stat_bufdt.end()));
                printf("avg dt [ms]: %6.2f | %6.2f\n",
                    std::accumulate(stat_offdt.begin(), stat_offdt.end(), 0.0) / stat_offdt.size(),
                    std::accumulate(stat_bufdt.begin(), stat_bufdt.end(), 0.0) / stat_bufdt.size());
                printf("min delta samples: %d\n", *std::min_element(stat_offds.begin(), stat_offds.end()));
                printf("max delta samples: %d\n", *std::max_element(stat_offds.begin(), stat_offds.end()));
                printf("avg delta samples: %d\n", std::accumulate(stat_offds.begin(), stat_offds.end(), 0) / stat_offds.size());

                isFinished = true;
                break;
            }

            std::this_thread::sleep_for(std::chrono::microseconds(50));
        }
    } catch (...) {
        std::cerr << "Error occurred in buffer streaming thread." << std::endl;
    }

    // Clean up resources
    alSourceStop(source);
    alDeleteSources(1, &source);
    alDeleteBuffers(BufferCount, buffers);
}

int main(int argc, char* argv[]) {
    if (argc < 2) {
        std::cerr << "Usage: " << argv[0] << " <BufferCount>" << std::endl;
        return -1;
    }
    BufferCount = std::stoi(argv[1]);

    ALCdevice* device = nullptr;
    // Attempt to open the default device
    device = alcOpenDevice(nullptr);
    if (!device) {
        std::cerr << "Failed to open device" << std::endl;
        return -1;
    }

    ALCint attributes[] = { 
        ALC_FREQUENCY, SampleRate, 
        ALC_REFRESH, 0,
        ALC_SYNC, 0,
        0 
    };
    ALCcontext* context = alcCreateContext(device, attributes);
    if (!context || alcMakeContextCurrent(context) == ALC_FALSE) {
        std::cerr << "Failed to create or set context" << std::endl;
        if (context) alcDestroyContext(context);
        alcCloseDevice(device);
        return -1;
    }

    std::thread workerThread(BufferStreamingThread);
    workerThread.join();

    alcDestroyContext(context);
    alcCloseDevice(device);

    return 0;
}

3) compile g++ -o test-al test-al.cpp -lopenal 4) run the test for 500 buffers (500/50 = 10 seconds) to collect statistics: ./test-al 500

Expected result: max delta samples: 512 and max dt about 10 ms +- jitter

Actual result: 

Statistics: [sampleOffset] | [processedBuffers]
min dt [ms]:   0.16 |   0.23
max dt [ms]:  60.41 |  60.41
avg dt [ms]:  25.11 |  30.34
min delta samples: 180
max delta samples: 2228
avg delta samples: 1200

For comparison, here is results from Linux Arch with the same USB sound card:

Statistics: [sampleOffset] | [processedBuffers]
min dt [ms]:  10.36 |  10.45
max dt [ms]:  10.91 |  21.54
avg dt [ms]:  10.65 |  19.98
min delta samples: 512
max delta samples: 512
avg delta samples: 512

As observed, Raspberry Pi OS can update the sample position by as much as 2228 samples in a single step (and even more!), while the buffer size is just 960 samples. Consequently, it occasionally updates the sample position only once per three buffers, resulting in significant lag and sound streaming breaks.

Device (s)

Raspberry Pi 4 Mod. B

System

$ uname -a && cat /etc/rpi-issue && vcgencmd version
Linux raspi 6.6.51+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.6.51-1+rpt3 (2024-10-08) aarch64 GNU/Linux
Raspberry Pi reference 2023-09-22
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 40f37458ae7cadea1aec913ae10b5e7008ebce0a, stage4
Aug 30 2024 19:17:39 
Copyright (c) 2012 Broadcom
version 2808975b80149bbfe86844655fe45c7de66fc078 (clean) (release) (start)

Logs

Raspberry Pi OS:

$ ./test-al 500
SampleRate:  48000
BufferSize:  960
BufferCount: 500
<...>
81001: time=9946.5 ms, offset=475678, buffers=495 => offset_dt=31.66 ms, delta=1114 => buffer_dt=31.66 ms
81002: time=9946.7 ms, offset=475678, buffers=495
...
81247: time=9978.1 ms, offset=475678, buffers=495
81248: time=9978.5 ms, offset=476792, buffers=496 => offset_dt=31.99 ms, delta=1114 => buffer_dt=31.99 ms
81249: time=9978.7 ms, offset=476792, buffers=496
...
81493: time=10010.3 ms, offset=476792, buffers=496
81494: time=10010.5 ms, offset=478840, buffers=498 => offset_dt=31.93 ms, delta=2048 => buffer_dt=31.93 ms
81495: time=10010.6 ms, offset=478840, buffers=498
81497: time=10010.9 ms, offset=478840, buffers=498
81498: time=10011.0 ms, offset=479020, buffers=498 => offset_dt=0.52 ms, delta=180
81499: time=10011.1 ms, offset=479020, buffers=498
81500: time=10011.3 ms, offset=479020, buffers=498
...
81735: time=10042.2 ms, offset=479020, buffers=498
81736: time=10042.4 ms, offset=0, buffers=500 => offset_dt=31.37 ms, delta=-479020 => buffer_dt=31.89 ms
Statistics: [sampleOffset] | [processedBuffers]
min dt [ms]:   0.16 |   0.23
max dt [ms]:  60.41 |  60.41
avg dt [ms]:  25.11 |  30.34
min delta samples: 180
max delta samples: 2228
avg delta samples: 1200

Linux Arch on the same USB sound card:

$ ./test-al 500
SampleRate:  48000
BufferSize:  960
BufferCount: 500
<...>
62494: time=9947.5 ms, offset=478208, buffers=498 => offset_dt=10.65 ms, delta=512 => buffer_dt=21.37 ms
62495: time=9947.7 ms, offset=478208, buffers=498
...
62559: time=9958.0 ms, offset=478208, buffers=498
62560: time=9958.1 ms, offset=478720, buffers=498 => offset_dt=10.62 ms, delta=512
62561: time=9958.3 ms, offset=478720, buffers=498
...
62626: time=9968.6 ms, offset=478720, buffers=498
62627: time=9968.7 ms, offset=479232, buffers=499 => offset_dt=10.61 ms, delta=512 => buffer_dt=21.24 ms
62628: time=9969.0 ms, offset=479232, buffers=499
...
62692: time=9979.3 ms, offset=479232, buffers=499
62693: time=9979.5 ms, offset=479744, buffers=499 => offset_dt=10.76 ms, delta=512
62694: time=9979.7 ms, offset=479744, buffers=499
...
62758: time=9990.0 ms, offset=479744, buffers=499
62759: time=9990.1 ms, offset=0, buffers=500 => offset_dt=10.62 ms, delta=-479744 => buffer_dt=21.39 ms
Statistics: [sampleOffset] | [processedBuffers]
min dt [ms]:  10.36 |  10.45
max dt [ms]:  10.91 |  21.54
avg dt [ms]:  10.65 |  19.98
min delta samples: 512
max delta samples: 512
avg delta samples: 512

Additional context

Tested with USB sound card CX31993. But with other sound cards it shows the same issue.

pelwell commented 1 month ago

I can't see this getting much attention anytime soon.

qrp73 commented 1 month ago

I believe this bug is a key factor contributing to choppy sound during audio and video playback, similar to what occurs on devices like the Raspberry Pi Zero 2W.

Therefore, addressing this issue is important to ensure smooth sound playback and avoid potential disruptions in audio performance. Which I believe is very important.

pelwell commented 1 month ago

And how long has this problem existed?

qrp73 commented 1 month ago

it seems that it exists for a long time, just tested it on an old RaspiOS Bullseye and the issue is present, maybe a little bit less worse than on Bookworm. But does it means that it should not be fixed? The sound playback is very important part of computer and should works well.

Any idea why it works different than on other Linux distro?

My first thought is that it may be related to the USB host driver issues, but the issue present even with RPI4 onboard HDMI sound. So, it looks like issue in sound subsystem in general.

popcornmix commented 1 month ago

My first thought is that it may be related to the USB host driver issues, but the issue present even with RPI4 onboard HDMI sound. So, it looks like issue in sound subsystem in general.

I can't think of any pi specific sound subsystem code that is common to hdmi and usb audio (unless you could suggest where you think the problem lies?).

In which case, it's a problem with upstream code which we are not going to know a lot about.

Is your test app using alsa directly, or going thought pipewire (possibly using the pipewire-pulse shim)?

qrp73 commented 1 month ago

Is your test app using alsa directly, or going thought pipewire (possibly using the pipewire-pulse shim)?

My test app uses OpenAL (libopenal-dev), which uses backend "pulse". Here is the log:

$ ALSOFT_LOGLEVEL=3 ./test-al 4
AL lib: (II) alc_initconfig: Initializing library v1.19.1-unknown UNKNOWN
AL lib: (II) alc_initconfig: Supported backends: jack, pulse, alsa, sndio, oss, port, null, wave
AL lib: (II) ReadALConfig: Loading config /etc/openal/alsoft.conf...
AL lib: (II) LoadConfigFromFile: found 'decoder/hq-mode' = 'false'
AL lib: (II) LoadConfigFromFile: found 'decoder/distance-comp' = 'true'
AL lib: (II) LoadConfigFromFile: found 'decoder/nfc' = 'true'
AL lib: (II) LoadConfigFromFile: found 'decoder/nfc-ref-delay' = ''
AL lib: (II) LoadConfigFromFile: found 'decoder/quad' = ''
AL lib: (II) LoadConfigFromFile: found 'decoder/surround51' = ''
AL lib: (II) LoadConfigFromFile: found 'decoder/surround61' = ''
AL lib: (II) LoadConfigFromFile: found 'decoder/surround71' = ''
AL lib: (II) ReadALConfig: Loading config /etc/xdg/alsoft.conf...
AL lib: (II) ReadALConfig: Loading config /home/pi/.alsoftrc...
AL lib: (II) ReadALConfig: Loading config /home/pi/.config/alsoft.conf...
AL lib: (II) GetProcBinary: Got path: /home/pi/SRC-CS/TestOpenAL/CPP
AL lib: (II) ReadALConfig: Loading config /home/pi/SRC-CS/TestOpenAL/CPP/alsoft.conf...
AL lib: (II) GetConfigValue: Key disable-cpu-exts not found
AL lib: (II) FillCPUCaps: Got features string:fp asimd evtstrm crc32 cpuid

AL lib: (II) FillCPUCaps: Extensions: -NEON
AL lib: (II) GetConfigValue: Key rt-prio not found
AL lib: (II) GetConfigValue: Key resampler not found
AL lib: (II) GetConfigValue: Key trap-al-error not found
AL lib: (II) GetConfigValue: Key trap-alc-error not found
AL lib: (II) GetConfigValue: Key reverb/boost not found
AL lib: (II) GetConfigValue: Key drivers not found
AL lib: (II) GetConfigValue: Key jack/spawn-server not found
AL lib: (WW) jack_msg_handler: Cannot connect to server socket err = No such file or directory
AL lib: (WW) jack_msg_handler: Cannot connect to server request channel
AL lib: (WW) jack_msg_handler: jack server is not running or cannot be started
AL lib: (WW) jack_msg_handler: JackShmReadWritePtr::~JackShmReadWritePtr - Init not done for -1, skipping unlock
AL lib: (WW) jack_msg_handler: JackShmReadWritePtr::~JackShmReadWritePtr - Init not done for -1, skipping unlock
AL lib: (WW) ALCjackBackendFactory_init: jack_client_open() failed, 0x11
AL lib: (WW) alc_initconfig: Failed to initialize backend "jack"
AL lib: (II) GetConfigValue: Key pulse/spawn-server not found
AL lib: (II) GetProcBinary: Got filename: test-al
AL lib: (II) alc_initconfig: Initialized backend "pulse"
AL lib: (II) alc_initconfig: Added "pulse" for playback
AL lib: (II) alc_initconfig: Added "pulse" for capture
AL lib: (II) GetConfigValue: Key excludefx not found
AL lib: (II) GetConfigValue: Key default-reverb not found
AL lib: (II) GetConfigValue: Key channels not found
AL lib: (II) GetConfigValue: Key sample-type not found
AL lib: (II) GetConfigValue: Key frequency not found
AL lib: (II) GetConfigValue: Key periods not found
AL lib: (II) GetConfigValue: Key period_size not found
AL lib: (II) GetConfigValue: Key sources not found
AL lib: (II) GetConfigValue: Key slots not found
AL lib: (II) GetConfigValue: Key sends not found
AL lib: (II) GetProcBinary: Got filename: test-al
AL lib: (II) GetConfigValue: Key pulse/allow-moves not found
AL lib: (II) ALCpulsePlayback_open: Connecting to "(default)"
AL lib: (II) GetConfigValue: Key ambi-format not found
AL lib: (II) alcOpenDevice: Created device 0x55a8193cd0, "CX31993 384Khz HIFI AUDIO Analog Stereo"
AL lib: (II) UpdateDeviceParams: ALC_FREQUENCY = 48000
AL lib: (II) UpdateDeviceParams: 0x1008 = 0 (0x0)
AL lib: (II) UpdateDeviceParams: 0x1009 = 0 (0x0)
AL lib: (II) GetConfigValue: Key frequency not found
AL lib: (II) GetConfigValue: Key sources not found
AL lib: (II) GetConfigValue: Key sends not found
AL lib: (II) GetConfigValue: Key hrtf not found
AL lib: (II) UpdateDeviceParams: Pre-reset: Stereo, Float, *48000hz, 1114 update size x3
AL lib: (II) ALCpulsePlayback_sinkInfoCallback: Active port: analog-output (Analog Output)
AL lib: (II) GetConfigValue: Key pulse/fix-rate not found
AL lib: (II) GetConfigValue: Key pulse/allow-moves not found
AL lib: (II) ALCpulsePlayback_bufferAttrCallback: minreq=8912, tlength=22280, prebuf=0
AL lib: (II) UpdateDeviceParams: Post-reset: Stereo, Float, 48000hz, 1114 update size x3
AL lib: (II) GetConfigValue: Key stereo-mode not found
AL lib: (II) aluInitRenderer: HRTF disabled
AL lib: (II) GetConfigValue: Key cf_level not found
AL lib: (II) aluInitRenderer: BS2B disabled
AL lib: (II) GetConfigValue: Key stereo-encoding not found
AL lib: (II) aluInitRenderer: UHJ disabled
AL lib: (II) UpdateDeviceParams: Channel config, Dry: 2, FOA: 0, Real: 0
AL lib: (II) UpdateDeviceParams: Allocating 2 channels, 16384 bytes
AL lib: (II) UpdateDeviceParams: Max sources: 256 (255 + 1), effect slots: 64, sends: 2
AL lib: (II) GetConfigValue: Key dither not found
AL lib: (II) GetConfigValue: Key dither-depth not found
AL lib: (II) UpdateDeviceParams: Dithering disabled
AL lib: (II) GetConfigValue: Key output-limiter not found
AL lib: (II) UpdateDeviceParams: Output limiter enabled
AL lib: (II) UpdateDeviceParams: Fixed device latency: 1000000ns
AL lib: (II) GetConfigValue: Key volume-adjust not found
AL lib: (II) alcCreateContext: Created context 0x55a81a24b0

I'm a newbie in Linux audio, so I don't know exactly how it works under the hood. I'm trying to port code originally written for Windows DirectSound (DirectX). In DirectSound, it is possible to assign events that are automatically triggered by the driver during sound buffer playback. This allows user code to simply wait for the event, which is convenient in terms of minimizing CPU load. However, in OpenAL, I don't see such a mechanism - I have to poll the buffer in a loop, which increases CPU load. Perhaps you could suggest a more efficient way to set an event for thread synchronization as the sound buffer plays (I'm interested in a 1/50 second interval).

popcornmix commented 1 month ago

So audio will be going though: Your app->openal->pulse->pipewire->alsa->kernel driver

so there many places for it to go wrong. Might be worth trying to disable pipewire (and its pulseaudio shim) which will hopefully mean openal uses alsa directly.

The result of that will narrow down the problem somewhat.

qrp73 commented 1 month ago

so there many places for it to go wrong. Might be worth trying to disable pipewire (and its pulseaudio shim) which will hopefully mean openal uses alsa directly.

Just tried to configure OpenAL to use ALSA directly.

Now OpenAL uses backend "alsa", but the issue still present:

$ ALSOFT_LOGLEVEL=3 ALSOFT_DRIVERS=alsa ./test-al 500
SampleRate:  48000
BufferSize:  960
BufferCount: 500
AL lib: (II) alc_initconfig: Initializing library v1.19.1-unknown UNKNOWN
AL lib: (II) alc_initconfig: Supported backends: jack, pulse, alsa, sndio, oss, port, null, wave
AL lib: (II) ReadALConfig: Loading config /etc/openal/alsoft.conf...
AL lib: (II) LoadConfigFromFile: found 'decoder/hq-mode' = 'false'
AL lib: (II) LoadConfigFromFile: found 'decoder/distance-comp' = 'true'
AL lib: (II) LoadConfigFromFile: found 'decoder/nfc' = 'true'
AL lib: (II) LoadConfigFromFile: found 'decoder/nfc-ref-delay' = ''
AL lib: (II) LoadConfigFromFile: found 'decoder/quad' = ''
AL lib: (II) LoadConfigFromFile: found 'decoder/surround51' = ''
AL lib: (II) LoadConfigFromFile: found 'decoder/surround61' = ''
AL lib: (II) LoadConfigFromFile: found 'decoder/surround71' = ''
AL lib: (II) ReadALConfig: Loading config /etc/xdg/alsoft.conf...
AL lib: (II) ReadALConfig: Loading config /home/pi/.alsoftrc...
AL lib: (II) ReadALConfig: Loading config /home/pi/.config/alsoft.conf...
AL lib: (II) GetProcBinary: Got path: /home/pi/SRC-CS/TestOpenAL/CPP
AL lib: (II) ReadALConfig: Loading config /home/pi/SRC-CS/TestOpenAL/CPP/alsoft.conf...
AL lib: (II) GetConfigValue: Key disable-cpu-exts not found
AL lib: (II) FillCPUCaps: Got features string:fp asimd evtstrm crc32 cpuid

AL lib: (II) FillCPUCaps: Extensions: -NEON
AL lib: (II) GetConfigValue: Key rt-prio not found
AL lib: (II) GetConfigValue: Key resampler not found
AL lib: (II) GetConfigValue: Key trap-al-error not found
AL lib: (II) GetConfigValue: Key trap-alc-error not found
AL lib: (II) GetConfigValue: Key reverb/boost not found
AL lib: (II) alc_initconfig: Initialized backend "alsa"
AL lib: (II) alc_initconfig: Added "alsa" for playback
AL lib: (II) alc_initconfig: Added "alsa" for capture
AL lib: (II) GetConfigValue: Key excludefx not found
AL lib: (II) GetConfigValue: Key default-reverb not found
AL lib: (II) GetConfigValue: Key channels not found
AL lib: (II) GetConfigValue: Key sample-type not found
AL lib: (II) GetConfigValue: Key frequency not found
AL lib: (II) GetConfigValue: Key periods not found
AL lib: (II) GetConfigValue: Key period_size not found
AL lib: (II) GetConfigValue: Key sources not found
AL lib: (II) GetConfigValue: Key slots not found
AL lib: (II) GetConfigValue: Key sends not found
AL lib: (II) GetConfigValue: Key alsa/device not found
AL lib: (II) ALCplaybackAlsa_open: Opening device "default"
AL lib: (II) GetConfigValue: Key ambi-format not found
AL lib: (II) alcOpenDevice: Created device 0x55a603e5d0, "ALSA Default"
AL lib: (II) UpdateDeviceParams: ALC_FREQUENCY = 48000
AL lib: (II) UpdateDeviceParams: 0x1008 = 0 (0x0)
AL lib: (II) UpdateDeviceParams: 0x1009 = 0 (0x0)
AL lib: (II) GetConfigValue: Key frequency not found
AL lib: (II) GetConfigValue: Key sources not found
AL lib: (II) GetConfigValue: Key sends not found
AL lib: (II) GetConfigValue: Key hrtf not found
AL lib: (II) UpdateDeviceParams: Pre-reset: Stereo, Float, *48000hz, 1114 update size x3
AL lib: (II) GetConfigValue: Key alsa/mmap not found
AL lib: (II) GetConfigValue: Key alsa/allow-resampler not found
AL lib: (II) UpdateDeviceParams: Post-reset: Stereo, Float, 48000hz, 1114 update size x3
AL lib: (II) GetConfigValue: Key stereo-mode not found
AL lib: (II) aluInitRenderer: HRTF disabled
AL lib: (II) GetConfigValue: Key cf_level not found
AL lib: (II) aluInitRenderer: BS2B disabled
AL lib: (II) GetConfigValue: Key stereo-encoding not found
AL lib: (II) aluInitRenderer: UHJ disabled
AL lib: (II) UpdateDeviceParams: Channel config, Dry: 2, FOA: 0, Real: 0
AL lib: (II) UpdateDeviceParams: Allocating 2 channels, 16384 bytes
AL lib: (II) UpdateDeviceParams: Max sources: 256 (255 + 1), effect slots: 64, sends: 2
AL lib: (II) GetConfigValue: Key dither not found
AL lib: (II) GetConfigValue: Key dither-depth not found
AL lib: (II) UpdateDeviceParams: Dithering disabled
AL lib: (II) GetConfigValue: Key output-limiter not found
AL lib: (II) UpdateDeviceParams: Output limiter enabled
AL lib: (II) UpdateDeviceParams: Fixed device latency: 1000000ns
AL lib: (II) GetConfigValue: Key volume-adjust not found
AL lib: (II) alcCreateContext: Created context 0x55a607a740

0: time=0.0 ms, offset=0, buffers=0
1: time=0.1 ms, offset=0, buffers=0
2: time=0.3 ms, offset=0, buffers=0
<...>
314: time=35.7 ms, offset=0, buffers=0
315: time=35.8 ms, offset=1114, buffers=1 => offset_dt=35.81 ms, delta=1114 => buffer_dt=35.81 ms
316: time=35.9 ms, offset=1114, buffers=1
<...>
686: time=78.3 ms, offset=1114, buffers=1
687: time=78.5 ms, offset=2228, buffers=1 => offset_dt=42.67 ms, delta=1114
688: time=78.6 ms, offset=3342, buffers=3 => offset_dt=0.14 ms, delta=1114 => buffer_dt=42.81 ms
689: time=78.8 ms, offset=3342, buffers=3
<...>
1060: time=121.0 ms, offset=3342, buffers=3
1061: time=121.1 ms, offset=4456, buffers=4 => offset_dt=42.49 ms, delta=1114 => buffer_dt=42.49 ms
1062: time=121.5 ms, offset=5570, buffers=4 => offset_dt=0.36 ms, delta=1114
1063: time=121.6 ms, offset=5570, buffers=5 => buffer_dt=0.48 ms
1064: time=121.7 ms, offset=5570, buffers=5
<...>
Statistics: [sampleOffset] | [processedBuffers]
min dt [ms]:   0.12 |   0.12
max dt [ms]:  44.93 |  44.93
avg dt [ms]:  23.58 |  23.80
min delta samples: 1114
max delta samples: 2228
avg delta samples: 1129

As you can see, it shows the same 1114 sample step and is unable to notify the app about the buffer overrun. You can see that it notifies 2 buffers at once in the 121.0 - 121.6 ms time interval, and before that, there is no sign of a buffer overrun.

Other Linux distro has very stable 512 sample step in this case and it works without buffer overrun. I suspect this 1114 sample step is some specific to Raspberry Pi implementation issue.

Just noticed:

AL lib: (II) UpdateDeviceParams: Pre-reset: Stereo, Float, *48000hz, 1114 update size x3

Where did this 1114 update size come from? Is it configured somewhere or hard-coded?

qrp73 commented 1 month ago

just tried to set period_size = 512 in alsoft.conf:

## drivers: (global)
#  Sets the backend driver list order, comma-seperated. Unknown backends and
#  duplicated names are ignored. Unlisted backends won't be considered for use
#  unless the list is ended with a comma (e.g. 'oss,' will try OSS first before
#  other backends, while 'oss' will try OSS only). Backends prepended with -
#  won't be considered for use (e.g. '-oss,' will try all available backends
#  except OSS). An empty list means to try all backends.
#drivers =
drivers = alsa

## period_size:
#  Sets the update period size, in frames. This is the number of frames needed
#  for each mixing update. Acceptable values range between 64 and 8192.
#period_size = 1024
period_size = 512

But it don't works. It uses alsa driver as specified in drivers variable, but don't have effect on period_size. On Raspberry Pi OS it still uses 1114.

Here is what OpenAL reports in the log when I set period size=512:

AL lib: (II) UpdateDeviceParams: Pre-reset: Stereo, Float, *48000hz, 557 update size x3

It's not clear why 557 instead of configured 512???

But actual update size is still 1114, only first update size is 557, all other is 1114:

273: time=32.5 ms, offset=0, buffers=0
274: time=32.8 ms, offset=557, buffers=0 => offset_dt=32.81 ms, delta=557
275: time=32.9 ms, offset=557, buffers=0
<...>
466: time=53.9 ms, offset=557, buffers=0
467: time=54.2 ms, offset=1671, buffers=1 => offset_dt=21.40 ms, delta=1114 => buffer_dt=54.21 ms
468: time=54.3 ms, offset=1671, buffers=1
<...>
661: time=75.2 ms, offset=1671, buffers=1
662: time=75.5 ms, offset=2785, buffers=2 => offset_dt=21.32 ms, delta=1114 => buffer_dt=21.32 ms
663: time=75.6 ms, offset=2785, buffers=2

For comparison, on Arch Linux, changing period_size has an effect. Furthermore, if it is not configured, OpenAL automatically selects the period_size based on the requested buffer size. However, on Raspberry Pi OS, it always remains fixed at a value of 1114.

Any idea where it is hard-coded to 1114 on Raspberry Pi OS? Is it firmware code?

popcornmix commented 1 month ago

Any idea where it is hard-coded to 1114 on Raspberry Pi OS? Is it firmware code?

No. The firmware is not involved in anything like this. Using the kms driver means all audio/display code purely runs on the arm side (and will be open source).

fridtjof commented 1 month ago

But it don't works. It uses alsa driver as specified in drivers variable, but don't have effect on period_size. On Raspberry Pi OS it still uses 1114.

Of note: Pipewire also hijacks alsa clients to make sure everything's under the same umbrella.

There's a difference between ALSA the kernel API (which to my knowledge is also used by Pipewire itself to actually talk to audio devices) and ALSA the userspace library. To check whether something's going through Pipewire, try looking at pw-top while something is outputting audio. If it shows up there, it's still going through Pipewire.

The package responsible for this is pipewire-alsa, which you could try uninstalling. Not sure if that will just work without more changes though, I haven't tried it myself in recent years.