(Skipped 16000 lines of initializations and other calls...)
19:59:20.265679 open("/usr/share/icons/Adwaita/16x16/actions/document-save-as.png", O_RDONLY) = 59
19:59:20.265698 fstat(59, {st_mode=S_IFREG|0644, st_size=689, ...}) = 0
19:59:20.265716 read(59, "\211PNG\r\n\32\n\0\0\0\rIHDR\0\0\0\20\0\0\0\20\10\3\0\0\0(-\17"..., 65536) = 689
19:59:20.265731 read(59, "", 65536) = 0
(More icons loading...)
19:59:20.284973 open("/lib64/libcanberra.so.0", O_RDONLY|O_CLOEXEC) = 59
19:59:20.284989 read(59, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\3203\0\0\0\0\0\0"..., 832) = 832
(...)
19:59:20.285112 open("/lib64/libvorbisfile.so.3", O_RDONLY|O_CLOEXEC) = 59
19:59:20.285127 read(59, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20!\0\0\0\0\0\0"..., 832) = 832
(More audio libraries loading...)
19:59:20.286375 open("/usr/lib64/libcanberra-0.30/libcanberra-pulse.so", O_RDONLY|O_CLOEXEC) = 59
19:59:20.286389 read(59, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\220!\0\0\0\0\0\0"..., 832) = 832
(More PulseAudio, X11, systemd libraries loading...)
(PulseAudio libraries reading configuration files below...)
19:59:20.291283 open("/etc/pulse/client.conf", O_RDONLY|O_CLOEXEC) = 66
19:59:20.291298 fcntl(66, F_GETFD) = 0x1 (flags FD_CLOEXEC)
19:59:20.291311 readlink("/proc/self/exe", "/usr/lib64/firefox/firefox", 99) = 26
19:59:20.291344 fstat(66, {st_mode=S_IFREG|0644, st_size=1201, ...}) = 0
19:59:20.291358 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5553ee7000
19:59:20.291372 read(66, "# This file is part of PulseAudi"..., 4096) = 1201
(Opening a socket to the X server and requesting some PulseAudio properties below...)
19:59:20.291430 socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC, 0) = 66
19:59:20.291459 connect(66, {sa_family=AF_LOCAL, sun_path=@"/tmp/.X11-unix/X0"}, 20) = 0
19:59:20.291560 getpeername(66, {sa_family=AF_LOCAL, sun_path=@"/tmp/.X11-unix/X0"}, [20]) = 0
19:59:20.291575 uname({sysname="Linux", nodename="localhost.localdomain", ...}) = 0
19:59:20.291589 access("/home/rg3/.Xauthority", R_OK) = 0
19:59:20.291605 open("/home/rg3/.Xauthority", O_RDONLY) = 67
19:59:20.291619 fstat(67, {st_mode=S_IFREG|0600, st_size=118, ...}) = 0
19:59:20.291640 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5553ee7000
19:59:20.291653 read(67, "\1\0\0\7deckard\0\0010\0\22MIT-MAGIC-COOKIE"..., 4096) = 118
19:59:20.291670 close(67) = 0
19:59:20.291681 munmap(0x7f5553ee7000, 4096) = 0
19:59:20.291694 getsockname(66, {sa_family=AF_LOCAL, NULL}, [2]) = 0
19:59:20.291716 fcntl(66, F_GETFL) = 0x2 (flags O_RDWR)
19:59:20.291727 fcntl(66, F_SETFL, O_RDWR|O_NONBLOCK) = 0
19:59:20.291739 fcntl(66, F_SETFD, FD_CLOEXEC) = 0
19:59:20.291751 poll([{fd=66, events=POLLIN|POLLOUT}], 1, 4294967295) = 1 ([{fd=66, revents=POLLOUT}])
19:59:20.291765 writev(66, [{"l\0\v\0\0\0\22\0\20\0\0\0", 12}, {"", 0}, {"MIT-MAGIC-COOKIE-1", 18}, {"\0\0", 2}, {";xm<Q\300\16m\3\234\221\317\355O\222\v", 16}, {"", 0}], 6) = 48
19:59:20.291796 recvfrom(66, 0x7f55271c85f0, 8, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
19:59:20.291809 poll([{fd=66, events=POLLIN}], 1, 4294967295) = 1 ([{fd=66, revents=POLLIN}])
19:59:20.291828 recvfrom(66, "\1\0\v\0\0\0\212\5", 8, 0, NULL, NULL) = 8
19:59:20.291852 recvfrom(66, "\300\226\262\0\0\0\240\1\377\377\37\0\0\1\0\0\16\0\377\377\1\7\0\0 \10\377\0\0\0\0"..., 5672, 0, NULL, NULL) = 5672
19:59:20.291872 poll([{fd=66, events=POLLIN|POLLOUT}], 1, 4294967295) = 1 ([{fd=66, revents=POLLOUT}])
19:59:20.291885 writev(66, [{"\20\0\5\0\f\0\0\0PULSE_SERVER", 20}], 1) = 20
19:59:20.291909 poll([{fd=66, events=POLLIN}], 1, 4294967295) = 1 ([{fd=66, revents=POLLIN}])
19:59:20.291934 recvmsg(66, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\1\0\0\0\0\0\241\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 4096}], msg_controllen=0, msg_flags=0}, 0) = 32
19:59:20.291961 poll([{fd=66, events=POLLIN|POLLOUT}], 1, 4294967295) = 1 ([{fd=66, revents=POLLOUT}])
19:59:20.291983 writev(66, [{"\24\0\6\0\230\2\0\0\241\1\0\0\37\0\0\0\0\0\0\0\377\3\0\0", 24}], 1) = 24
19:59:20.292005 poll([{fd=66, events=POLLIN}], 1, 4294967295) = 1 ([{fd=66, revents=POLLIN}])
19:59:20.292030 recvmsg(66, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 4096}], msg_controllen=0, msg_flags=0}, 0) = 32
19:59:20.292053 poll([{fd=66, events=POLLIN|POLLOUT}], 1, 4294967295) = 1 ([{fd=66, revents=POLLOUT}])
19:59:20.292065 writev(66, [{"\20\0\5\0\n\0\0\0PULSE_SINK\0\0", 20}], 1) = 20
(Finally Firefox connecting to the PulseAudio socket...)
19:59:20.293778 socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC, 0) = 66
19:59:20.293799 fcntl(66, F_GETFD) = 0x1 (flags FD_CLOEXEC)
19:59:20.293812 setsockopt(66, SOL_SOCKET, SO_PRIORITY, [6], 4) = 0
19:59:20.293826 fcntl(66, F_GETFL) = 0x2 (flags O_RDWR)
19:59:20.293838 fcntl(66, F_SETFL, O_RDWR|O_NONBLOCK) = 0
19:59:20.293850 connect(66, {sa_family=AF_LOCAL, sun_path="/run/user/1000/pulse/native"}, 110) = 0
Firefox right-click menu delay
Some days ago I started experiencing a small two or three seconds delay before the right-click menu showed up in Firefox the first time I right-clicked on something. It turned out to be related to PulseAudio and here’s the technical explanation.
Enabling PulseAudio
I had enabled PulseAudio a few days before I started experiencing the problem, but it took me some time to notice it happened consistently and frequently. By that time, a Firefox upgrade had rolled in and blurred the connection until I debugged the problem.
Before enabling PulseAudio, I was using plain ALSA with the dmix plugin, with excellent results. However, despite a very rough start in the first months or years, PulseAudio nowadays presents several significant technical advantages and works very well, and I wanted to try it out. Essentially, what PulseAudio achieves is a disconnection between the application playing sounds and a specific audio device. Applications talk to the PulseAudio daemon. The daemon, in the background, manages audio devices and routes audio to them dynamically. This means you can be playing music or a movie and if you suddenly connect a Bluetooth headset to the system, or a monitor through an HDMI cable, audio can start playing through that new device without restarting the application at all. The daemon can be controlled with a variety of command line and GUI tools.
Applications can talk to PulseAudio directly if they know how to use the PulseAudio library. If they only “speak” ALSA or OSS, there’s no problem. PulseAudio ships an ALSA plugin that lets you configure the PulseAudio daemon as a default virtual ALSA device (in that case, the route is alsa-libraries to PulseAudio to ALSA kernel driver to the device). It also ships a command line program launcher that wraps OSS audio devices transparently to the launched programs, so any specific OSS application can be re-routed through PulseAudio too.
PulseAudio, as shipped in Fedora, is set up through socket activation. This means PulseAudio is not running normally until someone tries to connect to it for the first time. At that moment, systemd launches PulseAudio and passes the new connection to it. There may be a small two or three seconds pause before the daemon is launched for the first time when an application starts using PulseAudio (do you start to see a connection with my problem there?).
Most users do not experience this pause normally. Full-fledged desktop environments like KDE or Gnome have notification and sound systems that start up with the desktop environment and probably request access to the sound devices or sound daemon early. When a KDE or Gnome desktop is fully loaded, PulseAudio is usually already running.
How this relates to the Firefox right-click menu
Users of more lightweight window managers like Fluxbox or i3 (the latter in my case) may end up in a fully loaded session with everything running and find out nobody has requested access to PulseAudio yet. The first application that tries to access an audio device, directly or indirectly, will have to wait just a few seconds before PulseAudio starts.
It turns out one of the first programs I usually launch in my session is Firefox and, at least in my setup and as it’s shipped in Fedora, Firefox triggers PulseAudio when right-clicking on the text of a webpage. At that moment PulseAudio is launched and the context menu takes two or three seconds to show up. It’s not a long time at all, but it’s very weird and noticeable.
I ran Firefox through strace to see what it’s doing. I didn’t interact with it for several seconds and then, at around 19:59:20, I right-clicked on a piece of text in my default location webpage. This is a selection of those lines.
As you can see, for some reason at that moment, apart from loading up some icons that may be needed for the context menu, Firefox also requests access to the sound system for the first time, loading some sound libraries in the process, and starts exchanging data with the PulseAudio daemon.
Firefox seems to be using a library called libcanberra for system sounds which in turn triggers PulseAudio usage. It tries to ask the X server about PulseAudio first (PulseAudio registers itself with some properties in the X server when launched in a certain way). Finally, it connects to the PulseAudio server socket.
The solution for this delay “problem” is very simple. Just launch PulseAudio with start-pulseaudio-x11 when loading the window manager. In i3, it’s as simple as adding the following line to ~/.i3/config.
exec --no-startup-id start-pulseaudio-x11
I’m sure other lightweight window managers have a similar mechanism. This will make i3 launch PulseAudio when starting up if not already running. The i3 session will not take longer to load. PulseAudio will be started in the background together with other processes and will be instantly available the first time a program requests access to it.
Load comments