Repository navigation
make check cannot generate correct out.pcm after rmmod #7
Description
Activity
I defer to @Cuda-Chen for confirmation.
Hi @freshLiver ,
Thanks for the reporting.
While I am investigating whether this issue will appear on PulseAudio-enabled environment,
I would like to share my finding if PulseAudio is enabled then executemake check:out.pcmwill be 0 size as the output is captured to other sound device (e.g., speakers).out.pcmwill contain the output with lagging if you set the sink tovsnd.
What's more, I am using Ubuntu 22.04 (Linux kernel version 5.15).
Hi @Cuda-Chen ,
Thanks for the information.
-
For the case that the output is captured by another sound device:
In the previously mentioned environment, the output is not captured by the default sound card, and it behaves similarly after I remove the driver of another sound card.
In my another environment which is a pulseaudio-powered system:
$ uname -a Linux LabPC2 6.1.0-20-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.1.85-1 (2024-04-11) x86_64 GNU/LinuxThis problem still exists and behaves similarly, according to the output of dmesg:
$ sudo dmesg -W [2100141.020602] FIFO file closed [2100177.038022] FIFO file /tmp/audio.pcm opened [2100177.038120] FIFO file closed [2100177.038176] FIFO file /tmp/audio.pcm opened [2100177.038228] FIFO file closed [2100177.038295] FIFO file /tmp/audio.pcm opened [2100177.038387] FIFO file closed [2100177.038456] FIFO file /tmp/audio.pcm opened [2100177.038642] FIFO file closed [2100177.038701] FIFO file /tmp/audio.pcm opened [2100177.040714] FIFO file closed [2100177.043919] FIFO file /tmp/audio.pcm opened [2100177.057328] Triggered [2100177.057334] START: channels 1 rate 22050 [2100179.072601] kernel_write: expect write 88200, but 65536 [2100179.072607] kernel_write: failed: -11 [2100181.084653] kernel_write: failed: -11 [2100181.084661] kernel_write: failed: -11 [2100182.061587] Triggered [2100182.061594] STOP ---- [2100182.061687] FIFO file closed [2100187.194256] FIFO file /tmp/audio.pcm opened [2100187.195882] Triggered [2100187.195891] START: channels 1 rate 22050 [2100187.324739] 5820 bytes written [2100187.448735] 5468 bytes written [2100187.572668] 5470 bytes written [2100187.696681] 5290 bytes written [2100187.696694] 178 bytes written [2100187.824690] 5644 bytes written [2100187.952685] 5646 bytes written [2100188.072721] 5292 bytes written [2100188.196716] 5288 bytes written [2100188.196736] 180 bytes written [2100188.324716] 5644 bytes written [2100188.448719] 5468 bytes written [2100188.572734] 5470 bytes written [2100188.696730] 5286 bytes written [2100188.696743] 182 bytes written [2100188.824728] 5644 bytes written [2100188.952695] 5646 bytes written [2100189.072674] 5292 bytes written [2100189.196738] 5284 bytes written [2100189.196761] 184 bytes written [2100189.324693] 5644 bytes written [2100189.448726] 5468 bytes written [2100189.572690] 5470 bytes written [2100189.696727] 5282 bytes written [2100189.696747] 186 bytes written [2100189.824691] 5644 bytes written [2100189.948731] 5468 bytes written [2100190.072744] 5470 bytes written [2100190.196734] 5280 bytes written [2100190.196751] 188 bytes written [2100190.324740] 5644 bytes written [2100190.324747] Triggered [2100190.324748] STOP
-
For the case that setting the sink to vsnd
I didn't encounter the lagging problem, the converted
out.wavsounds as smooth as the original audio.
-
Hi @freshLiver ,
Thanks for you reply.
I would like to conduct the steps these days to see the results of Linux Kernel 5.15.- changed the title
[-]`make check` cannot generator correct `out.pcm` after `rmmod`[/-][+]`make check` cannot generate correct `out.pcm` after `rmmod`[/+]on May 9, 2024 HI @freshLiver ,
After using your patch, I do not encounter any write errors which you mention.
For your information, I would like to write down the logs and the environments of mine.Environment
$ uname -a Linux jio-Aspire-V3-571G 5.15.0-106-generic #116-Ubuntu SMP Wed Apr 17 09:17:56 UTC 2024 x86_64 x86_64 x86_64 GNU/LinuxSyslog
journalctl -f
May 11 10:33:26 jio-Aspire-V3-571G systemd[4640]: Stopping Sound Service... May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSink/sbc May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSource/sbc May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSink/sbc_xq_453 May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSource/sbc_xq_453 May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSink/sbc_xq_512 May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSource/sbc_xq_512 May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSink/sbc_xq_552 May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSource/sbc_xq_552 May 11 10:33:26 jio-Aspire-V3-571G systemd[4640]: Stopped Sound Service. May 11 10:33:26 jio-Aspire-V3-571G systemd[4640]: pulseaudio.service: Consumed 1min 27.017s CPU time. May 11 10:33:26 jio-Aspire-V3-571G systemd[4640]: Closed Sound System. May 11 10:33:31 jio-Aspire-V3-571G gsd-media-keys[5129]: Unable to get default sink May 11 10:33:31 jio-Aspire-V3-571G gsd-media-keys[5129]: Unable to get default source ------ I AM SEPARATE (the first time make check) ------ May 11 10:35:35 jio-Aspire-V3-571G sudo[17662]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm May 11 10:35:35 jio-Aspire-V3-571G sudo[17662]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 11 10:35:35 jio-Aspire-V3-571G sudo[17662]: pam_unix(sudo:session): session closed for user root May 11 10:35:35 jio-Aspire-V3-571G sudo[17665]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd May 11 10:35:35 jio-Aspire-V3-571G sudo[17665]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 11 10:35:35 jio-Aspire-V3-571G sudo[17665]: pam_unix(sudo:session): session closed for user root May 11 10:35:35 jio-Aspire-V3-571G sudo[17670]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm May 11 10:35:35 jio-Aspire-V3-571G sudo[17670]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 11 10:35:35 jio-Aspire-V3-571G sudo[17670]: pam_unix(sudo:session): session closed for user root May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.062661:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.062817:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.065155:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.065252:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.081812:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.081913:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:35:35 jio-Aspire-V3-571G systemd[4640]: Reached target Sound Card. May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.085029:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.085180:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:35:36 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 11 10:35:36 jio-Aspire-V3-571G kernel: Triggered May 11 10:35:36 jio-Aspire-V3-571G kernel: START: channels 1 rate 22050 May 11 10:35:36 jio-Aspire-V3-571G kernel: 5996 bytes written May 11 10:35:36 jio-Aspire-V3-571G kernel: 5292 bytes written May 11 10:35:36 jio-Aspire-V3-571G kernel: 5470 bytes written May 11 10:35:36 jio-Aspire-V3-571G kernel: 5290 bytes written May 11 10:35:36 jio-Aspire-V3-571G kernel: 178 bytes written May 11 10:35:36 jio-Aspire-V3-571G kernel: 5820 bytes written May 11 10:35:36 jio-Aspire-V3-571G kernel: 5292 bytes written May 11 10:35:37 jio-Aspire-V3-571G kernel: 5470 bytes written May 11 10:35:37 jio-Aspire-V3-571G kernel: 5288 bytes written May 11 10:35:37 jio-Aspire-V3-571G kernel: 180 bytes written May 11 10:35:37 jio-Aspire-V3-571G kernel: 5644 bytes written May 11 10:35:37 jio-Aspire-V3-571G kernel: 5468 bytes written May 11 10:35:37 jio-Aspire-V3-571G kernel: 5646 bytes written May 11 10:35:37 jio-Aspire-V3-571G kernel: 5110 bytes written May 11 10:35:37 jio-Aspire-V3-571G kernel: 182 bytes written May 11 10:35:37 jio-Aspire-V3-571G kernel: 5644 bytes written May 11 10:35:37 jio-Aspire-V3-571G kernel: 5468 bytes written May 11 10:35:38 jio-Aspire-V3-571G kernel: 5470 bytes written May 11 10:35:38 jio-Aspire-V3-571G kernel: 5284 bytes written May 11 10:35:38 jio-Aspire-V3-571G kernel: 184 bytes written May 11 10:35:38 jio-Aspire-V3-571G kernel: 5644 bytes written May 11 10:35:38 jio-Aspire-V3-571G kernel: 5468 bytes written May 11 10:35:38 jio-Aspire-V3-571G kernel: 5646 bytes written May 11 10:35:38 jio-Aspire-V3-571G kernel: 5106 bytes written May 11 10:35:38 jio-Aspire-V3-571G kernel: 186 bytes written May 11 10:35:38 jio-Aspire-V3-571G kernel: 5644 bytes written May 11 10:35:38 jio-Aspire-V3-571G kernel: 5468 bytes written May 11 10:35:39 jio-Aspire-V3-571G kernel: 5470 bytes written May 11 10:35:39 jio-Aspire-V3-571G kernel: 5280 bytes written May 11 10:35:39 jio-Aspire-V3-571G kernel: 188 bytes written May 11 10:35:39 jio-Aspire-V3-571G kernel: 5644 bytes written May 11 10:35:39 jio-Aspire-V3-571G kernel: Triggered May 11 10:35:39 jio-Aspire-V3-571G kernel: STOP May 11 10:35:39 jio-Aspire-V3-571G sudo[17681]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd May 11 10:35:39 jio-Aspire-V3-571G sudo[17681]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 11 10:35:39 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103539.232367:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:35:39 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103539.232444:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:35:39 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103539.233598:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:35:39 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103539.233671:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:35:39 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103539.234115:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:35:39 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103539.234176:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:35:39 jio-Aspire-V3-571G sudo[17681]: pam_unix(sudo:session): session closed for user root ------ I AM SEPARATE (the second time make check) ------ May 11 10:37:25 jio-Aspire-V3-571G sudo[17965]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm May 11 10:37:25 jio-Aspire-V3-571G sudo[17965]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 11 10:37:25 jio-Aspire-V3-571G sudo[17965]: pam_unix(sudo:session): session closed for user root May 11 10:37:25 jio-Aspire-V3-571G sudo[17968]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd May 11 10:37:25 jio-Aspire-V3-571G sudo[17968]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 11 10:37:25 jio-Aspire-V3-571G sudo[17968]: pam_unix(sudo:session): session closed for user root May 11 10:37:25 jio-Aspire-V3-571G sudo[17973]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm May 11 10:37:25 jio-Aspire-V3-571G sudo[17973]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 11 10:37:25 jio-Aspire-V3-571G sudo[17973]: pam_unix(sudo:session): session closed for user root May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.595563:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.595630:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.596466:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.596529:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.613430:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.613528:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.619225:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.619341:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:37:26 jio-Aspire-V3-571G kernel: FIFO file closed May 11 10:37:26 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 11 10:37:26 jio-Aspire-V3-571G kernel: Triggered May 11 10:37:26 jio-Aspire-V3-571G kernel: START: channels 1 rate 22050 May 11 10:37:26 jio-Aspire-V3-571G kernel: 5820 bytes written May 11 10:37:26 jio-Aspire-V3-571G kernel: 5468 bytes written May 11 10:37:27 jio-Aspire-V3-571G kernel: 5470 bytes written May 11 10:37:27 jio-Aspire-V3-571G kernel: 5290 bytes written May 11 10:37:27 jio-Aspire-V3-571G kernel: 178 bytes written May 11 10:37:27 jio-Aspire-V3-571G kernel: 5644 bytes written May 11 10:37:27 jio-Aspire-V3-571G kernel: 5468 bytes written May 11 10:37:27 jio-Aspire-V3-571G kernel: 5470 bytes written May 11 10:37:27 jio-Aspire-V3-571G kernel: 5288 bytes written May 11 10:37:27 jio-Aspire-V3-571G kernel: 180 bytes written May 11 10:37:27 jio-Aspire-V3-571G kernel: 5644 bytes written May 11 10:37:27 jio-Aspire-V3-571G kernel: 5468 bytes written May 11 10:37:28 jio-Aspire-V3-571G kernel: 5646 bytes written May 11 10:37:28 jio-Aspire-V3-571G kernel: 5110 bytes written May 11 10:37:28 jio-Aspire-V3-571G kernel: 182 bytes written May 11 10:37:28 jio-Aspire-V3-571G kernel: 5644 bytes written May 11 10:37:28 jio-Aspire-V3-571G kernel: 5468 bytes written May 11 10:37:28 jio-Aspire-V3-571G kernel: 5470 bytes written May 11 10:37:28 jio-Aspire-V3-571G kernel: 5284 bytes written May 11 10:37:28 jio-Aspire-V3-571G kernel: 184 bytes written May 11 10:37:28 jio-Aspire-V3-571G kernel: 5644 bytes written May 11 10:37:28 jio-Aspire-V3-571G kernel: 5468 bytes written May 11 10:37:29 jio-Aspire-V3-571G kernel: 5470 bytes written May 11 10:37:29 jio-Aspire-V3-571G kernel: 5282 bytes written May 11 10:37:29 jio-Aspire-V3-571G kernel: 186 bytes written May 11 10:37:29 jio-Aspire-V3-571G kernel: 5644 bytes written May 11 10:37:29 jio-Aspire-V3-571G kernel: 5468 bytes written May 11 10:37:29 jio-Aspire-V3-571G kernel: 5470 bytes written May 11 10:37:29 jio-Aspire-V3-571G kernel: 5280 bytes written May 11 10:37:29 jio-Aspire-V3-571G kernel: 188 bytes written May 11 10:37:29 jio-Aspire-V3-571G kernel: 5820 bytes written May 11 10:37:29 jio-Aspire-V3-571G kernel: Triggered May 11 10:37:29 jio-Aspire-V3-571G kernel: STOP May 11 10:37:29 jio-Aspire-V3-571G sudo[17984]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd May 11 10:37:29 jio-Aspire-V3-571G sudo[17984]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 11 10:37:29 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103729.766703:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:37:29 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103729.766779:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:37:29 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103729.767124:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:37:29 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103729.767186:ERROR:pulse_util.cc(381)] pa_operation is nullptr. May 11 10:37:29 jio-Aspire-V3-571G sudo[17984]: pam_unix(sudo:session): session closed for user root
Hi @Cuda-Chen ,
Could you provide the detailed version of your Ubuntu 22.04 env? I'd like to build a virtual env for testing.
I just tested in the fresh-installed Ubuntu 22.04.4, and the first
make checkstill didn't generated the correct output (but with a slightly? different result).Env info
Installed packages: build-essential git tmux meson bison linux-headers-
uname -rcurl ffmpeg gcc-12Additional softwares: VirtualBox guest additions 6.1.44
vm@vm:~$ uname -a Linux vm 6.5.0-28-generic #29~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Thu Apr 4 14:39:20 UTC 2 x86_64 x86_64 x86_64 GNU/Linux vm@vm:~$ cat /etc/os-release PRETTY_NAME="Ubuntu 22.04.4 LTS" NAME="Ubuntu" VERSION_ID="22.04" VERSION="22.04.4 LTS (Jammy Jellyfish)" VERSION_CODENAME=jammy ID=ubuntu ID_LIKE=debian ... UBUNTU_CODENAME=jammy
Default output device changed automatically after
insmodIn this env, I found that the default output device will be automatically changed to vsnd (check the
*symbol before the index):vm@vm:~/vsnd$ pacmd list-sinks 1 sink(s) available. * index: 0 name: <alsa_output.pci-0000_00_05.0.analog-stereo> driver: <module-alsa-card.c> flags: HARDWARE HW_MUTE_CTRL HW_VOLUME_CTRL DECIBEL_VOLUME LATENCY state: SUSPENDED suspend cause: IDLE priority: 9039 volume: front-left: 29274 / 45% / -21.00 dB, front-right: 29274 / 45% / -21.00 dB balance 0.00 base volume: 65536 / 100% / 0.00 dB volume steps: 65537 muted: no current latency: 0.00 ms max request: 0 KiB max rewind: 0 KiB monitor source: 0 sample spec: s16le 2ch 48000Hz channel map: front-left,front-right Stereo used by: 0 linked by: 0 fixed latency: 99.94 ms card: 0 <alsa_card.pci-0000_00_05.0> module: 7 properties: alsa.resolution_bits = "16" device.api = "alsa" device.class = "sound" alsa.class = "generic" alsa.subclass = "generic-mix" alsa.name = "Intel 82801AA-ICH" alsa.id = "Intel ICH" alsa.subdevice = "0" alsa.subdevice_name = "subdevice #0" alsa.device = "0" alsa.card = "0" alsa.card_name = "Intel 82801AA-ICH" alsa.long_card_name = "Intel 82801AA-ICH with AD1980 at irq 21" alsa.driver_name = "snd_intel8x0" device.bus_path = "pci-0000:00:05.0" sysfs.path = "/devices/pci0000:00/0000:00:05.0/sound/card0" device.bus = "pci" device.vendor.id = "8086" device.vendor.name = "Intel Corporation" device.product.id = "2415" device.product.name = "82801AA AC'97 Audio Controller" device.form_factor = "internal" device.string = "front:0" device.buffering.buffer_size = "19188" device.buffering.fragment_size = "6396" device.access_mode = "mmap" device.profile.name = "analog-stereo" device.profile.description = "Analog Stereo" device.description = "Built-in Audio Analog Stereo" module-udev-detect.discovered = "1" device.icon_name = "audio-card-pci" ports: analog-output;output-amplifier-on: Analog Output / Amplifier (priority 9910, latency offset 0 usec, available: unknown) properties: analog-output;output-amplifier-off: Analog Output / No Amplifier (priority 9900, latency offset 0 usec, available: unknown) properties: active port: <analog-output;output-amplifier-off> vm@vm:~/vsnd$ sudo insmod vsnd.ko out_fifo_name=/tmp/audio.pcm vm@vm:~/vsnd$ pacmd list-sinks 2 sink(s) available. index: 0 name: <alsa_output.pci-0000_00_05.0.analog-stereo> driver: <module-alsa-card.c> flags: HARDWARE HW_MUTE_CTRL HW_VOLUME_CTRL DECIBEL_VOLUME LATENCY state: SUSPENDED suspend cause: IDLE priority: 9039 volume: front-left: 29274 / 45% / -21.00 dB, front-right: 29274 / 45% / -21.00 dB balance 0.00 base volume: 65536 / 100% / 0.00 dB volume steps: 65537 muted: no current latency: 0.00 ms max request: 0 KiB max rewind: 0 KiB monitor source: 0 sample spec: s16le 2ch 48000Hz channel map: front-left,front-right Stereo used by: 0 linked by: 0 fixed latency: 99.94 ms card: 0 <alsa_card.pci-0000_00_05.0> module: 7 properties: alsa.resolution_bits = "16" device.api = "alsa" device.class = "sound" alsa.class = "generic" alsa.subclass = "generic-mix" alsa.name = "Intel 82801AA-ICH" alsa.id = "Intel ICH" alsa.subdevice = "0" alsa.subdevice_name = "subdevice #0" alsa.device = "0" alsa.card = "0" alsa.card_name = "Intel 82801AA-ICH" alsa.long_card_name = "Intel 82801AA-ICH with AD1980 at irq 21" alsa.driver_name = "snd_intel8x0" device.bus_path = "pci-0000:00:05.0" sysfs.path = "/devices/pci0000:00/0000:00:05.0/sound/card0" device.bus = "pci" device.vendor.id = "8086" device.vendor.name = "Intel Corporation" device.product.id = "2415" device.product.name = "82801AA AC'97 Audio Controller" device.form_factor = "internal" device.string = "front:0" device.buffering.buffer_size = "19188" device.buffering.fragment_size = "6396" device.access_mode = "mmap" device.profile.name = "analog-stereo" device.profile.description = "Analog Stereo" device.description = "Built-in Audio Analog Stereo" module-udev-detect.discovered = "1" device.icon_name = "audio-card-pci" ports: analog-output;output-amplifier-on: Analog Output / Amplifier (priority 9910, latency offset 0 usec, available: unknown) properties: analog-output;output-amplifier-off: Analog Output / No Amplifier (priority 9900, latency offset 0 usec, available: unknown) properties: active port: <analog-output;output-amplifier-off> * index: 1 name: <alsa_output.platform-vsnd.0.mono-fallback> driver: <module-alsa-card.c> flags: HARDWARE DECIBEL_VOLUME LATENCY state: IDLE suspend cause: (none) priority: 9000 volume: mono: 65536 / 100% / 0.00 dB balance 0.00 base volume: 65536 / 100% / 0.00 dB volume steps: 65537 muted: no current latency: 97.45 ms max request: 4 KiB max rewind: 4 KiB monitor source: 2 sample spec: s16le 1ch 22050Hz channel map: mono Mono used by: 0 linked by: 0 fixed latency: 99.95 ms card: 1 <alsa_card.platform-vsnd.0> module: 23 properties: alsa.resolution_bits = "16" device.api = "alsa" device.class = "sound" alsa.class = "generic" alsa.subclass = "generic-mix" alsa.name = "vsnd PCM" alsa.id = "vsnd PCM" alsa.subdevice = "0" alsa.subdevice_name = "subdevice #0" alsa.device = "0" alsa.card = "1" alsa.card_name = "vsnd" alsa.long_card_name = "vsnd1" alsa.driver_name = "vsnd" device.bus_path = "platform-vsnd.0" sysfs.path = "/devices/platform/vsnd.0/sound/card1" device.form_factor = "internal" device.string = "hw:1" device.buffering.buffer_size = "4408" device.buffering.fragment_size = "4408" device.access_mode = "mmap" device.profile.name = "mono-fallback" device.profile.description = "Mono" device.description = "Built-in Audio Mono" module-udev-detect.discovered = "1" device.icon_name = "audio-card" ports: analog-output: Analog Output (priority 9900, latency offset 0 usec, available: unknown) properties: active port: <analog-output>
So a simple
aplay CantinaBand3.wavis be handled by the vsnd module and still cause many kernel_write failed (return -11). But this time, the FIFO file was only opened and closed once:$ sudo dmesg -W [sudo] password for vm: [ 803.186893] FIFO file closed [ 946.035333] FIFO file /tmp/audio.pcm opened [ 946.035514] Triggered [ 946.035516] START: channels 1 rate 22050 [ 946.138769] 4408 bytes written [ 946.138783] 178 bytes written [ 946.238874] 4230 bytes written [ 946.238895] 180 bytes written [ 946.338694] 4228 bytes written [ 946.338717] 182 bytes written [ 946.438615] 4226 bytes written [ 946.438637] 184 bytes written [ 946.538608] 4224 bytes written [ 946.538631] 186 bytes written [ 946.638343] 4222 bytes written [ 946.638353] 188 bytes written [ 946.738296] 4220 bytes written [ 946.738305] 190 bytes written [ 946.838491] 4218 bytes written [ 946.838513] 192 bytes written [ 946.938280] kernel_write: expect write 4216, but 120 [ 946.938293] 194 bytes written [ 947.038318] kernel_write: expect write 4214, but 118 [ 947.038339] 196 bytes written [ 947.138098] kernel_write: expect write 4212, but 116 [ 947.138107] 198 bytes written [ 947.238102] kernel_write: expect write 4210, but 114 [ 947.238116] 200 bytes written [ 947.338098] kernel_write: expect write 4208, but 112 [ 947.338107] 202 bytes written [ 947.440867] kernel_write: expect write 4206, but 110 [ 947.440876] 204 bytes written [ 947.537959] kernel_write: expect write 4204, but 108 [ 947.537975] 206 bytes written [ 947.637898] kernel_write: expect write 4202, but 106 [ 947.637912] 208 bytes written [ 947.737886] kernel_write: expect write 4200, but 104 [ 947.737906] 210 bytes written [ 947.841865] kernel_write: expect write 4198, but 102 [ 947.841882] 388 bytes written [ 947.937698] kernel_write: failed: -11 [ 947.937730] 214 bytes written [ 948.038658] kernel_write: expect write 4194, but 98 [ 948.038668] 216 bytes written [ 948.137565] kernel_write: failed: -11 ... # too many repeats [ 948.837265] kernel_write: failed: -11 [ 949.836744] kernel_write: failed: -11 [ 949.836753] kernel_write: failed: -11 [ 949.936696] kernel_write: expect write 4156, but 60 [ 949.936705] kernel_write: failed: -11 [ 950.236577] kernel_write: failed: -11 ... # too many repeats [ 955.030106] kernel_write: failed: -11 [ 955.030114] kernel_write: failed: -11 [ 955.038855] Triggered [ 955.038859] STOP
Changes on
verify.shTo prevent the default output device from being changed automatically after
insmod, I added some commands inverify.shto change and check the default output device:... sudo insmod vsnd.ko out_fifo_name=/tmp/audio.pcm + pacmd list-sinks + pacmd set-default-sink alsa_output.pci-0000_00_05.0.analog-stereo + pacmd list-sinks ...
Output of
make checkThe second
make checkcan still generate correct output. But in the firstmake check, the output pcm file size is no longer zero, but still has incorrect size apparently and has no sound.vm@vm:~/vsnd$ ./scripts/pulseaudio-rmmod.sh vsnd ------ I AM SEPARATOR (the first time make check) ------ vm@vm:~/vsnd$ make check make -C /lib/modules/6.5.0-28-generic/build M=/home/vm/vsnd modules make[1]: Entering directory '/usr/src/linux-headers-6.5.0-28-generic' warning: the compiler differs from the one used to build the kernel The kernel was built by: x86_64-linux-gnu-gcc-12 (Ubuntu 12.3.0-1ubuntu1~22.04) 12.3.0 You are using: gcc-12 (Ubuntu 12.3.0-1ubuntu1~22.04) 12.3.0 make[1]: Leaving directory '/usr/src/linux-headers-6.5.0-28-generic' scripts/verify.sh + sudo modprobe snd_pcm + sudo rmmod vsnd rmmod: ERROR: Module vsnd is not currently loaded + rm -f /tmp/audio.pcm + mkfifo /tmp/audio.pcm + sudo insmod vsnd.ko out_fifo_name=/tmp/audio.pcm + pacmd list-sinks 2 sink(s) available. index: 0 name: <alsa_output.pci-0000_00_05.0.analog-stereo> driver: <module-alsa-card.c> ... * index: 1 name: <alsa_output.platform-vsnd.0.mono-fallback> driver: <module-alsa-card.c> flags: HARDWARE DECIBEL_VOLUME LATENCY state: IDLE suspend cause: (none) priority: 9000 volume: mono: 65536 / 100% / 0.00 dB balance 0.00 base volume: 65536 / 100% / 0.00 dB volume steps: 65537 muted: no current latency: 69.20 ms max request: 4 KiB max rewind: 4 KiB monitor source: 2 sample spec: s16le 1ch 22050Hz channel map: mono Mono used by: 0 linked by: 0 fixed latency: 99.95 ms card: 1 <alsa_card.platform-vsnd.0> module: 23 properties: alsa.resolution_bits = "16" device.api = "alsa" device.class = "sound" alsa.class = "generic" alsa.subclass = "generic-mix" alsa.name = "vsnd PCM" alsa.id = "vsnd PCM" alsa.subdevice = "0" alsa.subdevice_name = "subdevice #0" alsa.device = "0" alsa.card = "1" alsa.card_name = "vsnd" alsa.long_card_name = "vsnd1" alsa.driver_name = "vsnd" device.bus_path = "platform-vsnd.0" sysfs.path = "/devices/platform/vsnd.0/sound/card1" device.form_factor = "internal" device.string = "hw:1" device.buffering.buffer_size = "4408" device.buffering.fragment_size = "4408" device.access_mode = "mmap" device.profile.name = "mono-fallback" device.profile.description = "Mono" device.description = "Built-in Audio Mono" module-udev-detect.discovered = "1" device.icon_name = "audio-card" ports: analog-output: Analog Output (priority 9900, latency offset 0 usec, available: unknown) properties: active port: <analog-output> + pacmd set-default-sink alsa_output.pci-0000_00_05.0.analog-stereo + pacmd list-sinks 2 sink(s) available. * index: 0 name: <alsa_output.pci-0000_00_05.0.analog-stereo> driver: <module-alsa-card.c> ... index: 1 name: <alsa_output.platform-vsnd.0.mono-fallback> driver: <module-alsa-card.c> flags: HARDWARE DECIBEL_VOLUME LATENCY state: IDLE suspend cause: (none) priority: 9000 volume: mono: 65536 / 100% / 0.00 dB balance 0.00 base volume: 65536 / 100% / 0.00 dB volume steps: 65537 muted: no current latency: 29.71 ms max request: 4 KiB max rewind: 4 KiB monitor source: 2 sample spec: s16le 1ch 22050Hz channel map: mono Mono used by: 0 linked by: 0 fixed latency: 99.95 ms card: 1 <alsa_card.platform-vsnd.0> module: 23 properties: alsa.resolution_bits = "16" device.api = "alsa" device.class = "sound" alsa.class = "generic" alsa.subclass = "generic-mix" alsa.name = "vsnd PCM" alsa.id = "vsnd PCM" alsa.subdevice = "0" alsa.subdevice_name = "subdevice #0" alsa.device = "0" alsa.card = "1" alsa.card_name = "vsnd" alsa.long_card_name = "vsnd1" alsa.driver_name = "vsnd" device.bus_path = "platform-vsnd.0" sysfs.path = "/devices/platform/vsnd.0/sound/card1" device.form_factor = "internal" device.string = "hw:1" device.buffering.buffer_size = "4408" device.buffering.fragment_size = "4408" device.access_mode = "mmap" device.profile.name = "mono-fallback" device.profile.description = "Mono" device.description = "Built-in Audio Mono" module-udev-detect.discovered = "1" device.icon_name = "audio-card" ports: analog-output: Analog Output (priority 9900, latency offset 0 usec, available: unknown) properties: active port: <analog-output> + sleep 1 + tee out.pcm + aplay -D plughw:CARD=vsnd,DEV=0 CantinaBand3.wav aplay: main:831: audio open error: Device or resource busy + sudo rmmod vsnd rmmod: ERROR: Module vsnd is in use + ls -l out.pcm -rw-rw-r-- 1 vm vm 53096 五 11 19:58 out.pcm + ffmpeg -f s16le -ar 22.05k -ac 1 -loglevel 8 -i out.pcm out.wav File 'out.wav' already exists. Overwrite? [y/N] y vm@vm:~/vsnd$ aplay out.wav <------------------------------ no sound!!! Playing WAVE 'out.wav' : Signed 16 bit Little Endian, Rate 22050 Hz, Mono ------ I AM SEPARATOR (the second time make check) ------ vm@vm:~/vsnd$ make check make -C /lib/modules/6.5.0-28-generic/build M=/home/vm/vsnd modules make[1]: Entering directory '/usr/src/linux-headers-6.5.0-28-generic' warning: the compiler differs from the one used to build the kernel The kernel was built by: x86_64-linux-gnu-gcc-12 (Ubuntu 12.3.0-1ubuntu1~22.04) 12.3.0 You are using: gcc-12 (Ubuntu 12.3.0-1ubuntu1~22.04) 12.3.0 make[1]: Leaving directory '/usr/src/linux-headers-6.5.0-28-generic' scripts/verify.sh + sudo modprobe snd_pcm + sudo rmmod vsnd rmmod: ERROR: Module vsnd is in use + rm -f /tmp/audio.pcm + mkfifo /tmp/audio.pcm + sudo insmod vsnd.ko out_fifo_name=/tmp/audio.pcm insmod: ERROR: could not insert module vsnd.ko: File exists + pacmd list-sinks 2 sink(s) available. * index: 0 name: <alsa_output.pci-0000_00_05.0.analog-stereo> driver: <module-alsa-card.c> ... index: 1 name: <alsa_output.platform-vsnd.0.mono-fallback> driver: <module-alsa-card.c> flags: HARDWARE DECIBEL_VOLUME LATENCY state: SUSPENDED suspend cause: IDLE priority: 9000 volume: mono: 65536 / 100% / 0.00 dB balance 0.00 base volume: 65536 / 100% / 0.00 dB volume steps: 65537 muted: no current latency: 0.00 ms max request: 0 KiB max rewind: 0 KiB monitor source: 2 sample spec: s16le 1ch 22050Hz channel map: mono Mono used by: 0 linked by: 0 fixed latency: 99.95 ms card: 1 <alsa_card.platform-vsnd.0> module: 23 properties: alsa.resolution_bits = "16" device.api = "alsa" device.class = "sound" alsa.class = "generic" alsa.subclass = "generic-mix" alsa.name = "vsnd PCM" alsa.id = "vsnd PCM" alsa.subdevice = "0" alsa.subdevice_name = "subdevice #0" alsa.device = "0" alsa.card = "1" alsa.card_name = "vsnd" alsa.long_card_name = "vsnd1" alsa.driver_name = "vsnd" device.bus_path = "platform-vsnd.0" sysfs.path = "/devices/platform/vsnd.0/sound/card1" device.form_factor = "internal" device.string = "hw:1" device.buffering.buffer_size = "4408" device.buffering.fragment_size = "4408" device.access_mode = "mmap" device.profile.name = "mono-fallback" device.profile.description = "Mono" device.description = "Built-in Audio Mono" module-udev-detect.discovered = "1" device.icon_name = "audio-card" ports: analog-output: Analog Output (priority 9900, latency offset 0 usec, available: unknown) properties: active port: <analog-output> + pacmd set-default-sink alsa_output.pci-0000_00_05.0.analog-stereo + pacmd list-sinks 2 sink(s) available. * index: 0 name: <alsa_output.pci-0000_00_05.0.analog-stereo> driver: <module-alsa-card.c> ... index: 1 name: <alsa_output.platform-vsnd.0.mono-fallback> driver: <module-alsa-card.c> flags: HARDWARE DECIBEL_VOLUME LATENCY state: SUSPENDED suspend cause: IDLE priority: 9000 volume: mono: 65536 / 100% / 0.00 dB balance 0.00 base volume: 65536 / 100% / 0.00 dB volume steps: 65537 muted: no current latency: 0.00 ms max request: 0 KiB max rewind: 0 KiB monitor source: 2 sample spec: s16le 1ch 22050Hz channel map: mono Mono used by: 0 linked by: 0 fixed latency: 99.95 ms card: 1 <alsa_card.platform-vsnd.0> module: 23 properties: alsa.resolution_bits = "16" device.api = "alsa" device.class = "sound" alsa.class = "generic" alsa.subclass = "generic-mix" alsa.name = "vsnd PCM" alsa.id = "vsnd PCM" alsa.subdevice = "0" alsa.subdevice_name = "subdevice #0" alsa.device = "0" alsa.card = "1" alsa.card_name = "vsnd" alsa.long_card_name = "vsnd1" alsa.driver_name = "vsnd" device.bus_path = "platform-vsnd.0" sysfs.path = "/devices/platform/vsnd.0/sound/card1" device.form_factor = "internal" device.string = "hw:1" device.buffering.buffer_size = "4408" device.buffering.fragment_size = "4408" device.access_mode = "mmap" device.profile.name = "mono-fallback" device.profile.description = "Mono" device.description = "Built-in Audio Mono" module-udev-detect.discovered = "1" device.icon_name = "audio-card" ports: analog-output: Analog Output (priority 9900, latency offset 0 usec, available: unknown) properties: active port: <analog-output> + sleep 1 + tee out.pcm + aplay -D plughw:CARD=vsnd,DEV=0 CantinaBand3.wav Playing WAVE 'CantinaBand3.wav' : Signed 16 bit Little Endian, Rate 22050 Hz, Mono + sudo rmmod vsnd rmmod: ERROR: Module vsnd is in use + ls -l out.pcm -rw-rw-r-- 1 vm vm 138120 五 11 19:58 out.pcm + ffmpeg -f s16le -ar 22.05k -ac 1 -loglevel 8 -i out.pcm out.wav File 'out.wav' already exists. Overwrite? [y/N] y vm@vm:~/vsnd$ aplay out.wav <------------------------------ correct result!! Playing WAVE 'out.wav' : Signed 16 bit Little Endian, Rate 22050 Hz, Mono
Syslog
And from the syslog, there are several differences compared to the original result:
- No write failure, but the FIFO file was still opened/closed many times.
- There are many writes after the rmmod command which should indicate the end of
aplay -D plughw:CARD=vsnd,DEV=0 CantinaBand3.wav - Error messages from pulseaudio
vm@vm:~/vsnd$ journalctl -f 五 11 19:57:39 vm gnome-shell[1513]: Window manager warning: W2 appears to be one of the offending windows with a timestamp of 1210479. Working around... 五 11 19:58:03 vm systemd[1353]: Stopping Sound Service... 五 11 19:58:03 vm systemd[1353]: Stopped Sound Service. 五 11 19:58:03 vm systemd[1353]: Closed Sound System. 五 11 19:58:03 vm sudo[4433]: vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd 五 11 19:58:03 vm sudo[4433]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) 五 11 19:58:03 vm sudo[4433]: pam_unix(sudo:session): session closed for user root 五 11 19:58:03 vm systemd[1353]: Listening on Sound System. 五 11 19:58:03 vm systemd[1353]: Starting Sound Service... 五 11 19:58:03 vm rtkit-daemon[1376]: Successfully made thread 4442 of process 4442 owned by '1000' high priority at nice level -11. 五 11 19:58:03 vm rtkit-daemon[1376]: Supervising 4 threads of 3 processes of 1 users. 五 11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range. 五 11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range. 五 11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range. 五 11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range. 五 11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range. 五 11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range. 五 11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range. 五 11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range. 五 11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range. 五 11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range. 五 11 19:58:03 vm pulseaudio[4442]: Disabling timer-based scheduling because running inside a VM. 五 11 19:58:03 vm rtkit-daemon[1376]: Supervising 4 threads of 3 processes of 1 users. 五 11 19:58:03 vm rtkit-daemon[1376]: Successfully made thread 4443 of process 4442 owned by '1000' RT at priority 5. 五 11 19:58:03 vm rtkit-daemon[1376]: Supervising 5 threads of 3 processes of 1 users. 五 11 19:58:03 vm pulseaudio[4442]: Disabling timer-based scheduling because running inside a VM. 五 11 19:58:03 vm rtkit-daemon[1376]: Supervising 5 threads of 3 processes of 1 users. 五 11 19:58:03 vm rtkit-daemon[1376]: Successfully made thread 4444 of process 4442 owned by '1000' RT at priority 5. 五 11 19:58:03 vm rtkit-daemon[1376]: Supervising 6 threads of 3 processes of 1 users. 五 11 19:58:03 vm dbus-daemon[533]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.121' (uid=1000 pid=4442 comm="/usr/bin/pulseaudio --daemonize=no --log-target=jo" label="unconfined") 五 11 19:58:03 vm systemd[1]: Condition check resulted in Bluetooth service being skipped. 五 11 19:58:03 vm systemd[1353]: Started Sound Service. ------ I AM SEPARATOR (the first time make check) ------ 五 11 19:58:07 vm sudo[4679]: vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm 五 11 19:58:07 vm sudo[4679]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) 五 11 19:58:07 vm sudo[4679]: pam_unix(sudo:session): session closed for user root 五 11 19:58:07 vm sudo[4682]: vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd 五 11 19:58:07 vm sudo[4682]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) 五 11 19:58:07 vm sudo[4682]: pam_unix(sudo:session): session closed for user root 五 11 19:58:07 vm sudo[4687]: vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm 五 11 19:58:07 vm sudo[4687]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) 五 11 19:58:07 vm sudo[4687]: pam_unix(sudo:session): session closed for user root 五 11 19:58:07 vm kernel: FIFO file closed 五 11 19:58:07 vm kernel: FIFO file /tmp/audio.pcm opened 五 11 19:58:07 vm kernel: FIFO file closed 五 11 19:58:07 vm kernel: FIFO file /tmp/audio.pcm opened 五 11 19:58:07 vm kernel: FIFO file closed 五 11 19:58:07 vm kernel: FIFO file /tmp/audio.pcm opened 五 11 19:58:07 vm kernel: FIFO file closed 五 11 19:58:07 vm kernel: FIFO file /tmp/audio.pcm opened 五 11 19:58:07 vm kernel: FIFO file closed 五 11 19:58:07 vm kernel: FIFO file /tmp/audio.pcm opened 五 11 19:58:07 vm pulseaudio[4442]: Disabling timer-based scheduling because running inside a VM. 五 11 19:58:07 vm kernel: FIFO file closed 五 11 19:58:07 vm rtkit-daemon[1376]: Supervising 6 threads of 3 processes of 1 users. 五 11 19:58:07 vm rtkit-daemon[1376]: Successfully made thread 4695 of process 4442 owned by '1000' RT at priority 5. 五 11 19:58:07 vm rtkit-daemon[1376]: Supervising 7 threads of 3 processes of 1 users. 五 11 19:58:07 vm kernel: FIFO file /tmp/audio.pcm opened 五 11 19:58:07 vm kernel: Triggered 五 11 19:58:07 vm kernel: START: channels 1 rate 22050 五 11 19:58:07 vm kernel: 4408 bytes written 五 11 19:58:08 vm kernel: 178 bytes written 五 11 19:58:08 vm kernel: 4230 bytes written 五 11 19:58:08 vm kernel: 180 bytes written 五 11 19:58:08 vm kernel: 4228 bytes written 五 11 19:58:08 vm kernel: 182 bytes written 五 11 19:58:08 vm kernel: 4226 bytes written 五 11 19:58:08 vm kernel: 184 bytes written 五 11 19:58:08 vm kernel: 4224 bytes written 五 11 19:58:08 vm kernel: 186 bytes written 五 11 19:58:08 vm kernel: 4222 bytes written 五 11 19:58:08 vm kernel: 188 bytes written 五 11 19:58:08 vm kernel: 4220 bytes written 五 11 19:58:08 vm kernel: 190 bytes written 五 11 19:58:08 vm kernel: 4218 bytes written 五 11 19:58:08 vm kernel: 192 bytes written 五 11 19:58:08 vm kernel: 4216 bytes written 五 11 19:58:08 vm kernel: 194 bytes written 五 11 19:58:08 vm kernel: 4214 bytes written 五 11 19:58:08 vm kernel: 196 bytes written 五 11 19:58:08 vm kernel: 4212 bytes written 五 11 19:58:08 vm gsd-media-keys[1720]: Unable to get default sink 五 11 19:58:08 vm gsd-media-keys[1720]: Unable to get default source 五 11 19:58:09 vm kernel: 198 bytes written 五 11 19:58:09 vm kernel: 4210 bytes written 五 11 19:58:09 vm sudo[4701]: vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd 五 11 19:58:09 vm sudo[4701]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) 五 11 19:58:09 vm sudo[4701]: pam_unix(sudo:session): session closed for user root vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv writes after rmmod 五 11 19:58:09 vm kernel: 200 bytes written 五 11 19:58:09 vm kernel: 4208 bytes written 五 11 19:58:09 vm kernel: 202 bytes written 五 11 19:58:09 vm kernel: 4206 bytes written 五 11 19:58:09 vm kernel: 204 bytes written 五 11 19:58:09 vm kernel: 4204 bytes written 五 11 19:58:09 vm kernel: 206 bytes written 五 11 19:58:09 vm kernel: 4202 bytes written 五 11 19:58:09 vm kernel: 208 bytes written 五 11 19:58:09 vm kernel: 4200 bytes written 五 11 19:58:09 vm kernel: 210 bytes written 五 11 19:58:09 vm kernel: 4198 bytes written 五 11 19:58:09 vm kernel: 212 bytes written 五 11 19:58:09 vm kernel: 4196 bytes written 五 11 19:58:09 vm kernel: 214 bytes written 五 11 19:58:09 vm kernel: 4194 bytes written 五 11 19:58:09 vm kernel: 216 bytes written 五 11 19:58:09 vm kernel: 4192 bytes written 五 11 19:58:10 vm kernel: 218 bytes written 五 11 19:58:10 vm kernel: 4190 bytes written 五 11 19:58:10 vm kernel: 220 bytes written 五 11 19:58:10 vm kernel: 4188 bytes written 五 11 19:58:10 vm kernel: 222 bytes written 五 11 19:58:10 vm kernel: 4186 bytes written 五 11 19:58:10 vm kernel: 224 bytes written 五 11 19:58:10 vm kernel: 4184 bytes written 五 11 19:58:10 vm kernel: 226 bytes written 五 11 19:58:10 vm kernel: 4182 bytes written 五 11 19:58:10 vm kernel: 228 bytes written 五 11 19:58:10 vm kernel: 4180 bytes written 五 11 19:58:10 vm kernel: 230 bytes written 五 11 19:58:10 vm kernel: 4178 bytes written 五 11 19:58:10 vm kernel: 232 bytes written 五 11 19:58:10 vm kernel: 4176 bytes written 五 11 19:58:10 vm kernel: 234 bytes written 五 11 19:58:10 vm kernel: 4174 bytes written 五 11 19:58:10 vm kernel: 236 bytes written 五 11 19:58:10 vm kernel: 4172 bytes written 五 11 19:58:11 vm kernel: 238 bytes written 五 11 19:58:11 vm kernel: 4170 bytes written 五 11 19:58:11 vm kernel: 240 bytes written 五 11 19:58:11 vm kernel: 4168 bytes written 五 11 19:58:11 vm kernel: 242 bytes written 五 11 19:58:11 vm kernel: 4166 bytes written 五 11 19:58:11 vm kernel: 244 bytes written 五 11 19:58:11 vm kernel: 4164 bytes written 五 11 19:58:11 vm kernel: 246 bytes written 五 11 19:58:11 vm kernel: 4162 bytes written 五 11 19:58:11 vm kernel: 248 bytes written 五 11 19:58:11 vm kernel: 4160 bytes written 五 11 19:58:11 vm kernel: 250 bytes written 五 11 19:58:11 vm kernel: 4158 bytes written 五 11 19:58:11 vm kernel: 252 bytes written 五 11 19:58:11 vm kernel: 4156 bytes written 五 11 19:58:11 vm kernel: 254 bytes written 五 11 19:58:11 vm kernel: 4154 bytes written 五 11 19:58:11 vm kernel: 256 bytes written 五 11 19:58:11 vm kernel: 4152 bytes written 五 11 19:58:12 vm kernel: 258 bytes written 五 11 19:58:12 vm kernel: 4150 bytes written 五 11 19:58:12 vm kernel: 260 bytes written 五 11 19:58:12 vm kernel: 4148 bytes written 五 11 19:58:12 vm kernel: 262 bytes written 五 11 19:58:12 vm kernel: 4146 bytes written 五 11 19:58:12 vm kernel: 264 bytes written 五 11 19:58:12 vm kernel: 4144 bytes written 五 11 19:58:12 vm kernel: 266 bytes written 五 11 19:58:12 vm kernel: 4142 bytes written 五 11 19:58:12 vm kernel: 268 bytes written 五 11 19:58:12 vm kernel: 4140 bytes written 五 11 19:58:12 vm kernel: 270 bytes written 五 11 19:58:12 vm kernel: 4138 bytes written 五 11 19:58:12 vm kernel: 272 bytes written 五 11 19:58:12 vm kernel: 4136 bytes written 五 11 19:58:12 vm kernel: 274 bytes written 五 11 19:58:12 vm kernel: 4134 bytes written 五 11 19:58:12 vm kernel: 276 bytes written 五 11 19:58:12 vm kernel: Triggered 五 11 19:58:12 vm kernel: STOP 五 11 19:58:28 vm dbus-daemon[533]: [system] Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms) 五 11 19:58:28 vm pulseaudio[4442]: GetManagedObjects() failed: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken. ------ I AM SEPARATOR (the second time make check) ------ 五 11 19:58:43 vm sudo[4944]: vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm 五 11 19:58:43 vm sudo[4944]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) 五 11 19:58:43 vm sudo[4944]: pam_unix(sudo:session): session closed for user root 五 11 19:58:43 vm sudo[4947]: vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd 五 11 19:58:43 vm sudo[4947]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) 五 11 19:58:43 vm sudo[4947]: pam_unix(sudo:session): session closed for user root 五 11 19:58:43 vm sudo[4952]: vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm 五 11 19:58:43 vm sudo[4952]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) 五 11 19:58:43 vm sudo[4952]: pam_unix(sudo:session): session closed for user root 五 11 19:58:44 vm kernel: FIFO file closed 五 11 19:58:44 vm kernel: FIFO file /tmp/audio.pcm opened 五 11 19:58:44 vm kernel: Triggered 五 11 19:58:44 vm kernel: START: channels 1 rate 22050 五 11 19:58:44 vm kernel: 5820 bytes written 五 11 19:58:44 vm kernel: 5468 bytes written 五 11 19:58:45 vm kernel: 5470 bytes written 五 11 19:58:45 vm kernel: 5290 bytes written 五 11 19:58:45 vm kernel: 178 bytes written 五 11 19:58:45 vm kernel: 5644 bytes written 五 11 19:58:45 vm kernel: 5468 bytes written 五 11 19:58:45 vm kernel: 5470 bytes written 五 11 19:58:45 vm kernel: 5288 bytes written 五 11 19:58:45 vm kernel: 180 bytes written 五 11 19:58:45 vm kernel: 5644 bytes written 五 11 19:58:45 vm kernel: 5468 bytes written 五 11 19:58:46 vm kernel: 5470 bytes written 五 11 19:58:46 vm kernel: 5286 bytes written 五 11 19:58:46 vm kernel: 182 bytes written 五 11 19:58:46 vm kernel: 5644 bytes written 五 11 19:58:46 vm kernel: 5468 bytes written 五 11 19:58:46 vm kernel: 5470 bytes written 五 11 19:58:46 vm kernel: 5284 bytes written 五 11 19:58:46 vm kernel: 184 bytes written 五 11 19:58:46 vm kernel: 5644 bytes written 五 11 19:58:46 vm kernel: 5468 bytes written 五 11 19:58:47 vm kernel: 5470 bytes written 五 11 19:58:47 vm kernel: 5282 bytes written 五 11 19:58:47 vm kernel: 186 bytes written 五 11 19:58:47 vm kernel: 5644 bytes written 五 11 19:58:47 vm kernel: 5468 bytes written 五 11 19:58:47 vm kernel: 5470 bytes written 五 11 19:58:47 vm kernel: 5280 bytes written 五 11 19:58:47 vm kernel: 188 bytes written 五 11 19:58:47 vm kernel: 5644 bytes written 五 11 19:58:47 vm kernel: Triggered 五 11 19:58:47 vm kernel: STOP 五 11 19:58:47 vm sudo[4961]: vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd 五 11 19:58:47 vm sudo[4961]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) 五 11 19:58:47 vm sudo[4961]: pam_unix(sudo:session): session closed for user root vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv new error message? 五 11 19:58:56 vm pulseaudio[4442]: ALSA woke us up to write new data to the device, but there was actually nothing to write. 五 11 19:58:56 vm pulseaudio[4442]: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers. 五 11 19:58:56 vm pulseaudio[4442]: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
Hi @freshLiver ,
I would like to provide my detail env and my experiment result.Env info
My env is running on a bare metal x86 machine.
Installed packages: build-essential git tmux meson bison linux-headers-uname -r curl ffmpeg gcc-11$ uname -a Linux jio-Aspire-V3-571G 5.15.0-106-generic #116-Ubuntu SMP Wed Apr 17 09:17:56 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux $ cat /etc/os-release PRETTY_NAME="Ubuntu 22.04.4 LTS" NAME="Ubuntu" VERSION_ID="22.04" VERSION="22.04.4 LTS (Jammy Jellyfish)" VERSION_CODENAME=jammy ID=ubuntu ID_LIKE=debian HOME_URL="https://www.ubuntu.com/" SUPPORT_URL="https://help.ubuntu.com/" BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/" PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy" UBUNTU_CODENAME=jammy
Output of
make checkI apply your changes on
verify.sh. What's more, I do not disable PulseAudio, then get the same situation of yours (firstmake checkout.wavdoes not contain any sound).
If I disable PulseAudio then runmake check,out.wavalways produces sound.Syslog
I get the alike result if I do not disable PluseAudio first.
$ journalctl -f ------ I AM SEPARATOR (the first time make check) ------ May 12 10:55:03 jio-Aspire-V3-571G sudo[5481]: pam_unix(sudo:auth): authentication failure; logname=jio uid=1000 euid=0 tty=/dev/pts/4 ruser=jio rhost= user=jio May 12 10:55:07 jio-Aspire-V3-571G sudo[5481]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm May 12 10:55:07 jio-Aspire-V3-571G sudo[5481]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 12 10:55:07 jio-Aspire-V3-571G sudo[5481]: pam_unix(sudo:session): session closed for user root May 12 10:55:07 jio-Aspire-V3-571G sudo[5484]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd May 12 10:55:07 jio-Aspire-V3-571G sudo[5484]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 12 10:55:07 jio-Aspire-V3-571G sudo[5484]: pam_unix(sudo:session): session closed for user root May 12 10:55:07 jio-Aspire-V3-571G sudo[5489]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm May 12 10:55:07 jio-Aspire-V3-571G sudo[5489]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 12 10:55:07 jio-Aspire-V3-571G sudo[5489]: pam_unix(sudo:session): session closed for user root May 12 10:55:07 jio-Aspire-V3-571G systemd[2899]: Reached target Sound Card. May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file closed May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file closed May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file closed May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file closed May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file closed May 12 10:55:07 jio-Aspire-V3-571G rtkit-daemon[1350]: Supervising 6 threads of 3 processes of 1 users. May 12 10:55:07 jio-Aspire-V3-571G rtkit-daemon[1350]: Successfully made thread 5497 of process 2908 owned by '1000' RT at priority 5. May 12 10:55:07 jio-Aspire-V3-571G rtkit-daemon[1350]: Supervising 7 threads of 3 processes of 1 users. May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 12 10:55:07 jio-Aspire-V3-571G kernel: Triggered May 12 10:55:08 jio-Aspire-V3-571G sudo[5504]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd May 12 10:55:08 jio-Aspire-V3-571G sudo[5504]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 12 10:55:08 jio-Aspire-V3-571G sudo[5504]: pam_unix(sudo:session): session closed for user root May 12 10:55:09 jio-Aspire-V3-571G kernel: START: channels 1 rate 22050 May 12 10:55:09 jio-Aspire-V3-571G kernel: kernel_write: expect write 88200, but 65536 May 12 10:55:11 jio-Aspire-V3-571G kernel: 882 bytes written May 12 10:55:11 jio-Aspire-V3-571G kernel: kernel_write: expect write 87318, but 65536 May 12 10:55:12 jio-Aspire-V3-571G kernel: 176 bytes written May 12 10:55:12 jio-Aspire-V3-571G kernel: Triggered May 12 10:55:12 jio-Aspire-V3-571G kernel: STOP ------ I AM SEPARATOR (the second time make check) ------ May 12 10:56:07 jio-Aspire-V3-571G sudo[5788]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm May 12 10:56:07 jio-Aspire-V3-571G sudo[5788]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 12 10:56:07 jio-Aspire-V3-571G sudo[5788]: pam_unix(sudo:session): session closed for user root May 12 10:56:07 jio-Aspire-V3-571G sudo[5791]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd May 12 10:56:07 jio-Aspire-V3-571G sudo[5791]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 12 10:56:07 jio-Aspire-V3-571G sudo[5791]: pam_unix(sudo:session): session closed for user root May 12 10:56:07 jio-Aspire-V3-571G sudo[5796]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm May 12 10:56:07 jio-Aspire-V3-571G sudo[5796]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 12 10:56:07 jio-Aspire-V3-571G sudo[5796]: pam_unix(sudo:session): session closed for user root May 12 10:56:08 jio-Aspire-V3-571G kernel: FIFO file closed May 12 10:56:08 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 12 10:56:08 jio-Aspire-V3-571G kernel: Triggered May 12 10:56:08 jio-Aspire-V3-571G kernel: START: channels 1 rate 22050 May 12 10:56:09 jio-Aspire-V3-571G kernel: 5820 bytes written May 12 10:56:09 jio-Aspire-V3-571G kernel: 5468 bytes written May 12 10:56:09 jio-Aspire-V3-571G kernel: 5470 bytes written May 12 10:56:09 jio-Aspire-V3-571G kernel: 5290 bytes written May 12 10:56:09 jio-Aspire-V3-571G kernel: 178 bytes written May 12 10:56:09 jio-Aspire-V3-571G kernel: 5644 bytes written May 12 10:56:09 jio-Aspire-V3-571G kernel: 5468 bytes written May 12 10:56:09 jio-Aspire-V3-571G kernel: 5470 bytes written May 12 10:56:09 jio-Aspire-V3-571G kernel: 5288 bytes written May 12 10:56:09 jio-Aspire-V3-571G kernel: 180 bytes written May 12 10:56:10 jio-Aspire-V3-571G kernel: 5644 bytes written May 12 10:56:10 jio-Aspire-V3-571G kernel: 5468 bytes written May 12 10:56:10 jio-Aspire-V3-571G kernel: 5470 bytes written May 12 10:56:10 jio-Aspire-V3-571G kernel: 5286 bytes written May 12 10:56:10 jio-Aspire-V3-571G kernel: 182 bytes written May 12 10:56:10 jio-Aspire-V3-571G kernel: 5644 bytes written May 12 10:56:10 jio-Aspire-V3-571G kernel: 5468 bytes written May 12 10:56:10 jio-Aspire-V3-571G kernel: 5470 bytes written May 12 10:56:10 jio-Aspire-V3-571G kernel: 5284 bytes written May 12 10:56:10 jio-Aspire-V3-571G kernel: 184 bytes written May 12 10:56:11 jio-Aspire-V3-571G kernel: 5644 bytes written May 12 10:56:11 jio-Aspire-V3-571G kernel: 5468 bytes written May 12 10:56:11 jio-Aspire-V3-571G kernel: 5470 bytes written May 12 10:56:11 jio-Aspire-V3-571G kernel: 5282 bytes written May 12 10:56:11 jio-Aspire-V3-571G kernel: 186 bytes written May 12 10:56:11 jio-Aspire-V3-571G kernel: 5644 bytes written May 12 10:56:11 jio-Aspire-V3-571G kernel: 5468 bytes written May 12 10:56:11 jio-Aspire-V3-571G kernel: 5470 bytes written May 12 10:56:11 jio-Aspire-V3-571G kernel: 5280 bytes written May 12 10:56:11 jio-Aspire-V3-571G kernel: 188 bytes written May 12 10:56:11 jio-Aspire-V3-571G kernel: 5644 bytes written May 12 10:56:11 jio-Aspire-V3-571G kernel: Triggered May 12 10:56:11 jio-Aspire-V3-571G kernel: STOP May 12 10:56:11 jio-Aspire-V3-571G sudo[5805]: jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd May 12 10:56:11 jio-Aspire-V3-571G sudo[5805]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 12 10:56:11 jio-Aspire-V3-571G sudo[5805]: pam_unix(sudo:session): session closed for user root May 12 10:56:30 jio-Aspire-V3-571G kernel: FIFO file closed
Thanks for the system info, @Cuda-Chen !
And I just found that the repeated FIFO open/close seems caused by the
insmodinstead ofaplay.Therefore, I suspect that this might be due to the module not being fully initialized yet. I tried simply adding
sleep 1before theinsmod, and after running a few simple tests, the issue did not reoccur.Could you please try this in your environment as well?
Hi @freshLiver ,
Sorry for the late reply.
I will conduct the "sleep 1before theinsmodtest in these days.I tried simply adding sleep 1 before the
insmod, and after running a ...Sorry, I made a mistake. The
sleepcommand should be added afterinsmod.Hi @freshLiver ,
I tried simply adding sleep 1 before the
insmod, and after running a ...Sorry, I made a mistake. The
sleepcommand should be added afterinsmod.It seems that the
sleepafterinsmoddoes not solve the repeated FIFO open/close scene:$ journalctl -f ------ I AM SEPARATOR (the first time make check) ------ May 19 09:14:28 jio-Aspire-V3-571G systemd[4649]: Reached target Sound Card. May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file closed May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file closed May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file closed May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file closed May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file closed May 19 09:14:28 jio-Aspire-V3-571G rtkit-daemon[1456]: Supervising 6 threads of 3 processes of 1 users. May 19 09:14:28 jio-Aspire-V3-571G rtkit-daemon[1456]: Successfully made thread 9338 of process 4658 owned by '1000' RT at priority 5. May 19 09:14:28 jio-Aspire-V3-571G rtkit-daemon[1456]: Supervising 7 threads of 3 processes of 1 users. May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 19 09:14:28 jio-Aspire-V3-571G kernel: Triggered May 19 09:14:30 jio-Aspire-V3-571G kernel: START: channels 1 rate 22050 May 19 09:14:30 jio-Aspire-V3-571G kernel: kernel_write: expect write 88200, but 65536 May 19 09:14:30 jio-Aspire-V3-571G sudo[9346]: jio : TTY=pts/5 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd May 19 09:14:30 jio-Aspire-V3-571G sudo[9346]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 19 09:14:30 jio-Aspire-V3-571G sudo[9346]: pam_unix(sudo:session): session closed for user root May 19 09:14:32 jio-Aspire-V3-571G kernel: 882 bytes written May 19 09:14:32 jio-Aspire-V3-571G kernel: kernel_write: expect write 87318, but 65536 May 19 09:14:33 jio-Aspire-V3-571G kernel: kernel_write failed May 19 09:14:33 jio-Aspire-V3-571G kernel: Triggered May 19 09:14:33 jio-Aspire-V3-571G kernel: STOP ------ I AM SEPARATOR (the second time make check) ------ May 19 09:16:00 jio-Aspire-V3-571G sudo[9626]: jio : TTY=pts/5 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm May 19 09:16:00 jio-Aspire-V3-571G sudo[9626]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 19 09:16:00 jio-Aspire-V3-571G sudo[9626]: pam_unix(sudo:session): session closed for user root May 19 09:16:00 jio-Aspire-V3-571G sudo[9629]: jio : TTY=pts/5 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd May 19 09:16:00 jio-Aspire-V3-571G sudo[9629]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 19 09:16:00 jio-Aspire-V3-571G sudo[9629]: pam_unix(sudo:session): session closed for user root May 19 09:16:00 jio-Aspire-V3-571G sudo[9634]: jio : TTY=pts/5 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm May 19 09:16:00 jio-Aspire-V3-571G sudo[9634]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 19 09:16:00 jio-Aspire-V3-571G sudo[9634]: pam_unix(sudo:session): session closed for user root May 19 09:16:02 jio-Aspire-V3-571G kernel: FIFO file closed May 19 09:16:02 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened May 19 09:16:02 jio-Aspire-V3-571G kernel: Triggered May 19 09:16:02 jio-Aspire-V3-571G kernel: START: channels 1 rate 22050 May 19 09:16:03 jio-Aspire-V3-571G kernel: 5820 bytes written May 19 09:16:03 jio-Aspire-V3-571G kernel: 5468 bytes written May 19 09:16:03 jio-Aspire-V3-571G kernel: 5470 bytes written May 19 09:16:03 jio-Aspire-V3-571G kernel: 5290 bytes written May 19 09:16:03 jio-Aspire-V3-571G kernel: 178 bytes written May 19 09:16:03 jio-Aspire-V3-571G kernel: 5644 bytes written May 19 09:16:03 jio-Aspire-V3-571G kernel: 5468 bytes written May 19 09:16:03 jio-Aspire-V3-571G kernel: 5470 bytes written May 19 09:16:03 jio-Aspire-V3-571G kernel: 5288 bytes written May 19 09:16:03 jio-Aspire-V3-571G kernel: 180 bytes written May 19 09:16:04 jio-Aspire-V3-571G kernel: 5644 bytes written May 19 09:16:04 jio-Aspire-V3-571G kernel: 5468 bytes written May 19 09:16:04 jio-Aspire-V3-571G kernel: 5470 bytes written May 19 09:16:04 jio-Aspire-V3-571G kernel: 5286 bytes written May 19 09:16:04 jio-Aspire-V3-571G kernel: 182 bytes written May 19 09:16:04 jio-Aspire-V3-571G kernel: 5644 bytes written May 19 09:16:04 jio-Aspire-V3-571G kernel: 5468 bytes written May 19 09:16:04 jio-Aspire-V3-571G kernel: 5470 bytes written May 19 09:16:04 jio-Aspire-V3-571G kernel: 5284 bytes written May 19 09:16:04 jio-Aspire-V3-571G kernel: 184 bytes written May 19 09:16:05 jio-Aspire-V3-571G kernel: 5644 bytes written May 19 09:16:05 jio-Aspire-V3-571G kernel: 5468 bytes written May 19 09:16:05 jio-Aspire-V3-571G kernel: 5470 bytes written May 19 09:16:05 jio-Aspire-V3-571G kernel: 5282 bytes written May 19 09:16:05 jio-Aspire-V3-571G kernel: 186 bytes written May 19 09:16:05 jio-Aspire-V3-571G kernel: 5644 bytes written May 19 09:16:05 jio-Aspire-V3-571G kernel: 5468 bytes written May 19 09:16:05 jio-Aspire-V3-571G kernel: 5470 bytes written May 19 09:16:05 jio-Aspire-V3-571G kernel: 5280 bytes written May 19 09:16:05 jio-Aspire-V3-571G kernel: 188 bytes written May 19 09:16:05 jio-Aspire-V3-571G kernel: 5644 bytes written May 19 09:16:05 jio-Aspire-V3-571G kernel: Triggered May 19 09:16:05 jio-Aspire-V3-571G kernel: STOP May 19 09:16:05 jio-Aspire-V3-571G sudo[9644]: jio : TTY=pts/5 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd May 19 09:16:05 jio-Aspire-V3-571G sudo[9644]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000) May 19 09:16:05 jio-Aspire-V3-571G sudo[9644]: pam_unix(sudo:session): session closed for user root $ dmesg -W ------ I AM SEPARATOR (the first time make check) ------ [ 314.697972] FIFO file /tmp/audio.pcm opened [ 314.698094] FIFO file closed [ 314.698197] FIFO file /tmp/audio.pcm opened [ 314.698251] FIFO file closed [ 314.698339] FIFO file /tmp/audio.pcm opened [ 314.698413] FIFO file closed [ 314.698500] FIFO file /tmp/audio.pcm opened [ 314.698674] FIFO file closed [ 314.698781] FIFO file /tmp/audio.pcm opened [ 314.702722] FIFO file closed [ 314.704888] FIFO file /tmp/audio.pcm opened [ 314.711622] Triggered [ 314.711627] START: channels 1 rate 22050 [ 316.731118] kernel_write: expect write 88200, but 65536 [ 316.731193] 882 bytes written [ 318.715116] kernel_write: expect write 87318, but 65536 [ 318.715147] kernel_write failed [ 319.717213] Triggered [ 319.717237] STOP [ 319.717305] FIFO file closed ------ I AM SEPARATOR (the second time make check) ------ [ 409.397916] FIFO file /tmp/audio.pcm opened [ 409.401056] Triggered [ 409.401061] START: channels 1 rate 22050 [ 409.530983] 5820 bytes written [ 409.654960] 5468 bytes written [ 409.778954] 5470 bytes written [ 409.902960] 5290 bytes written [ 409.903001] 178 bytes written [ 410.030961] 5644 bytes written [ 410.154964] 5468 bytes written [ 410.278966] 5470 bytes written [ 410.402963] 5288 bytes written [ 410.403010] 180 bytes written [ 410.530957] 5644 bytes written [ 410.654959] 5468 bytes written [ 410.778956] 5470 bytes written [ 410.902964] 5286 bytes written [ 410.903005] 182 bytes written [ 411.030957] 5644 bytes written [ 411.154950] 5468 bytes written [ 411.278950] 5470 bytes written [ 411.402949] 5284 bytes written [ 411.403016] 184 bytes written [ 411.530954] 5644 bytes written [ 411.654952] 5468 bytes written [ 411.778955] 5470 bytes written [ 411.902952] 5282 bytes written [ 411.903017] 186 bytes written [ 412.030952] 5644 bytes written [ 412.154904] 5468 bytes written [ 412.278954] 5470 bytes written [ 412.402954] 5280 bytes written [ 412.403024] 188 bytes written [ 412.530953] 5644 bytes written [ 412.531017] Triggered [ 412.531030] STOPWhat's more, my environment is complaining about cannot find
errname, so I change your patch invsnd.cas follows:diff --git a/vsnd.c b/vsnd.c index adb5841..22f10fe 100644 --- a/vsnd.c +++ b/vsnd.c @@ -222,7 +226,19 @@ static unsigned int vsnd_pos_update(struct vsnd_pcm *pcm_data) unsigned int size = byte_left_to_write; if (src_off + size > pcm_data->pcm_buffer_size) size = pcm_data->pcm_buffer_size - src_off; - kernel_write(vsnd->fifo_fp, src_data + src_off, size, NULL); + again: + ret = kernel_write(vsnd->fifo_fp, src_data + src_off, size, NULL); + if (ret < 0) { + // if (ret == -EAGAIN && retry_limit--) { + // goto again; + // } + //pr_err("kernel_write: failed: %s", errname(ret)); + pr_err("kernel_write failed"); + } else if (ret < size) { + pr_warn("kernel_write: expect write %d, but %d", size, ret); + } else { + pr_info("%d bytes written", ret); + } byte_left_to_write -= size; src_off = (src_off + size) % pcm_data->pcm_buffer_size; } while (byte_left_to_write > 0);
@Cuda-Chen , thanks for testing and sharing the result,
I might try to enable some configs (e.g., CONFIG_SND_DEBUG) on the 5.15 kernel to check whether there will have some debug messages reported by the kernel.
And, for the
errnamesymbol, since this optionCONFIG_SYMBOLIC_ERRNAMEis enabled in all my testing environments, I assumed it was enabled by default in Ubuntu. Sorry for not handling it.Hi @freshLiver ,
I might try to enable some configs (e.g., CONFIG_SND_DEBUG) on the 5.15 kernel to check whether there will have some debug messages reported by the kernel.
You can share the configs here as we have gotten the same result yet different environment.
And, for the
errnamesymbol, since this optionCONFIG_SYMBOLIC_ERRNAMEis enabled in all my testing environments, I assumed it was enabled by default in Ubuntu. Sorry for not handling it.That's okey, as there are zillion of options, and some of the options require re-compilation.
No problem, I will post my kernel config (maybe using the gist to avoid making this page too long) once I have reproduced the problem on the custom kernels.
For configs of the testing environments above, I think they should be available via the apt?
2 remaining items
Sure, and when I was trying to reproduce the problem, I found that the writes after
rmmoddon't appear to be merely delayed. If we check the size after all writes have completed, we will find that the output file is much larger than the expected size and its content is entirely zeros:+ ls -l out.pcm -rw-r--r-- 1 user user 84456 May 27 2024 out.pcm <------- size before all writes done + ffmpeg -f s16le -ar 22.05k -ac 1 -loglevel 8 -i out.pcm out.wav [ 238.170629] 392 bytes written [ 238.267125] 4016 bytes written user@localhost:/mnt$ [ 238.267845] 394 bytes written [ 238.363233] 4014 bytes written ... [ 241.166242] 276 bytes written [ 241.169218] Triggered [ 241.169741] STOP [ 241.170160] vsnd_hw_free called user@localhost:/mnt$ ls -l out* -rw-r--r-- 1 user user 216580 May 27 00:07 out.pcm <------- size after all writes done user@localhost:/mnt$ diff out.pcm <(head -c 216580 /dev/zero) && echo zero zero
Additionally, it is worth noting that if I disable the pulseaudio service, the previously mentioned issues do not occur during the process, and the resulting audio file also sounds no problem as expected:
user@localhost:/mnt$ systemctl --user stop pulseaudio{.socket,} user@localhost:/mnt$ ./scripts/verify.sh + sudo modprobe snd_pcm + sudo rmmod vsnd rmmod: ERROR: Module vsnd is not currently loaded + rm -f /tmp/audio.pcm + mkfifo /tmp/audio.pcm + sudo insmod vsnd.ko out_fifo_name=/tmp/audio.pcm + tee out.pcm + sleep 1 + aplay -D plughw:CARD=vsnd,DEV=0 CantinaBand3.wav [ 1726.186125] FIFO file closed Playing WAVE 'CantinaBand3.wav' : Signed 16 bit Little Endian, R[ 1794.967182] FIFO file /tmp/audio.pcm opened ate 22050 Hz, Mo[ 1794.970675] vsnd_hw_params called no [ 1794.971712] vsnd_prepare called [ 1794.972949] Triggered [ 1794.973686] START: channels 1 rate 22050 [ 1795.103143] 5820 bytes written ... [ 1798.107200] 5820 bytes written [ 1798.108196] Triggered [ 1798.108991] STOP [ 1798.109993] vsnd_hw_free called + sudo rmmod vsnd + ls -l out.pcm -rw-r--r-- 1 user user 138296 May 27 2024 out.pcm + ffmpeg -f s16le -ar 22.05k -ac 1 -loglevel 8 -i out.pcm out.wav File 'out.wav' already exists. Overwrite? [y/N] y -rw-r--r-- 1 user user 138296 May 27 00:33 out.pcm -rw-r--r-- 1 user user 138374 May 27 00:33 out.wav <----- sounds no problemHi @freshLiver ,
For my knowledge, both PulseAudio and PipeWire are downstream of ALSA. So I suspect there is something funny happens when these downstream components receive the data sent from ALSA.
I suspect there is something funny happens ...
Agree, I have similar opinion as the problems above didn't occur when neither PulseAudio nor PipeWire was enabled.
But I also think it will be good that if there is a workaround for this issue, since most distributions use one of them the by default.
Hi @freshLiver ,
For debugging the PulseAudio, you can first disable PulseAudio then launch
pluseaudio -vvvvvto check the status of PulseAudio.
I put the reference here: https://fedoraproject.org/wiki/How_to_debug_PulseAudio_problemsReacted by YuanI'm currently tracing the problem with gdb, and there are some new findings:
- The write errors occurred during the execution of the PA module
module-udev-detect
The problem will not happen if you comment out theload-module module-udev-detectin PA config. And if you load the module manually by usingpactl load-module module-udev-detect, it will write data to the FIFO and cause write errors. - the EAGAIN is returned from pipe.c (updated: fix wrong line number)
- The write errors occurred during the execution of the PA module
Hi @freshLiver ,
Thanks for your report!
For PulseAudio, I found that the reference count ofvsndcannot be decreased if PulseAudio is enabled.As I have little knowledge of debugging the kernel module, I would like to ask that may you leave the steps?
I have read the kernel document (https://docs.kernel.org/dev-tools/gdb-kernel-debugging.html), it seems that I have to launch a VM, and I am curious are there any alternatives for debugging.I found that the reference count of vsnd cannot be decreased
Thanks for the information! Could you provide the detailed information about the reference count?
I am curious are there any alternatives for debugging.
Maybe you can try user-mode linux, but I'm using qemu as I'm more familiar with it.
Here are the brief steps for building my testing environment:
- prepare a rootfs with needed packages (I use systemd/mkosi to generate the rootfs image)
- defconfig + debug configs mentioned in the kernel doc + sound card configs (make sure the needed modules are built into the kernel, so that you don't need to copy the modules to rootfs)
- add the path of
vmlinux-gdb.pyscript to the gdb config file and make sure your gdb has python supported - run qemu with options mentioned in the doc, and attach gdb to it
- use
lx-symbols /path/to/vsnd/dirto load the vsnd symbol after the module is inserted to the kernel
Thanks for the information! Could you provide the detailed information about the reference count?
For the reference count observation, it is mentioned in #1 (comment), and for you ease I re-post here:
$ lsmod | grep vsnd vsnd 16384 1 snd_pcm 143360 7 snd_hda_codec_hdmi,snd_hda_intel,snd_hda_codec,vsnd,snd_hda_core snd 106496 24 snd_hda_codec_generic,snd_seq,snd_seq_device,snd_hda_codec_hdmi,snd_hwdep,snd_hda_intel,snd_hda_codec,snd_hda_codec_realtek,snd_timer,vsnd,snd_pcm,snd_rawmidiHere are the brief steps for building my testing environment:
omitted as it is lengthyI will try on it as well as user-mode linux. Once I have any findings or some setting problems, I will leave comments here.
Reacted by YuanI found that this problem may be relative to the open flag in
vsnd_open.According to the description of
open()from The Open Group Base Specifications, open a FIFO with flagO_RDWRis undefined:O_RDWR
Open for reading and writing. The result is undefined if this flag is applied to a FIFO.
And if I change the open flag to
O_WRONLY,vsnd_open()will encounter an ENXIO error while executing theudev-detectmodule (manually load it viapactl load-moduleafter the vsnd is inserted into kernel). According to the man page of open(2):ENXIO O_NONBLOCK | O_WRONLY is set, the named file is a FIFO, and no process has the FIFO open for reading.
As for scripts/verify.sh, since it opens the read end through
tee out.pcm < /tmp/audio.pcm >/dev/null &before writing data, I didn't encounter any open error when running this script.To address the problem and eliminate the undefined behavior, a simple workaround might be to add a buffer and write data to the buffer when vsnd fails to open the FIFO, indicating that no read end exists.
To address the problem and eliminate the undefined behavior, a simple workaround might be to add a buffer and write data to the buffer when vsnd fails to open the FIFO, indicating that no read end exists.
It is reasonably fair to forbid non-blocking mode for this FIFO based driver model.
Do you mean that the
vsnd_openshould fall back to blocking mode when there is no reader, instead of writing to a buffer?Do you mean that the
vsnd_openshould fall back to blocking mode when there is no reader, instead of writing to a buffer?Yes, keep it simple and stupid.
I made some changes to implement the fallback mechanism:
diff --git a/vsnd.c b/vsnd.c old mode 100644 new mode 100755 index adb5841..45f890f --- a/vsnd.c +++ b/vsnd.c @@ -328,7 +328,7 @@ static int vsnd_open(struct snd_pcm_substream *substream) struct vsnd_pcm *pcm_data; int dev_id = substream->pcm->device; void *fifo_fp; - int err = 0; + int err = 0, oflags = O_WRONLY | O_NONBLOCK; /* Create and configure PCM data structures */ pcm_data = kzalloc(sizeof(*pcm_data), GFP_KERNEL); @@ -342,9 +342,15 @@ static int vsnd_open(struct snd_pcm_substream *substream) /* CAUTION: We need to open this FIFO pipe as for both read-write as opening * for write-only will cause 'flip_close()' to crash. */ - fifo_fp = filp_open(out_fifo_name[dev_id], O_RDWR | O_NONBLOCK, 0); +retry: + fifo_fp = filp_open(out_fifo_name[dev_id], oflags, 0); if (IS_ERR(fifo_fp)) { - pr_err("Failed to open FIFO file."); + if (PTR_ERR(fifo_fp) == -ENXIO && (oflags & O_NONBLOCK)) { + pr_warn("no read end exists, fallback to blocking mode"); + oflags &= ~O_NONBLOCK; + goto retry; + } + pr_err("Failed to open FIFO file with 0x%x, err:%ld.", oflags, PTR_ERR(fifo_fp)); err = -EIO; goto finally; }
But during the execution of
verify.shscript, it stuck at the aplay command. And after checking the logs of PA, I found that it's because the PA (withmodule-udev-detectenabled) stuck at the initialization step as there is no reader exists. And in order to finish the PA initialization, I had to manually read the FIFO file several times. (updated: pulseaudio log, not system journal)update 2: I have also tried fall back to
O_RDWRinstead ofO_WRONLY, but result in kernel errors and system stuck:[ 128.279827] no read end exists, fallback to O_RDWR [ 128.287839] START: channels 1 rate 22050 [ 129.189331] BUG: scheduling while atomic: swapper/0/0/0x00000100 [ 129.190127] STOP [ 129.190784] Modules linked in: vsnd(O-) [last unloaded: vsnd] [ 129.193035] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G O 5.15.149 #8 [ 129.193039] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014 [ 129.193044] Call Trace: [ 129.193058] <IRQ> [ 129.193063] dump_stack_lvl+0x33/0x46 [ 129.193073] __schedule_bug.cold+0x3e/0x4a [ 129.193080] __schedule+0x5c7/0x6c0 [ 129.193091] schedule+0x53/0xa0 [ 129.193094] pipe_write+0x449/0x620 [ 129.193101] ? wait_woken+0x70/0x70 [ 129.193105] __kernel_write+0x28b/0x310 [ 129.193107] kernel_write+0x6e/0x150 [ 129.193110] vsnd_timer_elapsed+0x162/0x1c0 [vsnd] [ 129.193114] ? vsnd_runtime_free+0x10/0x10 [vsnd] [ 129.193116] call_timer_fn+0x22/0xf0 [ 129.193123] __run_timers+0x204/0x270 [ 129.193126] run_timer_softirq+0x14/0x30 [ 129.193128] __do_softirq+0xbb/0x26a [ 129.193149] irq_exit_rcu+0x7e/0xa0 [ 129.193162] sysvec_apic_timer_interrupt+0x66/0x80 [ 129.193170] </IRQ> [ 129.193170] <TASK> [ 129.193171] asm_sysvec_apic_timer_interrupt+0x16/0x20 [ 129.193179] RIP: 0010:default_idle+0xb/0x10 [ 129.193183] Code: fb 65 48 8b 04 25 00 ad 01 00 f0 80 60 02 df c3 cc cc cc cc 0f ae f0 0f ae 38 0f ae f0 eb b5 eb 07 0f 00 2d 27 42 55 00 fb f4 <c3> cc cc cc cc 65 8b 15 59 32 36 7e 89 d2 48 8b 05 70 00 52 01 48 [ 129.193185] RSP: 0018:ffffffff82803eb0 EFLAGS: 00000206 [ 129.193187] RAX: ffffffff81cb2300 RBX: ffffffff82814940 RCX: ffff888003a57370 [ 129.193188] RDX: 0000000000007655 RSI: ffffffff82803e40 RDI: 0000000000007656 [ 129.193190] RBP: 0000000000000000 R08: 0000000000007655 R09: 0000000000000324 [ 129.193191] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000 [ 129.193192] R13: 0000000000000000 R14: ffffffff82814118 R15: 0000000000000000 [ 129.193194] ? mwait_idle+0x70/0x70 [ 129.193199] default_idle_call+0x2e/0xb0 [ 129.193201] do_idle+0x1ee/0x260 [ 129.193208] cpu_startup_entry+0x14/0x20 [ 129.193211] start_kernel+0x63c/0x665 [ 129.193218] secondary_startup_64_no_verify+0xc2/0xcb [ 129.193224] </TASK> [ 129.193226] bad: scheduling from the idle thread!
And about the usage of
O_RDWRflag mentioned before, I notice that fifo(7) says that it's not undefined behavior under linux, sorry for the misunderstanding.Under Linux, opening a FIFO for read and write will succeed both in blocking and nonblocking mode. POSIX leaves this behavior undefined. This can be used to open a FIFO for writing while there are no readers available.
To avoid the issue where vsnd gets stuck waiting for a reader during PulseAudio initialization, I tried several different methods to handle the situation when no reader exists during the open call:
-
Fallback to
O_RDWR | O_NONBLOCKmode (#700350f)This approach is similar to the current implementation. Since
verify.shadds asleepbetweenteeandaplay, theteebecomes the reader during PulseAudio initialization, andaplayencounters anEBUSYerror when attempting to open the PCM device because vsnd is already occupied by PulseAudio.In my test environment, although removing the
sleepallowsaplayto occupy vsnd first (due to some delay betweenmodule-udev-detectandinsmod), this approach is obviously unreliable. Any delay betweeninsmodandteemight result in PulseAudio getting vsnd first, causingaplayto encounter theEBUSYerror. -
Directly fail vsnd_open and return
ENXIO(#792cd33)With a
sleepbetweenteeandaplay, PulseAudio seems to attempt multipleopencalls. As a result, sometimes PulseAudio successfully opens due to the presence oftee, causingaplay's reader to disappear and leading to anopenfailure (ENXIO).Moving the
sleepbefore theteecan solve this, but it will cause PulseAudio initialization fail and fail to recognize vsnd. -
Make vsnd_open succeed but without actually opening and writing to the FIFO (#f97e367)
With a
sleepbetweenteeandaplay, the situation is similar to situation 1. -
Based on method 3, add substreams to avoid competition between PulseAudio and aplay (#2b2dd19)
With a
sleepbetweenteeandaplay, PulseAudio makes multiple open calls, and tee might be treated as a reader in one of those attempts, causing subsequent aplay to be judged as open without a reader.In several of my test environments, this issue can be resolved by adding a sleep before tee, as PulseAudio's initialization process seems to involve only one open that performs a write, and other open calls are immediately closed.
After these tests, I think the previously encountered issue of out.wav sounds lagged is due to PulseAudio (or PipeWire) initialization and aplay write data interleaved to the FIFO.
-
Hi @freshLiver ,
Thanks for your thorough examinations!
For the user-mode Linux environment, though I am quite busy these weeks (for my working and supporting other project), I think I can create a document of how to debugging thevsndwith user-mode Linux environment once I figure out the compilation settings and the installation of with PulseAudio and PipeWire.
Environment (Ubuntu 24.04 LTS)
➜ vsnd git:(master) ✗ uname -a Linux vm 6.8.0-31-generic #31-Ubuntu SMP PREEMPT_DYNAMIC Sat Apr 20 00:40:06 UTC 2024 x86_64 x86_64 x86_64 GNU/LinuxProblem Description
Overview
If we exeute the following commands:
The content of
out.pcmwill be empty (size 0) after the firstmake checkwas executed. However, if we executemake checkagain, this time theout.pcmwould be filled with correct date. Is this expected behaviour?The sciprt
pipewire-rmmod.shis used to performrmmodin pipewire-powered system for convenience:Details
Setup
For the detailed output info, some
pr_{info,warn,err}are inserted intovsnd.c:And
ls -l outputis inserted intoverify.sh:Outputs
Syslog (journalctl -f)
According to the output of journalctl during the first
make check, the vsnd will first open/close the FIFO file many times.And after the last open, vsnd did some
kernel_writeon the FIFO file but with many EAGAIN errors.I have tried this several times, each time has similar result, and I have no idea why this happened.