Re: Improving Nautilus startup time

[michael meeks <michael meeks novell com>]

Hi there,

On Wed, 2006-03-08 at 18:33 -0600, Federico Mena Quintero wrote:
> I wrote a little program to extract a timeline of Nautilus's startup
> from an strace log.  The first timeline is here:
> 
> http://primates.ximian.com/~federico/news-2006-03.html#login-time-1

	This is interesting indeed. Of course - while interesting, it's hard to
tell if various gaps are just time-slicing artefacts from yielding to
other processes (?) it's not clear how to remove that factor - perhaps
aggregating multiple runs ?

> I'm currently looking at improving the startup time of gnome-vfs-daemon.
> I suspect that this is actually the big delay we see when activating any
> bonobo server (i.e. the reason why gedit and gnome-terminal start much
> slower than, say, gnome-calculator).

	That is interesting. Of course a ping to b-a-s is quite fast; and we
can process incoming calls during b-a-s spawns of other apps; ie.

	nautilus		b-a-s
		-> fork gvfsd ->
				fork/spawn gvfsd
		-> do something ->
		<- something done
		<- return gvfsd

	if that makes any sense. Now the problem is: b-a-s activation is not
threaded - so if 'do something' is in fact another potentially slow
activation; then the 'fork gvfsd' call may have completed - but we can't
return the value to nautilus until we've completed the subsequent
activation.

	That may explain part of it.

	Another simple to fix / easy enough thing to do is to make sure that
gnome-vfs-daemon registers it's factory as early as possible [ this is
good practice anyway FWIW ], and then does further init after that. That
means that nautilus can get on with what it's doing while the vfsd
starts tidying up.

	Of course - it's hard to know what exactly the daemon does :-)

	wrt. threading the b-a-s activation piece; it's not actually -that-
difficult. We just use the thread-per-request POA policy, create our
objects with that POA - use '1-big-lock' to protect the entire existing
activation-server core; drop that lock before we
bonobo_activation_server_by_forking; and add a little locking / queue
mgmt to that method.

	Of course - before doing that, I guess we need to be able to blame
b-a-s effectively for causing the problem ;-) to that end I hacked up
this patch a while back; so you can get a dump of what is blocking what
- for my logins that showed almost nothing blocking anything else ;-)
but ... times change etc.

	HTH,

		Michael.

-- 
 michael meeks novell com  <><, Pseudo Engineer, itinerant idiot

--- Begin Message ---

• From: michael meeks <michael meeks novell com>
• To: Rodrigo Moya <rodrigo novell com>
• Subject: timing b-a-s bottlenecks ?
• Date: Wed, 08 Feb 2006 17:46:09 +0000

Hi there,

	So - I knocked up a patch that works for me - it seems to show that
there's a number of synchronous things happening at startup - but either
way - as we add async stuff to the panel we should start to see
activations stacking up & blocking each other inside b-a-s;

	If you apply the attached patch - then run b-a-s from the console (you
need to build it with bonobo-activation debug enabled (cf. configure)).

	Then do:

	/opt/gnome/libexec/bonobo-activation-server \
		 --register-server 2>&1 | tee /tmp/log

	So - that should print out some 'stuff' possibly I screwed the patch
up ;-) but hopefully some idea of the timing overlaps & delays returning
to clients.

	Either way - things should -seem- to get worse with the panel fix,
whereas in fact timing wise they'll get better ;-) so the timing numbers
are not actually that useful ;-) but would be interesting - if you could
make a log (?)

	If not just send your patch & I'll have a play :-)

	HTH,

		Michael.

-- 
 michael meeks novell com  <><, Pseudo Engineer, itinerant idiot

Index: bonobo-activation/bonobo-activation-fork-server.c
===================================================================
RCS file: /cvs/gnome/libbonobo/bonobo-activation/bonobo-activation-fork-server.c,v
retrieving revision 1.25.2.2
diff -u -p -u -r1.25.2.2 bonobo-activation-fork-server.c
--- bonobo-activation/bonobo-activation-fork-server.c	13 Jan 2006 14:44:26 -0000	1.25.2.2
+++ bonobo-activation/bonobo-activation-fork-server.c	8 Feb 2006 17:40:26 -0000
@@ -24,7 +24,7 @@
  */
 
 #include <config.h>
-
+#include <glib/gtimer.h>
 #include <bonobo-activation/bonobo-activation-private.h>
 #include <bonobo-activation/bonobo-activation-i18n.h>
 #include <bonobo-activation/bonobo-activation-init.h>
@@ -229,6 +229,7 @@ bonobo_activation_server_by_forking (
         GMainContext *context;
         char **newenv = NULL;
         char **cmd;
+        static GTimer *timer = NULL;
 
 #if defined(__APPLE__) && defined(HAVE_NSGETENVIRON) && defined(HAVE_CRT_EXTERNS_H)
 # include <crt_externs.h>
@@ -333,7 +334,17 @@ bonobo_activation_server_by_forking (
 
         ai.iorbuf[0] = '\0';
         ai.done = FALSE;
+
+        if (!timer)
+                timer = g_timer_new ();
         
+        if (g_slist_length (running_activations))
+        {
+                EXEActivateInfo *blocked_ai = g_slist_last (running_activations)->data;
+                g_timer_start (timer);
+                g_warning ("activation of '%s' blocking activation of '%s' ",
+                           ai.exename, blocked_ai->exename);
+        }
         running_activations = g_slist_prepend (running_activations, &ai);
 
 	/* Spawn */
@@ -360,6 +371,8 @@ bonobo_activation_server_by_forking (
 				     ex_Bonobo_GeneralError, errval);
 
                 running_activations = g_slist_remove (running_activations, &ai);
+                if (!running_activations)
+                        g_timer_stop (timer);
 
                 g_source_destroy (source);
                 g_source_unref (source);
@@ -403,6 +416,17 @@ bonobo_activation_server_by_forking (
                 g_main_context_unref (context);
         
         running_activations = g_slist_remove (running_activations, &ai);
+        if (g_slist_length (running_activations))
+        {
+                EXEActivateInfo *blocked_ai = g_slist_last (running_activations)->data;
+                
+                g_warning ("activation of '%s' completed; unblocking activation of '%s' "
+                           "time burned so far %g secs",
+                           ai.exename, blocked_ai->exename,
+                           g_timer_elapsed (timer, NULL));
+        }
+        if (!running_activations)
+                g_timer_stop (timer);
 
         retval = exe_activate_info_to_retval (&ai, ev); 
 

--- End Message ---

Index: bonobo-activation/bonobo-activation-fork-server.c
===================================================================
RCS file: /cvs/gnome/libbonobo/bonobo-activation/bonobo-activation-fork-server.c,v
retrieving revision 1.25.2.2
diff -u -p -u -r1.25.2.2 bonobo-activation-fork-server.c
--- bonobo-activation/bonobo-activation-fork-server.c	13 Jan 2006 14:44:26 -0000	1.25.2.2
+++ bonobo-activation/bonobo-activation-fork-server.c	8 Feb 2006 17:40:26 -0000
@@ -24,7 +24,7 @@
  */
 
 #include <config.h>
-
+#include <glib/gtimer.h>
 #include <bonobo-activation/bonobo-activation-private.h>
 #include <bonobo-activation/bonobo-activation-i18n.h>
 #include <bonobo-activation/bonobo-activation-init.h>
@@ -229,6 +229,7 @@ bonobo_activation_server_by_forking (
         GMainContext *context;
         char **newenv = NULL;
         char **cmd;
+        static GTimer *timer = NULL;
 
 #if defined(__APPLE__) && defined(HAVE_NSGETENVIRON) && defined(HAVE_CRT_EXTERNS_H)
 # include <crt_externs.h>
@@ -333,7 +334,17 @@ bonobo_activation_server_by_forking (
 
         ai.iorbuf[0] = '\0';
         ai.done = FALSE;
+
+        if (!timer)
+                timer = g_timer_new ();
         
+        if (g_slist_length (running_activations))
+        {
+                EXEActivateInfo *blocked_ai = g_slist_last (running_activations)->data;
+                g_timer_start (timer);
+                g_warning ("activation of '%s' blocking activation of '%s' ",
+                           ai.exename, blocked_ai->exename);
+        }
         running_activations = g_slist_prepend (running_activations, &ai);
 
 	/* Spawn */
@@ -360,6 +371,8 @@ bonobo_activation_server_by_forking (
 				     ex_Bonobo_GeneralError, errval);
 
                 running_activations = g_slist_remove (running_activations, &ai);
+                if (!running_activations)
+                        g_timer_stop (timer);
 
                 g_source_destroy (source);
                 g_source_unref (source);
@@ -403,6 +416,17 @@ bonobo_activation_server_by_forking (
                 g_main_context_unref (context);
         
         running_activations = g_slist_remove (running_activations, &ai);
+        if (g_slist_length (running_activations))
+        {
+                EXEActivateInfo *blocked_ai = g_slist_last (running_activations)->data;
+                
+                g_warning ("activation of '%s' completed; unblocking activation of '%s' "
+                           "time burned so far %g secs",
+                           ai.exename, blocked_ai->exename,
+                           g_timer_elapsed (timer, NULL));
+        }
+        if (!running_activations)
+                g_timer_stop (timer);
 
         retval = exe_activate_info_to_retval (&ai, ev);