Some optimization opportunities

Sat Jun 19 11:38:05 CEST 2004

On Saturday 19 June 2004 11:02, Daniël Mantione wrote:
> Hi,
>
> This week I dropped my laptop unfortunately it didn't survive. Now I
> find myself using my old K6 again. Not that I don't have a fast desktop,
> but often it runs that other commercial operating system and it's often
> more convenient to use the k6 than reboot my computer.
...
> = -1 ENOENT (No such file or directory) 32761 15:36:39.651355
> access("/usr/opt/kde3/share/icons/crystalsvg/16x16/devices/www.png", R_OK)
> = -1 ENOENT (No such file or directory) 32761 15:36:39.651961
> access("/etc/opt/kde3/share/icons/crystalsvg/16x16/filesystems/www.png",
> R_OK) = -1 ENOENT (No such file or directory) 32761 15:36:39.652560
> access("/usr/opt/kde3/share/icons/crystalsvg/16x16/filesystems/www.png",
> R_OK) = 0 32761 15:36:39.653258
> open("/usr/opt/kde3/share/icons/crystalsvg/16x16/filesystems/www.png",
> O_RDONLY|O_LARGEFILE) = 12 32761 15:36:39.653793 fstat64(12,
> {st_mode=S_IFREG|0644, st_size=926, ...}) = 0 32761 15:36:39.654312
> fstat64(12, {st_mode=S_IFREG|0644, st_size=926, ...}) = 0 32761
> 15:36:39.654765 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40e6e000 32761 15:36:39.655238
> _llseek(12, 0, [0], SEEK_SET) = 0
> 32761 15:36:39.656136 read(12,
> "\211PNG\r\n\32\n\0\0\0\rIHDR\0\0\0\20\0\0\0\20\10\6\0\0"..., 4096) = 926
> 32761 15:36:39.657881 close(12)         = 0
...
> "access" system calls. More seriously, an "access" system call is done for
> each subdirectory. This is a scalability issue, if more subdirectories
> will be added in the future, things will slow down.
>
> I'm going to throw all my icons in a single subdirectory.

Yes, icons are searched in a lot of directories, I found the same thing when I 
running KDE on my old K6/200, but it's now almost 2 years ago.
On my current system (AMD Athlon XP 2000+) it looks like this

11:26:20.312424 access("/opt/kde/share/apps/konqueror/icons/crystalsvg/16x16/
actions/www.png", R_OK) = -1 ENOENT (No such file or directory)
11:26:20.312516 access("/opt/kde/share/icons/crystalsvg/16x16/actions/
www.png", R_OK) = -1 ENOENT (No such file or directory)
11:26:20.312585 access("/opt/kde/share/icons/crystalsvg/16x16/apps/www.png", 
R_OK) = -1 ENOENT (No such file or directory)
11:26:20.312648 access("/opt/kde/share/icons/crystalsvg/16x16/devices/
www.png", R_OK) = -1 ENOENT (No such file or directory)
11:26:20.312711 access("/opt/kde/share/icons/crystalsvg/16x16/filesystems/
www.png", R_OK) = 0
11:26:20.312804 open("/opt/kde/share/icons/crystalsvg/16x16/filesystems/
www.png", O_RDONLY|O_LARGEFILE) = 12

I'm afraid changing the search behaviour might break apps which rely on it.
But it would be nice if you could spend some time to improve this issue.

> Lastly, there are some unnecessary system calls while loading the image.
> "fstat64" is being called twice and the "_llseek" system call is a nop.

Well, I think calling stat() twice instead of once is something we can live 
with.

> The next interresting point I saw was during opening op qtrc:
>
> 32761 15:36:37.710200 open("/usr/lib/qt3//etc/settings/qtrc",
> O_RDONLY|O_LARGEFILE) = 5 32761 15:36:37.711074 fstat64(5,
> {st_mode=S_IFREG|0644, st_size=6529, ...}) = 0 32761 15:36:37.712417
> fstat64(5, {st_mode=S_IFREG|0644, st_size=6529, ...}) = 0 32761
> 15:36:37.712924 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40979000 32761 15:36:37.713365
> read(5, "[3.1]\nlibraryPath=/root/.kde/lib"..., 4096) = 4096 32761
> 15:36:37.732684 brk(0)            = 0x80ae000
> 32761 15:36:37.733075 brk(0x80af000)    = 0x80af000
> 32761 15:36:37.748649 brk(0)            = 0x80af000
> 32761 15:36:37.749015 brk(0x80b0000)    = 0x80b0000
> 32761 15:36:37.763967 brk(0)            = 0x80b0000
> 32761 15:36:37.764336 brk(0x80b1000)    = 0x80b1000
> 32761 15:36:37.767200 read(5, "hi Mincho^eAr Pl Kaitim Big5^eAr"..., 4096)
> = 2433 32761 15:36:37.781304 brk(0)            = 0x80b1000
> 32761 15:36:37.781690 brk(0x80b2000)    = 0x80b2000
> 32761 15:36:37.792246 brk(0)            = 0x80b2000
> 32761 15:36:37.792614 brk(0x80b3000)    = 0x80b3000
> 32761 15:36:37.799938 fstat64(5, {st_mode=S_IFREG|0644, st_size=6529, ...})
> = 0 32761 15:36:37.800689 close(5)          = 0
> 32761 15:36:37.801111 munmap(0x40979000, 4096) = 0
> 32761 15:36:37.801552 fcntl64(4, F_SETLKW64, {type=F_UNLCK,
> whence=SEEK_SET, start=0, len=0}, 0xbfffdff0) = 0 32761 15:36:37.802112
> close(4)          = 0
> 32761 15:36:37.803218 access("/root/.qt/qtrc", F_OK) = -1 ENOENT (No such
> file or directory) 32761 15:36:37.805648 brk(0)            = 0x80b3000
> 32761 15:36:37.806039 brk(0x80b4000)    = 0x80b4000
> 32761 15:36:37.818747 brk(0)            = 0x80b4000
> 32761 15:36:37.819153 brk(0x80b5000)    = 0x80b5000
> 32761 15:36:37.826493 brk(0)            = 0x80b5000
> 32761 15:36:37.826891 brk(0x80b6000)    = 0x80b6000
> 32761 15:36:37.834954 brk(0)            = 0x80b6000
> 32761 15:36:37.835353 brk(0x80b7000)    = 0x80b7000
> 32761 15:36:37.843527 brk(0)            = 0x80b7000
> 32761 15:36:37.843926 brk(0x80b8000)    = 0x80b8000
> 32761 15:36:37.852115 brk(0)            = 0x80b8000
> 32761 15:36:37.852516 brk(0x80b9000)    = 0x80b9000
> 32761 15:36:37.860777 brk(0)            = 0x80b9000
> 32761 15:36:37.861219 brk(0x80ba000)    = 0x80ba000
> 32761 15:36:37.870319 brk(0)            = 0x80ba000
> 32761 15:36:37.870715 brk(0x80bb000)    = 0x80bb000
> 32761 15:36:37.877668 open("/usr/X11R6/lib/X11/locale/locale.alias",
> O_RDONLY) = 4
>
> Apparently a lot of memory is needed here, only it is allocated 4kb at a
> time. It's unclear how many system call overhead there is, as likely a lot
> happens between each system call. It is however interresting to see that
> it takes about 90 ms to parse qtrc (the time between opening and closing
> the file), which is a lot compared to decompressing the png files. 20 kb
> of memory is allocated, qtrc is 6529 bytes large.

AFAIK this is inside Qt. 90 ms is quite long. Parsing an average .desktop file 
with KConfig takes approx. 10 ms (on a K6/200). So loading qtrc can probably 
be optimized, but this happens only once while a KDE app starts, so not that 
much win  (... ok 50 ms would be actually a win). Maybe you can do something 
about it in Qt ? 

> Another observation:
...
> 32761 15:36:42.464204 gettimeofday({1087565802, 464393}, NULL) = 0
> 32761 15:36:42.465155 gettimeofday({1087565802, 465353}, NULL) = 0
> 32761 15:36:42.466002 gettimeofday({1087565802, 466196}, NULL) = 0
> 32761 15:36:42.466913 gettimeofday({1087565802, 467113}, NULL) = 0
> 32761 15:36:42.467762 gettimeofday({1087565802, 467961}, NULL) = 0
> 32761 15:36:42.468747 gettimeofday({1087565802, 468946}, NULL) = 0
> 32761 15:36:42.469698 gettimeofday({1087565802, 469896}, NULL) = 0
> 32761 15:36:42.470562 gettimeofday({1087565802, 470756}, NULL) = 0
> 32761 15:36:42.475218 gettimeofday({1087565802, 475440}, NULL) = 0
> 32761 15:36:42.475899 gettimeofday({1087565802, 476089}, NULL) = 0
> 32761 15:36:42.476416 gettimeofday({1087565802, 476590}, NULL) = 0
> 32761 15:36:42.477673 gettimeofday({1087565802, 478056}, NULL) = 0
> 32761 15:36:42.479127 gettimeofday({1087565802, 479343}, NULL) = 0
> 32761 15:36:42.479735 gettimeofday({1087565802, 479921}, NULL) = 0
> 32761 15:36:42.480452 gettimeofday({1087565802, 480642}, NULL) = 0
> 32761 15:36:42.482380 gettimeofday({1087565802, 482612}, NULL) = 0
> 32761 15:36:42.482945 gettimeofday({1087565802, 483115}, NULL) = 0
> 32761 15:36:42.483548 gettimeofday({1087565802, 483726}, NULL) = 0
> 32761 15:36:42.484345 gettimeofday({1087565802, 484540}, NULL) = 0
>
> Calling gettimeofday this often seems a little strange to me and certainly
> an important part of the 35 ms here is wasted due to system call overhead.

Do you know where this happens ? It must be some loop where nothing else 
interesting happens I think.

> I hope this info is usefull in further optimizing KDE. I am not subscribed
> to this list, however I will monitor the archives the next days. 

There's not that much traffic here, so it would be nice if you could 
subscribe.
Helping hands in optimizing KDE are alwas needed :-)

Bye
Alex
-- 
Work: alexander.neundorf at jenoptik.com - http://www.jenoptik-los.de
Home: neundorf at kde.org                - http://www.kde.org
      alex at neundorf.net               - http://www.neundorf.net