Postcards from the Fridge

Monday, August 21, 2006

Thanks for All the Fish

Well, today SOC draws to a close, so I decided to write up how things currently stand. Thanks to all the Gnomers for letting me work on this!


The point of this project was to investigate why nautilus's startup performance was slow, and to find different ways to fix the problem.

Nautilus's startup is slow because it keeps blocking and allows other applications to run.

Sometimes it is lucky and completes its startup quickly. Other times it isn't, and gnome-panel (and all of the plugins) or other startup applications get in the way.

Problem definition
  1. minimize the amount of time between nautilus startup and mapping of the icons.
  2. Remove the variability in the gnome startup times.
I would argue that it is most important for the file manager to start up. In particular the problem that I was solving (which is one that I see every time I start up any modern based Linux, be it on Fedora, Ubuntu or SUSE). The X session starts, the panel shows up but it takes seconds for the icons to finally appear on the screen.


The general problem

When I started this project, I had very little idea about the overall architecture of gnome. When do various components start up? Which pieces were responsible for which parts of the system? There is documentation for some of the individual components (Nautilus's documentation is pretty good), but nothing that describes the overall startup of the gnome desktop. There are quite a few articles describing the exact startup sequences of Linux from the boot loader to the init scripts. It would be helpful if there was something similar for gnome, so it was at least clear how things were intended to work.

The problem of understanding and analyzing the complex startup of gnome is actually a more general problem. Gnome starts multiple threads, and multiple processes, each with interlocking dependencies. A few general tools have been developed for Linux which help to understand these startup sequences. No single tool seems to have all of the features needed to truly understand what is happening, so I tried a bunch of different tools.

1) Bootchart (

The first tool that I used to determine how exactly things were starting up was the "bootchart" tool. This tool was originally designed to track the startup of programs in the Linux boot process. Fortunately it is also flexible enough to monitor and track any other set of processes that are started at a later date. It gives a nice graphical chart of when various processes started, and how much each used the cpu during the specified time period.

The initial bootchart images were the first indication that something was unusual about nautilus startup. Different charts of the same gnome startup sequence provided a radically different view when things started up, and how longs things took to start. Sometimes the panel would begin first, and sometimes the gnome-settings-daemon would. This was my first clue that some sort of race was happening. If there wasn't a race, each startup should have an identical series of steps, with little to no variability.

2) strace + 'access' hacks and Federico's visualization tool.

Next I started to use the analysis tools and techniques that others had used before me. In particular, I used strace to generate, and Federico's tool to analyze the result. This provided the most complete data. I've detailed in an earlier blog entry how to get it all started up.

Once thing I haven't mentioned yet, is that I wrote a small python script to sort through the strace results. This will replace "pids" with the actual name of the processes. This makes reading the strace results much easier. (It will trace clones, forks and execs, so you can see exactly what is running when...)

import fileinput
import string



for line in fileinput.input():
__pid = line.split()[0]

__if pid_to_name.has_key(pid):
____start =line.find(" ")
____print pid_to_name[pid] + " " +line[start:-1]
__ else:
____print line[:-1]

__if "execve(" in line:
____param = line.split()[2]
____pid_to_name[pid] = param.split("\"")[1]

__if "clone(" in line:
____new_name = pid_to_name[pid] + (".%d"%thread)
____thread = thread + 1
____new_pid = line.split("=")[-1].strip()
____pid_to_name[new_pid] = new_name

__ if "<... clone resumed>" in line:
____new_name = pid_to_name[pid] + (".%d"%thread)
____thread = thread + 1
____new_pid = line.split("=")[-1].strip()
____pid_to_name[new_pid] = new_name

3) NPTL Trace Tool (

Next, I wanted to try to visualized how the different thread interacted with the hope that I would be able to see some clear patterns as to why nautilus was continually yielding the CPU.

The NPTL trace tool looked like promising avenue, because it had a graphical interface (using ntt_paje), and it was able to analyze a the complex interaction of threaded applications. It can provide a visualization, as well as statistics about the amount of locks held, and report on the various pthread calls that were made.

The trace tool produced the results into a format the Paje visualization tool could open and analyze. Paje itself is a little clunky and requires that the GNUstep environment is installed. I was able to capture a trace of a generic application, but unfortunately when I tried to run the trace tool an nautilus, it seg faulted.

4) frysk (

This was another tool that promised to make visualization and debugging of complicated threading applications/environments easy to do. It, unfortunately, is still immature. When I tried to monitor system calls that nautilus made, it also crashed. However, this project is one to watch. It provides a graphical interface analyze how, and allows you to add arbitrary rules to analyze how a process and set of threads were executing.

5) Ideal tool

The ideal tool would be one that shows both when applications are running, and why they vacate the CPU when they are finished. Strace is really a poor man's version of this tool. However, it doesn't have any way to indicate when the scheduler decided to swap the running process, so if an application spends all of its time in user space, the strace method will never detect that the running application has changed.

6) Dishonorable mention

Two tools that I tried to use, but were unsuccessful were AMD's code analyst and Intel's VTune.

AMD get props for releasing their Code Analyist as GPL. It provides a GUI interface to oprofile, and some other niceties. Unfortunately, the number of distributions that it supports is rather small, and it wouldn't build on my Fedora 5 box. Even worse (in my opinion) was Intel's vtune. They provided a binary which could be used on Linux for non-commercial profiling. However, once it detected that my processor was an AMD chip, it wouldn't let me use it.

Experiments: Summary

Since it may have been difficult to follow what happened over the course of the summer, I'm going to summarize my experiments, and show how I came to the conclusions that I did.


First, my goal was to work with "warm-booting" nautilus, after everything had been loaded into the disk cache. Second, I automated the startup and collection, so that I could run the same test repeatedly, and then analyze the results by either looking at visualizations, or running the tests through gnumeric.

My goals were to remove the variability in the nautilus startup, and minimize the overall nautilus startup time.

Test 1 Full startup

I added tracing information which started at the first line of "main" in nautilus, and stopped when the icons were painted on the screen. (in icon_container expose_event).


The startup times were highly variable, and other processes (such as those launched by gnome-panel) would run in between the startup of nautilus and the drawing of the icons.

Test 2 Full startup w/a high gnome-session priority

I edited the ".gnome/gnome-session" file, and set the priority of nautilus to 10, which was higher than that of gnome-panel.

No change. Nautilus was STILL interrupted by gnome-panel processes.

Test 3 Launch simply (no wm, no gnome-panel)

Next, I removed the "wm" and "gnome-panel" from the session file, and retimed nautilus's startup.


The nautilus startup times were still highly variable. Nautilus was being interrupted by the gnome-volume-manager, and the various daemons that were launched internally by gnome-session. (gnome-keyring)

One interesting part of this investigation was that sometimes "gnome_vfs_get_volume_monitor()" took and long time to start, and other times it was very quick. Federico had seen this, and he explained what was happening. Various gnome-daemons/services are launched on demand, and this call was causing this to take place.

Test 3 Launch simply (no wm, no gnome-panel) w/a gnome-vfs preloader
I wanted to see if nautilus startup times would because a little, if the gnome-vfs-daemon was prestarted before nautilus started to launch. I modified the disk mount applet to call the gnome-volume-manager, and
exit. Then, I modified the gnome-session-manager to call this "gnome-vfs" preloader, and wait for 2 seconds while it started. The 2 second delay is an unacceptable "real" solution, but it was enough to see prestarting the daemon would increase startup time.


The variability totally disappeared, and the startup times dropped to about 1/2 second.

Test 4 Launch complete session w/preloader.

I decided to go for broke. I had the preloader within gnome-session, so I decided to try with gnome-panel and the gnome-wm turned back on.


unfortunately, the variability was back. Upon closer investigation the applications were still interrupting nautilus between the time it was initially launched and the first icons were painted on the screen.

Nautilus was yielding the cpu, and other applications (gnome-panel) were running before the nautilus startup could complete.

Test 5 Launch complete session w/preloader & niced gnome-panel.
Now, I wanted to see what happened if I made the nautilus the highest priority process, and basically made sure that it was the highest priority. However, since I was not able to easily boost its priority (without becomes root), I decided to drop the priority of the processes competing for the CPU. I ran the gnome-panel with a nice of 19.


Nautilus's startup was very snappy, but the gnome-panel never seemed to be painted. The variability was there because other applications (gnome-keyring) could still occasionally interrupt the startup.

Next Steps

To really solve the startup problem, nautilus probably has to be rearchitected to stop blocking or it must somehow be made a higher priority than the other applications that startup.

Here are some ideas on how to fix things:
0) Incorporate gnome-vfs startup in gnome-session

This should probably be done even if it doesn't completely solve the nautilus startup problem. gnome-vfs is needed by the gnome desktop. Launching it "on-demand" only causes blocking and unnecessary
contention. (I haven't tried this yet. )

1) Rearchitecture Nautilus to remove all of the yielding.

This is a bigger change than I could do. Even minimizing the number of times that it yields would reduce the chance that it would be interrupted.

2) Remove the on-demand loading (or at least short circuit it, so it is never used in a properly running desktop. )

IMHO, the on-demand loading is a bad idea. Ideally all of the dependencies for an application would be running before it starts. It would reduce the amount of times that applications block, and could
possibly reduce thrashing as multiple applications wait for a component to start.

3) Modify nautilus to give gnome-session a thumbs up ONLY after the icons have painted.

Right now, gnome-session and the applications that it launch have a handshake that wait for an application to start. This response handshake would have to be modified to only respond after the icons have been painted.

I've been working on getting this to work, but I can't figured out where the handshake takes place.

4) Boost nautilus's priority

If we can boost nautilus's priority, it may (possibly) not be interrupted. I couldn't figure out how to do this without root privileges.


In any event, this has been a lot of fun. I learned more about nautilus & gnome that I thought possible.

Thanks to all!

Tuesday, August 01, 2006

Ah ha!

A whole bunch has happened since I blogged last....

For the most part, I figured out why nautilus startup time is so slow AND so variable.

Nautilus is basically yields the CPU again and again as it starts up. Even if nautilus is one of the first components launched, other components (ie, the panel, applets and more) will interrupt it, and prevent it from drawing the first icon on the screen. Sometimes nautilus has the CPU for most of the time, and the startup times are very good. However sometimes it will yield the CPU, and it will be seconds before it starts running again.

First Blind Alley

As you can see is some of my last posts, I knew that nautilus was yielding the CPU. However, I thought it was doing this because it was waiting for threads/components that weren't yet running. (In particular the gnome-vfs-daemon).

I initially thought that nautilus also relied on gnome-volume-manager since gnome-volume-manager's execution was often interleaved with nautilus's startup. However, I found one run where this didn't happen, and nautilus started up just fine.. Therefore it can't be a dependency. (I also discovered gnome-volume-manager was being launched by one of the gnome startup scripts)

I modified the trash applet to preload the vfs-daemon before nautilus started up. I modified gnome-session to call this hacked applet, wait 2 seconds, and then finally start nautilus. This guaranteed that gnome-vfs-daemon was started before nautilus started. This worked, sort-of, as nautilus start-up times were much more reproducible (as long as the panel wasn't running). It is an imperfect solution, because that sleep is really unacceptable, but it could tell me if dependencies were the problem.

The interesting thing to note is that nautilus blocked several times from when executing main to the icon-painting. Nautilus did some handshaking with various threads, and this caused things to block.

With this fix in place, I went for broke and turned on the panel. The reproducible startup times that I had, were then completely shot to hell. All of the blocking of the main nautilus process provided opportunities for the panel & applet to run. Once they started, nautilus might not execute again for a couple of seconds.

So, on a whim, I decide to run the gnome-panel with a nice value of 19. This worked pretty well. Most of the nautilus startup times were on the order of 0.5 seconds. However, every so often, the times would jump. This was because other non-panel processes (such as gnome-volume-manager) started running when nautilus blocked.

What is Next?

I'm currently trying to figure out if I can reduce he amount of blocking that nautilus is doing.
First, I have to figure out exactly what it is waiting on.