Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

simple_capture receives sound from pulseaudio driver only when another program captures audio (pavucontrol,guvcview,ffmpeg,firefox). #106

Closed
fidergo-stephane-gourichon opened this issue Dec 12, 2019 · 32 comments
Labels

Comments

@fidergo-stephane-gourichon

Hi. Congratulations for the work done for the past months since the last time we interacted!

Context

I'm writing a program that so far opens a device full-duplex to record sound and play the same. It will do something else later.

By default miniaudio tried to reach pulseaudio, which is fine until something wrong happens.

Observed

The program starts (and chooses a correct full-duplex device), but receives no audio (the callback is not called regulary, only a few times in the first seconds). But if I run pavucontrol, then the program receives audio normally and produces a correct record file. And when pavucontrol stops, the program no longer receives audio regularly. I can start and stop pavucontrol as many times as I want, the effect happens.

In #57 you offered me to try to compile with MA_NO_PULSEAUDIO defined. I tried that.

With that option, the problem no longer happens. We have the expected behavior.

Expected

Program captures audio (and plays it simultaneously), whether pavucontrol is opened or not.

Additional information

  • simple_playback has no such issue.
  • (More could be discussed, but let's stay simple for one issue report) I had to make sure that the wished devices are the default devices in pulseaudio. This can be discussed separately.
  • Fun fact: the default ALSA device is the one that routes through pulseaudio, so technically miniaudio still uses pulse but does not know it.

But why mentioning simple_capture in title then?

Because I though maybe I use the miniaudio API wrong, or maybe this is specific to full-duplex.
So, to simplify the issue I checked behavior of simple_capture.
And I confirm that the issue also happens. Exactly the same. And the same workaround.
So, the problem is unrelated to fullduplex.

Software environment

Xubuntu 18.04.
miniaudio current git master:

commit 1ca6f80698acbdbf9ae4a9f4200975d919de31f8
Author: David Reid <mackron@gmail.com>
Date:   2019-10-19 07:46:44 +1000

    Fix some tests.

    These compilation errors are a result of the recent change to dr_wav to
    add support for allocation callbacks.

What now?

I can do more tests if you wish, like last time, with specific build options, bring logs, share my complete programs if needed.
So far, been using this:

gcc ../simple_capture.c -DMA_DEBUG_OUTPUT=true -o ../bin/simple_capture -Wall -Wpedantic -pedantic -lpthread -ldl -lm
@mackron
Copy link
Owner

mackron commented Dec 14, 2019

I can't reproduce this. I think the first thing to do is check that miniaudio is choosing the correct device. Could you inspect device.capture.name and check that it's choosing the device you're expecting? miniaudio passed NULL to the dev parameter of pa_stream_connect_record() which is well defined as the default device: https://freedesktop.org/software/pulseaudio/doxygen/stream_8h.html#abfd34293aae8f170f572d1093c1bcdf9)

I'm not sure what's going on with this. It doesn't make sense that an external program would affect this. Are other capture programs working, do you know?

@fidergo-stephane-gourichon
Copy link
Author

fidergo-stephane-gourichon commented Dec 16, 2019

In what environment did you try to reproduce?

I can't reproduce this

In what environment did you try to reproduce? Here Xubuntu 18.04, but see below (pulseeffects installed).

Correct device? Yes!

I think the first thing to do is check that miniaudio is choosing the correct device.

Yes, it definitely choose the expected device. And launching/closing pavucontrol does not change the device. Given the attention I provided to details, I would have noticed. You're right to ask anyway!

Could you inspect device.capture.name and check that it's choosing the device you're expecting?

Thanks to -DMA_DEBUG_OUTPUT=true I get details:

[miniaudio] Endian:  LE
[miniaudio] SSE2:    YES
[miniaudio] AVX2:    NO
[miniaudio] AVX512F: NO
[miniaudio] NEON:    NO
[miniaudio] Endian:  LE
[miniaudio] SSE2:    YES
[miniaudio] AVX2:    NO
[miniaudio] AVX512F: NO
[miniaudio] NEON:    NO
[PulseAudio] Capture attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalBufferSizeInFrames=1320
[PulseAudio] Capture actual attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalBufferSizeInFrames=1320
[PulseAudio]
  Audio interne Stéréo analogique (Capture)
    Format:      32-bit IEEE Floating Point -> 16-bit Signed Integer
    Channels:    2 -> 2
    Sample Rate: 44100 -> 44100
    Buffer Size: 1320/3 (440)
    Conversion:
      Pre Format Conversion:    NO
      Post Format Conversion:   YES
      Channel Routing:          NO
      SRC:                      NO
      Channel Routing at Start: NO
      Passthrough:              NO
Press Enter to stop recording...
......................................................................................................................................................................................^C

The line " Audio interne Stéréo analogique (Capture)" is from this line :

        printf("  %s (%s)\n", pDevice->capture.name, "Capture");

and is definitely the correct device.

Other capture programs do work

Are other capture programs working, do you know?

Of course, I use playback every day (it's my desktop machine where I listen to music and plays videos in the browser), and capture sometimes (e.g. with audacity).

Just tested again. Audacity works when targetting pulse as well as when targetting alsa.

Also, this works as expected:

parecord -v -r /tmp/sample.wav

Why could another program change something?

It doesn't make sense that an external program would affect this.

I suspect there's something about "lazy stream" happening. Pulseaudio does not instruct the lower level driver to actually start recording and consume the CPU/interrupt path/resources to actually receive data, until some program triggers it.

As you know pavucontrol displays real-time audio amplitude (dB). This may be what triggers pulseaudio to actually request audio data, and stop requesting it when pavucontrol stops.

It might be something subtle in the pulseaudio API that miniaudio does ont.
It might also be a bug, which is like previous line but intended by pulseaudio developers ;-).

What next?

Anyway, studying source code and/or API calls of parecord might help.

Ubuntu 18.04 runs this parecord: https://git.launchpad.net/~ubuntu-audio-dev/pulseaudio/tag/?h=ubuntu/1%2511.1-1ubuntu7.4 ... but...

Ah, I realize that installing pulseeffects on my 18.04 pulled a specific build of pulseaudio:

dpkg -l '*pulseaudio*'

Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name                    Version          Architecture     Description
+++-=======================-================-================-===================================================
ii  gstreamer1.0-pulseaudio 1.14.5-0ubuntu1~ amd64            GStreamer plugin for PulseAudio
un  libsdl1.2debian-pulseau <none>           <none>           (no description available)
ii  osspd-pulseaudio        1.3.2-9          amd64            OSS Proxy Daemon: PulseAudio backend
ii  pulseaudio              1:12.2-9~bionic1 amd64            PulseAudio sound server
ii  pulseaudio-module-bluet 1:12.2-9~bionic1 amd64            Bluetooth module for PulseAudio sound server
ii  pulseaudio-module-gconf 1:12.2-9~bionic1 amd64            GConf module for PulseAudio sound server
un  pulseaudio-module-gsett <none>           <none>           (no description available)
ii  pulseaudio-module-zeroc 1:12.2-9~bionic1 amd64            Zeroconf module for PulseAudio sound server
ii  pulseaudio-utils        1:12.2-9~bionic1 amd64            Command line tools for the PulseAudio sound server
ii  xfce4-pulseaudio-plugin 0.4.1-0ubuntu1   amd64            Xfce4 panel plugin to control pulseaudio

This gives details about the PPA:

apt-cache policy pulseaudio-utils

pulseaudio-utils:
  Installed: 1:12.2-9~bionic1
  Candidate: 1:12.2-9~bionic1
  Version table:
 *** 1:12.2-9~bionic1 500
        500 http://ppa.launchpad.net/mikhailnov/pulseeffects/ubuntu bionic/main amd64 Packages
        100 /var/lib/dpkg/status
     1:11.1-1ubuntu7.4 500
        500 http://fr.archive.ubuntu.com/ubuntu bionic-updates/main amd64 Packages
     1:11.1-1ubuntu7 500
        500 http://fr.archive.ubuntu.com/ubuntu bionic/main amd64 Packages

In theory this is just another build of an unmodified pulseaudio because pulseeffects requires a more recent one than the one on Ubuntu 18.04.

Alternatively, it might be a buggy pulseaudio. Still, this works on this pulseaudio version:

parecord -v -r /tmp/sample.wav

So, perhaps the bug actually occurs even on regular pulseaudio versions, starting from somewhere between after 1.11.1 and 1.12.2.

https://packages.ubuntu.com/search?keywords=pulseaudio&searchon=names&exact=1&suite=all&section=all shows that 1.12.2 is the version in Ubuntu disco (19.04) while eoan (19.10) runs pulseaudio 1.13.0.

Note that audacity, pavucontrol and others are not aware of the changed version of pulseaudio, they target the regular 1.11.1 from vanilla 18.04 and work. I've never seen a problem with any program since I installed pulseeffects.

So, the possibility of some subtle way of using pulseaudio APIs remains.

Next step

I can uninstall pulseeffects and the PPA in my 18.04, but PPAs reintroduce some Windows-ish style in installed programs, they tend to keep some modified state even when the PPA itself is uninstalled.

It's "easy" to boot a vanilla 18.04/19.04/19.10 in a VM or on a USB stick and try to reproduce.

I have a Xubuntu 19.10 on the same machine. I can try to reproduce there and keep you updated.

Anyway, thanks again for your feedback.

@fidergo-stephane-gourichon
Copy link
Author

fidergo-stephane-gourichon commented Dec 16, 2019

Reproduced again with vanilla pulseaudio on 18.04

Just removed PPA with ppa-purge as suggested in https://askubuntu.com/questions/307/how-can-ppas-be-removed , checked that pulseaudio is indeed 1.11.1. Bug still reproduced.

Exact code used

Exact code I use it on: https://github.com/fidergo-stephane-gourichon/miniaudio/commits/issue_106_investigate

Steps to reproduce, with surprises.

git clone https://github.com/fidergo-stephane-gourichon/miniaudio/commits/issue_106_investigate
cd miniaudio/
cd examples/build
cc ../simple_playback_emscripten.c -o ../bin/simple_playback_emscripten -Wall -Wpedantic -std=c89 -ansi -pedantic -lpthread -ldl -lm -DMA_DEBUG_OUTPUT=true
../bin/simple_capture /tmp/a.wav

Output here is:

[miniaudio] Endian:  LE
[miniaudio] SSE2:    YES
[miniaudio] AVX2:    NO
[miniaudio] AVX512F: NO
[miniaudio] NEON:    NO
[miniaudio] Endian:  LE
[miniaudio] SSE2:    YES
[miniaudio] AVX2:    NO
[miniaudio] AVX512F: NO
[miniaudio] NEON:    NO
[PulseAudio] Capture attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalBufferSizeInFrames=1320
[PulseAudio] Capture actual attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalBufferSizeInFrames=1320
[PulseAudio]
  Audio interne Stéréo analogique (Capture)
    Format:      32-bit IEEE Floating Point -> 16-bit Signed Integer
    Channels:    2 -> 2
    Sample Rate: 44100 -> 44100
    Buffer Size: 1320/3 (440)
    Conversion:
      Pre Format Conversion:    NO
      Post Format Conversion:   YES
      Channel Routing:          NO
      SRC:                      NO
      Channel Routing at Start: NO
      Passthrough:              NO
Press Enter to stop recording...
..

Each callback causes a dot to appear. It does appear at low frequency.

  • Launch audacity. Program is not affected.
  • Enable monitor on audacity. Dots appear at a normal (much higher) rate, regularly. This means that simple_capture works normally and record audio that can be played later.
  • Disable monitor on audacity. Dots again appear at a low rate. Bug is here again.

Audacity uses ALSA API through PortAudio V19.6.0 revision 396fe4b6, and offers only one capture device: pulse. So, audacity is actually routed to the ALSA-compatibility layer of pulseaudio.

Other programs: all similar, except parecord.

Replacing audacity with guvcview had same result. When guvcview records a video, the bug is temporarily not observed. guvcview uses portaudio.

Replacing audacity with ffmpeg had same result. When ffmpeg -f alsa -i pulse -t 3 out.wav runs, the bug is temporarily not observed.

Replacing audacity with parecord -v -r /tmp/sample.wav did not workaround the bug. I'm surprised.

Notice that all those examples are similar. I have one capture device basically, which is HDA Intel audio analog, reachable through ALSA, and pulseaudio gets exclusive access to it, publicizing its own ALSA-compliant interface which is the one other programs use, so it's normal that all attempts actually go through pulseaudio.

Summary

Programs being affected:

  • simple_capture targets pulseaudio API and suffers from the bug
  • parecord targets pulseaudio API directly and does not suffer from the bug
  • other programs targets ALSA API, get served by pulseaudio compatibility layer of ALSA that routes through pulseaudio, and do not suffer from the bug

Programs which, when capturing audio, cause the bug not to be observed on simple_capture:

  • audacity
  • guvcview
  • ffmpeg

Programs which, when capturing audio, do not change the bug status on simple_capture:

  • parecord

Conclusion

Perhaps on your environment you've got some program that monitors the audio input at all times, which causes the bug to not appear?

What is your distro and desktop environment? Here is Xubuntu 18.04.

Can you reproduce it with the information above?

Getting more information from callback during bug?

Remember: when bug happens, the callback is sometimes called, e.g. 5-10 times within 2-3 seconds, then no longer, then again after some variable time (5 seconds, 30 seconds).

Have you got any suggestion as to what to log inside the callback to get more information?

Thanks!

@fidergo-stephane-gourichon fidergo-stephane-gourichon changed the title simple_capture receives sound from pulseaudio driver only when pavucontrol is opened simple_capture receives sound from pulseaudio driver only when another program captures audio (pavucontrol,guvcview,ffmpeg). Dec 16, 2019
@fidergo-stephane-gourichon fidergo-stephane-gourichon changed the title simple_capture receives sound from pulseaudio driver only when another program captures audio (pavucontrol,guvcview,ffmpeg). simple_capture receives sound from pulseaudio driver only when another program captures audio (pavucontrol,guvcview,ffmpeg,firefox). Dec 16, 2019
@fidergo-stephane-gourichon
Copy link
Author

Tried again, opening a videoconferencing web page on Firefox. As soon as firefox captures audio, the bug disappears. When Firefox stops capturing audio, bug is there again.

@fidergo-stephane-gourichon
Copy link
Author

Here's a diff between outputs of pacmd list-source-outputs.

The essential differences are flags, and the fact that simple_capture does not request any specific latency?

--- ffmpeg.log	2019-12-16 02:19:26.993681972 +0100
+++ simple_capture.log	2019-12-16 02:18:51.053353595 +0100
@@ -1,31 +1,31 @@
-    index: 209
+    index: 199
 	driver: <protocol-native.c>
-	flags: 
+	flags: START_CORKED FIX_FORMAT FIX_RATE FIX_CHANNELS 
 	state: RUNNING
 	source: 2 <alsa_input.pci-0000_00_1b.0.analog-stereo>
 	volume: front-left: 65536 / 100% / 0,00 dB,   front-right: 65536 / 100% / 0,00 dB
 	        balance 0,00
 	muted: no
 	current latency: 0,00 ms
-	requested latency: 1,33 ms
-	sample spec: s16le 2ch 48000Hz
+	requested latency: n/a
+	sample spec: s16le 2ch 44100Hz
 	channel map: front-left,front-right
 	             Stéréo
 	resample method: (null)
 	owner module: 12
-	client: 540 <ALSA plug-in [ffmpeg]>
+	client: 396 <simple_capture>
 	properties:
-		media.name = "ALSA Capture"
-		application.name = "ALSA plug-in [ffmpeg]"
+		media.name = "miniaudi0"
+		application.name = "simple_capture"
 		native-protocol.peer = "UNIX socket client"
 		native-protocol.version = "32"
-		application.process.id = "21377"
+		application.process.id = "19896"
 		application.process.user = "stephane"
 		application.process.host = "n551jk"
-		application.process.binary = "ffmpeg"
+		application.process.binary = "simple_capture"
 		application.language = "C"
 		window.x11.display = ":0.0"
 		application.process.machine_id = "c420354243104b93b5ce5524c873c531"
 		application.process.session_id = "c2"
-		module-stream-restore.id = "source-output-by-application-name:ALSA plug-in [ffmpeg]"
+		module-stream-restore.id = "source-output-by-application-name:simple_capture"

@fidergo-stephane-gourichon
Copy link
Author

Reproduced on Ubuntu 19.10

No special modifications here, just installed Xubuntu 19.10, running XFCE.

Just plain packages:

apt-cache policy pulseaudio

pulseaudio:
  Installed: 1:13.0-1ubuntu1
  Candidate: 1:13.0-1ubuntu1
  Version table:
 *** 1:13.0-1ubuntu1 500
        500 http://fr.archive.ubuntu.com/ubuntu eoan/main amd64 Packages
        100 /var/lib/dpkg/status

and

dpkg -l '*pulseaudio*'

Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name                          Version         Architecture Description
+++-=============================-===============-============-==================================================
ii  gstreamer1.0-pulseaudio:amd64 1.16.1-1ubuntu1 amd64        GStreamer plugin for PulseAudio
un  libsdl1.2debian-pulseaudio    <none>          <none>       (no description available)
ii  pulseaudio                    1:13.0-1ubuntu1 amd64        PulseAudio sound server
ii  pulseaudio-equalizer          1:13.0-1ubuntu1 amd64        Equalizer sink module for PulseAudio sound server
ii  pulseaudio-module-bluetooth   1:13.0-1ubuntu1 amd64        Bluetooth module for PulseAudio sound server
ii  pulseaudio-utils              1:13.0-1ubuntu1 amd64        Command line tools for the PulseAudio sound server
ii  xfce4-pulseaudio-plugin:amd64 0.4.2-1         amd64        Xfce4 panel plugin to control pulseaudio

What now?

  • Perhaps on your environment you've got some program that monitors the audio input at all times, which causes the bug to not appear?
  • On what distro and desktop environment did you try to reproduce the bug?
  • Can you reproduce it with the wealth of information above?

@mackron
Copy link
Owner

mackron commented Dec 17, 2019

Thanks for taking the time to gather that info. I was testing on Linux Mint (based on Ubuntu), but I'll try Ubuntu 19.10 in a VM when I get a chance. This is definitely a strange one...

@mackron
Copy link
Owner

mackron commented Dec 21, 2019

I'm still not reproducing this, unfortunately. Fresh install of Ubuntu 19.10 on a VM using my Blue Yeti connected through the virtual USB port. Requested latency looks fine. Everything working as expected. I wonder if it's a device or driver specific thing which doesn't like some kind of parameter miniaudio is using? I'm not sure what's going on...

If possible, can you dump the contents of the ma_device object after it's been initialised?

Something to try: in simple_capture could you set the buffer size to something large, like this?

deviceConfig.bufferSizeInMilliseconds = 1000;

I'm doubtful this will help, but it's a quick and easy thing to eliminate (I've had issues with other backends in the past where a small buffer size causes things to collapse, albeit with different symptoms).

FYI:

1 source output(s) available.
    index: 1
	driver: <protocol-native.c>
	flags: START_CORKED FIX_FORMAT FIX_RATE FIX_CHANNELS 
	state: RUNNING
	source: 3 <alsa_input.usb-Blue_Microphones_Yeti_Stereo_Microphone_REV8-00.analog-stereo>
	volume: front-left: 65536 / 100% / 0.00 dB,   front-right: 65536 / 100% / 0.00 dB
	        balance 0.00
	muted: no
	current latency: 0.00 ms
	requested latency: 99.95 ms
	sample spec: s16le 2ch 44100Hz
	channel map: front-left,front-right
	             Stereo
	resample method: (null)
	owner module: 12
	client: 11 <simple_capture>
	properties:
		media.name = "miniaudi0"
		application.name = "simple_capture"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "33"
		application.process.id = "2194"
		application.process.user = "david"
		application.process.host = "david-VirtualBox"
		application.process.binary = "simple_capture"
		application.language = "C"
		window.x11.display = ":0.0"
		application.process.machine_id = "f688b5d169d74030accd33030bf885d9"
		application.process.session_id = "2"
		module-stream-restore.id = "source-output-by-application-name:simple_capture"
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name                          Version         Architecture Description
+++-=============================-===============-============-=================
ii  gstreamer1.0-pulseaudio:amd64 1.16.1-1ubuntu1 amd64        GStreamer plugin 
un  libsdl1.2debian-pulseaudio    <none>          <none>       (no description a
ii  pulseaudio                    1:13.0-1ubuntu1 amd64        PulseAudio sound 
ii  pulseaudio-module-bluetooth   1:13.0-1ubuntu1 amd64        Bluetooth module 
ii  pulseaudio-utils              1:13.0-1ubuntu1 amd64        Command line tool
ii  xfce4-pulseaudio-plugin:amd64 0.4.2-1         amd64        Xfce4 panel plugi

@mackron
Copy link
Owner

mackron commented Dec 21, 2019

I'm suspecting the bug is coming from ma_device_read__pulse(), but without reproducing it's hard to be sure. I've added some debug output (dev branch). Are you able to run that with #define MA_DEBUG_OUTPUT and show me what you see (it'll output a lot)?

@fidergo-stephane-gourichon
Copy link
Author

Thanks for taking the time to gather that info. I was testing on Linux Mint (based on Ubuntu), but I'll try Ubuntu 19.10 in a VM when I get a chance. This is definitely a strange one...

I guess each time it is with the default desktop environment of those distros.

Test with Ubuntu 18.04 default desktop environment: reproduced

As section title says. So, the hypothesis of something in the desktop environment seems less believable.

@fidergo-stephane-gourichon
Copy link
Author

fidergo-stephane-gourichon commented Dec 22, 2019

deviceConfig.bufferSizeInMilliseconds = 1000;

Just tried this, changed nothing else.

Now, recording appears to be correct (not sure full-duplex will be okay).

The dots in my test code now appear in batches, roughly 3 batches per second, of varying length. Here is a "text histogram" of these lengths.

Left columns: number of times observed, right column length of the batch of callbacks.

grep '^.....................' script.txt | awk '{ print length }' | sort | uniq -c

  1 25
  1 26
  3 29
317 30
 13 31
206 34
 19 35

I also notice that when stopping the program, the end of the recording is lost, by a length up to the time delta between two batches. For example, if I start the program, wait for the first dot, say "1, 2, 3, 4" and press Enter right after, the recorded file sometimes contains the "4", sometimes is cut before it.

@fidergo-stephane-gourichon
Copy link
Author

I'm suspecting the bug is coming from ma_device_read__pulse(), but without reproducing it's hard to be sure. I've added some debug output (dev branch). Are you able to run that with #define MA_DEBUG_OUTPUT and show me what you see (it'll output a lot)?

I piped the output through uniq -c to make it more manageable.

gcc ../simple_capture.c          -DMA_DEBUG_OUTPUT=true   -o ../bin/simple_capture          -std=c89  -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g && ../bin/simple_capture /tmp/a.wav  2>&1 | uniq -c

      1 [miniaudio] Endian:  LE
      1 [miniaudio] SSE2:    YES
      1 [miniaudio] AVX2:    NO
      1 [miniaudio] AVX512F: NO
      1 [miniaudio] NEON:    NO
      1 [PulseAudio] Capture attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalBufferSizeInFrames=1320
      1 [PulseAudio] Capture actual attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalBufferSizeInFrames=1320
      1 [PulseAudio]
      1   Audio interne Stéréo analogique (Capture)
      1     Format:      32-bit IEEE Floating Point -> 16-bit Signed Integer
      1     Channels:    2 -> 2
      1     Sample Rate: 44100 -> 44100
      1     Buffer Size: 1320/3 (440)
      1     Conversion:
      1       Pre Format Conversion:    NO
      1       Post Format Conversion:   YES
      1       Channel Routing:          NO
      1       SRC:                      NO
      1       Channel Routing at Start: NO
      1       Passthrough:              NO
      1 Press Enter to stop recording...
    610 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1696
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
   4821 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1568
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
    612 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=128
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
    301 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=64
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
   4815 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1280
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
    606 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=416
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
    301 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=352
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
   4856 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=992
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
    599 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=704
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
    302 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=640
      1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()

   3187 [PulseAudio] ma_device_read__pulse: No data available. Waiting.

I also tried with pavucontrol running, for a comparison.

Running the program for 10 seconds with and without pavucontrol running.

I can attach full log if that is of any use.

Command:

gcc ../simple_capture.c          -DMA_DEBUG_OUTPUT=true   -o ../bin/simple_capture          -std=c89  -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g && { sleep 10 ; echo ; } | ../bin/simple_capture /tmp/a.wav  2>&1 | grep ma_device_read__pulse | uniq -c | sort | uniq -c

In log below :

  • second column: count of consecutive repetitions in plain output
  • sorted numerically by second column
  • first column : number of time the line "second column + text" was observed in total

Without pavucontrol (bug):

      8       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1248
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1696
      4       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=384
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=448
      1     315 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
      1     607 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
      1     626 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
      1    2263 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
      1    4858 [PulseAudio] ma_device_read__pulse: No data available. Waiting.

With pavucontrol (no bug):

   1313       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1056
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1088
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1120
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1184
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1248
     46       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=128
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1280
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1312
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1376
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1408
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1440
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1472
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1536
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1568
     16       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=160
      4       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1632
     13       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1664
     27       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1696
     54       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1728
    872       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
      3       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=192
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=224
      3       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=256
    102       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=32
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=352
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=416
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=448
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=480
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=544
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=576
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=608
     79       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=64
      3       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=672
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=704
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=768
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=800
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=896
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=928
     57       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=96
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=960
      7      18 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
    207      19 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
    261      20 [PulseAudio] ma_device_read__pulse: No data available. Waiting.
     21      21 [PulseAudio] ma_device_read__pulse: No data available. Waiting.

What I read in logs

  • when pavucontrol is absent (bug happens), the program typically writes thousands of times "no data available" between data bits
  • when pavucontrol is active (no bug), the program typically receives about 20 times "no data available" between data bits (is that even normal?)

Interesting: test with latency 100ms

Based on your indication

deviceConfig.bufferSizeInMilliseconds = 1000;

I also tried

deviceConfig.bufferSizeInMilliseconds = 100;

and the result was intermediate: some short streaks of correct sound, stuck one after the other, because most of the continuous audio signal was lost. Total length of audio file was about 10% of wall clock time of recording.

Hunch

It looks like increasing requested latency to 1000ms works around the problem.
Still, feels a band aid that only hints at another problem.

The fact that it works for you on an USB audio device is interesting.

I wonder if it's a device or driver specific thing which doesn't like some kind of parameter miniaudio is using? I'm not sure what's going on...

Yes, the problem might be related to some slightly different (though still correct maybe) behavior in lower layer (ALSA?) depending on whether the device is on-board or USB, or perhaps specific to my hardware.

Machine is pretty ordinary laptop (Asus n551jk).

lspci | grep -i audio

00:03.0 Audio device: Intel Corporation Xeon E3-1200 v3/4th Gen Core Processor HD Audio Controller (rev 06)
00:1b.0 Audio device: Intel Corporation 8 Series/C220 Series Chipset High Definition Audio Controller (rev 05)
  • Is it normal that "ma_device_read__pulse: No data available. Waiting." appears even once?

Where are we ?

  • You asked to increase latency, I did and reported.
  • You asked to try dev branch, I did and reported.

I will try with an USB audio device soon.

Still open to hearing from you.

Hope this helps.

@fidergo-stephane-gourichon
Copy link
Author

Bug reproduced with two audio USB device with different form factors, yet reporting with same USB ID "1b3f:2008 Generalplus Technology Inc."

So, happens not only with internal device, also with USB devices.

Here's pacmd list-source-outputs when using one:

1 source output(s) available.
    index: 66
	driver: <protocol-native.c>
	flags: START_CORKED FIX_FORMAT FIX_RATE FIX_CHANNELS 
	state: RUNNING
	source: 7 <alsa_input.usb-GeneralPlus_USB_Audio_Device-00.analog-mono>
	volume: mono: 65536 / 100% / 0,00 dB
	        balance 0,00
	muted: no
	current latency: 0,00 ms
	requested latency: n/a
	sample spec: s16le 1ch 44100Hz
	channel map: mono
	             Mono
	resample method: (null)
	owner module: 12
	client: 123 <simple_capture>
	properties:
		media.name = "miniaudi0"
		application.name = "simple_capture"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "32"
		application.process.id = "32265"
		application.process.user = "stephane"
		application.process.host = "n551jk"
		application.process.binary = "simple_capture"
		application.language = "C"
		window.x11.display = ":0.0"
		application.process.machine_id = "c420354243104b93b5ce5524c873c531"
		application.process.session_id = "c2"
		module-stream-restore.id = "source-output-by-application-name:simple_capture"

@mackron
Copy link
Owner

mackron commented Jan 3, 2020

I apologise for the delay on this. I have pushed a potential fix to the dev branch with some more debug output (596d9d5). Could you give that a go?

That earlier debug output helped a lot. The way capture should work is that you map a buffer, and then later drop that buffer. I could see from your logs that the buffer wasn't getting dropped. I'm suspecting this is due to what PulseAudio calls "holes", which I think are just chunks of silent audio (not sure why PulseAudio does this). The way miniaudio was handling this was slightly wrong, I think.

when pavucontrol is active (no bug), the program typically receives about 20 times "no data available" between data bits (is that even normal?)

Yes, because in capture mode it needs to continuously poll for data, which miniaudio does every millisecond, and it can take several milliseconds (proportional to the size of the buffer).

I also notice that when stopping the program, the end of the recording is lost, by a length up to the time delta between two batches.

I would expect this. This will be due to a segment being partially filled, but not yet delivered to the program, and then the program stopping the stream. For playback PulseAudio lets you drain the buffer to make sure everything is processed, but there's no equivalent for capture so miniaudio would need to implement the logic manually. I don't think the added maintenance cost is worth it because using a smaller and more realistic buffer size will mitigate the problem.

@fidergo-stephane-gourichon
Copy link
Author

fidergo-stephane-gourichon commented Jan 3, 2020

Hi! Thanks for your reply.

Tried f77f046 (same code as 596d9d5 )

No real progress, no regression observed.

Standard run

As if we did not know the bug existed

gcc ../simple_capture.c          -DMA_DEBUG_OUTPUT=true   -o ../bin/simple_capture          -std=c89  -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g && { sleep 10 ; echo ; } | ../bin/simple_capture /tmp/a.wav  2>&1 | grep ma_device_read__pulse | uniq -c | sort | uniq -c

In file included from ../simple_capture.c:4:
../../miniaudio.h: In function ‘ma_device_read__pulse’:
../../miniaudio.h:16841:20: warning: unused variable ‘readableSizeInBytes’ [-Wunused-variable]
16841 |             size_t readableSizeInBytes;
      |                    ^~~~~~~~~~~~~~~~~~~
      8       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
   8744       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=0
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1408
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1696
      4       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=288
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=384
   8744       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture0

The generated media file has duration 59ms:

mediainfo /tmp/a.wav 

General
Complete name                            : /tmp/a.wav
Format                                   : Wave
File size                                : 20.7 KiB
Duration                                 : 59 ms
Overall bit rate mode                    : Constant
Overall bit rate                         : 2 870 kb/s

Audio
Format                                   : PCM
Format profile                           : Float
Codec ID                                 : 3
Codec ID/Hint                            : IEEE 
Duration                                 : 59 ms
Bit rate mode                            : Constant
Bit rate                                 : 2 822 kb/s
Channel(s)                               : 2 channels
Sampling rate                            : 44.1 kHz
Bit depth                                : 32 bits
Stream size                              : 20.6 KiB (100%)

Running with pavucontrol at some points in time

Recorded file only plays audio that could be heard while pavucontrol was active.
About 6 seconds out of 10 second total run time

gcc ../simple_capture.c          -DMA_DEBUG_OUTPUT=true   -o ../bin/simple_capture          -std=c89  -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g && { sleep 10 ; echo ; } | ../bin/simple_capture /tmp/a.wav  2>&1 | grep ma_device_read__pulse | uniq -c | sort | uniq -c

In file included from ../simple_capture.c:4:
../../miniaudio.h: In function ‘ma_device_read__pulse’:
../../miniaudio.h:16841:20: warning: unused variable ‘readableSizeInBytes’ [-Wunused-variable]
16841 |             size_t readableSizeInBytes;
      |                    ^~~~~~~~~~~~~~~~~~~
    841       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
   9410       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=0
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1024
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1056
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1216
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1280
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1376
      4       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1472
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1568
     99       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1696
    511       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
      3       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=224
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=256
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=32
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=352
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=480
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=576
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=608
     98       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=64
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=640
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=672
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=768
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=800
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=832
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=864
    100       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=96
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=960
   9410       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture0

Thank you for your attention.

@fidergo-stephane-gourichon
Copy link
Author

Tried on another machine.

Bug also occurs there.

cd /localdata/home/stephane/SG/projects/free_software_involvement/bydate/2020/2020-01-03/miniaudio/examples/build/ && gcc ../simple_capture.c          -DMA_DEBUG_OUTPUT=true   -o ../bin/simple_capture          -std=c89  -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g && { sleep 10 ; echo ; } | ../bin/simple_capture /tmp/a.wav  2>&1 | grep ma_device_read__pulse | uniq -c | sort | uniq -c

In file included from ../simple_capture.c:4:0:
../../miniaudio.h: In function ‘ma_device_read__pulse’:
../../miniaudio.h:16841:20: warning: unused variable ‘readableSizeInBytes’ [-Wunused-variable]
             size_t readableSizeInBytes;
                    ^~~~~~~~~~~~~~~~~~~
      2       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
   9207       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=0
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1572
      1       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_peek(). bytesMapped=1760
   9207       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture0

Here's a filtered lshw for that other machine:

export LC_ALL=C ; lshw -class multimedia

  *-multimedia:0            
       description: Audio device
       product: Wrestler HDMI Audio
       vendor: Advanced Micro Devices, Inc. [AMD/ATI]
       physical id: 1.1
       bus info: pci@0000:00:01.1
       version: 00
       width: 32 bits
       clock: 33MHz
       capabilities: pm pciexpress msi bus_master cap_list
       configuration: driver=snd_hda_intel latency=0
       resources: irq:28 memory:feb44000-feb47fff
  *-multimedia:1
       description: Audio device
       product: SBx00 Azalia (Intel HDA)
       vendor: Advanced Micro Devices, Inc. [AMD/ATI]
       physical id: 14.2
       bus info: pci@0000:00:14.2
       version: 40
       width: 64 bits
       clock: 33MHz
       capabilities: pm bus_master cap_list
       configuration: driver=snd_hda_intel latency=32
       resources: irq:16 memory:feb40000-feb43fff

And here's the same for the machine where I've been doing all the tests till now:

export LC_ALL=C ; lshw -class multimedia

  *-multimedia:0            
       description: Audio device
       product: Xeon E3-1200 v3/4th Gen Core Processor HD Audio Controller
       vendor: Intel Corporation
       physical id: 3
       bus info: pci@0000:00:03.0
       version: 06
       width: 64 bits
       clock: 33MHz
       capabilities: pm msi pciexpress bus_master cap_list
       configuration: driver=snd_hda_intel latency=0
       resources: irq:40 memory:f7a14000-f7a17fff
  *-multimedia:1
       description: Audio device
       product: 8 Series/C220 Series Chipset High Definition Audio Controller
       vendor: Intel Corporation
       physical id: 1b
       bus info: pci@0000:00:1b.0
       version: 05
       width: 64 bits
       clock: 33MHz
       capabilities: pm msi pciexpress bus_master cap_list
       configuration: driver=snd_hda_intel latency=0
       resources: irq:39 memory:f7a10000-f7a13fff

@fidergo-stephane-gourichon
Copy link
Author

All tests today on Xubuntu 19.10 running kernel 5.3.0-23-generic, all updates applied, 1:13.0-1ubuntu1, no multimedia-related PPA.

mackron added a commit that referenced this issue Jan 3, 2020
@mackron
Copy link
Owner

mackron commented Jan 3, 2020

Hmm, I thought for sure that would fix it... Another potential fix here, with some extra logging: 3f23492.

With this code I can reproduce one of your issues - the part where the callback isn't fired regularly. However, launching pavucontrol doesn't change anything at all. The way I did this was I just set the buffer size to something small. Are we sure this isn't just due to the buffer size being too small?

@fidergo-stephane-gourichon
Copy link
Author

Maybe epsilon progress, bug still fundamentally there

Tried d1f1983, same behavior here.

With this code I can reproduce one of your issues - the part where the callback isn't fired regularly.

Ah. I don't observe any change, don't know if there is change here.

Dot test

I did the dot test again (rebased my changes on my branch https://github.com/fidergo-stephane-gourichon/miniaudio/commits/issue_106_investigate only one commit is relevant fidergo-stephane-gourichon@2b326bb

I have same behavior: dot appear regularly when pavucontrol runs?

export LC_ALL=C ; git describe --all --long ; gcc ../simple_capture.c         -o ../bin/simple_capture          -std=c89  -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g && ../bin/simple_capture /tmp/a.wav

heads/issue_106_investigate-0-ge4183ce
Press Enter to stop recording...
............................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................

How to assess correct buffer size?

Fun instant: on my latest test I could hear in the recording the click noise of the mouse button that closed pavucontrol, right before no more audio was received.

However, launching pavucontrol doesn't change anything at all.

I confirm again the buggy result here: launching pavucontrol at any time causes audio to be recorded, and closing it causes no more audio to be received.

When pavucontrol is not launched at all, audio file is 9ms long now (3.48kb file size).

The way I did this was I just set the buffer size to something small. Are we sure this isn't just due to the buffer size being too small?

I guess simple_capture.c sets the parameter.
How can I assert if the buffer size is too small?

More logs (gathered)

Below is the result of an adjusted command line (states the git version every time, keeps all log lines -- they output in alphabetical order).

Could it be that:

  • the Blue Yeti has something different that causes the bug not to appear (less probable, here USB devices also reproduce the bug)
  • or the use of a virtual machine prevents the bug from being observed?
export LC_ALL=C ; git describe --all --long ; gcc ../simple_capture.c          -DMA_DEBUG_OUTPUT=true   -o ../bin/simple_capture          -std=c89  -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g && { sleep 10 ; echo ; } | ../bin/simple_capture /tmp/a.wav  2>&1 | uniq -c | sort | uniq -c

heads/dev-0-gd1f1983
      1       1       Channel Routing at Start: NO
      1       1       Channel Routing:          NO
      1       1       Passthrough:              NO
      1       1       Post Format Conversion:   YES
      1       1       Pre Format Conversion:    NO
      1       1       SRC:                      NO
      1       1     Buffer Size: 1320/3 (440)
      1       1     Channels:    2 -> 2
      1       1     Conversion:
      1       1     Format:      32-bit IEEE Floating Point -> 16-bit Signed Integer
      1       1     Sample Rate: 44100 -> 44100
      1       1   Audio interne Stéréo analogique (Capture)
      1       1 Press Enter to stop recording...
      1       1 [PulseAudio]
      1       1 [PulseAudio] Capture actual attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalBufferSizeInFrames=1320
      1       1 [PulseAudio] Capture attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalBufferSizeInFrames=1320
    665       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=104, mappedBufferFramesRemainingCapture=104
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=112, mappedBufferFramesRemainingCapture=112
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=144, mappedBufferFramesRemainingCapture=144
     52       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=16, mappedBufferFramesRemainingCapture=16
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=160, mappedBufferFramesRemainingCapture=160
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=200, mappedBufferFramesRemainingCapture=200
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=208, mappedBufferFramesRemainingCapture=208
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=216, mappedBufferFramesRemainingCapture=216
      2       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=232, mappedBufferFramesRemainingCapture=232
    187       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=24, mappedBufferFramesRemainingCapture=24
      2       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=264, mappedBufferFramesRemainingCapture=264
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=280, mappedBufferFramesRemainingCapture=280
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=304, mappedBufferFramesRemainingCapture=304
      3       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=32, mappedBufferFramesRemainingCapture=32
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=336, mappedBufferFramesRemainingCapture=336
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=344, mappedBufferFramesRemainingCapture=344
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=352, mappedBufferFramesRemainingCapture=352
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=360, mappedBufferFramesRemainingCapture=360
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=368, mappedBufferFramesRemainingCapture=368
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=384, mappedBufferFramesRemainingCapture=384
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=392, mappedBufferFramesRemainingCapture=392
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=400, mappedBufferFramesRemainingCapture=400
     10       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=416, mappedBufferFramesRemainingCapture=416
    121       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=424, mappedBufferFramesRemainingCapture=424
     22       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=432, mappedBufferFramesRemainingCapture=432
    244       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=440, mappedBufferFramesRemainingCapture=440
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=56, mappedBufferFramesRemainingCapture=56
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=64, mappedBufferFramesRemainingCapture=64
      2       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=72, mappedBufferFramesRemainingCapture=72
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=88, mappedBufferFramesRemainingCapture=88
      1       1 [miniaudio] AVX2:    NO
      1       1 [miniaudio] AVX512F: NO
      1       1 [miniaudio] Endian:  LE
      1       1 [miniaudio] NEON:    NO
      1       1 [miniaudio] SSE2:    YES
      2       8 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       9 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
     93      10 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
    293      11 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
     19      12 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     596 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1    1193 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1    3289 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0

Thank you for your attention.

@fidergo-stephane-gourichon
Copy link
Author

fidergo-stephane-gourichon commented Jan 4, 2020

Bug reproduced on a third machine

  • an older laptop
  • on a freshly installed Debian 10.2 (plus some packages I need, but no PPA or special package that could interfere)
  • using default desktop environment Mate

Hardware info

Filtered lshw:

lshw -class multimedia
  *-multimedia              
       description: Audio device
       produit: GT216 HDMI Audio Controller
       fabriquant: NVIDIA Corporation
       identifiant matériel: 0.1
       information bus: pci@0000:01:00.1
       version: a1
       bits: 32 bits
       horloge: 33MHz
       fonctionnalités: pm msi pciexpress bus_master cap_list
       configuration: driver=snd_hda_intel latency=0
       ressources: irq:16 mémoire:fde7c000-fde7ffff
  *-multimedia
       description: Audio device
       produit: 82801I (ICH9 Family) HD Audio Controller
       fabriquant: Intel Corporation
       identifiant matériel: 1b
       information bus: pci@0000:00:1b.0
       version: 03
       bits: 64 bits
       horloge: 33MHz
       fonctionnalités: pm msi pciexpress bus_master cap_list
       configuration: driver=snd_hda_intel latency=0
       ressources: irq:32 mémoire:fbff8000-fbffbfff

Test

Dot test confirmed.

Tested with the monitor mode of audacity, pavucontrol, and the mate "sound preference" app. When focusing on the latter, bug occurs when and only when the "input" tab is visible (and shows input level as a varying number of squares).

git describe --all --long ; gcc ../simple_capture.c   -o ../bin/simple_capture          -std=c11  -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g && ../bin/simple_capture /tmp/a.wav
heads/issue_106_investigate-0-ged74603
Press Enter to stop recording...
...........................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................

Conclusion

So far:

  • all my tests on real machines with attached input or USB input show the bug.
  • all your tests on virtual machines don't reproduce the bug.

May I suggest that you contact me in private? You can find contact info very easily, one click from http://gourichon.org/stephane/ and I'll try to stay connected to this temp audio/video/chat (will not always be in front, just in case, there's no cost anyway).

@mackron
Copy link
Owner

mackron commented Jan 4, 2020

OK, I've got a suspicion this is just a simple matter of the buffer being too small. Considering the experiment we tried earlier where we set the buffer size to something huge seems to have fixed the issue, albeit with more latency, I think it's important to explore this route a bit further. By default miniaudio uses what it calls low-latency mode (10ms per period), however it's also got what it calls a "conservative" mode which uses a larger buffer size (100ms per period). I think we should first try using this mode. To do this, add the following line to the device config:

deviceConfig.performanceProfile = ma_performance_profile_conservative;

That will use a buffer size of 100ms per period which I think will be too much latency, but it'll be a good test. If this works, I would try setting your config like this:

deviceConfig.periods = 3;
deviceConfig.bufferSizeInMilliseconds = 20 * deviceConfig.periods;

That will set the latency to 20ms which is much more reasonable. If this works I'm sure it's just a problem with the buffer size. Whatever it is that causes other programs to affect the behaviour your program is a mystery, but I'm suspecting it's some kind of internal buffer management by PulseAudio.

There's no real way to know for sure what buffer size to use beforehand without testing on target hardware and using the largest buffer size that works for all of them.

@fidergo-stephane-gourichon
Copy link
Author

Ok, done that.

Short version: does not fix.

Commit ids given for reference.

Set conservative profile

Result: recording for automated 10 seconds now produce a file with about 4 seconds of audio. Parts are skipped here and there.

fidergo-stephane-gourichon@5a8c598

export LC_ALL=C ; git describe --all --long ; gcc ../simple_capture.c          -DMA_DEBUG_OUTPUT=true   -o ../bin/simple_capture          -std=c89  -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g && { sleep 10 ; echo ; } | ../bin/simple_capture /tmp/a.wav  2>&1 | uniq -c | sort | uniq -c

heads/issue_106_investigate-0-g5a8c598
      1       1       Channel Routing at Start: NO
      1       1       Channel Routing:          NO
      1       1       Passthrough:              NO
      1       1       Post Format Conversion:   YES
      1       1       Pre Format Conversion:    NO
      1       1       SRC:                      NO
      1       1     Buffer Size: 13200/3 (4400)
      1       1     Channels:    2 -> 2
      1       1     Conversion:
      1       1     Format:      32-bit IEEE Floating Point -> 16-bit Signed Integer
      1       1     Sample Rate: 44100 -> 44100
      1       1   Audio interne Stéréo analogique (Capture)
      1       1 Press Enter to stop recording...
      1       1 [PulseAudio]
      1       1 [PulseAudio] ......................ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] ....ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] Capture actual attr: maxlength=52800, tlength=17600, prebuf=-1, minreq=-1, fragsize=17600; internalBufferSizeInFrames=13200
      1       1 [PulseAudio] Capture attr: maxlength=52800, tlength=17600, prebuf=-1, minreq=-1, fragsize=17600; internalBufferSizeInFrames=13200
      1       1 [PulseAudio] ma_device_......................read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__..............pulse: Call pa_stream_drop()
     69       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. map......................pedBufferFramesCapacityCapture=4400, mappedBufferFramesRemainingCapture=4400
      2       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=1024, mappedBufferFramesRemainingCapture=1024
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=1064, mappedBufferFramesRemainingCapture=1064
      2       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=120, mappedBufferFramesRemainingCapture=120
      2       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=1256, mappedBufferFramesRemainingCapture=1256
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=1296, mappedBufferFramesRemainingCapture=1296
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=1576, mappedBufferFramesRemainingCapture=1576
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=160, mappedBufferFramesRemainingCapture=160
      2       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=1608, mappedBufferFramesRemainingCapture=1608
      2       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=1888, mappedBufferFramesRemainingCapture=1888
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=1928, mappedBufferFramesRemainingCapture=1928
      2       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=2120, mappedBufferFramesRemainingCapture=2120
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=2160, mappedBufferFramesRemainingCapture=2160
      2       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=2512, mappedBufferFramesRemainingCapture=2512
      2       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=3024, mappedBufferFramesRemainingCapture=3024
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=3064, mappedBufferFramesRemainingCapture=3064
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=3376, mappedBufferFramesRemainingCapture=3376
      2       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=3888, mappedBufferFramesRemainingCapture=3888
      3       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=392, mappedBufferFramesRemainingCapture=392
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=3928, mappedBufferFramesRemainingCapture=3928
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=4280, mappedBufferFramesRemainingCapture=4280
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=4400, mappedBufferF...........................ramesRemainingCapture=4400
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=4400, mappedBufferFramesRemainingCaptur..............e=4400
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=4400, mappedBufferFramesRemainingCapture=44......................00
     32       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=4400, mappedBufferFramesRemainingCapture=4400
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=672, mappedBufferFramesRemainingCapture=672
      2       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=744, mappedBufferFramesRemainingCapture=744
      1       1 [PulseAudio] ma_device_read__pulse: N.......................o data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      2       1 [PulseAudio] ma_device_read__pulse: No data ava...........................ilable. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Wa..........................iting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Wait.........ing. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. map.........pedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferF.....ramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFrame....sCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapac...........................ityCapture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacit.......................yCapture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBuff.......................erFramesRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFram....esRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFrames.......................RemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRe.......................mainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingC.......................apture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0......................, mappedBufferFramesRemainingCapture=0
      2       1 [miniaudio] AVX2:    NO
      2       1 [miniaudio] AVX512F: NO
      2       1 [miniaudio] Endian:  LE
      2       1 [miniaudio] NEON:    NO
      2       1 [miniaudio] SSE2:    YES
      1       2 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       3 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       4 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       5 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       6 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       9 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1      10 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      2      11 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1      13 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      2      14 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      2      18 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      2      21 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      2      27 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1      28 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     180 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     286 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     290 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     292 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      3     293 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     300 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      2     303 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     304 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      2     307 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     308 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     309 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      2     310 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     312 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     314 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     317 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     318 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     319 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     320 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     322 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     324 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     597 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     636 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
mediainfo /tmp/a.wav 

General
Complete name                            : /tmp/a.wav
Format                                   : Wave
File size                                : 1.66 MiB
Duration                                 : 4 s 935 ms
Overall bit rate mode                    : Constant
Overall bit rate                         : 2 823 kb/s

Audio
Format                                   : PCM
Format profile                           : Float
Codec ID                                 : 3
Codec ID/Hint                            : IEEE 
Duration                                 : 4 s 935 ms
Bit rate mode                            : Constant
Bit rate                                 : 2 822 kb/s
Channel(s)                               : 2 channels
Sampling rate                            : 44.1 kHz
Bit depth                                : 32 bits
Stream size                              : 1.66 MiB (100%)

3 periods * 20 milliseconds

fidergo-stephane-gourichon@8fd94d9

Result: recording for automated 10 seconds now produce a file with about 0.3 seconds of audio.

export LC_ALL=C ; git describe --all --long ; gcc ../simple_capture.c          -DMA_DEBUG_OUTPUT=true   -o ../bin/simple_capture          -std=c89  -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g && { sleep 10 ; echo ; } | ../bin/simple_capture /tmp/a.wav  2>&1 | uniq -c | sort | uniq -c

heads/issue_106_investigate-0-g8fd94d9
      1       1       Channel Routing at Start: NO
      1       1       Channel Routing:          NO
      1       1       Passthrough:              NO
      1       1       Post Format Conversion:   YES
      1       1       Pre Format Conversion:    NO
      1       1       SRC:                      NO
      1       1     Buffer Size: 2640/3 (880)
      1       1     Channels:    2 -> 2
      1       1     Conversion:
      1       1     Format:      32-bit IEEE Floating Point -> 16-bit Signed Integer
      1       1     Sample Rate: 44100 -> 44100
      1       1   Audio interne Stéréo analogique (Capture)
      1       1 Press Enter to stop recording...
      1       1 [PulseAudio]
      1       1 [PulseAudio] ....ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] Capture actual attr: maxlength=10560, tlength=3520, prebuf=-1, minreq=-1, fragsize=3520; internalBufferSizeInFrames=2640
      1       1 [PulseAudio] Capture attr: maxlength=10560, tlength=3520, prebuf=-1, minreq=-1, fragsize=3520; internalBufferSizeInFrames=2640
      1       1 [PulseAudio] ma_device_read__puls....e: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
     18       1 [PulseAudio] ma_device_read__pulse: Call pa_stream_drop()
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=376, mappedBufferFramesRemainingCapture=376
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=392, mappedBufferFramesRemainingCapture=392
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=400, mappedBufferFramesRemainingCapture=400
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=496, mappedBufferFramesRemainingCapture=496
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=512, mappedBufferFramesRemainingCapture=512
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=520, mappedBufferFramesRemainingCapture=520
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=848, mappedBufferFramesRemainingCapture=848
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=864, mappedBufferFramesRemainingCapture=864
      1       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=872, mappedBufferFramesRemainingCapture=872
      9       1 [PulseAudio] ma_device_read__pulse: Mapped. mappedBufferFramesCapacityCapture=880, mappedBufferFramesRemainingCapture=880
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. map..pedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferF......ramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityC......apture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCap..ture=0, mappedBufferFramesRemainingCapture=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture......=0
      1       1 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      2       1 [miniaudio] AVX2:    NO
      2       1 [miniaudio] AVX512F: NO
      2       1 [miniaudio] Endian:  LE
      2       1 [miniaudio] NEON:    NO
      2       1 [miniaudio] SSE2:    YES
      1       4 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       8 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1       9 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1      11 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1      15 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     313 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     319 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     321 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     324 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     327 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     331 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     644 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1     658 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1    2116 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
      1    3935 [PulseAudio] ma_device_read__pulse: No data available. Waiting. mappedBufferFramesCapacityCapture=0, mappedBufferFramesRemainingCapture=0
mediainfo /tmp/a.wav 

General
Complete name                            : /tmp/a.wav
Format                                   : Wave
File size                                : 103 KiB
Duration                                 : 299 ms
Overall bit rate mode                    : Constant
Overall bit rate                         : 2 827 kb/s

Audio
Format                                   : PCM
Format profile                           : Float
Codec ID                                 : 3
Codec ID/Hint                            : IEEE 
Duration                                 : 299 ms
Bit rate mode                            : Constant
Bit rate                                 : 2 822 kb/s
Channel(s)                               : 2 channels
Sampling rate                            : 44.1 kHz
Bit depth                                : 32 bits
Stream size                              : 103 KiB (100%)

@mackron mackron mentioned this issue Sep 12, 2020
9 tasks
mackron added a commit that referenced this issue Nov 1, 2020
  * The main loop is now handled properly by pa_threaded_mainloop.
  * Rather than waiting for operations to complete inline, the main
    loop is now iterated on a separate thread.
  * Data is now written and read to and from the relevant stream via
    callbacks rather than a hacky loop.
  * Code overall has been simplified.
  * Includes a rant about bad API design in PulseAudio.

This should hopefully address these public issues:

  * #106
  * #187
@mackron
Copy link
Owner

mackron commented Nov 1, 2020

I'm not sure if you're still using miniaudio, but I've finally got around to doing a complete refactor of the PulseAudio backend. If you're still interested in this, are you able to give that another try? The changes are currently in the dev branch.

@fidergo-stephane-gourichon
Copy link
Author

Hi!

Tested on yet another computer, running Xubuntu 20.04 and 1:13.99.1-1ubuntu3.7 .

Summary: same behavior (bug/no bug depending on environment)

lshw output:

  *-multimedia
       description: Audio device
       product: Intel Corporation
       vendor: Intel Corporation
       physical id: 1f.3
       bus info: pci@0000:00:1f.3
       version: 00
       width: 64 bits
       clock: 33MHz
       capabilities: pm msi bus_master cap_list
       configuration: driver=snd_hda_intel latency=32
       resources: iomemory:600-5ff iomemory:600-5ff irq:171 memory:6026100000-6026103fff memory:6026000000-60260fffff

Thanks for the long explanation about the Pulseaudio API visible in source code. It is very instructive.
I understand your frustration given how async APIs are complicated to deal with.

(
    set -xv
    export LC_ALL=C
    git describe --all --long
    gcc ../simple_capture.c \
    -DMA_DEBUG_OUTPUT=true \
    -o ../bin/simple_capture \
    -std=c89 \
    -Wall -Wpedantic -pedantic \
    -lpthread -ldl -lm -g \
     && \
     { sleep 10 ; echo ; } \
     | ../bin/simple_capture /tmp/a.wav
     mediainfo  /tmp/a.wav
)

produces this output:

+ export LC_ALL=C
+ LC_ALL=C
+ git describe --all --long
heads/dev-0-gc844455
+ gcc ../simple_capture.c -DMA_DEBUG_OUTPUT=true -o ../bin/simple_capture -std=c89 -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g
+ sleep 10
+ ../bin/simple_capture /tmp/a.wav
[miniaudio] Endian:  LE
[miniaudio] SSE2:    YES
[miniaudio] AVX2:    NO
[miniaudio] AVX512F: NO
[miniaudio] NEON:    NO
[PulseAudio] Capture attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalPeriodSizeInFrames=440
[PulseAudio] Capture actual attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalPeriodSizeInFrames=440
Press Enter to stop recording...
+ echo
+ mediainfo /tmp/a.wav
General
Complete name                            : /tmp/a.wav
Format                                   : Wave
File size                                : 22.4 KiB
Duration                                 : 64 ms
Overall bit rate mode                    : Constant
Overall bit rate                         : 2 862 kb/s

Audio
Format                                   : PCM
Format profile                           : Float
Codec ID                                 : 3
Codec ID/Hint                            : IEEE
Duration                                 : 64 ms
Bit rate mode                            : Constant
Bit rate                                 : 2 822 kb/s
Channel(s)                               : 2 channels
Sampling rate                            : 44.1 kHz
Bit depth                                : 32 bits
Stream size                              : 22.3 KiB (100%)

but if pavucontrol is running, the output is this:

+ export LC_ALL=C
+ LC_ALL=C
+ git describe --all --long
heads/dev-0-gc844455
+ gcc ../simple_capture.c -DMA_DEBUG_OUTPUT=true -o ../bin/simple_capture -std=c89 -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g
+ sleep 10
+ ../bin/simple_capture /tmp/a.wav
[miniaudio] Endian:  LE
[miniaudio] SSE2:    YES
[miniaudio] AVX2:    NO
[miniaudio] AVX512F: NO
[miniaudio] NEON:    NO
[PulseAudio] Capture attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalPeriodSizeInFrames=440
[PulseAudio] Capture actual attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalPeriodSizeInFrames=440
Press Enter to stop recording...
+ echo
+ mediainfo /tmp/a.wav
General
Complete name                            : /tmp/a.wav
Format                                   : Wave
File size                                : 3.36 MiB
Duration                                 : 9 s 977 ms
Overall bit rate mode                    : Constant
Overall bit rate                         : 2 823 kb/s

Audio
Format                                   : PCM
Format profile                           : Float
Codec ID                                 : 3
Codec ID/Hint                            : IEEE
Duration                                 : 9 s 977 ms
Bit rate mode                            : Constant
Bit rate                                 : 2 822 kb/s
Channel(s)                               : 2 channels
Sampling rate                            : 44.1 kHz
Bit depth                                : 32 bits
Stream size                              : 3.36 MiB (100%)

@mackron
Copy link
Owner

mackron commented Nov 2, 2020

That's a shame. I was hoping the refactor would coincidentally fix it. Could you try this variation of the simple_capture example? The main part I care about is the tryAutoSpawn config variable in the context config.

#define MINIAUDIO_IMPLEMENTATION
#include "../miniaudio.h"

#include <stdlib.h>
#include <stdio.h>

void data_callback(ma_device* pDevice, void* pOutput, const void* pInput, ma_uint32 frameCount)
{
    ma_encoder* pEncoder = (ma_encoder*)pDevice->pUserData;
    MA_ASSERT(pEncoder != NULL);

    ma_encoder_write_pcm_frames(pEncoder, pInput, frameCount);

    (void)pOutput;
}

int main(int argc, char** argv)
{
    ma_result result;
    ma_encoder_config encoderConfig;
    ma_encoder encoder;
    ma_device_config deviceConfig;
    ma_device device;
    ma_context_config contextConfig;

    if (argc < 2) {
        printf("No input file.\n");
        return -1;
    }

    encoderConfig = ma_encoder_config_init(ma_resource_format_wav, ma_format_f32, 2, 44100);

    if (ma_encoder_init_file(argv[1], &encoderConfig, &encoder) != MA_SUCCESS) {
        printf("Failed to initialize output file.\n");
        return -1;
    }


    contextConfig = ma_context_config_init();
    contextConfig.pulse.tryAutoSpawn = MA_TRUE;

    deviceConfig = ma_device_config_init(ma_device_type_capture);
    deviceConfig.capture.format   = encoder.config.format;
    deviceConfig.capture.channels = encoder.config.channels;
    deviceConfig.sampleRate       = encoder.config.sampleRate;
    deviceConfig.dataCallback     = data_callback;
    deviceConfig.pUserData        = &encoder;

    result = ma_device_init_ex(NULL, 0, &contextConfig, &deviceConfig, &device);
    if (result != MA_SUCCESS) {
        printf("Failed to initialize capture device.\n");
        return -2;
    }

    result = ma_device_start(&device);
    if (result != MA_SUCCESS) {
        ma_device_uninit(&device);
        printf("Failed to start device.\n");
        return -3;
    }

    printf("Press Enter to stop recording...\n");
    getchar();
    
    ma_device_uninit(&device);
    ma_encoder_uninit(&encoder);

    return 0;
}

@fidergo-stephane-gourichon
Copy link
Author

Hi!

Your changes

Ok, I see this diff:

diff -u ../simple_capture.c  ../106_issuecomment-720287517.c

--- ../simple_capture.c	2020-11-01 06:44:10.989571518 +0100
+++ ../106_issuecomment-720287517.c	2020-11-02 08:51:16.778070015 +0100
@@ -1,13 +1,3 @@
-/*
-Demonstrates how to capture data from a microphone using the low-level API.
-
-This example simply captures data from your default microphone until you press Enter. The output is saved to the file
-specified on the command line.
-
-Capturing works in a very similar way to playback. The only difference is the direction of data movement. Instead of
-the application sending data to the device, the device will send data to the application. This example just writes the
-data received by the microphone straight to a WAV file.
-*/
 #define MINIAUDIO_IMPLEMENTATION
 #include "../miniaudio.h"
 
@@ -31,6 +21,7 @@
     ma_encoder encoder;
     ma_device_config deviceConfig;
     ma_device device;
+    ma_context_config contextConfig;
 
     if (argc < 2) {
         printf("No input file.\n");
@@ -44,6 +35,10 @@
         return -1;
     }
 
+
+    contextConfig = ma_context_config_init();
+    contextConfig.pulse.tryAutoSpawn = MA_TRUE;
+
     deviceConfig = ma_device_config_init(ma_device_type_capture);
     deviceConfig.capture.format   = encoder.config.format;
     deviceConfig.capture.channels = encoder.config.channels;
@@ -51,7 +46,7 @@
     deviceConfig.dataCallback     = data_callback;
     deviceConfig.pUserData        = &encoder;
 
-    result = ma_device_init(NULL, &deviceConfig, &device);
+    result = ma_device_init_ex(NULL, 0, &contextConfig, &deviceConfig, &device);
     if (result != MA_SUCCESS) {
         printf("Failed to initialize capture device.\n");
         return -2;
@@ -66,7 +61,7 @@
 
     printf("Press Enter to stop recording...\n");
     getchar();
-    
+
     ma_device_uninit(&device);
     ma_encoder_uninit(&encoder); 

Script for easy reproducible results

#!/bin/sh

(
    set -xv
    set -eu
    SRC=${1:-../simple_capture.c}
    SRCFILENAME="${SRC##*/}"
    STEM="${SRCFILENAME%.c}"
    export LC_ALL=C
    git describe --all --long
    gcc "${SRC}" \
        -DMA_DEBUG_OUTPUT=true \
        -o ../bin/"${STEM}" \
        -std=c89 \
        -Wall -Wpedantic -pedantic \
        -lpthread -ldl -lm -g

    { sleep 10 ; echo ; } \
        | ../bin/"${STEM}" /tmp/${STEM}.wav

    mediainfo /tmp/${STEM}.wav
)

Run with same miniaudio as before c844455

bash test_miniaudio.sh ../106_issuecomment-720287517.c 

+ set -eu
+ SRC=../106_issuecomment-720287517.c
+ SRCFILENAME=106_issuecomment-720287517.c
+ STEM=106_issuecomment-720287517
+ export LC_ALL=C
+ LC_ALL=C
+ git describe --all --long
heads/dev-0-gc844455
+ gcc ../106_issuecomment-720287517.c -DMA_DEBUG_OUTPUT=true -o ../bin/106_issuecomment-720287517 -std=c89 -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g
+ sleep 10
+ ../bin/106_issuecomment-720287517 /tmp/106_issuecomment-720287517.wav
[miniaudio] Endian:  LE
[miniaudio] SSE2:    YES
[miniaudio] AVX2:    NO
[miniaudio] AVX512F: NO
[miniaudio] NEON:    NO
[PulseAudio] Capture attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalPeriodSizeInFrames=440
[PulseAudio] Capture actual attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalPeriodSizeInFrames=440
Press Enter to stop recording...
+ echo
+ mediainfo /tmp/106_issuecomment-720287517.wav
General
Complete name                            : /tmp/106_issuecomment-720287517.wav
Format                                   : Wave
File size                                : 22.9 KiB
Duration                                 : 66 ms
Overall bit rate mode                    : Constant
Overall bit rate                         : 2 845 kb/s

Audio
Format                                   : PCM
Format profile                           : Float
Codec ID                                 : 3
Codec ID/Hint                            : IEEE 
Duration                                 : 66 ms
Bit rate mode                            : Constant
Bit rate                                 : 2 822 kb/s
Channel(s)                               : 2 channels
Sampling rate                            : 44.1 kHz
Bit depth                                : 32 bits
Stream size                              : 22.9 KiB (100%)

Run with latest dev 27a7fea

+ set -eu
+ SRC=../106_issuecomment-720287517.c
+ SRCFILENAME=106_issuecomment-720287517.c
+ STEM=106_issuecomment-720287517
+ export LC_ALL=C
+ LC_ALL=C
+ git describe --all --long
heads/dev-0-g27a7fea
+ gcc ../106_issuecomment-720287517.c -DMA_DEBUG_OUTPUT=true -o ../bin/106_issuecomment-720287517 -std=c89 -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g
+ sleep 10
+ ../bin/106_issuecomment-720287517 /tmp/106_issuecomment-720287517.wav
[miniaudio] Endian:  LE
[miniaudio] SSE2:    YES
[miniaudio] AVX2:    NO
[miniaudio] AVX512F: NO
[miniaudio] NEON:    NO
[PulseAudio] Capture attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalPeriodSizeInFrames=440
[PulseAudio] Capture actual attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalPeriodSizeInFrames=440
Press Enter to stop recording...
+ echo
+ mediainfo /tmp/106_issuecomment-720287517.wav
General
Complete name                            : /tmp/106_issuecomment-720287517.wav
Format                                   : Wave
File size                                : 21.2 KiB
Duration                                 : 61 ms
Overall bit rate mode                    : Constant
Overall bit rate           the               : 2 851 kb/s

Audio
Format                                   : PCM
Format profile                           : Float
Codec ID                                 : 3
Codec ID/Hint                            : IEEE 
Duration                                 : 61 ms
Bit rate mode                            : Constant
Bit rate                                 : 2 822 kb/s
Channel(s)                               : 2 channels
Sampling rate                            : 44.1 kHz
Bit depth                                : 32 bits
Stream size                              : 21.2 KiB (100%)

Conclusion

This is puzzling how given your knowledge of the API, things work your side on all your tests, and on none of my machines (at least 4 machines tested so far, plus 2 USB devices). (IIRC you test only in VMs accessing a real USB device?)

Looks like the thing to try would be to trace the API calls and replies of the simplest working pulseaudio client that records sound, and compare with what simple_capture does?

Also, my setup is very basic: *ubuntu, default kernel, common sound devices. Nothing fancy really.

I'm okay to do more tests, still. Keep up the good work!

@mackron
Copy link
Owner

mackron commented Nov 2, 2020

I think it'll come down to something simple. I've had another similar report as well: #187 which I think could be related. I'm asking my (small) community if anybody is using capture with PulseAudio as well. It may well be the I'm the outlier. This is certainly an annoying one!

@mackron
Copy link
Owner

mackron commented Nov 2, 2020

OK, good news. I was able to reproduce this. The bad news is that I have no idea how to actually fix it. Will continue working on this throughout the week.

mackron added a commit that referenced this issue Nov 3, 2020
This should fix the following puplic issues:

  * #106
  * #187
@mackron
Copy link
Owner

mackron commented Nov 3, 2020

OK, I've fixed this on my computer. Are you able to get that another try to confirm it's working for you? Here's the commit: 2dc604e.

Changes are in the dev branch.

@fidergo-stephane-gourichon
Copy link
Author

OK, I've fixed this on my computer. Are you able to get that another try to confirm it's working for you?

Yes!

And the audio file seems fine, no glitch, no cut, nearly 10s long.

Here's the commit: 2dc604e.

So it's all about MA_PA_STREAM_ADJUST_LATENCY ?

I'd be interested in an explanation.

Here's the log, same test condition as previous:

bash test_miniaudio.sh

+ set -eu
+ SRC=../simple_capture.c
+ SRCFILENAME=simple_capture.c
+ STEM=simple_capture
+ export LC_ALL=C
+ LC_ALL=C
+ git describe --all --long
heads/dev-0-g0d0f7e4
+ gcc ../simple_capture.c -DMA_DEBUG_OUTPUT=true -o ../bin/simple_capture -std=c89 -Wall -Wpedantic -pedantic -lpthread -ldl -lm -g
+ sleep 10
+ ../bin/simple_capture /tmp/simple_capture.wav
[miniaudio] Endian:  LE
[miniaudio] SSE2:    YES
[miniaudio] AVX2:    NO
[miniaudio] AVX512F: NO
[miniaudio] NEON:    NO
[PulseAudio] Capture attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalPeriodSizeInFrames=440
[PulseAudio] Capture actual attr: maxlength=5280, tlength=1760, prebuf=-1, minreq=-1, fragsize=1760; internalPeriodSizeInFrames=440
Press Enter to stop recording...
+ echo
+ mediainfo /tmp/simple_capture.wav
General
Complete name                            : /tmp/simple_capture.wav
Format                                   : Wave
File size                                : 3.36 MiB
Duration                                 : 9 s 995 ms
Overall bit rate mode                    : Constant
Overall bit rate                         : 2 822 kb/s

Audio
Format                                   : PCM
Format profile                           : Float
Codec ID                                 : 3
Codec ID/Hint                            : IEEE 
Duration                                 : 9 s 995 ms
Bit rate mode                            : Constant
Bit rate                                 : 2 822 kb/s
Channel(s)                               : 2 channels
Sampling rate                            : 44.1 kHz
Bit depth                                : 32 bits
Stream size                              : 3.36 MiB (100%)

@mackron
Copy link
Owner

mackron commented Nov 3, 2020

Great! Yes, all down to PA_STREAM_ADJUST_LATENCY. I have no explanation at all as to why that flag is necessary - I just discovered it through trial and error.

I'll leave this issue open until I get this released which should hopefully be tomorrow night (one last unrelated thing to do). Thanks a lot for all of your work and patience on this one!

@mackron
Copy link
Owner

mackron commented Nov 8, 2020

This has been released. I'm going to go ahead and close this one with great pleasure. Thanks a lot for all your work on this one!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants