[reposting to the list since it went over the size limit] Ross Burton wrote:
What is xrdb/cpp *doing* in the 10% of the startup time? It doesn't perform any I/O as gnome-settings-daemon does that instead, and streams the contents of the files into xrdb's stdin.
Most of the work it's doing is reading the binary of the C compiler, which after all is over 4 MB in size:
$ ls -l /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 -rwxr-xr-x 1 root root 4417892 2005-08-07 19:57 /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1
To figure out what was happening, I patched the kernel to log every block read from the filesystem, taking heavy inspiration and code from ssp's ext3 patch for sysprof. If we aggregate this data into sequential reads, what it's doing is (the numbers, like 1062-1078, are the offset in the file in 4k blocks starting from 0):
(gnome-settings-/3980): /usr/local/gnome/share/control-center-2.0/xrdb/Xaw.ad 0-0 (gnome-settings-/3980): /usr/local/gnome/share/control-center-2.0/xrdb/General.ad 0-0 (gnome-settings-/3980): /usr/local/gnome/share/control-center-2.0/xrdb/Tk.ad 0-0 (gnome-settings-/3980): /usr/local/gnome/share/control-center-2.0/xrdb/Editres.ad 0-0 (gnome-settings-/3980): /usr/local/gnome/share/control-center-2.0/xrdb/Motif.ad 0-0 (gnome-settings-/3980): /usr/local/gnome/share/control-center-2.0/xrdb/Emacs.ad 0-0 (gnome-settings-/4018): /home/apps/X11R6.8-CVS/bin/xrdb 0-7 (xrdb/4018): /home/apps/X11R6.8-CVS/lib/libXmuu.so.1.0 0-3 (sh/4025): /usr/bin/cpp-4.0 0-7 (cpp/4025): /usr/bin/cpp-4.0 8-22 (cpp/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 0-7 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 1062-1078 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 890-921 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 54-85 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 674-705 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 808-839 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 926-957 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 1042-1061 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 222-253 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 706-727 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 351-382 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 870-889 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 616-647 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 1018-1041 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 584-615 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 958-973 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 86-101 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 922-925 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 976-1007 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 729-760 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 489-520 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 8-31 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 303-350 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 32-53 (cc1/4026): /usr/lib/gcc/i486-linux-gnu/4.0.2/cc1 846-869
For an exact list of the reads it performs and the time it takes, see the attached file, which logs single reads and the numbers are again block offsets. So, as Owen says, most of the time is spent just reading the cc1 binary into memory. I have no idea why it's reading around all over the place instead of performing one big sequential read of the whole file though. Cheers, Lorenzo
Attachment:
xrdb.iolog.gz
Description: GNU Zip compressed data