Reducing gconf roundtrips

[Behdad Esfahbod <behdad behdad org>]

Hi all,

Following up on the gconf discussion a few weeks ago and with help from 
Matthias, I looked into profiling and reducing roundtrips during login.
Here is a first report.

Methodology
===========

I needed a simple and reproducible way to trace all the roundtrips, with 
annotations about their cause.  For this, I decided to use gconf-client 
tracing.  I tweaked gconf-client.c to:

  1) Use g_message instead of printf.  This allows enabling process name and 
pid logging using glib.

  2) Improve gconf-client to trace ALL remote queries.  I basically tagged 
each request with either "REMOTE:" or "CACHED:" depending where it was 
fulfilled.  Requests that produce multiple remote queries add a REMOTE: line 
for each.

These are committed into gconf master already (though, after a couple 
optimization patches).

With the move to g_message, I also had to neuter gnome-session's custom g_log 
handler to get the messages I want.

  gnome-session, UNCONFIRMED
  Bug 579766 – gnome-session log handler gets in the way

I then use the following script to trace the login.  For more accuracy, make 
sure you test a warm login, and that you don't have any other X session 
running (otherwise, NetworkManager fails to grab its bus name and gives up.) 
Here's the script:

----------------------------------
#!/bin/bash

export GCONF_DEBUG_TRACE_CLIENT=1
export G_MESSAGES_PREFIXED=all

f=xsession-errors

startx -- :2 &> $f &
pid=$!
fstart=$f.$pid.start

sleep 15

cp $f $fstart
killall xinit
echo saved $fstart
----------------------------------

I run this in a fresh new account on Fedora Rawhide.

Analyzing Login
===============

We can then easily massage the saved xsession-errors file to extract all kind 
of interesting output.  Lets see how many REMOTE and CACHED requests we had:

$ cat 0.before | grep GConf | grep REMOTE | wc -l
428
$ cat 0.before | grep GConf | grep CACHED | wc -l
732

>>> 428+732
1160

And the breakdown of the requests based on cause:

$ cat 0.before | grep GConf | grep 'REMOTE\|CACHED' | sed "s/.*GConf-Message: 
//" | sed "s/'.*'/'...'/"  | sort | uniq -c | sort -n
      1 REMOTE: Getting all dirs in '...'
      1 REMOTE: Removing notify from engine at '...'
      3 REMOTE: Checking whether directory '...' exists...
      5 REMOTE: Getting all values in '...'
     41 REMOTE: All dirs at '...'
     51 CACHED: Checking whether key '...' is writable
     58 REMOTE: Adding notify to engine at '...'
     77 REMOTE: Caching values in '...'
    242 REMOTE: Query for '...'
    681 CACHED: Query for '...'

As can be seen, there is no writes.  This may well just be the case for a 
fresh user.  Testing on a real desktop with applets, icons on the desktop, etc 
will be a logical followup.

So, more than half of the REMOTE queries is for single keys.  Fortunately most 
of those are for "negative" keys.  That is, keys not in the database. 
Applying the neg-caching patch Matthias wrote significantly improves things. 
the patch is upstream now.  With that:

$ cat 1.negcaching | grep 'GConf-Message:' | grep REMOTE | wc -l
245
$ cat 1.negcaching | grep 'GConf-Message:' | grep CACHED | wc -l
915

>>> 245+915
1160

$ cat 1.negcaching | grep GConf | grep 'REMOTE\|CACHED' | sed 
"s/.*GConf-Message: //" | sed "s/'.*'/'...'/"  | sort | uniq -c | sort -n
      1 REMOTE: Getting all dirs in '...'
      1 REMOTE: Removing notify from engine at '...'
      3 REMOTE: Checking whether directory '...' exists...
      5 CACHED: Getting all values in '...'
     41 REMOTE: All dirs at '...'
     51 CACHED: Checking whether key '...' is writable
     58 REMOTE: Adding notify to engine at '...'
     64 REMOTE: Query for '...'
     77 REMOTE: Caching values in '...'
    859 CACHED: Query for '...'

Not bad.

I then went through the log, finding the cause of each of the about 70 
"REMOTE: Query for" calls and filing bugs to do prefetching if appropriate.
Note that the results above (both) actually contain the fix for 
gnome-settings-daemon since Jens was so awesome he committed and pushed them 
in 2.26.1.  Anyway, the bugs and their status:

  gnome-settings-daemon, FIXED
  Bug 578542 – Preload gconf tree for kbd

  gnome-settings-daemon, FIXED
  Bug 578539 – keybindings plugin gconf access pattern

  gnome-power-manager, FIXED
  Bug 578545 – preload gconf tree /apps/gnome-power-manager recursively

  gnome-session, FIXED
  Bug 578533 – Don't preload gconf dir /apps/nautilus/preferences

  gnome-session, FIXED
  Bug 578537 – More gconf stupidity^Woptimizations

  nautilus and gnome-desktop, FIXED
  Bug 578993 – Prefetch gconf tree /desktop/gnome/background

  gnome-panel, UNCONFIRMED
  Bug 578541 – preloads /apps/panel/general too late

  gnome-panel, UNCONFIRMED
  Bug 578992 – More gconf

  nm-applet, UNCONFIRMED
  Bug 578546 – Preload gconf dir for /apps/nm-applet

  PackageKit, FIXED
  No bugzilla.  Richard committed the fix.

The following do not directly affect REMOTE calls, but reduce CACHED lookups 
immensely:

  gnome-panel, UNCONFIRMED
  Bug 578532 – Cache value of /desktop/gnome/interface/menus_have_icons
  (Saves some 180 CACHED lookups of the same key in a row!)


With those fixes (except for the PackageKit one that I forgot to test since it 
was not in bugzilla), lets see how things look now:

$ cat 2.apps | grep 'GConf-Message:' | grep REMOTE | wc -l
253
$ cat 2.apps | grep 'GConf-Message:' | grep CACHED | wc -l
783

>>> 253+783
1036

Ouch.  Disappointing, but not really surprising when we look at the breakdown:

$ cat 2.apps | grep GConf | grep 'REMOTE\|CACHED' | sed "s/.*GConf-Message: 
//" | sed "s/'.*'/'...'/"  | sort | uniq -c | sort -n
      3 REMOTE: Checking whether directory '...' exists...
      5 CACHED: Getting all values in '...'
     10 REMOTE: Suggesting sync
     14 REMOTE: Getting all dirs in '...'
     21 REMOTE: Query for '...'
     51 CACHED: Checking whether key '...' is writable
     54 REMOTE: All dirs at '...'
     58 REMOTE: Adding notify to engine at '...'
     93 REMOTE: Caching values in '...'
    727 CACHED: Query for '...'

I think I did something wrong in the first two runs as I don't see nm-applet 
suggest_sync requests, and see 1 remote_notify request instead.  So, lets say 
the two previous runs should have had 18 more REMOTE requests.  We'll get to 
that later.

The drop in CACHED queries is because of the mentioned fix in gnome-panel.
REMOTE queries went down from 64 to 21.  The remaining cases seem optimal and 
hard to optimize by way of prefetching.

On the other hand, "REMOTE: All dirs at" went from 41 to 54, and "REMOTE: 
Caching values in" from 77 to 93.  What's going on is that the overhead of 
prefetching is showing.  Federico pointed out the stupidity of 
PREFETCH_RECURSIVE in Barcelona.

Basically, the entire prefetching thing is implemented on the gconf-client 
side.  It first fetches all keys under the requested dir and caches them, then 
lists all dir under the dir and recurses.  It doesn't have to be like that 
though.  If we push the logic across the wire, we can do it all in one 
request.  Currently a ONELEVEL prefetch generates two requests: adding notify, 
then listing all keys.  It doesn't have to be like that either.

So, what I propose is to add a full gconf_client_add_dir()-equivalent method 
to the wire.  With that we can save:

     54 REMOTE: All dirs at '...'
     93 REMOTE: Caching values in '...'

That would bring us down to 106 REMOTE queries.  The remaining ones are:

      3 REMOTE: Checking whether directory '...' exists...

This is gconf_client_dir_exists() calls gnome-panel is making.  These can be 
cached if we track sub-directories on the client side.  Not hard.  Not not 
immediately worth the effort.

     10 REMOTE: Suggesting sync

This is nm-applet stupidity that should be fixed, since there is no writes 
involved at all.

  nm-applet, UNCONFIRMED
  Bug 578995 – Don't call gconf_client_suggest_sync()


     14 REMOTE: Getting all dirs in '...'

This is mostly more nm-applet stupidity.  Tracked in the same bug.
One is from g-s-d keybindings plugin.  These also can be obviated if we track 
sub-directories in the cache.

Fix the nm-applet and we'll be down to 84.  Of which 58 will be hooking up 
notifies and harder to optimize.

Also saves a couple ones is the silly bug:

  gnome-settings-daemon, UNCONFIRMED
  Bug 578538 – Neuter dummy plugin


Todo
====

So, to get there, there's the easy stuff:

  - Fix nm-applet bugs,

And the hard one:

  - Add a combined "add notify, get all onelevel/recursively" call to the 
Bonobo protocol.  Anyone volunteering to look into that?


Next step will be profiling login of a seasoned account.

The logs are available here:

  http://www.gnome.org/~behdad/login/gconf/2009-04-27/

Cheers,
behdad