Bug 93651 - pulseaudio has long startup time when nvidia hdmi/dp sound is enabled
Summary: pulseaudio has long startup time when nvidia hdmi/dp sound is enabled
Status: RESOLVED MOVED
Alias: None
Product: PulseAudio
Classification: Unclassified
Component: alsa (show other bugs)
Version: unspecified
Hardware: Other All
: medium normal
Assignee: pulseaudio-bugs
QA Contact: pulseaudio-bugs
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-01-10 13:57 UTC by Tom Yan
Modified: 2018-07-30 10:20 UTC (History)
1 user (show)

See Also:
i915 platform:
i915 features:


Attachments
pulseaudio -vvv before I blacklist snd-hda-intel (216.28 KB, text/plain)
2016-01-10 13:58 UTC, Tom Yan
Details
pulseaudio -vvv after I blacklisted snd-hda-intel (139.08 KB, text/plain)
2016-01-10 13:59 UTC, Tom Yan
Details
pulseaudio -vvv with builtin audio enabled (380.47 KB, text/plain)
2016-01-10 15:04 UTC, Tom Yan
Details
pulseaudio -vvv --log-time (101.97 KB, text/plain)
2016-01-10 21:13 UTC, Tom Yan
Details

Description Tom Yan 2016-01-10 13:57:15 UTC
So I have the following cards:
[tom@localhost ~]$ aplay -l
**** List of PLAYBACK Hardware Devices ****
card 0: STX [Xonar STX], device 0: Multichannel [Multichannel]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: STX [Xonar STX], device 1: Digital [Digital]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 1: NVidia [HDA NVidia], device 3: HDMI 0 [HDMI 0]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 1: NVidia [HDA NVidia], device 7: HDMI 1 [HDMI 1]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 1: NVidia [HDA NVidia], device 8: HDMI 2 [HDMI 2]
  Subdevices: 1/1
  Subdevice #0: subdevice #0

And this is how /dev/snd/ looks like:
[tom@localhost ~]$ ls -l /dev/snd/
total 0
drwxr-xr-x  2 root root       80 Jan 10 21:39 by-path
crw-rw----+ 1 root audio 116,  7 Jan 10 21:39 controlC0
crw-rw----+ 1 root audio 116,  2 Jan 10 21:39 controlC1
crw-rw----+ 1 root audio 116,  6 Jan 10 21:39 hwC1D0
crw-rw----+ 1 root audio 116,  9 Jan 10 21:39 pcmC0D0c
crw-rw----+ 1 root audio 116,  8 Jan 10 21:39 pcmC0D0p
crw-rw----+ 1 root audio 116, 11 Jan 10 21:39 pcmC0D1c
crw-rw----+ 1 root audio 116, 10 Jan 10 21:39 pcmC0D1p
crw-rw----+ 1 root audio 116,  3 Jan 10 21:39 pcmC1D3p
crw-rw----+ 1 root audio 116,  4 Jan 10 21:40 pcmC1D7p
crw-rw----+ 1 root audio 116,  5 Jan 10 21:39 pcmC1D8p
crw-rw----+ 1 root audio 116,  1 Jan 10 21:39 seq
crw-rw----+ 1 root audio 116, 33 Jan 10 21:39 timer

And you can see that the pulseaudio takes much longer (5 seconds!) to start before I blacklist snd-hda-intel (so that card 1 is gone):

Jan 10 21:31:33 localhost systemd[257]: Starting Sound Service...
Jan 10 21:31:33 localhost systemd[257]: Started D-Bus User Message Bus.
Jan 10 21:31:39 localhost systemd[257]: Started Sound Service.
Jan 10 21:31:39 localhost systemd[257]: Reached target Default.
Jan 10 21:31:39 localhost systemd[257]: Startup finished in 5.830s.

Jan 10 21:32:16 localhost systemd[248]: Starting Sound Service...
Jan 10 21:32:17 localhost systemd[248]: Started D-Bus User Message Bus.
Jan 10 21:32:17 localhost systemd[248]: Started Sound Service.
Jan 10 21:32:17 localhost systemd[248]: Reached target Default.
Jan 10 21:32:17 localhost systemd[248]: Startup finished in 306ms.

(https://gist.github.com/tomty89/76e9ce98ba85121fc12d/revisions?diff=split)

And the reason seems to be somehow pulse tries to open /dev/snd/pcmC1D{0,1,9-13}p (well also /dev/snd/pcmC1D0c) which does not exist. Please see my attached logs for details.

P.S. I do NOT file this bug report because it is blocking the login shell from popping up after I entered my password in the tty, though I think that could be an issue (of systemd?) too. I file this here merely because I think pulseaudio is doing something silly for HDMI/DP sound devices. As you can see it's being random (9-13, but not >=14, 4-6 or 2, or the existing 3, 7 and 8).
Comment 1 Tom Yan 2016-01-10 13:58:12 UTC
Created attachment 120929 [details]
pulseaudio -vvv before I blacklist snd-hda-intel
Comment 2 Tom Yan 2016-01-10 13:59:37 UTC
Created attachment 120930 [details]
pulseaudio -vvv after I blacklisted snd-hda-intel

You can diff it with "before" for better reading
Comment 3 Tom Yan 2016-01-10 15:04:02 UTC
Created attachment 120932 [details]
pulseaudio -vvv with builtin audio enabled

It seems that it's not really about hdmi/dp sound, but snd-hda-intel in general. I just enabled the builtin realtek hd audio, similar thing happen to it as well, while it has no hdmi PCM. My Xonar STX, which use snd-virtuoso instead, has both the analog and iec958 PCMs just like the realtek, but it doesn't suffer from this issue.

[tom@localhost ~]$ aplay -l
**** List of PLAYBACK Hardware Devices ****
card 0: STX [Xonar STX], device 0: Multichannel [Multichannel]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: STX [Xonar STX], device 1: Digital [Digital]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 1: PCH [HDA Intel PCH], device 0: ALC887-VD Analog [ALC887-VD Analog]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 1: PCH [HDA Intel PCH], device 1: ALC887-VD Digital [ALC887-VD Digital]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 2: NVidia [HDA NVidia], device 3: HDMI 0 [HDMI 0]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 2: NVidia [HDA NVidia], device 7: HDMI 1 [HDMI 1]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 2: NVidia [HDA NVidia], device 8: HDMI 2 [HDMI 2]
  Subdevices: 1/1
  Subdevice #0: subdevice #0

[tom@localhost ~]$ aplay -L
null
    Discard all samples (playback) or generate zero samples (capture)
pulse
    PulseAudio Sound Server
default:CARD=STX
    Xonar STX, Multichannel
    Default Audio Device
sysdefault:CARD=STX
    Xonar STX, Multichannel
    Default Audio Device
front:CARD=STX,DEV=0
    Xonar STX, Multichannel
    Front speakers
surround21:CARD=STX,DEV=0
    Xonar STX, Multichannel
    2.1 Surround output to Front and Subwoofer speakers
surround40:CARD=STX,DEV=0
    Xonar STX, Multichannel
    4.0 Surround output to Front and Rear speakers
surround41:CARD=STX,DEV=0
    Xonar STX, Multichannel
    4.1 Surround output to Front, Rear and Subwoofer speakers
surround50:CARD=STX,DEV=0
    Xonar STX, Multichannel
    5.0 Surround output to Front, Center and Rear speakers
surround51:CARD=STX,DEV=0
    Xonar STX, Multichannel
    5.1 Surround output to Front, Center, Rear and Subwoofer speakers
surround71:CARD=STX,DEV=0
    Xonar STX, Multichannel
    7.1 Surround output to Front, Center, Side, Rear and Woofer speakers
iec958:CARD=STX,DEV=0
    Xonar STX, Multichannel
    IEC958 (S/PDIF) Digital Audio Output
default:CARD=PCH
    HDA Intel PCH, ALC887-VD Analog
    Default Audio Device
sysdefault:CARD=PCH
    HDA Intel PCH, ALC887-VD Analog
    Default Audio Device
front:CARD=PCH,DEV=0
    HDA Intel PCH, ALC887-VD Analog
    Front speakers
surround21:CARD=PCH,DEV=0
    HDA Intel PCH, ALC887-VD Analog
    2.1 Surround output to Front and Subwoofer speakers
surround40:CARD=PCH,DEV=0
    HDA Intel PCH, ALC887-VD Analog
    4.0 Surround output to Front and Rear speakers
surround41:CARD=PCH,DEV=0
    HDA Intel PCH, ALC887-VD Analog
    4.1 Surround output to Front, Rear and Subwoofer speakers
surround50:CARD=PCH,DEV=0
    HDA Intel PCH, ALC887-VD Analog
    5.0 Surround output to Front, Center and Rear speakers
surround51:CARD=PCH,DEV=0
    HDA Intel PCH, ALC887-VD Analog
    5.1 Surround output to Front, Center, Rear and Subwoofer speakers
surround71:CARD=PCH,DEV=0
    HDA Intel PCH, ALC887-VD Analog
    7.1 Surround output to Front, Center, Side, Rear and Woofer speakers
iec958:CARD=PCH,DEV=0
    HDA Intel PCH, ALC887-VD Digital
    IEC958 (S/PDIF) Digital Audio Output
hdmi:CARD=NVidia,DEV=0
    HDA NVidia, HDMI 0
    HDMI Audio Output
hdmi:CARD=NVidia,DEV=1
    HDA NVidia, HDMI 1
    HDMI Audio Output
hdmi:CARD=NVidia,DEV=2
    HDA NVidia, HDMI 2
    HDMI Audio Output
Comment 4 Tanu Kaskinen 2016-01-10 16:24:07 UTC
If the sound card probing takes several seconds, it's an issue in the alsa kernel driver. It shouldn't take that long.

PulseAudio tries to access those nonexistent devices, because the best way to figure out whether a given alsa device can be used is to actually try to use it. Also, PulseAudio doesn't directly use the /dev/snd/* files; instead, PulseAudio uses logical device names like "front", "surround51", "iec958" and "hdmi". Alsa's configuration files define how those names map to the actual device files. The seemingly random selection of device numbers is due to the hdmi device numbering convention in alsa. PulseAudio probes devices named "hdmi:x,[0-7]", and the hdmi devices numbered 0-7 typically correspond to actual device numbers 3 and 7-13 (I don't know the history behind that convention).
Comment 6 Tanu Kaskinen 2016-01-10 16:39:00 UTC
If you pass the --log-time command line option, each log message will have a timestamp. That will help to pinpoint, or at least narrow down, the operation(s) that are causing the delay.
Comment 7 Tom Yan 2016-01-10 17:39:16 UTC
(In reply to Tanu Kaskinen from comment #4)
> PulseAudio tries to access those nonexistent devices, because the best way
> to figure out whether a given alsa device can be used is to actually try to
> use it.

Well yes, but I don't suppose keep trying and failing on things doesn't exist is an efficient way, even if assume it's not bugged? Shouldn't there be faster way to filter out what's on the "list" does not exist first?

> PulseAudio uses logical device names like "front", "surround51", "iec958"
> and "hdmi". Alsa's configuration files define how those names map to the
> actual device files.

But now it seems like PulseAudio even try to open hdmi logical devices on a card even when the card does not have a single one itself, as per aplay -L

Will attach another log with timestamps with all my three cards enabled.
Comment 8 Tanu Kaskinen 2016-01-10 20:47:40 UTC
(In reply to Tom Yan from comment #7)
> Well yes, but I don't suppose keep trying and failing on things doesn't
> exist is an efficient way, even if assume it's not bugged? Shouldn't there
> be faster way to filter out what's on the "list" does not exist first?

Failing due to non-exitent device should be very fast. If there is a faster way, patches are welcome to improve the code, but the speed gains will be rather minimal in any case. I expect your delays to be caused by devices that actually exist.
Comment 9 Tom Yan 2016-01-10 21:11:57 UTC
(In reply to Tanu Kaskinen from comment #8)
> (In reply to Tom Yan from comment #7)
> > Well yes, but I don't suppose keep trying and failing on things doesn't
> > exist is an efficient way, even if assume it's not bugged? Shouldn't there
> > be faster way to filter out what's on the "list" does not exist first?
> 
> Failing due to non-exitent device should be very fast. If there is a faster
> way, patches are welcome to improve the code, but the speed gains will be
> rather minimal in any case. I expect your delays to be caused by devices
> that actually exist.

Seems you're right. And it seems the issue only affect the hdmi/dp sound devices on my nvidia card particularly, no matter which or whether any drm driver is loaded or whether a monitor is connected to it. I just enabled my iGPU and I didn't experience the same huge delay with it, if I set "id=NVidia enable=0" to snd-hda-intel.

I am gonna post an ouput of `pulseaudio -vvv --log-time` with my only DP monitor connected to my motherboard's DP port instead, plus the nvidia blob driver uninstalled, and these:

[tom@localhost ~]$ grep . /etc/modprobe.d/*
/etc/modprobe.d/nouveau.conf:blacklist nouveau
/etc/modprobe.d/snd-hda-intel.conf:options snd-hda-intel id=HDMI enable=0
/etc/modprobe.d/snd-virtuoso.conf:blacklist snd-virtuoso

So the only card left is:

[tom@localhost ~]$ aplay -l
**** List of PLAYBACK Hardware Devices ****
card 0: NVidia [HDA NVidia], device 3: HDMI 0 [HDMI 0]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: NVidia [HDA NVidia], device 7: HDMI 1 [HDMI 1]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: NVidia [HDA NVidia], device 8: HDMI 2 [HDMI 2]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
Comment 10 Tom Yan 2016-01-10 21:13:01 UTC
Created attachment 120937 [details]
pulseaudio -vvv --log-time
Comment 11 Tom Yan 2016-01-10 21:21:41 UTC
In case it matters:

01:00.0 VGA compatible controller [0300]: NVIDIA Corporation GM107 [GeForce GTX 750 Ti] [10de:1380] (rev a2) (prog-if 00 [VGA controller])
	Subsystem: eVga.com. Corp. Device [3842:3751]

01:00.1 Audio device [0403]: NVIDIA Corporation Device [10de:0fbc] (rev a1)
	Subsystem: eVga.com. Corp. Device [3842:3751]
Comment 12 Tom Yan 2016-01-10 21:28:04 UTC
FWIW I've got this card for quite a while and I didn't experience this issue in the past. Then after some time I started to have snd-hda-intel blacklisted since I no longer needed the HDMI sound. And recently I needed snd-hda-intel back for some testing so I noticed this issue, but I don't know when did it started.
Comment 13 Raymond 2016-01-11 01:33:24 UTC
http://git.alsa-project.org/?p=alsa-lib.git;a=tree;f=src/conf/cards;hb=HEAD

Most sound card does not support multi streamingand they don't have multiple HDMI devices
Comment 14 Tom Yan 2016-01-11 08:18:53 UTC
(In reply to Raymond from comment #13)
> http://git.alsa-project.org/?p=alsa-lib.git;a=tree;f=src/conf/cards;hb=HEAD
> 
> Most sound card does not support multi streamingand they don't have multiple
> HDMI devices

That's not true. Most graphic cards these days have more than 1 hdmi / dp port. For example, both my motherboard and my nvidia card has an hdmi port AND a dp++ port (dp/tmds), that's why there are three sound devices listed in aplay.

I do think multi streaming is possible on them, because I recall I have tried that when I have more than 1 monitor.

And what does it have to do with the issue anyway?
Comment 15 David Henningsson 2016-01-11 08:53:55 UTC
I saw in the log that the pauses are exactly one second long, so may I wildly guess that when this happens, you will also see something like
"Codec timeout, polling the codec once" messages in dmesg when this happens?
Comment 16 Raymond 2016-01-11 09:53:37 UTC
cat /proc/asound/card0/pcm0p/sub0/status


You can add pa_alsa_dump(PA_LOG_INFO, u->pcm_handle);

 when underrun occur

http://cgit.freedesktop.org/pulseaudio/pulseaudio/tree/src/modules/alsa/alsa-sink.c

if (!u->first && !u->after_rewind) 
     if (pa_log_ratelimit(PA_LOG_INFO)) 
          pa_log_info("Underrun!"); }
Comment 17 Tom Yan 2016-01-11 15:53:33 UTC
(In reply to David Henningsson from comment #15)
> I saw in the log that the pauses are exactly one second long, so may I
> wildly guess that when this happens, you will also see something like
> "Codec timeout, polling the codec once" messages in dmesg when this happens?

Nope, just checked with journalctl -k.
Comment 18 GitLab Migration User 2018-07-30 10:20:29 UTC
-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/pulseaudio/pulseaudio/issues/357.


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.