Bug 95150

Created attachment 123289 [details]
kernel config

kernel config to reproduce the multiple pulseaudio instance issue

Created attachment 123290 [details]
dmesg log

When there are multiple pulseaudio instances, racing is observed (for example, alsamixer interface doesn't refresh when plug on/off a audio jack) so raise the importance to "high".

Additionally, after apply patches below, we observed only 1 pulseaudio instance when Ubuntu 15.10 boot up. So we guess the multiple pulseaudio instances issue maybe timing related, yet we need pulseaudio expert to help find out the root cause.

Patches that can remove the multiple pulseaudio instances issue, FYI. The patches should not be regarded as a fix for this issue, they are not in upstream yet and further modification may required, and not fully tested to pulseaudio.
Repo: https://git.kernel.org/pub/scm/linux/kernel/git/lenb/linux.git
Branch: x86
Commit id (begin from earliest):
	6e0c25e64e0fb65a42dfc63ad5f660302e07cd87
	16caa2834b2f08cdfd130baa490c45822edef256
	ce5c7b5eaad93c7b0043a7509eec319fe0a0e8a0
	ca376a9909f1151484854c46dc7f01be6d6d9bdb
	4a62ba36cf4fb77ea35dee1f5992e0e7c48dad14
	540cc882de7d1da2e71591e215f0e04cb89883fa
	433f82c8ab3fcaa7ff3b852d01cc74dbdf6d94f1
	65ae86d4fa3473d24445ea402b190e4b4342172e
	3152b94afb8c27595f9b1bfa67885015cb569ba2

What's the output from "ps aux | grep pulse" and "sudo netstat -lxp | grep pulse"?

(In reply to Tanu Kaskinen from comment #5)
> What's the output from "ps aux | grep pulse" and "sudo netstat -lxp | grep
> pulse"?

Please find outputs below:

1.	root@APL-Audio:~# ps aux | grep pulse
test      2306  0.0  0.0 157724  5460 ?        S    23:03   0:00 /usr/bin/pulseaudio --start --log-target=syslog
test      2312  0.0  0.0 157724   684 ?        Ss   23:03   0:00 /usr/bin/pulseaudio --start --log-target=syslog
test      2315  0.0  0.0 157724  2128 ?        S    23:03   0:00 /usr/bin/pulseaudio --start --log-target=syslog
test      2342  0.0  0.0 157724  5492 ?        Sl   23:03   0:00 /usr/bin/pulseaudio --start --log-target=syslog
test      2345  0.0  0.0   4480   852 ?        S    23:03   0:00 /bin/sh /usr/bin/start-pulseaudio-x11
test      2355  0.0  0.0 157724  5396 ?        Sl   23:03   0:00 /usr/bin/pulseaudio --start --log-target=syslog
root      2989  0.0  0.0  13700  2420 pts/6    S+   23:05   0:00 grep --color=auto pulse

2.	root@APL-Audio:~# netstat -lxp |grep pulse
root@APL-Audio:~#
(show nothing)

3.	root@APL-Audio:~# netstat -lxp
Active UNIX domain sockets (only servers)
Proto RefCnt Flags       Type       State         I-Node   PID/Program name    Path
unix  2      [ ACC ]     STREAM     LISTENING     14455    2044/dbus-daemon    @/tmp/dbus-kBVg40bwx4
unix  2      [ ACC ]     STREAM     LISTENING     12057    2124/dbus-daemon    @/tmp/dbus-u9fZIpVSiK
unix  2      [ ACC ]     STREAM     LISTENING     14086    2152/gnome-session  @/tmp/.ICE-unix/2152
unix  2      [ ACC ]     STREAM     LISTENING     1560     1/init              /run/systemd/fsck.progress
unix  2      [ ACC ]     STREAM     LISTENING     12151    2117/ibus-daemon    @/tmp/dbus-Jod4tJQ2
unix  2      [ ACC ]     STREAM     LISTENING     15131    1776/NetworkManager /var/run/NetworkManager/private-dhcp
unix  2      [ ACC ]     STREAM     LISTENING     11252    1930/X              @/tmp/.X11-unix/X0
unix  2      [ ACC ]     STREAM     LISTENING     290      1/init              /run/systemd/private
unix  2      [ ACC ]     STREAM     LISTENING     8998     1/init              /var/run/avahi-daemon/socket
unix  2      [ ACC ]     STREAM     LISTENING     9001     1/init              /var/run/dbus/system_bus_socket
unix  2      [ ACC ]     STREAM     LISTENING     9004     1/init              /var/run/cups/cups.sock
unix  2      [ ACC ]     STREAM     LISTENING     9007     1/init              /run/acpid.socket
unix  2      [ ACC ]     SEQPACKET  LISTENING     305      1/init              /run/udev/control
unix  2      [ ACC ]     STREAM     LISTENING     9009     1/init              /run/uuidd/request
unix  2      [ ACC ]     STREAM     LISTENING     307      1/init              /run/systemd/journal/stdout
unix  2      [ ACC ]     STREAM     LISTENING     11573    1776/NetworkManager /var/run/NetworkManager/private
unix  2      [ ACC ]     STREAM     LISTENING     13882    2076/gnome-keyring- /run/user/1000/keyring/control
unix  2      [ ACC ]     STREAM     LISTENING     9787     1766/cgmanager      /sys/fs/cgroup/cgmanager/sock
unix  2      [ ACC ]     STREAM     LISTENING     13894    2076/gnome-keyring- /run/user/1000/keyring/pkcs11
unix  2      [ ACC ]     STREAM     LISTENING     13898    2076/gnome-keyring- /run/user/1000/keyring/ssh
unix  2      [ ACC ]     STREAM     LISTENING     15244    2583/systemd        /run/user/0/systemd/private
unix  2      [ ACC ]     STREAM     LISTENING     11919    1947/systemd        /run/user/1000/systemd/private
unix  2      [ ACC ]     STREAM     LISTENING     11253    1930/X              /tmp/.X11-unix/X0
unix  2      [ ACC ]     STREAM     LISTENING     14087    2152/gnome-session  /tmp/.ICE-unix/2152
unix  2      [ ACC ]     STREAM     LISTENING     11966    1951/upstart        @/com/ubuntu/upstart-session/1000/1951
unix  2      [ ACC ]     STREAM     LISTENING     8896     1674/rpcbind        /run/rpcbind.sock

Is pulseaudio the normal Ubuntu version? netstat shows that pulseaudio isn't listening on any sockets, which is weird, because pulseaudio startup should fail if loading module-native-protocol-unix fails. (But then again, it's already very weird that there are multiple instances running.)

Does /run/user/1000/pulse/pid exist? If it does, does the pid in that file correspond to any of the running pulseaudio processes? (Replace 1000 in the file path with the uid of the "test" user.)

After answering those questions, add this to /home/test/.config/pulse/client.conf:

extra-arguments = --log-target=newfile:/tmp/pulse.log --log-level=debug

Then reboot. /tmp should now contain a log file for each of the started instances. Please attach them here.

Created attachment 123313 [details]
/tmp/pulse.log

(In reply to Tanu Kaskinen from comment #7)
> Is pulseaudio the normal Ubuntu version? netstat shows that pulseaudio isn't
> listening on any sockets, which is weird, because pulseaudio startup should
> fail if loading module-native-protocol-unix fails. (But then again, it's
> already very weird that there are multiple instances running.)

The system is newly installed Ubuntu 15.10 without any change on pulseaudio, just the kernel be updated to a newer commit on drm-intel repo. The Ubuntu image is Intel internally shared revision.

> 
> Does /run/user/1000/pulse/pid exist? If it does, does the pid in that file
> correspond to any of the running pulseaudio processes? (Replace 1000 in the
> file path with the uid of the "test" user.)

With original kernel of Ubuntu, only 1 pulseaudio process is observed, and the pid matches /run/user/119/pulse/pid.
With new kernel, after boot up, multiple pulseaudio processes are observed, there's no folder besides 1000/ on /run/user/, and /run/user/1000/pulse/ is not existing. A few minutes later, /run/user/1000/pulse/pid appears and the value matches one of the pulseaudio processes. Still no other folders besides 1000/ on /run/user/.

> 
> After answering those questions, add this to
> /home/test/.config/pulse/client.conf:
> 
> extra-arguments = --log-target=newfile:/tmp/pulse.log --log-level=debug
> 
> Then reboot. /tmp should now contain a log file for each of the started
> instances. Please attach them here.

Please find logs attached. And please notice it looks there are 2 phases after boot up: 
(1) in a few minutes after boot up, the /tmp/pulse.log has only 4 lines:
  D: [pulseaudio] conf-parser.c: Parsing configuration file '/home/test/.config/pulse/client.conf'
  I: [pulseaudio] main.c: setrlimit(RLIMIT_NICE, (31, 31)) failed: Operation not permitted
  I: [pulseaudio] main.c: setrlimit(RLIMIT_RTPRIO, (9, 9)) failed: Operation not permitted
  D: [pulseaudio] core-rtclock.c: Timer slack is set to 50 us.
commands such as "alsamixer" and "aplay -l" does not respond;
(2) a few more minutes later, more contents appears on /tmp/pulse.log and commands such as "alsamixer" and "aplay -l" works normal. Yet multiple pulseaudio processes are existing at this time.

/home/test/.config/pulse/client.conf did not exists, and I created one.

[    1.119931] [drm:drm_edid_to_eld] ELD: no CEA Extension found

So something gets stuck between

D: [pulseaudio] core-rtclock.c: Timer slack is set to 50 us.

and

I: [pulseaudio] core-util.c: Failed to acquire high-priority scheduling: Input/output error

Either setpriority() or rtkit_make_high_priority() gets stuck. I suspect the latter. We communicate with rtkit via D-Bus, and I would guess that rtkit-daemon is not responding to our MakeThreadHighPriority() method calls. The calls time out eventually, which is why we don't get stuck permanently. The timeout for D-Bus method calls is 30 seconds if I recall correctly, but in case of failure, we retry several times, so the delay grows much bigger.

You need to debug rtkit to figure out why it doesn't respond.

Multiple pulseaudio instances can be explained by the fact that multiple applications try to use pulseaudio, and each of them autospawns a new instance. The spawned instances would otherwise be short-lived, but they get stuck in the same place as the first instance. Once the first instance gets past the hang, the extra instances should die eventually.

Created attachment 123342 [details]
add dmesg file on SKL

-- 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/323.