Bug 58758

For some reason, even though files are duplicate, apparently, under most distros, it does not necessarily trigger a delay. 

There are probably other conditions at play (maybe in the cases the former file is loaded first, and in other cases this is the latter).

For instance, using ArchLinux / Manjaro, as of today, triggers about 10 to 15 seconds delay at the startup of KDE, unless I remove the file /etc/xdg/autostart/pulseaudio.desktop. It doens't occur, here, with Mint 14 KDE / Kubuntu 12.10.

pulseaudio.desktop runs start-pulseaudio-x11 and pulseaudio-kde.desktop runs start-pulseaudio-kde.

start-pulseaudio-x11 starts pulseaudio if it's not already running and loads module-x11-publish, module-x11-cork-request and module-x11-xsmp.

start-pulseaudio-kde starts pulseaudio if it's not already running and loads module-device-manager.

start-pulseaudio-x11 shouldn't be omitted on KDE as requested on this bug, because then module-x11-publish, module-x11-cork-request and module-x11-xsmp wouldn't get loaded, even though they are as relevant on KDE as on any other desktop environment.

The real bug is the delay that start-pulseaudio-x11 apparently causes on some systems. I don't see any reason why that should happen, so I hope someone will investigate this (I'm not volunteering).

Unsure about start-pulseaudio-x11, but confirming that adding  "NotShowIn=KDE;" to the end of the pulseaudio.desktop fixed the delay in Archlinux + KDE 4.10 for me on multiple systems.

Could someone set "log-level = debug" and "log-time = yes" in /etc/pulse/daemon.conf, reproduce this error, and post the logs here please?

Created attachment 78833 [details]
Debug log as requested in comment above

The debug log above was generated on my Debian Sid system with the pulseaudio package version 2.0-6.1.

In case it is useful to you, below is the reportbug information on related packages:

Package: pulseaudio
Version: 2.0-6.1

-- System Information:
Debian Release: 7.0
  APT prefers unstable
  APT policy: (500, 'unstable'), (500, 'stable'), (1, 'experimental')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 3.2.0-4-amd64 (SMP w/2 CPU cores)
Locale: LANG=en_GB.UTF-8, LC_CTYPE=en_GB.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash

Versions of packages pulseaudio depends on:
ii  adduser                       3.113+nmu3
ii  consolekit                    0.4.5-3.1
ii  libasound2                    1.0.25-4
ii  libasound2-plugins            1.0.25-2
ii  libc6                         2.13-38
ii  libcap2                       1:2.22-1.2
ii  libdbus-1-3                   1.6.8-1
ii  libfftw3-3                    3.3.2-3.1
ii  libgcc1                       1:4.7.2-5
ii  libice6                       2:1.0.8-2
ii  libltdl7                      2.4.2-1.2
ii  liborc-0.4-0                  1:0.4.16-2
ii  libpulse0                     2.0-6.1
ii  libsamplerate0                0.1.8-5
ii  libsm6                        2:1.2.1-2
ii  libsndfile1                   1.0.25-5
ii  libspeexdsp1                  1.2~rc1-7
ii  libstdc++6                    4.7.2-5
ii  libsystemd-daemon0            44-11
ii  libsystemd-login0             44-11
ii  libtdb1                       1.2.10-2
ii  libudev0                      175-7.2
ii  libwebrtc-audio-processing-0  0.1-2
ii  libx11-6                      2:1.5.0-1
ii  libx11-xcb1                   2:1.5.0-1
ii  libxcb1                       1.8.1-2
ii  libxtst6                      2:1.2.1-1
ii  lsb-base                      4.1+Debian9
ii  udev                          175-7.2

Versions of packages pulseaudio recommends:
ii  gstreamer0.10-pulseaudio  0.10.31-3+nmu1
ii  pulseaudio-module-x11     2.0-6.1
ii  rtkit                     0.10-2

Versions of packages pulseaudio suggests:
pn  paman             <none>
pn  paprefs           <none>
pn  pavucontrol       <none>
pn  pavumeter         <none>
ii  pulseaudio-utils  2.0-6.1

-- no debconf information

module-x11-xsmp seems to take a lot of time to connect to the session manager. The root cause might be a bug in the KDE session manager, but we should be able to improve things in PulseAudio too. It would be better not to block in pa__init() of module-x11-xsmp. I'm not sure if this is possible, though, if the API of libSM is designed to be synchronous...

Perhaps we could comment out module-x11-xsmp from start-pulseaudio-x11, and even deprecate the whole module? The purpose of the module is to keep pulseaudio alive for the duration of an X11 session, but don't module-systemd-login and module-console-kit do that well enough anyway? Is module-x11-xsmp perhaps needed in Solaris or something like that?

Matthew, could you verify that commenting out module-x11-xsmp from start-pulseaudio-x11 fixes the issue for you?

Created attachment 78930 [details]
Debug log for updated start-pulseaudio-x11

Tanu, I updated /usr/bin/start-pulseaudio-x11 as follows, please can you confirm this is what you meant :-)

$ diff -su /usr/bin/start-pulseaudio-x11.orig /usr/bin/start-pulseaudio-x11
--- /usr/bin/start-pulseaudio-x11.orig  2013-05-06 12:35:37.940319792 +0100
+++ /usr/bin/start-pulseaudio-x11       2013-05-06 12:36:58.360891563 +0100
@@ -27,6 +27,7 @@
     /usr/bin/pactl load-module module-x11-cork-request "display=$DISPLAY" > /dev/null
 
     if [ x"$SESSION_MANAGER" != x ] ; then
-       /usr/bin/pactl load-module module-x11-xsmp "display=$DISPLAY session_manager=$SESSION_MANAGER" > /dev/null
+#      /usr/bin/pactl load-module module-x11-xsmp "display=$DISPLAY session_manager=$SESSION_MANAGER" > /dev/null
+       /usr/bin/pactl "display=$DISPLAY session_manager=$SESSION_MANAGER" > /dev/null
     fi
 fi

The delay is still present with this modified version of start-pulseaudio-x11.

I meant that just comment out the line that mentions module-x11-xsmp. The line that you added doesn't do anything useful (but the change that you did was enough to prove that module-x11-xsmp is not the one to blame, so don't worry).

Do you edit these logs before you send them? According to the logs, your machine-id is ${my_machine-id} and only four modules are loaded during startup: module-device-restore, module-stream-restore, module-card-restore and module-augment-properties. There's no sign of any ALSA modules getting loaded, despite there being log messages from an ALSA sink. Also, it looks like the log level is "info", not "debug" as instructed.

In the new log the delay happens at some point after module-x11-cork-request has been loaded and before kmix creating a probe connection. Please enable full debug logging.

You could also try adding module-x11-xsmp back to start-pulseaudio-x11 and commenting out module-x11-cork-request and/or module-x11-publish instead. The idea would be to find out if one of the modules loaded by start-pulseaudio-x11 causes the delay.

(In reply to comment #9)
> Do you edit these logs before you send them? According to the logs, your
> machine-id is ${my_machine-id} and only four modules are loaded during
> startup: module-device-restore, module-stream-restore, module-card-restore
> and module-augment-properties. There's no sign of any ALSA modules getting
> loaded, despite there being log messages from an ALSA sink. Also, it looks
> like the log level is "info", not "debug" as instructed.

Yes, I wasn't sure if machine-id value is sensitive from a security POV, so I have edited it out - if it isn't then I won't bother in future :-)

I logged in and out a few times to check if there was still the delay and so the messages repeated a few times - I tried to cut it down to what looked like only one login event but I might have pruned a bit too much!

The log level is definitely 'debug'.  I'm getting the log by grepping /var/log/messages for pulseaudio.  

Looking at the log file now there are lines like:
May  6 16:42:04 debian pulseaudio[7281]: (6648.654|   0.000) [alsa-sink] alsa-sink.c: Device suspended...

So I must have messed up the debug log; I'll give it another go.

> You could also try adding module-x11-xsmp back to start-pulseaudio-x11 and
> commenting out module-x11-cork-request and/or module-x11-publish instead.
> The idea would be to find out if one of the modules loaded by
> start-pulseaudio-x11 causes the delay.

Ok, will do.  Thanks for the feedback.

(In reply to comment #9)
> Do you edit these logs before you send them? According to the logs, your
> machine-id is ${my_machine-id} and only four modules are loaded during
> startup: module-device-restore, module-stream-restore, module-card-restore
> and module-augment-properties. There's no sign of any ALSA modules getting
> loaded, despite there being log messages from an ALSA sink. Also, it looks
> like the log level is "info", not "debug" as instructed.

As a side note, it might be worth checking that syslog does not apply rate limiting of log messages, which I have found to be a problem sometimes (and also, that --log-target=file:/tmp/pulse.log can be a good workaround).

(In reply to comment #11)
> As a side note, it might be worth checking that syslog does not apply rate
> limiting of log messages, which I have found to be a problem sometimes (and
> also, that --log-target=file:/tmp/pulse.log can be a good workaround).

Yep that was a problem - after Tanu commented that it looked like bits were missing I looked through /var/log/messages and found lines about rate limiting that my grep command had hidden.

I didn't get time to reconfigure rsyslogd yesterday, but will try to get the debug output tonight.

(In reply to comment #10)
> Yes, I wasn't sure if machine-id value is sensitive from a security POV, so
> I have edited it out - if it isn't then I won't bother in future :-)

It's not security sensitive to my knowledge. It's just a random number identifying your machine, and any user on your machine is able to read it.

> I logged in and out a few times to check if there was still the delay and so
> the messages repeated a few times - I tried to cut it down to what looked
> like only one login event but I might have pruned a bit too much!
> 
> The log level is definitely 'debug'.  I'm getting the log by grepping
> /var/log/messages for pulseaudio.  

The effective level is definitely 'info', so this sounds like a bug. I haven't heard such problems before, though, and I'm not able to reproduce it (setting "log-level = info" in daemon.conf) with the current code.

You can override the verbosity, if you edit the command line for starting pulseaudio in start-pulseaudio-x11 and start-pulseaudio-kde: adding "-vvvv" to the command line should provide sufficient verbosity.

Created attachment 79002 [details]
Debug log for 'normal' case

Updated log for the existing setup.

Created attachment 79003 [details]
Debug log for variations on the normal case

Log containing variations of the normal case by commenting out each line out in turn:
1. noxmsp
2. nopublish
3. nocork

(In reply to comment #15)
> Created attachment 79003 [details]
> Debug log for variations on the normal case
> 
> Log containing variations of the normal case by commenting out each line out
> in turn:
> 1. noxmsp
> 2. nopublish
> 3. nocork

Hmm, now there seems to be no delay in the noxsmp case, while all other cases have the delay during (or possibly before) loading module-x11-xsmp. This would indicate that the delay does happen in module-x11-xsmp, but then there's attachment 78930 [details] that shows a delay elsewhere...

The log level was still 'info'. Did you add "-vvvv" to the pulseaudio command lines in start-pulseaudio-x11 and start-pulseaudio-kde?

Created attachment 79033 [details]
Debug log for normal setup and all variations

> The log level was still 'info'. Did you add "-vvvv" to the pulseaudio
> command lines in start-pulseaudio-x11 and start-pulseaudio-kde?

The previous logs were using -vvvvv (5x v), attached is a log using -vvvv (4x v); the log doesn't look any more or less verbose than the previous one though.

Here's the relevant lines of the config files:

matt@debian:~$ grep log /etc/pulse/daemon.conf
; log-target = auto
; log-level = notice
; log-meta = no
; log-time = no
; log-backtrace = 0
log-level = debug
log-time = yes
matt@debian:~$ grep pulseaudio /usr/bin/start-pulseaudio-kde
/usr/bin/pulseaudio --start -vvvv "$@"
matt@debian:~$ grep pulseaudio /usr/bin/start-pulseaudio-x11
/usr/bin/pulseaudio --start -vvvv "$@"

(The noxmsp, nocork & nopublish variants are based on the generic start-pulseaudio-x11)

(In reply to comment #17)
> Created attachment 79033 [details]
> Debug log for normal setup and all variations
> 
> > The log level was still 'info'. Did you add "-vvvv" to the pulseaudio
> > command lines in start-pulseaudio-x11 and start-pulseaudio-kde?
> 
> The previous logs were using -vvvvv (5x v), attached is a log using -vvvv
> (4x v); the log doesn't look any more or less verbose than the previous one
> though.

Hmm, syslog might filter out messages with too low priority (LOG_DEBUG).

> Here's the relevant lines of the config files:
> 
> matt@debian:~$ grep log /etc/pulse/daemon.conf
> ; log-target = auto
> ; log-level = notice
> ; log-meta = no
> ; log-time = no
> ; log-backtrace = 0
> log-level = debug
> log-time = yes
> matt@debian:~$ grep pulseaudio /usr/bin/start-pulseaudio-kde
> /usr/bin/pulseaudio --start -vvvv "$@"
> matt@debian:~$ grep pulseaudio /usr/bin/start-pulseaudio-x11
> /usr/bin/pulseaudio --start -vvvv "$@"

Looks good.

> (The noxmsp, nocork & nopublish variants are based on the generic
> start-pulseaudio-x11)

Now the noxsmp case has the delay again.

What if you comment out all of those modules from start-pulseaudio-x11? What if you remove start-pulseaudio-x11 altogether or put NowtShowIn=KDE to pulseaudio.desktop as originally suggested?

I'm suspecting that the delay might happen even without start-pulseaudio-x11. When module-x11-xsmp is loaded, the delay consistently happens during the execution of start-pulseaudio-x11, but in the noxsmp case the delay seems to happen after start-pulseaudio-x11 has finished its job.

Hmm, actually the "delay" that I'm seeing in the noxsmp case could be explained just by there being no client activity. There aren't any ongoing processes inside pulseaudio that should be generating log messages during the quiet period. Thus, if the KDE startup is still being delayed in the noxsmp case, it doesn't look like a pulseaudio problem (although it's not completely impossible either).

Anyone know of an easy way to reproduce this from scratch? Like say get <iso> of <distro>, install, and "omg delayed startup!".

At this point, one of us being able to reproduce this in a VM might speed up resolution of this.

(In reply to comment #19)
> Anyone know of an easy way to reproduce this from scratch? Like say get
> <iso> of <distro>, install, and "omg delayed startup!".
> 
> At this point, one of us being able to reproduce this in a VM might speed up
> resolution of this.

Issue exists by default on ArchLinux, get the x86-64 iso but arch doesn't come with KDE preinstalled.

Okay, so I've pinned this down now. The problem is in module-zeroconf-publish. It calls avahi_client_new(), which tries to ping the Avahi server via D-Bus and then blocks until it gets a reply. This reply might only come after a D-Bus timeout which IIRC is 20s.

The root cause is that Avahi basically only makes blocking D-Bus calls. I'm trying to see if we can move over all these sorts of calls in module-zeroconf-publish to a separate thread.

It's of course good to fix problems in module-zeroconf-publish too, but that module doesn't seem to be related to the original problem. start-pulseaudio-x11 doesn't have anything to do with module-zeroconf-publish, and module-zeroconf-publish doesn't seem to be loaded at all in the logs that have been attached.

I've got a VM running Arch Linux with kdebase, kmultimedia-kmix and pulseaudio, and I go from hitting enter on the kdm login screen to start of the login sound is ~9-10s seconds. Doesn't seem to match the reported lag.

Tanu pointed out that the logs posted didn't mention module-zeroconf-publish. Was this edited out of the logs by any chance?

An easy way for people seeing this problem to verify the fix is to add User=root to /usr/share/dbus-1/system-services/org.freedesktop.Avahi.service

Ping? This is the last blocker for 4.0. I'd really like to close this before the release, but I'd rather not hold it up much longer.

I'm not using Arch at the moment (Kubuntu) but I can re-install it to check your fix. I'll report back in a day or two, I hope it will be OK for you.

(In reply to comment #25)
> I'm not using Arch at the moment (Kubuntu) but I can re-install it to check
> your fix. I'll report back in a day or two, I hope it will be OK for you.

That would be great.

Hmm, I'm sorry but I couldn't reproduce the issue on my setup (under a fresh Manjaro Linux which is Arch based ; I used to have this problem under both distros -- I installed this one because this is MUCH faster to install ;-).

It might be some kind of concurrency issue that occured before when I had a SSD drive, which is not the case anymore. Really sorry.

Does anyone still encounter the problem nowadays ?

Well, it's good to know that it's working out of the box. Thanks for testing this! Let's see if anyone else is still facing the problem and whether the avahi fixes help them.

I am running Arch and getting the slow startup time. Setting User=root in "/usr/share/dbus-1/system-services/org.freedesktop.Avahi.service" did NOT fix the problem for me, unfortunately.

Upgrade to PulseAudio just pushed to Arch repo this week (version 4.0-6) completely fixed the problem for me. So maybe it was downstream and this can be marked resolved now.

Arch's current package is a git snapshot, so that sounds about right.