Closed mkkot closed 2 years ago
What is also found out is:
[mk@linux ~]$ pacmd list-sources |grep 'name: <alsa_input.pci-0000_04_00.0.iec958-stereo>' -A60 |grep 'configured latency'
configured latency: 1837.33 ms; range is 0.50 .. 1837.33 ms
[mk@linux ~]$ pavucontrol &
[1] 4179
[mk@linux ~]$ pacmd list-sources |grep 'name: <alsa_input.pci-0000_04_00.0.iec958-stereo>' -A60 |grep 'configured latency'
configured latency: 40.00 ms; range is 0.50 .. 1837.33 ms
Hello,
That's a very odd problem.
Can you provide the output when you run the audio_async_loopback program? From a data flow perspective, the program is fairly straight forward. It opens the source specified on the command line, reads samples, then writes samples to the default Pulseaudio sink (which is opened by passing NULL as the 4th argument to pa_simple_new). My guess is that something is going on with the sink.
I'm thinking this might be caused by the "suspend-on-idle" module. Can you comment out "load-module module-suspend-on-idle" in /etc/pulse/default.pa, reboot, and give it a try?
If that works, then perhaps my program can be modified to feed 0 value samples to the sink if nothing is coming in. As of now, if input samples stop coming in for whatever reason, the output buffer will eventually drain and no samples will be written to the sink. Perhaps we could do something like sending an additional periodic signal to the sink output thread, which can then check to see the last time any samples were written, and if some threshold has elapsed, write a block of 0 value samples.
Hey Jacob, thanks for your answer. The output is not very helpful:
INIT: Received 64 chunks without a single IEC 61937 data burst; assuming PCM
Using default sink buffer size of 10240 bytes
I commented out the module but that doesn't change a thing.
Actually I don't think the problem is there as the source is always in running state anyway:
pacmd list-sources |grep 'name: <alsa_input.pci-0000_04_00.0.iec958-stereo>' -A60
name: <alsa_input.pci-0000_04_00.0.iec958-stereo>
driver: <module-alsa-card.c>
flags: HARDWARE DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
state: RUNNING
suspend cause: (none)
priority: 9037
volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
balance 0.00
base volume: 65536 / 100% / 0.00 dB
volume steps: 65537
muted: no
current latency: 144.65 ms
max rewind: 0 KiB
sample spec: s16le 2 k 48000 Hz
channel map: front-left,front-right
Stereo
used by: 1
linked by: 1
configured latency: 1837.33 ms; range is 0.50 .. 1837.33 ms
card: 0 <alsa_card.pci-0000_04_00.0>
module: 6
properties:
alsa.resolution_bits = "16"
device.api = "alsa"
device.class = "sound"
alsa.class = "generic"
alsa.subclass = "generic-mix"
alsa.name = "CA0132 Digital"
alsa.id = "CA0132 Digital"
alsa.subdevice = "0"
alsa.subdevice_name = "subdevice #0"
alsa.device = "1"
alsa.card = "0"
alsa.card_name = "HDA Creative"
alsa.long_card_name = "HDA Creative at 0xfcd04000 irq 33"
alsa.driver_name = "snd_hda_intel"
device.bus_path = "pci-0000:04:00.0"
sysfs.path = "/devices/pci0000:00/0000:00:02.1/0000:01:00.2/0000:02:01.0/0000:04:00.0/sound/card0"
device.bus = "pci"
device.vendor.id = "1102"
device.vendor.name = "Creative Labs"
device.product.id = "0012"
device.product.name = "Sound Core3D [Sound Blaster Recon3D / Z-Series] (SB1570 SB Audigy Fx)"
device.string = "iec958:0"
device.buffering.buffer_size = "352768"
device.buffering.fragment_size = "176384"
device.access_mode = "mmap+timer"
device.profile.name = "iec958-stereo"
device.profile.description = "Cyfrowe stereo (IEC958)"
device.description = "Sound Core3D [Sound Blaster Recon3D / Z-Series] (SB1570 SB Audigy Fx) Cyfrowe stereo (IEC958)"
module-udev-detect.discovered = "1"
device.icon_name = "audio-card-pci"
ports:
iec958-stereo-input: Digital Input (S/PDIF) (priority 0, latency offset 0 usec, available: unknown)
properties:
active port: <iec958-stereo-input>
index: 2
name: <alsa_output.pci-0000_08_00.1.hdmi-stereo.monitor>
driver: <module-alsa-card.c>
flags: DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
Interesting. Can you grab the output of pulseaudio -vvvv as the audio_async_loopback program is running (but without pavucontrol running)? I'm curious to see what is actually happening as the sound is disappearing and coming back. If you could make a note of any messages that correlate in time with the audio leaving and coming back, that would help too. Also, you're probably already aware, but you'll have to disable autospawn and manually kill pulseaudio before running "pulseaudio -vvvv".
Another thing you can try is to manually specify the sink name string as the 4th argument to pa_simple_new in pcm_sink.c. It's worth a shot.
Jacob, I successfully compiled audio_async_loopback with hardcoded sink alsa_output.pci-0000_04_00.0.analog-stereo. The effect was identical, though.
About pulseaudio -vvv... it's very chatty. So I'm pasting the fragment that is repeating all the time, regardless if sound is played or not. I think the frequency of those messages correspond to the "chokes":
D: [alsa-sink-CA0132 Analog] source.c: Processing rewind...
D: [alsa-sink-CA0132 Analog] protocol-native.c: Implicit underrun of 'Audio Async Loopback'
D: [alsa-sink-CA0132 Analog] sink.c: alsa_output.pci-0000_04_00.0.analog-stereo: Found underrun 1268 bytes ago (1268 bytes ahead in playback buffer)
D: [alsa-sink-CA0132 Analog] sink.c: alsa_output.pci-0000_04_00.0.analog-stereo: Found underrun 1268 bytes ago (1224 bytes ahead in playback buffer)
D: [alsa-sink-CA0132 Analog] sink.c: alsa_output.pci-0000_04_00.0.analog-stereo: Found underrun 1268 bytes ago (1216 bytes ahead in playback buffer)
D: [alsa-sink-CA0132 Analog] protocol-native.c: Requesting rewind due to end of underrun.
D: [alsa-sink-CA0132 Analog] alsa-sink.c: Requested to rewind 2556 bytes.
D: [alsa-sink-CA0132 Analog] alsa-sink.c: Limited to 2048 bytes.
D: [alsa-sink-CA0132 Analog] alsa-sink.c: before: 512
D: [alsa-sink-CA0132 Analog] alsa-sink.c: after: 512
D: [alsa-sink-CA0132 Analog] alsa-sink.c: Rewound 2048 bytes.
With pavucontrol is enabled I can see tons of messages like bellow when audio_async_loopback starts:
: [alsa-sink-CA0132 Analog] sink.c: alsa_output.pci-0000_04_00.0.analog-stereo: Found underrun 776 bytes ago (1556 bytes ahead in playback buffer)
D: [alsa-sink-CA0132 Analog] sink.c: alsa_output.pci-0000_04_00.0.analog-stereo: Found underrun 776 bytes ago (1552 bytes ahead in playback buffer)
D: [alsa-sink-CA0132 Analog] sink.c: alsa_output.pci-0000_04_00.0.analog-stereo: Found underrun 776 bytes ago (1548 bytes ahead in playback buffer)
D: [alsa-sink-CA0132 Analog] sink.c: alsa_output.pci-0000_04_00.0.analog-stereo: Found underrun 776 bytes ago (1548 bytes ahead in playback buffer)
D: [alsa-sink-CA0132 Analog] sink.c: alsa_output.pci-0000_04_00.0.analog-stereo: Found underrun 1956 bytes ago (380 bytes ahead in playback buffer)
D: [alsa-sink-CA0132 Analog] sink.c: alsa_output.pci-0000_04_00.0.analog-stereo: Found underrun 1956 bytes ago (156 bytes ahead in playback buffer)
D: [alsa-sink-CA0132 Analog] sink.c: alsa_output.pci-0000_04_00.0.analog-stereo: Found underrun 1956 bytes ago (144 bytes ahead in playback buffer)
D: [alsa-sink-CA0132 Analog] protocol-native.c: Requesting rewind due to end of underrun.
D: [alsa-sink-CA0132 Analog] alsa-sink.c: Requested to rewind 2348 bytes.
D: [alsa-sink-CA0132 Analog] alsa-sink.c: Limited to 2076 bytes.
D: [alsa-sink-CA0132 Analog] alsa-sink.c: before: 519
D: [alsa-sink-CA0132 Analog] alsa-sink.c: after: 519
D: [alsa-sink-CA0132 Analog] alsa-sink.c: Rewound 2076 bytes.
D: [alsa-sink-CA0132 Analog] sink.c: Processing rewind...
D: [alsa-sink-CA0132 Analog] sink.c: latency = 21702
D: [alsa-sink-CA0132 Analog] sink-input.c: Have to rewind 2076 bytes on render memblockq.
D: [alsa-sink-CA0132 Analog] source.c: Processing rewind...
What is different, when pavucontrol is enabled, those messages stop after few seconds. Then, when I start playing sound, NO new messages are shown.
I see a bunch of under-runs which is a sign that the clock domain compensation might not be working properly, perhaps due to scheduling jitter or something. I initially tuned the loop and buffer target values on my system to achieve as low of latency as possible. Unfortunately, I can't really test that without your exact hardware, but what I can say is that I also experience some discontinuities when I attempt to run this on my laptop.
As a quick hack, you could try the following:
#define DEBUG
on line 22 of config.hPCM_SINK_BUFFER_TARGET_SAMPLES
and PCM_SINK_SAMPLE_BUFFER_SIZE
values on line 69 and 75 of config.h by 256.If any of these help, it's a sign that it could at least be fixed. That said, I'd probably want to switch over to Pipewire before investing too much time into making this work better with Pulseaudio.
I enabled debug and typical output looks like:
Buffer: 2047 Ratio: 0.999744 Avg: -128
FYI when I started using your app I've changed line 93 to
#define PCM_SINK_PA_BUFFER_SIZE 10240u /* 26.5 milliseconds */
and this is my normal setup since lower values crack.
Now, after increasing PCM_SINK_BUFFER_TARGET_SAMPLES and PCM_SINK_SAMPLE_BUFFER_SIZE there is improvement, sound is not interrupted anymore (or this can be barely heard). However, the delay is few seconds and I don't think this is the way to proceed.
Regardless those values increased I can still observe those messages appearing every few seconds:
D: [alsa-sink-CA0132 Analog] protocol-native.c: Implicit underrun of 'Audio Async Loopback'
D: [alsa-sink-CA0132 Analog] sink.c: alsa_output.pci-0000_04_00.0.analog-stereo: Found underrun 1208 bytes ago (1332 bytes ahead in playback buffer)
D: [alsa-sink-CA0132 Analog] sink.c: alsa_output.pci-0000_04_00.0.analog-stereo: Found underrun 1208 bytes ago (1288 bytes ahead in playback buffer)
D: [alsa-sink-CA0132 Analog] sink.c: alsa_output.pci-0000_04_00.0.analog-stereo: Found underrun 1208 bytes ago (1276 bytes ahead in playback buffer)
D: [alsa-sink-CA0132 Analog] protocol-native.c: Requesting rewind due to end of underrun.
D: [alsa-sink-CA0132 Analog] alsa-sink.c: Requested to rewind 2556 bytes.
I reverted those changes and opened pavucontrol. The debugging output printing speed increased like 3 times and those are values I can see:
Buffer: 1019 Ratio: 0.999753 Avg: -123
Buffer: 1275 Ratio: 0.999753 Avg: -123
Buffer: 0891 Ratio: 0.999753 Avg: -123
Buffer: 1147 Ratio: 0.999753 Avg: -123
Buffer: 0123 Ratio: 0.999753 Avg: -123
Buffer: 0379 Ratio: 0.999753 Avg: -123
Buffer: 0635 Ratio: 0.999753 Avg: -123
Buffer: 0891 Ratio: 0.999753 Avg: -123
Buffer: 1147 Ratio: 0.999753 Avg: -123
Buffer: 0763 Ratio: 0.999753 Avg: -123
Buffer: 1019 Ratio: 0.999753 Avg: -123
Buffer: 1275 Ratio: 0.999753 Avg: -123
No messages from pulseaudio -vvv in with pavucontrol enabled.
Adding 1000000 as 3rd parameter slightly improves choking (which is still ugly) but also increases latency.
The other thing that I notice is CPU peaks when pavucontrol is disabled. Every few seconds my CPU fan speeds up and slows down which is very annoying. This is not happening with pavucontrol opened.
I think that this is some pulseaudio issue after all. Pavucontrol somehow increases performance of the whole audio system. It enables some monitoring on sinks to be able to show volume levels. Lowers latency. I think that the only thing missing here is to find out what is different with both setups and tell pulseaudio to change its behavior. However I have diff analyzed pacmd outputs and the only thing I found is on comment #2. Maybe I could ask Lennard Poettering to take a look?
I just made a commit that might help this issue. Please give it another try, perhaps with a latency argument of 50000.
Keep in mind that it takes several seconds, perhaps even over a minute, for the control loop to settle, so you might hear some discontinuities when the program is first started, but they should disappear after it's been running for a while.
You can uncomment the #define DEBUG again if you want. The way to know if things are working as intended is when the "Avg:" value floats around 0. This is the offset from the target buffer level. If it's constantly pegged to a large negative or positive value, this indicates that there's a discrepancy between the data input and output speed.
You made it!
This is every 200th message from debug:
Buffer: 0036 Ratio: 1.000091 Avg: 45
Buffer: 0010 Ratio: 1.000175 Avg: 87
Buffer: 0084 Ratio: 1.000215 Avg: 107
Buffer: 0032 Ratio: 1.000195 Avg: 97
Buffer: 0072 Ratio: 1.000177 Avg: 88
Buffer: 0018 Ratio: 1.000161 Avg: 80
Buffer: 0026 Ratio: 1.000152 Avg: 76
Buffer: 0032 Ratio: 1.000133 Avg: 66
Buffer: 0072 Ratio: 1.000126 Avg: 62
Buffer: 0014 Ratio: 1.000117 Avg: 58
Buffer: 0020 Ratio: 1.000120 Avg: 59
Buffer: 0026 Ratio: 1.000111 Avg: 55
Buffer: 0030 Ratio: 1.000098 Avg: 49
Buffer: 0196 Ratio: 1.000092 Avg: 45
Buffer: 0168 Ratio: 1.000092 Avg: 45
Buffer: 0012 Ratio: 1.000094 Avg: 47
Buffer: 0304 Ratio: 1.000056 Avg: 28
Buffer: 0018 Ratio: 1.000025 Avg: 12
Buffer: 0180 Ratio: 1.000001 Avg: 0
Buffer: 0052 Ratio: 0.999995 Avg: -2
Buffer: 0116 Ratio: 0.999994 Avg: -2
Buffer: 0050 Ratio: 0.999991 Avg: -4
Buffer: 0210 Ratio: 0.999996 Avg: -1
Buffer: 0050 Ratio: 0.999998 Avg: 0
Buffer: 0018 Ratio: 0.999994 Avg: -3
Buffer: 0178 Ratio: 0.999989 Avg: -5
Buffer: 0176 Ratio: 0.999994 Avg: -3
Buffer: 0016 Ratio: 0.999986 Avg: -6
Buffer: 0080 Ratio: 0.999981 Avg: -9
Buffer: 0270 Ratio: 0.999985 Avg: -7
Buffer: 0014 Ratio: 0.999996 Avg: -1
Buffer: 0142 Ratio: 1.000005 Avg: 2
Buffer: 0238 Ratio: 1.000009 Avg: 4
Buffer: 0142 Ratio: 0.999988 Avg: -6
Buffer: 0270 Ratio: 0.999949 Avg: -25
Buffer: 0202 Ratio: 0.999910 Avg: -44
Buffer: 0102 Ratio: 0.999926 Avg: -37
Buffer: 0004 Ratio: 1.000057 Avg: 28
Buffer: 0010 Ratio: 1.000182 Avg: 91
Buffer: 0022 Ratio: 1.000230 Avg: 114
Buffer: 0002 Ratio: 1.000217 Avg: 108
Buffer: 0076 Ratio: 1.000214 Avg: 106
Buffer: 0024 Ratio: 1.000213 Avg: 106
Buffer: 0002 Ratio: 1.000190 Avg: 95
Buffer: 0076 Ratio: 1.000173 Avg: 86
Buffer: 0212 Ratio: 1.000158 Avg: 78
Buffer: 0124 Ratio: 1.000167 Avg: 83
Buffer: 0004 Ratio: 1.000176 Avg: 87
Buffer: 0014 Ratio: 1.000182 Avg: 91
Buffer: 0024 Ratio: 1.000178 Avg: 88
Buffer: 0000 Ratio: 1.000184 Avg: 91
Buffer: 0010 Ratio: 1.000200 Avg: 100
Buffer: 0020 Ratio: 1.000214 Avg: 106
Buffer: 0000 Ratio: 1.000197 Avg: 98
Buffer: 0042 Ratio: 1.000191 Avg: 95
Buffer: 0052 Ratio: 1.000190 Avg: 95
Buffer: 0060 Ratio: 1.000181 Avg: 90
Buffer: 0006 Ratio: 1.000178 Avg: 89
Buffer: 0142 Ratio: 1.000172 Avg: 86
Buffer: 0280 Ratio: 1.000168 Avg: 84
Buffer: 0032 Ratio: 1.000150 Avg: 74
Buffer: 0038 Ratio: 1.000126 Avg: 62
Buffer: 0012 Ratio: 1.000107 Avg: 53
Buffer: 0114 Ratio: 1.000089 Avg: 44
Buffer: 0182 Ratio: 1.000069 Avg: 34
Buffer: 0024 Ratio: 1.000065 Avg: 32
Buffer: 0028 Ratio: 1.000055 Avg: 27
Buffer: 0160 Ratio: 1.000066 Avg: 33
Buffer: 0162 Ratio: 1.000081 Avg: 40
Buffer: 0038 Ratio: 1.000073 Avg: 36
Buffer: 0010 Ratio: 1.000066 Avg: 32
I reverted default contents of config.h and did not use any latency argument.
There are some buffer underruns sometimes but I guess it's just callibrating.
Keep in mind that it takes several seconds, perhaps even over a minute, for the control loop to settle, so you might hear some discontinuities when the program is first started, but they should disappear after it's been running for a while.
Yeah, about that. It's true if I wait with playing input stream. If I do it too quickly, I hear high pitch clicks and they don't go away, unless I stop playback and wait few seconds.
I will be testing your fix for some time and come back with summary. Anyway, thanks a lot. You app is the only one I know for this purpose.
Hey Jacob, I'm using the app with:
./audio_async_loopback alsa_input.pci-0000_04_00.0.iec958-stereo 15000
With this setting there are no problems whatsoever. I don't have to wait for it to "stabilize", it just works.
Actually, I'm so happy about your app that I prepared an AUR package: https://aur.archlinux.org/packages/audio_async_loopback-git
and provided some documentation about it: https://wiki.archlinux.org/title/PulseAudio/Examples#Capture_digital_input_from_S/PDIF_and_play_on_analog_output_in_(nearly)_real_time
Thanks again for creating it!
Hey, that’s great! I appreciate it and I’m glad it can be of use to other people. I’ve been planning to make some improvements to this program at some point, such as:
What effort would be required to ensure that the AUR package stays up to date?
Hey Jacob, I'm happy that you've appreciated my work :)
What effort would be required to ensure that the AUR package stays up to date?
Since this is my first AUR package, I'm not exactly sure but I expect it to be very little. The process is highly automated.
Anyway, maybe it is a good moment to actually start using numbered releases?
Hey @jakemoroni , thanks for the app you wrote!
On my system this program gives "choking sound", so audio lasts for just about half second every 5 seconds. I noticed that it starts to work correctly when I open pavucontrol. When I close it, sound is choking again.
So I keep pavucontrol opened. But this is not the smartest solution.
This is what happens when I run pulseaudio with debugging output and close pavucontrol:
I was trying to load all those modules with pactl module-load, but they require parameters to start. I don't know what the parameters should be.
If I could ask you just to look at those messages. Maybe it is obvious for you what pulseaudio unloads but is required for your app to work. Then I could focus on fixing this one thing.
This is how I run your app:
To me it seems that this is not right:
Any ideas?