Postcards from the Fridge

Monday, May 29, 2006

X startup & other goodies

I've been automating the generation of the boot charts for gnome-session. (More on that later)

I've begun to notice a few things.

1) X takes a long time (3-4 seconds) to startup even with a warm cache.

In all of my warm-cache charts, gnome-session didn't execute until a few seconds after X started.

I was wondering if this was something to do with the gnome-session (ie, it has a lot of libraries that need to be loaded, etc.), so I decided to start X with the simplest of all xapps "xdpyinfo".

Even with this simple application, the whole startup/teardown takes 3-4 seconds.

It is easy to reproduce this:
A) Drop to the console mode (init 3)
B) Create a script called "startup-xdpyinfo.sh"

"xinit /usr/bin/xdpyinfo -- /usr/bin/X :0"
C) time "startup-xdpyinfo.sh"

(NOTE: I would be really interested to hear what other's times are. I am using the Xorg 7.0 release from FC5, and "ATI Radeon XPRESS 200M 5955", and my times are 3-4 seconds for the entire startup/shutdown. )

When running bootchart, I get the following (all of my runs look very similar to this) :



Here's the script I used to generate the graphs:

#!/bin/bash
TIME=`date +%m%d%H%M.%S`
script -c "time /sbin/bootchartd start /home/gnome/no_xinit/startup-xdpyinfo.sh" ./xdpy-$TIME.log
bootchart bootchart.tgz
#rm bootchart.tgz
mv ./bootchart.svgz ./xdpy-$TIME.svgz

NOTE: If I run X with the "-probeonly" option, the times are only 2
seconds, so it is appears as if X is probing for 2 seconds.

Here's a graph of that:



2) Components don't startup in the same sequences during the login.

The startup sequence is not always constant. There may be some inefficiencies because of this.

If Process A depends on Process B, but they start in parallel, Process A could be waiting, but Process B can't run because Process A is on the CPU.

However, you also don't want to add dependencies that don't exist.

I have to look into this more. Here's my first pass at determining the startup order:

A) gnome-session -> gconfd-2 -> gnome-keyring-daemon -> bonobo-activation-run-query->

B) gnome-settings- -or- metacity (Start in Parallel?)

C) (Always after Metacity) gnome-panel -> Nautilus

D) The rest:

gnome-volume-manager -> gnome-vfs-daemon-> wnck-applet -> gnome-settings -> notification-ar -> clock-applet -> mixer_applet2 -> mapping-deamon ->

3) xrdb is almost always in a "zombie" state.

All of the graphs that I've looked at show the 'xrb' command started by gnome-settings becomes a Zombie. This might be related to an error message that I receive about "gnome-settings-daemon" failing during startup.

NOTE: I was able to initiate a gnome-session shutdown programmability (Thanks Vincent) using "gnome-session-save --kill".

Questions:
1) What is the most appropriate time to start a shutdown? (ie, how do we know that everything is up and initialized? ) Currently, the shutdown command is is one of the startup programs that gnome-session runs.

However, since the startup programs don't run in any particular order, it can begin the shutdown early or late in the startup cycle. This means that there is a large variation in the total startup/shutdown time. This is annoying when trying to profile, and improve startup time.

Friday, May 26, 2006

First steps and Gnome-startup visualization

Hi all,
My project was accepted for Google Summer of code 2006. Wahoo!

I'll be looking at optimizing the startup performance of Nautilus to both make it faster to start and easier to profile. I've been around the block a bit for profiling (Buy my book, wink, wink... ) , and I've been wanting to do some optimization for GNOME for a while. Now I have a good reason, sweet.

In any event, while I wait for jhbuild to complete on my dodgy internet connection, I have been playing with bootchart to see what the system is doing when gnome starts up.

A lot of work had been done to optimize the system startup time using bootchart, but it can also be used to track the startup of anything. (In this case, I track "startx")

Here's how to do it:
1) Download and build the rpm. (You'll need a bunch of java libraries)

2) Install the RPM.

3) reboot your machine, and start in init level 3. (pass "3" to the boot parameters or modify your inittab)

4) log in as root

(We'll now gather the "cold disk cache" statistics)
5) Tell bootchart to monitor startx and any processes that it generates: "bootchartd start startx"

6) Log out as soon as possible.

7) Run "bootchart". This will generate an SVG file named "./bootchart.svgz" which contains the graph of the startup time.

(Now we'll gather the "warm disk cache" statistics.)


8) Tell bootchart to monitor startx and any processes that it generates: "bootchartd start startx"

9) Log out as soon as possible.

10) Run "bootchart". This will generate an SVG file named "./bootchart.svgz" which contains the graph of the startup time.

Here is an example from FC4:

FC4 cold disk cache:















FC4 warm disk cache:

















Observations:
1) esd seems to start when we try to logout. That's pretty annoying, and I'm sure it is a bug.
2) In the warm cache case, xkbcomp does a lot of disk I/O.

Here's the same thing for FC5:
FC5 gnome startup (cold disk cache):


FC5-Gnome startup (warm disk cache):




Observations:

1) gconfd-2 chews up a chunck of CPU time
2) The esd bug still appears (look at the cold cache chart)

As I see more things, I'll post them.