Re: Login time

[Federico Mena Quintero <federico ximian com>]

El mar, 10-04-2007 a las 14:30 +1000, Magnus Boman escribi�> Looking at the page http://live.gnome.org/GnomePerformance/LoginTime you
> want to patch Nautilus to see when the Desktop is loaded and painted.
> Would it be possible to see this via strace? If that's the case, it
> should be easy to use strace and fifo in combination with a script to
> see when it's done?

Yes, you can use strace.  Last week I was working on a patch to add
checkpoints to Nautilus/eel, which plot-timeline.py can pick up later.
Patches attached.

You need to put the following in ~/nautilus-debug-log.conf :

  [debug log]
  enable domains = checkpoint

> If the above is true, the I guess the same goes for gnome-panel and
> gnome-session?

Yup!

Gnome-session is easier, since it already has a lot of interesting
logging points --- you could put calls to program_log() close to those
points and get interesting info in the strace.  For gnome-panel, you'll
have to see where the checkpoints should be :)

  Federico

Index: ChangeLog
===================================================================
RCS file: /cvsroot/nautilus/ChangeLog,v
retrieving revision 1.1.1.1
diff -u -p -r1.1.1.1 ChangeLog
--- ChangeLog	4 Apr 2007 18:07:22 -0000	1.1.1.1
+++ ChangeLog	4 Apr 2007 22:54:31 -0000
@@ -1,3 +1,34 @@
+2007-04-04  Federico Mena Quintero  <federico novell com>
+
+	* libnautilus-private/nautilus-debug-log.h
+	(NAUTILUS_DEBUG_LOG_DOMAIN_CHECKPOINT): New macro with a
+	"checkpoint" domain for profiiling.
+	(nautilus_checkpoint): New prototype.
+
+	* libnautilus-private/nautilus-debug-log.c (nautilus_debug_logv):
+	If the domain is "checkpoint", do an access() call to pick it up
+	later with strace.
+	(nautilus_checkpoint): New function; logs a non-milestone message
+	on the "checkpoint" domain.
+
+	* libnautilus-private/nautilus-module.c (load_module_dir):
+	Checkpoint the start/end of loading a module.
+
+	* src/nautilus-application.c (nautilus_application_instance_init):
+	Checkpoint this function, and the block where we launch the volume monitor.
+	(nautilus_application_startup): Checkpoint this function.
+
+	* src/nautilus-main.c (main): Checkpoint where we call gtk_main().
+
+	* src/nautilus-desktop-window.c (nautilus_desktop_window_new):
+	Checkpoint this function.
+
+	* libnautilus-private/nautilus-icon-container.c
+	(nautilus_icon_container_instance_init): Checkpoint this function.
+	(size_allocate): Checkpoint this function.
+	(expose_event): Checkpoint this function.
+	(redo_layout_internal): Checkpoint this function.
+
 2006-10-02  Alexander Larsson  <alexl redhat com>
 
 	* NEWS:
Index: libnautilus-private/nautilus-debug-log.c
===================================================================
RCS file: /cvsroot/nautilus/libnautilus-private/nautilus-debug-log.c,v
retrieving revision 1.1.1.1
diff -u -p -r1.1.1.1 nautilus-debug-log.c
--- libnautilus-private/nautilus-debug-log.c	4 Apr 2007 18:07:22 -0000	1.1.1.1
+++ libnautilus-private/nautilus-debug-log.c	4 Apr 2007 18:10:30 -0000
@@ -153,6 +153,16 @@ nautilus_debug_logv (gboolean is_milesto
 		goto out;
 
 	str = g_strdup_vprintf (format, args);
+
+	if (strcmp (domain, NAUTILUS_DEBUG_LOG_DOMAIN_CHECKPOINT) == 0) {
+		char *checkpoint_str;
+
+		checkpoint_str = g_strdup_printf ("MARK: %s: %s", g_get_prgname(), str);
+		access (checkpoint_str, F_OK);
+		g_free (checkpoint_str);
+
+	}
+
 	gettimeofday (&tv, NULL);
 
 	tm = *localtime (&tv.tv_sec);
@@ -690,3 +700,26 @@ nautilus_debug_log_clear (void)
  out:
 	unlock ();
 }
+
+/**
+ * nautilus_checkpoint:
+ * @format: Format string
+ * @...: Arguments for format string
+ * 
+ * Logs a non-milestone message to the debug log under the
+ * NAUTILUS_DEBUG_DOMAIN_CHECKPOINT domain, and also does an access(2) call of
+ * this form:
+ *
+ *    access ("MARK: nautilus: <message>", F_OK)
+ *
+ * This call can be searched for in strace logs for profiling purposes.
+ **/
+void
+nautilus_checkpoint (const char *format, ...)
+{
+	va_list args;
+
+	va_start (args, format);
+	nautilus_debug_logv (FALSE, NAUTILUS_DEBUG_LOG_DOMAIN_CHECKPOINT, NULL, format, args);
+	va_end (args);
+}
Index: libnautilus-private/nautilus-debug-log.h
===================================================================
RCS file: /cvsroot/nautilus/libnautilus-private/nautilus-debug-log.h,v
retrieving revision 1.1.1.1
diff -u -p -r1.1.1.1 nautilus-debug-log.h
--- libnautilus-private/nautilus-debug-log.h	4 Apr 2007 18:07:22 -0000	1.1.1.1
+++ libnautilus-private/nautilus-debug-log.h	4 Apr 2007 18:08:34 -0000
@@ -30,6 +30,7 @@
 #define NAUTILUS_DEBUG_LOG_DOMAIN_USER		"USER"   /* always enabled */
 #define NAUTILUS_DEBUG_LOG_DOMAIN_ASYNC		"async"	 /* when asynchronous notifications come in */
 #define NAUTILUS_DEBUG_LOG_DOMAIN_GLOG          "GLog"	 /* used for GLog messages; don't use it yourself */
+#define NAUTILUS_DEBUG_LOG_DOMAIN_CHECKPOINT    "checkpoint" /* for profiling using strace */
 
 void nautilus_debug_log (gboolean is_milestone, const char *domain, const char *format, ...);
 
@@ -55,4 +56,7 @@ int nautilus_debug_log_get_max_lines (vo
 /* For testing only */
 void nautilus_debug_log_clear (void);
 
+/* For profiling using strace */
+void nautilus_checkpoint (const char *format, ...);
+
 #endif /* NAUTILUS_DEBUG_LOG_H */
Index: libnautilus-private/nautilus-icon-container.c
===================================================================
RCS file: /cvsroot/nautilus/libnautilus-private/nautilus-icon-container.c,v
retrieving revision 1.1.1.1
diff -u -p -r1.1.1.1 nautilus-icon-container.c
--- libnautilus-private/nautilus-icon-container.c	4 Apr 2007 18:07:22 -0000	1.1.1.1
+++ libnautilus-private/nautilus-icon-container.c	5 Apr 2007 01:36:46 -0000
@@ -1629,6 +1629,8 @@ lay_down_icons (NautilusIconContainer *c
 static void
 redo_layout_internal (NautilusIconContainer *container)
 {
+	nautilus_checkpoint ("nautilus-icon-container.c: redo_layout_internal() START");
+
 	finish_adding_new_icons (container);
 
 	/* Don't do any re-laying-out during stretching. Later we
@@ -1647,6 +1649,8 @@ redo_layout_internal (NautilusIconContai
 	process_pending_icon_to_reveal (container);
 	process_pending_icon_to_rename (container);
 	nautilus_icon_container_update_visible_icons (container);
+
+	nautilus_checkpoint ("nautilus-icon-container.c: redo_layout_internal() END");
 }
 
 static gboolean
@@ -3077,6 +3081,8 @@ size_allocate (GtkWidget *widget,
 	NautilusIconContainer *container;
 	gboolean need_layout_redone;
 
+	nautilus_checkpoint ("nautilus-icon-container.c: size_allocate() START");
+
 	container = NAUTILUS_ICON_CONTAINER (widget);
 
 	need_layout_redone = !container->details->has_been_allocated;
@@ -3092,6 +3098,8 @@ size_allocate (GtkWidget *widget,
 	if (need_layout_redone) {
 		redo_layout (container);
 	}
+
+	nautilus_checkpoint ("nautilus-icon-container.c: size_allocate() END");
 }
 
 static void
@@ -3101,6 +3109,8 @@ realize (GtkWidget *widget)
 	GdkBitmap *stipple;
 	GtkAdjustment *vadj;
 
+	nautilus_checkpoint ("nautilus-icon-container.c: realize() START");
+
 	GTK_WIDGET_CLASS (parent_class)->realize (widget);
 
 	/* Set up DnD.  */
@@ -3122,6 +3132,7 @@ realize (GtkWidget *widget)
 	g_signal_connect (vadj, "value_changed",
 			  G_CALLBACK (handle_vadjustment_changed), widget);
 
+	nautilus_checkpoint ("nautilus-icon-container.c: realize() END");
 }
 
 static void
@@ -3160,6 +3171,8 @@ style_set (GtkWidget *widget,
 {
 	NautilusIconContainer *container;
 	gboolean frame_text;
+
+	nautilus_checkpoint ("nautilus-icon-container.c: style_set() START");
 	
 	container = NAUTILUS_ICON_CONTAINER (widget);
 
@@ -3177,6 +3190,8 @@ style_set (GtkWidget *widget,
 	}
 	
 	GTK_WIDGET_CLASS (parent_class)->style_set (widget, previous_style);
+
+	nautilus_checkpoint ("nautilus-icon-container.c: style_set() END");
 }
 
 static gboolean
@@ -4442,12 +4457,23 @@ static gboolean
 expose_event (GtkWidget      *widget,
 	      GdkEventExpose *event)
 {
+	gboolean retval;
+
 /*	g_warning ("Expose Icon Container %p '%d,%d: %d,%d'",
 		   widget,
 		   event->area.x, event->area.y,
 		   event->area.width, event->area.height); */
-	
-	return GTK_WIDGET_CLASS (parent_class)->expose_event (widget, event);
+
+	nautilus_checkpoint ("nautilus-icon-container.c: expose_event(x=%d, y=%d, w=%d, h=%d)",
+			     event->area.x,
+			     event->area.y,
+			     event->area.width,
+			     event->area.height);
+
+	retval = GTK_WIDGET_CLASS (parent_class)->expose_event (widget, event);
+
+	nautilus_checkpoint ("nautilus-icon-container.c: finished expose_event()");
+	return retval;
 }
 
 static AtkObject *
@@ -4898,7 +4924,9 @@ nautilus_icon_container_instance_init (N
 {
 	NautilusIconContainerDetails *details;
 	EelBackground *background;
-	
+
+	nautilus_checkpoint ("nautilus-icon-container.c: nautilus_icon_container_instance_init() START");
+
 	details = g_new0 (NautilusIconContainerDetails, 1);
 
 	details->icon_set = g_hash_table_new (g_direct_hash, g_direct_equal);
@@ -4940,6 +4968,8 @@ nautilus_icon_container_instance_init (N
 	eel_preferences_add_callback (NAUTILUS_PREFERENCES_THEME,
 				      nautilus_icon_container_theme_changed,
 				      container);	
+
+	nautilus_checkpoint ("nautilus-icon-container.c: nautilus_icon_container_instance_init() END");
 }
 
 typedef struct {
@@ -5687,13 +5717,20 @@ static void
 finish_adding_icon (NautilusIconContainer *container,
 		    NautilusIcon *icon)
 {
+	nautilus_checkpoint ("nautilus-icon-container.c: finish_adding_icon() START");
+
 	nautilus_icon_container_update_icon (container, icon);
+
+	nautilus_checkpoint ("nautilus-icon-container.c: finish_adding_icon() eel_canvas_item_show() START");
 	eel_canvas_item_show (EEL_CANVAS_ITEM (icon->item));
+	nautilus_checkpoint ("nautilus-icon-container.c: finish_adding_icon() eel_canvas_item_show() END");
 
 	g_signal_connect_object (icon->item, "event",
 				 G_CALLBACK (item_event_callback), container, 0);
 
 	g_signal_emit (container, signals[ICON_ADDED], 0, icon->data);
+
+	nautilus_checkpoint ("nautilus-icon-container.c: finish_adding_icon() END");
 }
 
 static void
@@ -5703,10 +5740,13 @@ finish_adding_new_icons (NautilusIconCon
 	NautilusIcon *icon;
 	double bottom;
 
+	nautilus_checkpoint ("nautilus-icon-contaienr.c: finish_adding_new_icons() START");
+
 	new_icons = container->details->new_icons;
 	container->details->new_icons = NULL;
 
 	/* Position most icons (not unpositioned manual-layout icons). */
+
 	new_icons = g_list_reverse (new_icons);
 	no_position_icons = semi_position_icons = NULL;
 	for (p = new_icons; p != NULL; p = p->next) {
@@ -5782,6 +5822,8 @@ finish_adding_new_icons (NautilusIconCon
 		lay_down_icons (container, no_position_icons, bottom + ICON_PAD_BOTTOM);
 		g_list_free (no_position_icons);
 	}
+
+	nautilus_checkpoint ("nautilus-icon-contaienr.c: finish_adding_new_icons() END");
 }
 
 /**
Index: libnautilus-private/nautilus-module.c
===================================================================
RCS file: /cvsroot/nautilus/libnautilus-private/nautilus-module.c,v
retrieving revision 1.1.1.1
diff -u -p -r1.1.1.1 nautilus-module.c
--- libnautilus-private/nautilus-module.c	4 Apr 2007 18:07:22 -0000	1.1.1.1
+++ libnautilus-private/nautilus-module.c	4 Apr 2007 18:50:12 -0000
@@ -27,6 +27,7 @@
 #include <eel/eel-gtk-macros.h>
 #include <gmodule.h>
 #include <libgnome/gnome-macros.h>
+#include "nautilus-debug-log.h"
 
 #define NAUTILUS_TYPE_MODULE    	(nautilus_module_get_type ())
 #define NAUTILUS_MODULE(obj)		(G_TYPE_CHECK_INSTANCE_CAST ((obj), NAUTILUS_TYPE_MODULE, NautilusModule))
@@ -196,7 +197,9 @@ load_module_dir (const char *dirname)
 				filename = g_build_filename (dirname, 
 							     name, 
 							     NULL);
+				nautilus_checkpoint ("nautilus-module.c: calling nautilus_module_load_file (%s)", filename);
 				nautilus_module_load_file (filename);
+				nautilus_checkpoint ("nautilus-module.c: finished nautilus_module_load_file (%s)", filename);
 				g_free (filename);
 			}
 		}
Index: src/nautilus-application.c
===================================================================
RCS file: /cvsroot/nautilus/src/nautilus-application.c,v
retrieving revision 1.1.1.1
diff -u -p -r1.1.1.1 nautilus-application.c
--- src/nautilus-application.c	4 Apr 2007 18:07:22 -0000	1.1.1.1
+++ src/nautilus-application.c	4 Apr 2007 18:50:52 -0000
@@ -170,6 +170,8 @@ nautilus_application_get_n_windows (void
 static void
 nautilus_application_instance_init (NautilusApplication *application)
 {
+	nautilus_checkpoint ("nautilus-application.c: nautilus_application_instance_init() START");
+
 	/* Create an undo manager */
 	application->undo_manager = nautilus_undo_manager_new ();
 
@@ -178,12 +180,14 @@ nautilus_application_instance_init (Naut
 	 * used anymore */
 
 	/* Watch for volume unmounts so we can close open windows */
+	nautilus_checkpoint ("nautilus-application.c: nautilus_application_instance_init() calling signal_connect on gnome_vfs_get_volume_monitor()");
 	g_signal_connect_object (gnome_vfs_get_volume_monitor (), "volume_unmounted",
 				 G_CALLBACK (volume_unmounted_callback), application, 0);
 	g_signal_connect_object (gnome_vfs_get_volume_monitor (), "volume_pre_unmount",
 				 G_CALLBACK (volume_unmounted_callback), application, 0);
 	g_signal_connect_object (gnome_vfs_get_volume_monitor (), "volume_mounted",
 				 G_CALLBACK (volume_mounted_callback), application, 0);
+	nautilus_checkpoint ("nautilus-application.c: nautilus_application_instance_init() finished signal_connect on gnome_vfs_get_volume_monitor()");
 
 	/* register views */
 	fm_icon_view_register ();
@@ -200,6 +204,8 @@ nautilus_application_instance_init (Naut
 
 	/* register property pages */
 	nautilus_image_properties_page_register ();
+
+	nautilus_checkpoint ("nautilus-application.c: nautilus_application_instance_init() END");
 }
 
 NautilusApplication *
@@ -427,6 +433,8 @@ remove_desktop_dot_hidden (void)
 static void
 finish_startup (NautilusApplication *application)
 {
+	nautilus_checkpoint ("nautilus-application.c: nautilus-application finish_startup() START");
+
 	/* initialize nautilus modules */
 	nautilus_module_init ();
 
@@ -446,6 +454,8 @@ finish_startup (NautilusApplication *app
 
 	/* Initialize the desktop link monitor singleton */
 	nautilus_desktop_link_monitor_get ();
+
+	nautilus_checkpoint ("nautilus-application.c: nautilus-application finish_startup() END");
 }
 
 static void
@@ -543,12 +553,15 @@ nautilus_application_startup (NautilusAp
 	const CORBA_char *corba_geometry;
 	int num_failures;
 
+	nautilus_checkpoint ("nautilus-application.c: nautilus_application_startup() START");
+
 	num_failures = 0;
 
 	/* Check the user's ~/.nautilus directories and post warnings
 	 * if there are problems.
 	 */
 	if (!kill_shell && !check_required_directories (application)) {
+		nautilus_checkpoint ("nautilus-application.c: nautilus_application_startup() END bailing out");
 		return;
 	}
 
@@ -722,6 +735,8 @@ nautilus_application_startup (NautilusAp
 
  out:
 	CORBA_exception_free (&ev);
+
+	nautilus_checkpoint ("nautilus-application.c: nautilus_application_startup() END");
 }
 
 
Index: src/nautilus-desktop-window.c
===================================================================
RCS file: /cvsroot/nautilus/src/nautilus-desktop-window.c,v
retrieving revision 1.1.1.1
diff -u -p -r1.1.1.1 nautilus-desktop-window.c
--- src/nautilus-desktop-window.c	4 Apr 2007 18:07:22 -0000	1.1.1.1
+++ src/nautilus-desktop-window.c	4 Apr 2007 18:51:18 -0000
@@ -34,6 +34,7 @@
 #include <eel/eel-vfs-extensions.h>
 #include <libgnome/gnome-macros.h>
 #include <libgnomevfs/gnome-vfs-utils.h>
+#include <libnautilus-private/nautilus-debug-log.h>
 #include <libnautilus-private/nautilus-file-utilities.h>
 
 struct NautilusDesktopWindowDetails {
@@ -110,6 +111,8 @@ nautilus_desktop_window_new (NautilusApp
 	NautilusDesktopWindow *window;
 	int width_request, height_request;
 
+	nautilus_checkpoint ("nautilus-desktop-window.c: nautilus_desktop_window_new() START");
+
 	width_request = gdk_screen_get_width (screen);
 	height_request = gdk_screen_get_height (screen);
 
@@ -131,6 +134,8 @@ nautilus_desktop_window_new (NautilusApp
 	 */
 	nautilus_desktop_window_update_directory (window);
 
+	nautilus_checkpoint ("nautilus-desktop-window.c: nautilus_desktop_window_new() END");
+
 	return window;
 }
 
Index: src/nautilus-main.c
===================================================================
RCS file: /cvsroot/nautilus/src/nautilus-main.c,v
retrieving revision 1.1.1.1
diff -u -p -r1.1.1.1 nautilus-main.c
--- src/nautilus-main.c	4 Apr 2007 18:07:22 -0000	1.1.1.1
+++ src/nautilus-main.c	4 Apr 2007 18:51:03 -0000
@@ -527,6 +527,7 @@ main (int argc, char *argv[])
 		g_free (startup_id_copy);
 
 		if (is_event_loop_needed ()) {
+			nautilus_checkpoint ("nautilus-main.c: STARTING MAIN LOOP!");
 			gtk_main ();
 		}
 	}

Index: eel/eel-background.c
===================================================================
RCS file: /cvsroot/eel/eel/eel-background.c,v
retrieving revision 1.1.1.1
diff -u -p -r1.1.1.1 eel-background.c
--- eel/eel-background.c	5 Apr 2007 00:56:17 -0000	1.1.1.1
+++ eel/eel-background.c	5 Apr 2007 02:40:11 -0000
@@ -44,12 +44,29 @@
 #include <libgnomevfs/gnome-vfs-ops.h>
 #include <math.h>
 #include <stdio.h>
+#include <unistd.h>
 
 /* To work with desktop background */
 #include <X11/Xlib.h>
 #include <X11/Xatom.h>
 #include <gdk/gdkx.h>
 
+static void
+program_log (const char *format, ...)
+{
+	va_list args;
+	char *formatted, *str;
+
+	va_start (args, format);
+	formatted = g_strdup_vprintf (format, args);
+	va_end (args);
+
+	str = g_strdup_printf ("MARK: %s: %s", g_get_prgname(), formatted);
+	g_free (formatted);
+
+	access (str, F_OK);
+	g_free (str);
+}
 
 /* FIXME: This could really be eliminated now */
 typedef struct {
@@ -824,6 +841,8 @@ make_root_pixmap (GdkScreen *screen, gin
 	GdkPixmap *gdk_pixmap;
 	int screen_num;
 
+	program_log ("eel-background.c: make_root_pixmap() START");
+
 	screen_num = gdk_screen_get_number (screen);
 
 	gdk_flush ();
@@ -834,6 +853,7 @@ make_root_pixmap (GdkScreen *screen, gin
         if (display == NULL) {
                 g_warning ("Unable to open display '%s' when setting background pixmap\n",
                            (display_name) ? display_name : "NULL");
+		program_log ("eel-background.c: make_root_pixmap() END abnormally");
                 return NULL;
         }
 
@@ -855,6 +875,8 @@ make_root_pixmap (GdkScreen *screen, gin
 	gdk_drawable_set_colormap (GDK_DRAWABLE (gdk_pixmap),
 				   gdk_drawable_get_colormap (gdk_screen_get_root_window (screen)));
 
+	program_log ("eel-background.c: make_root_pixmap() END");
+
 	return gdk_pixmap;
 }
 
@@ -932,6 +954,8 @@ eel_background_ensure_realized (EelBackg
 	GtkStyle *style;
 	gboolean changed;
 
+	program_log ("eel-background.c: eel_background_ensure_realized() START");
+
 	/* Try to parse the color spec.  If we fail, default to the style's color */
 
         eel_background_ensure_image_nonswapped (background);
@@ -960,12 +984,14 @@ eel_background_ensure_realized (EelBackg
 	 */
 	if (background->details->background_pixmap != NULL &&
 	    !background->details->background_changes_with_size) {
+		program_log ("eel-background.c: eel_background_ensure_realized() END");
 		return FALSE;
 	}
 
 	/* If the window size is the same as last time, don't update */
 	if (entire_width == background->details->background_entire_width &&
 	    entire_height == background->details->background_entire_height) {
+		program_log ("eel-background.c: eel_background_ensure_realized() END");
 		return FALSE;
 	}
 
@@ -974,6 +1000,8 @@ eel_background_ensure_realized (EelBackg
 		background->details->background_pixmap = NULL;
 	}
 
+	program_log ("eel-background.c: eel_background_ensure_realized() about to draw background");
+
 	changed = FALSE;
 	if (get_pixmap_size (background, entire_width, entire_height,
 			      &pixmap_width, &pixmap_height, &background->details->background_changes_with_size)) {
@@ -999,6 +1027,8 @@ eel_background_ensure_realized (EelBackg
 	
         eel_background_start_swap (background);
 	
+	program_log ("eel-background.c: eel_background_ensure_realized() END");
+
 	return changed;
 }
 
@@ -1010,6 +1040,8 @@ eel_background_get_pixmap_and_color (Eel
 				     GdkColor      *color,
 				     gboolean      *changes_with_size)
 {
+	program_log ("eel-background.c: eel_background_get_pixmap_and_color() START");
+
 	eel_background_ensure_realized (background, window, entire_width, entire_height);
 	
 	*color = background->details->background_color;
@@ -1018,6 +1050,9 @@ eel_background_get_pixmap_and_color (Eel
 	if (background->details->background_pixmap != NULL) {
 		return g_object_ref (background->details->background_pixmap);
 	} 
+
+	program_log ("eel-background.c: eel_background_get_pixmap_and_color() END");
+
 	return NULL;
 }
 
@@ -1090,8 +1125,12 @@ eel_background_expose (GtkWidget        
 void
 eel_background_pre_draw (EelBackground *background, int entire_width, int entire_height)
 {
+	program_log ("eel-background.c: eel_background_pre_draw() START");
+
 	eel_background_ensure_image_scaled (background, entire_width, entire_height);
 	eel_background_ensure_gradient_buffered (background, entire_width, entire_height);
+
+	program_log ("eel-background.c: eel_background_pre_draw() END");
 }
 
 void
@@ -1118,6 +1157,8 @@ eel_background_draw (EelBackground *back
 	static const int PIXBUF_WIDTH = 256;
 	static const int PIXBUF_HEIGHT = 64;
 
+	program_log ("eel-background.c: eel_background_draw() START");
+
 	pixbuf = gdk_pixbuf_new (GDK_COLORSPACE_RGB, FALSE, 8, PIXBUF_WIDTH, PIXBUF_HEIGHT);
 
 	/* x & y are relative to the drawable
@@ -1142,6 +1183,8 @@ eel_background_draw (EelBackground *back
 	}
 	
 	g_object_unref (pixbuf);
+
+	program_log ("eel-background.c: eel_background_draw() END");
 }
 
 void
@@ -1743,6 +1786,8 @@ eel_background_set_up_widget (EelBackgro
 		return;
 	}
 
+	program_log ("eel-background.c: eel_background_set_up_widget() START");
+
 	gdk_drawable_get_size (widget->window, &window_width, &window_height);
 
 	/* 
@@ -1754,12 +1799,14 @@ eel_background_set_up_widget (EelBackgro
 		window_height = gdk_screen_get_height (screen);
 	}
 
+	program_log ("eel-background.c: eel_background_set_up_widget() eel_background_get_pixmap_and_color() START");
 	pixmap = eel_background_get_pixmap_and_color (background,
 						      widget->window,
 						      window_width,
 						      window_height,
 						      &color, 
 						      &changes_with_size);
+	program_log ("eel-background.c: eel_background_set_up_widget() eel_background_get_pixmap_and_color() END");
 
 	style = gtk_widget_get_style (widget);
 	
@@ -1792,6 +1839,7 @@ eel_background_set_up_widget (EelBackgro
 				      &pixmap_width, &pixmap_height, &background->details->background_changes_with_size)) {
 
       				root_pixmap = make_root_pixmap (gdk_drawable_get_screen(window), pixmap_width, pixmap_height);		
+				program_log ("eel-background.c: eel_background_set_up_widget() make_root_pixmap() END");
 
 				gc = gdk_gc_new (root_pixmap);
 				eel_background_pre_draw (background,  window_width, window_height);
@@ -1799,11 +1847,13 @@ eel_background_set_up_widget (EelBackgro
 						     0, 0, 0, 0,
 						     pixmap_width, pixmap_height);
 				g_object_unref (gc);
+				program_log ("eel-background.c: eel_background_set_up_widget() drew root pixmap");
 			}
 		}	
 		
 		if (root_pixmap != NULL) {
 			set_root_pixmap (root_pixmap, gdk_drawable_get_screen (window));
+			program_log ("eel-background.c: eel_background_set_up_widget() set root pixmap");
 			g_object_unref (root_pixmap);
 		}
 	} 	
@@ -1811,6 +1861,8 @@ eel_background_set_up_widget (EelBackgro
 	if (pixmap) {
 		g_object_unref (pixmap);
 	}
+
+	program_log ("eel-background.c: eel_background_set_up_widget() END");
 }
 
 static void
Index: eel/eel-canvas.c
===================================================================
RCS file: /cvsroot/eel/eel/eel-canvas.c,v
retrieving revision 1.1.1.1
diff -u -p -r1.1.1.1 eel-canvas.c
--- eel/eel-canvas.c	5 Apr 2007 00:56:17 -0000	1.1.1.1
+++ eel/eel-canvas.c	5 Apr 2007 01:31:53 -0000
@@ -66,6 +66,7 @@
 #include <math.h>
 #include <string.h>
 #include <stdio.h>
+#include <unistd.h>
 #include <gdk/gdkprivate.h>
 #include <gtk/gtkmain.h>
 #include <gtk/gtksignal.h>
@@ -83,6 +84,23 @@ static void group_remove                
 					 EelCanvasItem  *item);
 static void redraw_and_repick_if_mapped (EelCanvasItem *item);
 
+static void
+program_log (const char *format, ...)
+{
+	va_list args;
+	char *formatted, *str;
+
+	va_start (args, format);
+	formatted = g_strdup_vprintf (format, args);
+	va_end (args);
+
+	str = g_strdup_printf ("MARK: %s: %s", g_get_prgname(), formatted);
+	g_free (formatted);
+
+	access (str, F_OK);
+	g_free (str);
+}
+
 /*** EelCanvasItem ***/
 
 /* Some convenience stuff */
@@ -343,6 +361,8 @@ eel_canvas_item_dispose (GObject *object
 static void
 eel_canvas_item_realize (EelCanvasItem *item)
 {
+	program_log ("eel_canvas_item_realize() START");
+
 	if (item->parent && !(item->parent->object.flags & EEL_CANVAS_ITEM_REALIZED))
 		(* EEL_CANVAS_ITEM_GET_CLASS (item->parent)->realize) (item->parent);
 	
@@ -352,6 +372,8 @@ eel_canvas_item_realize (EelCanvasItem *
 	GTK_OBJECT_SET_FLAGS (item, EEL_CANVAS_ITEM_REALIZED);
 
 	eel_canvas_item_request_update (item);
+
+	program_log ("eel_canvas_item_realize() END");
 }
 
 /* Unrealize handler for canvas items */
@@ -766,24 +788,31 @@ eel_canvas_item_show (EelCanvasItem *ite
 {
 	g_return_if_fail (EEL_IS_CANVAS_ITEM (item));
 
+	program_log ("eel_canvas_item_show() START");
+
 	if (!(item->object.flags & EEL_CANVAS_ITEM_VISIBLE)) {
 		item->object.flags |= EEL_CANVAS_ITEM_VISIBLE;
 		
-		if (!(item->object.flags & EEL_CANVAS_ITEM_REALIZED))
+		if (!(item->object.flags & EEL_CANVAS_ITEM_REALIZED)) {
 			(* EEL_CANVAS_ITEM_GET_CLASS (item)->realize) (item);
+		}
 
 		if (item->parent != NULL) {
 			if (!(item->object.flags & EEL_CANVAS_ITEM_MAPPED) &&
-			    item->parent->object.flags & EEL_CANVAS_ITEM_MAPPED)
+			    item->parent->object.flags & EEL_CANVAS_ITEM_MAPPED) {
 				(* EEL_CANVAS_ITEM_GET_CLASS (item)->map) (item);
+			}
 		} else {
 			if (!(item->object.flags & EEL_CANVAS_ITEM_MAPPED) &&
-			    GTK_WIDGET_MAPPED (GTK_WIDGET (item->canvas)))
+			    GTK_WIDGET_MAPPED (GTK_WIDGET (item->canvas))) {
 				(* EEL_CANVAS_ITEM_GET_CLASS (item)->map) (item);
+			}
 		}
 
 		redraw_and_repick_if_mapped (item);
 	}
+
+	program_log ("eel_canvas_item_show() END");
 }
 
 
@@ -1090,6 +1119,8 @@ eel_canvas_item_request_update (EelCanva
 	if (item->object.flags & EEL_CANVAS_ITEM_NEED_UPDATE)
 		return;
 
+	program_log ("eel_canvas_item_request_update (%p) START", item);
+
 	item->object.flags |= EEL_CANVAS_ITEM_NEED_UPDATE;
 
 	if (item->parent != NULL) {
@@ -1099,6 +1130,8 @@ eel_canvas_item_request_update (EelCanva
 		/* Have reached the top of the tree, make sure the update call gets scheduled. */
 		eel_canvas_request_update (item->canvas);
 	}
+
+	program_log ("eel_canvas_item_request_update (%p) END", item);
 }
 
 /**
@@ -3261,7 +3294,9 @@ eel_canvas_get_item_at (EelCanvas *canva
 static void
 eel_canvas_request_update (EelCanvas *canvas)
 {
+	program_log ("eel_canvas_request_update() START");
 	EEL_CANVAS_GET_CLASS (canvas)->request_update (canvas);
+	program_log ("eel_canvas_request_update() END");
 }
 
 static void