Nautilus Performance Analysis

[Alan Cox <alan lxorguk ukuu org uk>]

(Im not on the list so cc me any comments)

Why does Nautilus completely suck on my box ?
---------------------------------------------

30 seconds to start up and open a directory containing 1700 files made me
curious. However this isnt a flame. This is the result of staring a
megabytes of strace, some tcpdumps and a kernel profile. Hopefully it will
help fix it

Environment
-----------

AMD Athlon 550, 256Mb XFCE, Nautilus, no other activity but irc clients and the
like. NFS home directory off a K6/2 over 100Mbit half duplex ethernet. NIS
based passords, lan fairly quiet.

Nautilus 1.0.4 with all its own icons and files local on IDE disk
Glibc 2.2.3


Big things
----------

My initial assumption was that nautilus did extremely daft things over NFS
and this was the killer issue. For the directory scanning it does some daft
things but they are not the big ones. The big breakages appear to be
cache handling bugs, or complete lack of caching

Looking at the profile for the main thread I see

-	Repeated reloads of /usr/share/eel/fonts/urw/n019003l.pfb 

-	Repeated long stat walks in search of image files, without caching
	the found path when it completes. The icon for a given file isnt
	going to walk, remember the locatiom

-	During the scan it keeps stating my home directory, .Trash and then
	doing a getuid() and a password/NIS lookup. The fact it isnt 
	doing a name/uid cache is killing it over networks. In fact this
	not the NFS handling appears to be a major culprit. Cache uid/name
	entries. NIS or LDAP really work better if you do.

-	Early on the file names are read over a pipe/socket from another
	thread. They are sent one at a time and this causes a mass of task	
	switches, enough I can see it on x86, while on other platforms it
	will hurt far more. Shove things down sockets in big chunks, it
	really pays off

-	Repeated reparsing of i-regular.xml, several times a second
	

Just reading the strace log is painful because you can see repeat after
repeat after repeat. Sections like

14:20:05 lstat64("/usr/share/eel/fonts/urw/n019003l.pfb",
{st_mode=S_IFREG|0644, st_size=36026, ...}) = 0
14:20:05 open("/usr/share/eel/fonts/urw/n019003l.pfb", O_RDONLY) = 24
14:20:05 fstat64(24, {st_mode=S_IFREG|0644, st_size=36026, ...}) = 0
14:20:05 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x40025000
14:20:05 read(24, "\200\1]\6\0\0%!PS-AdobeFont-1.0: Nimbus"..., 4096) = 4096
14:20:05 close(24)                      = 0
14:20:05 munmap(0x40025000, 4096)       = 0
14:20:05 lstat64("/home/anarchy", {st_mode=S_IFDIR|0755, st_size=35840,
...}) = 0
14:20:05 stat64("/home/anarchy", {st_mode=S_IFDIR|0755, st_size=35840, ...})
= 014:20:05 access("/home/anarchy/.Trash", F_OK) = -1 ENOENT (No such file
or directory)
14:20:05 geteuid32()                    = 502
14:20:05 lstat64("/home/anarchy", {st_mode=S_IFDIR|0755, st_size=35840,
...}) = 0
14:20:05 stat64("/home/anarchy", {st_mode=S_IFDIR|0755, st_size=35840, ...})
= 014:20:05 access("/home/anarchy/.Trash", F_OK) = -1 ENOENT (No such file
or directory)
14:20:05 geteuid32()                    = 502
14:20:05 lstat64("/home/anarchy", {st_mode=S_IFDIR|0755, st_size=35840,
...}) = 0
14:20:05 stat64("/home/anarchy", {st_mode=S_IFDIR|0755, st_size=35840, ...})
= 014:20:05 access("/home/anarchy/.Trash", F_OK) = -1 ENOENT (No such file
or directory)
14:20:05 geteuid32()                    = 502
14:20:05 lstat64("/home/anarchy", {st_mode=S_IFDIR|0755, st_size=35840,
...}) = 0
14:20:05 stat64("/home/anarchy", {st_mode=S_IFDIR|0755, st_size=35840, ...})
= 014:20:05 access("/home/anarchy/.Trash", F_OK) = -1 ENOENT (No such file
or directory)
14:20:05 geteuid32()                    = 502
14:20:05 open("/etc/passwd", O_RDONLY)  = 24
14:20:05 fcntl64(0x18, 0x1, 0, 0x1)     = 0
14:20:05 fcntl64(0x18, 0x2, 0x1, 0x2)   = 0
14:20:05 fstat64(24, {st_mode=S_IFREG|0644, st_size=1230, ...}) = 0
14:20:05 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x40025000
14:20:05 read(24, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1230
14:20:05 read(24, "", 4096)             = 0
14:20:05 close(24)                      = 0
14:20:05 munmap(0x40025000, 4096)       = 0
14:20:05 open("/var/yp/binding/lxorg.2", O_RDONLY) = 24
14:20:05 readv(24, [{"\377\377", 2}, {"\1\0\0\0\302\250\227\1\3\266\0\0",
12}], 2) = 14
14:20:05 socket(PF_INET, SOCK_DGRAM, IPPROTO_UDP) = 25
14:20:05 bind(25, {sin_family=AF_INET, sin_port=htons(618),
sin_addr=inet_addr("0.0.0.0")}}, 16) = -1 EACCES (Permission denied)
14:20:05 ioctl(25, 0x5421, [1])         = 0
14:20:05 setsockopt(25, SOL_IP, IP_RECVERR, [1], 4) = 0
14:20:05 fcntl64(0x19, 0x2, 0x1, 0x2)   = 0
14:20:05 close(24)                      = 0
[and the rest of a NIS lookup]

Repeat endlessly

8 secods later the pattern changes, and the new game is  statting a file
being told it isnt there and checking again several times

14:20:13 lstat64("/home/anarchy/readvcd-0.2/.directory", 0xbfffec40) = -1
ENOENT (No such file or directory)
14:20:13 lstat64("/home/anarchy/readvcd-0.2/.directory", 0xbfffec40) = -1
ENOENT (No such file or directory)
14:20:13 lstat64("/home/anarchy/readvcd-0.2/.directory", 0xbfffec40) = -1
ENOENT (No such file or directory)
14:20:13 lstat64("/home/anarchy/readvcd-0.2/.directory", 0xbfffec40) = -1
ENOENT (No such file or directory)
14:20:13 lstat64("/home/anarchy/scarab-1.3/.directory", 0xbfffec40) = -1
ENOENT (No such file or directory)
14:20:13 lstat64("/home/anarchy/scarab-1.3/.directory", 0xbfffec40) = -1
ENOENT (No such file or directory)
14:20:13 lstat64("/home/anarchy/scarab-1.3/.directory", 0xbfffec40) = -1
ENOENT (No such file or directory)
14:20:13 lstat64("/home/anarchy/RPMS/.directory", 0xbfffec40) = -1 ENOENT
(No such file or directory)
14:20:13 lstat64("/home/anarchy/scarab-1.3/.directory", 0xbfffec40) = -1
ENOENT (No such file or directory)
14:20:13 lstat64("/home/anarchy/scarab-1.3/.directory", 0xbfffec40) = -1
ENOENT (No such file or directory)

After a second of that we go back to the incredible..

14:20:13 open("/usr/share/eel/fonts/urw/n019003l.pfb", O_RDONLY) = 24
14:20:13 fstat64(24, {st_mode=S_IFREG|0644, st_size=36026, ...}) = 0
14:20:13 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x40025000
14:20:13 read(24, "\200\1]\6\0\0%!PS-AdobeFont-1.0: Nimbus"..., 4096) = 4096
14:20:13 close(24)                      = 0
14:20:13 munmap(0x40025000, 4096)       = 0
14:20:13 lstat64("/usr/share/eel/fonts/urw/n019003l.pfb",
{st_mode=S_IFREG|0644, st_size=36026, ...}) = 0
14:20:13 open("/usr/share/eel/fonts/urw/n019003l.pfb", O_RDONLY) = 24
14:20:13 fstat64(24, {st_mode=S_IFREG|0644, st_size=36026, ...}) = 0
14:20:13 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x40025000
14:20:13 read(24, "\200\1]\6\0\0%!PS-AdobeFont-1.0: Nimbus"..., 4096) = 4096
14:20:13 close(24)                      = 0
14:20:13 munmap(0x40025000, 4096)       = 0
14:20:13 lstat64("/usr/share/eel/fonts/urw/n019003l.pfb",
{st_mode=S_IFREG|0644, st_size=36026, ...}) = 0
14:20:13 open("/usr/share/eel/fonts/urw/n019003l.pfb", O_RDONLY) = 24
14:20:13 fstat64(24, {st_mode=S_IFREG|0644, st_size=36026, ...}) = 0
14:20:13 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x40025000
14:20:13 read(24, "\200\1]\6\0\0%!PS-AdobeFont-1.0: Nimbus"..., 4096) = 4096
14:20:13 close(24)                      = 0
14:20:13 munmap(0x40025000, 4096)       = 0

Again and again

This (and no other syscalls) pattern repeats for 4 seconds..

Nautilus then seems to query preference data over Corba, then .. load the
font again!

This is followed by the directory scan pattern with some directories being
checked 15 + times in a via lstat

17 seconds in from the start we load the font a few more times for luck,
scan for icons a bit then go back to loading the font repeatedly, then 
more directory scanning, followed by more repeated font loading

38 seconds in we load the directory-view-ui.xml and the pattern changes
totally and looks like an active app polling events

(Not the timings are skewed by the strace, it actually takes about 20
seconds without trace)



Weird Image Viewer Properties
-----------------------------

Loading a jpeg over NFS (ie double clicking it) takes 25 seconds to view
on my Athlon 550. Loading it off disk takes < 1. Looking at tcpdump traces
it seems the jpeg reader is asking the OS to read tiny little bits at a time

Also an image load appears to cause another full screen window covering
the desktop to be generated ???