[folks] core: Add a profiling API and implement some profiling points



commit 3deab10a238fb77a68f96fb74ce75a4f37c347a8
Author: Philip Withnall <philip tecnocode co uk>
Date:   Sun Jun 24 17:55:43 2012 +0100

    core: Add a profiling API and implement some profiling points
    
    The API outputs messages in the format accepted by Federicoâs
    plot-timeline.py (http://people.gnome.org/~federico/news-2006-03.html#timeline-tools)
    so graphs can easily be generated by running:
    
        strace -ttt -f -o /tmp/logfile folks-inspect
        python plot-timeline.py -o graph.png /tmp/logfile
    
    So far, the BackendStore, IndividualAggregator and Backend and PersonaStore
    classes for all the backends have been annotated.

 HACKING                                          |   15 +++++
 NEWS                                             |    1 +
 backends/eds/Makefile.am                         |    2 +
 backends/eds/eds-backend.vala                    |    4 +
 backends/eds/lib/edsf-persona-store.vala         |   23 +++++++
 backends/key-file/Makefile.am                    |    2 +
 backends/key-file/kf-backend.vala                |    4 +
 backends/key-file/kf-persona-store.vala          |   10 +++
 backends/libsocialweb/Makefile.am                |    2 +
 backends/libsocialweb/lib/swf-persona-store.vala |   10 +++
 backends/libsocialweb/sw-backend.vala            |    4 +
 backends/telepathy/Makefile.am                   |    2 +
 backends/telepathy/lib/tpf-persona-store.vala    |   24 +++++++-
 backends/telepathy/tp-backend.vala               |    4 +
 backends/tracker/Makefile.am                     |    2 +
 backends/tracker/lib/Makefile.am                 |    2 +
 backends/tracker/lib/trf-persona-store.vala      |   17 +++++
 backends/tracker/tr-backend.vala                 |    4 +
 configure.ac                                     |   11 +++
 folks/Makefile.am                                |    5 ++
 folks/backend-store.vala                         |   42 +++++++++++--
 folks/individual-aggregator.vala                 |   10 +++
 folks/internal.vala                              |   72 ++++++++++++++++++++++
 folks/persona-store.vala                         |    3 +
 24 files changed, 269 insertions(+), 6 deletions(-)
---
diff --git a/HACKING b/HACKING
index b25573d..6db61e0 100644
--- a/HACKING
+++ b/HACKING
@@ -127,3 +127,18 @@ hooks for each test. Simply run:
         make -C tests/<dir> <test name>.gdb
 
 Then use gdb as normal.
+
+Profiling folks
+===============
+
+Folks has various profiling points throughout its startup code, in order to be
+able to profile the startup process. In order to use this:
+ 1. Compile folks with --enable-profiling.
+ 2. strace -ttt -f -o /tmp/logfile folks-inspect # or some other folks program
+ 3. python plot-timeline.py -o output.png /tmp/logfile
+ 4. Examine output.png for obvious problems
+
+This is based on Federico Mena Quinteroâs plot-timeline.py, described on:
+http://people.gnome.org/~federico/news-2006-03.html#timeline-tools. The Python
+script itself can be downloaded from
+http://gitorious.org/projects/performance-scripts.
diff --git a/NEWS b/NEWS
index c7799c2..63a0e8d 100644
--- a/NEWS
+++ b/NEWS
@@ -9,6 +9,7 @@ Bugs fixed:
 â Bug 678474 â potential-match should be smarter with accents
 â Bug 678781 â memory leak in e-d-s backend
 â Bug 678811 â Fix eds backend unit tests
+â Bug 678734 â Add profiling API
 
 API changes:
 
diff --git a/backends/eds/Makefile.am b/backends/eds/Makefile.am
index e17c753..18a037e 100644
--- a/backends/eds/Makefile.am
+++ b/backends/eds/Makefile.am
@@ -21,6 +21,7 @@ eds_la_SOURCES = \
 
 eds_deps = \
 	folks \
+	folks-internal \
 	folks-eds \
 	gee-1.0 \
 	gio-2.0 \
@@ -55,6 +56,7 @@ eds_la_LIBADD = \
 	$(AM_LIBADD) \
 	$(top_builddir)/backends/eds/lib/libfolks-eds.la \
 	$(top_builddir)/folks/libfolks.la \
+	$(top_builddir)/folks/libfolks-internal.la \
 	$(GIO_LIBS) \
 	$(GLIB_LIBS) \
 	$(GEE_LIBS) \
diff --git a/backends/eds/eds-backend.vala b/backends/eds/eds-backend.vala
index bc1d4b1..bdf9b3b 100644
--- a/backends/eds/eds-backend.vala
+++ b/backends/eds/eds-backend.vala
@@ -99,6 +99,8 @@ public class Folks.Backends.Eds.Backend : Folks.Backend
    */
   public override async void prepare () throws GLib.Error
     {
+      Internal.profiling_start ("preparing Eds.Backend");
+
       lock (this._is_prepared)
         {
           if (this._is_prepared || this._prepare_pending)
@@ -132,6 +134,8 @@ public class Folks.Backends.Eds.Backend : Folks.Backend
               this._prepare_pending = false;
             }
         }
+
+      Internal.profiling_end ("preparing Eds.Backend");
     }
 
   /**
diff --git a/backends/eds/lib/edsf-persona-store.vala b/backends/eds/lib/edsf-persona-store.vala
index a215f3a..81814c8 100644
--- a/backends/eds/lib/edsf-persona-store.vala
+++ b/backends/eds/lib/edsf-persona-store.vala
@@ -612,6 +612,9 @@ public class Edsf.PersonaStore : Folks.PersonaStore
    */
   public override async void prepare () throws PersonaStoreError
     {
+      Internal.profiling_start ("preparing Edsf.PersonaStore (ID: %s)",
+          this.id);
+
       /* FIXME: https://bugzilla.gnome.org/show_bug.cgi?id=652637 */
       lock (this._is_prepared)
         {
@@ -629,6 +632,9 @@ public class Edsf.PersonaStore : Folks.PersonaStore
                * addressbook.open() will fail if we don't. */
               this._source_registry = yield create_source_registry ();
 
+              Internal.profiling_point ("created SourceRegistry in " +
+                  "Edsf.PersonaStore (ID: %s)", this.id);
+
               /* We know _source_registry != null because otherwise
                * create_source_registry() would've thrown an error. */
               ((!) this._source_registry).source_removed.connect (
@@ -646,6 +652,9 @@ public class Edsf.PersonaStore : Folks.PersonaStore
               debug ("Successfully finished opening address book %p for " +
                   "persona store â%sâ (%p).", this._addressbook, this.id, this);
 
+              Internal.profiling_point ("opened address book in " +
+                  "Edsf.PersonaStore (ID: %s)", this.id);
+
               this._notify_if_default ();
               this._update_trust_level ();
             }
@@ -734,6 +743,9 @@ public class Edsf.PersonaStore : Folks.PersonaStore
               yield ((!) this._addressbook).get_backend_property (
                   "supported-fields", null, out supported_fields);
 
+              Internal.profiling_point ("got supported fields in " +
+                  "Edsf.PersonaStore (ID: %s)", this.id);
+
               var prop_set = new HashSet<string> ();
 
               /* We get a comma-separated list of fields back. */
@@ -798,6 +810,9 @@ public class Edsf.PersonaStore : Folks.PersonaStore
               yield ((!) this._addressbook).get_backend_property (
                   "capabilities", null, out capabilities);
 
+              Internal.profiling_point ("got capabilities in " +
+                  "Edsf.PersonaStore (ID: %s)", this.id);
+
               if (capabilities != null)
                 {
                   string[] caps = ((!) capabilities).split (",");
@@ -825,6 +840,9 @@ public class Edsf.PersonaStore : Folks.PersonaStore
               got_view = yield ((!) this._addressbook).get_view (
                   this._query_str, null, out this._ebookview);
 
+              Internal.profiling_point ("opened book view in " +
+                  "Edsf.PersonaStore (ID: %s)", this.id);
+
               if (got_view == false)
                 {
                   throw new PersonaStoreError.INVALID_ARGUMENT (
@@ -932,6 +950,8 @@ public class Edsf.PersonaStore : Folks.PersonaStore
               this.notify_property ("is-quiescent");
             }
         }
+
+      Internal.profiling_end ("preparing Edsf.PersonaStore");
     }
 
   /* Temporaries for _open_address_book(). See the complaint below. */
@@ -2098,6 +2118,9 @@ public class Edsf.PersonaStore : Folks.PersonaStore
           warning ("Error in address book view query: %s", err.message);
         }
 
+      Internal.profiling_point ("initial query complete in " +
+          "Edsf.PersonaStore (ID: %s)", this.id);
+
       /* The initial query is complete, so signal that we've reached
        * quiescence (even if there was an error). */
       if (this._is_quiescent == false)
diff --git a/backends/key-file/Makefile.am b/backends/key-file/Makefile.am
index 0a10ba7..0e359c8 100644
--- a/backends/key-file/Makefile.am
+++ b/backends/key-file/Makefile.am
@@ -16,6 +16,7 @@ key_file_la_VALAFLAGS = \
 	--vapidir=. \
 	--vapidir=$(top_srcdir)/folks \
 	--pkg folks \
+	--pkg folks-internal \
 	--pkg gee-1.0 \
 	--pkg gio-2.0 \
 	--pkg gobject-2.0 \
@@ -43,6 +44,7 @@ key_file_la_LIBADD = \
 	$(GLIB_LIBS) \
 	$(GEE_LIBS) \
 	$(top_builddir)/folks/libfolks.la \
+	$(top_builddir)/folks/libfolks-internal.la \
 	$(NULL)
 
 key_file_la_LDFLAGS = \
diff --git a/backends/key-file/kf-backend.vala b/backends/key-file/kf-backend.vala
index 912c176..405aef3 100644
--- a/backends/key-file/kf-backend.vala
+++ b/backends/key-file/kf-backend.vala
@@ -96,6 +96,8 @@ public class Folks.Backends.Kf.Backend : Folks.Backend
    */
   public override async void prepare () throws GLib.Error
     {
+      Internal.profiling_start ("preparing Kf.Backend");
+
       lock (this._is_prepared)
         {
           if (this._is_prepared || this._prepare_pending)
@@ -148,6 +150,8 @@ public class Folks.Backends.Kf.Backend : Folks.Backend
               this._prepare_pending = false;
             }
         }
+
+      Internal.profiling_end ("preparing Kf.Backend");
     }
 
   /**
diff --git a/backends/key-file/kf-persona-store.vala b/backends/key-file/kf-persona-store.vala
index bbddf57..2e3c268 100644
--- a/backends/key-file/kf-persona-store.vala
+++ b/backends/key-file/kf-persona-store.vala
@@ -178,6 +178,8 @@ public class Folks.Backends.Kf.PersonaStore : Folks.PersonaStore
    */
   public override async void prepare ()
     {
+      Internal.profiling_start ("preparing Kf.PersonaStore (ID: %s)", this.id);
+
       lock (this._is_prepared)
         {
           if (this._is_prepared || this._prepare_pending)
@@ -206,11 +208,17 @@ public class Folks.Backends.Kf.PersonaStore : Folks.PersonaStore
                           null);
                       unowned string contents_s = (string) contents;
 
+                      Internal.profiling_point ("loaded file in " +
+                          "Kf.PersonaStore (ID: %s)", this.id);
+
                       if (contents_s.length > 0)
                         {
                           this._key_file.load_from_data (contents_s,
                               contents_s.length,
                               KeyFileFlags.KEEP_COMMENTS);
+
+                          Internal.profiling_point ("parsed data in " +
+                              "Kf.PersonaStore (ID: %s)", this.id);
                         }
                       break;
                     }
@@ -306,6 +314,8 @@ public class Folks.Backends.Kf.PersonaStore : Folks.PersonaStore
               this._prepare_pending = false;
             }
         }
+
+      Internal.profiling_end ("preparing Kf.PersonaStore (ID: %s)", this.id);
     }
 
   /**
diff --git a/backends/libsocialweb/Makefile.am b/backends/libsocialweb/Makefile.am
index 83f096a..65fc1b9 100644
--- a/backends/libsocialweb/Makefile.am
+++ b/backends/libsocialweb/Makefile.am
@@ -21,6 +21,7 @@ libsocialweb_la_SOURCES = \
 
 libsocialweb_deps = \
 	folks \
+	folks-internal \
 	folks-libsocialweb \
 	gee-1.0 \
 	gio-2.0 \
@@ -53,6 +54,7 @@ libsocialweb_la_LIBADD = \
 	$(GLIB_LIBS) \
 	$(GEE_LIBS) \
 	$(top_builddir)/folks/libfolks.la \
+	$(top_builddir)/folks/libfolks-internal.la \
 	$(SW_CLIENT_LIBS) \
 	lib/libfolks-libsocialweb.la \
 	$(NULL)
diff --git a/backends/libsocialweb/lib/swf-persona-store.vala b/backends/libsocialweb/lib/swf-persona-store.vala
index e8736ef..8cc53be 100644
--- a/backends/libsocialweb/lib/swf-persona-store.vala
+++ b/backends/libsocialweb/lib/swf-persona-store.vala
@@ -316,6 +316,8 @@ public class Swf.PersonaStore : Folks.PersonaStore
    */
   public override async void prepare () throws GLib.Error
     {
+      Internal.profiling_start ("preparing Swf.PersonaStore (ID: %s)", this.id);
+
       lock (this._is_prepared)
         {
           if (!this._is_prepared && !this._prepare_pending)
@@ -329,6 +331,9 @@ public class Swf.PersonaStore : Folks.PersonaStore
                 {
                   caps = yield this._get_static_capabilities ();
 
+                  Internal.profiling_point ("got capabilities in " +
+                      "Swf.PersonaStore (ID: %s)", this.id);
+
                   if (caps == null)
                     {
                       throw new PersonaStoreError.INVALID_ARGUMENT (
@@ -366,6 +371,9 @@ public class Swf.PersonaStore : Folks.PersonaStore
                   new HashTable<weak string, weak string> (str_hash,
                       str_equal));
 
+              Internal.profiling_point ("opened view in Swf.PersonaStore " +
+                  "(ID: %s)", this.id);
+
               /* Propagate errors from the contacts_query_open_view()
                * callback. */
               if (contact_view == null)
@@ -406,6 +414,8 @@ public class Swf.PersonaStore : Folks.PersonaStore
               this._contact_view.start ();
             }
         }
+
+      Internal.profiling_end ("preparing Swf.PersonaStore (ID: %s)", this.id);
     }
 
   private void contacts_added_cb (GLib.List<unowned Contact> contacts)
diff --git a/backends/libsocialweb/sw-backend.vala b/backends/libsocialweb/sw-backend.vala
index e85dc67..bbb3ff1 100644
--- a/backends/libsocialweb/sw-backend.vala
+++ b/backends/libsocialweb/sw-backend.vala
@@ -95,6 +95,8 @@ public class Folks.Backends.Sw.Backend : Folks.Backend
    */
   public override async void prepare () throws GLib.Error
     {
+      Internal.profiling_start ("preparing Sw.Backend");
+
       lock (this._is_prepared)
         {
           if (!this._is_prepared && !this._prepare_pending)
@@ -123,6 +125,8 @@ public class Folks.Backends.Sw.Backend : Folks.Backend
                 });
             }
         }
+
+      Internal.profiling_end ("preparing Sw.Backend");
     }
 
   /**
diff --git a/backends/telepathy/Makefile.am b/backends/telepathy/Makefile.am
index c2826e1..95932e6 100644
--- a/backends/telepathy/Makefile.am
+++ b/backends/telepathy/Makefile.am
@@ -21,6 +21,7 @@ telepathy_la_SOURCES = \
 
 telepathy_deps = \
 	folks \
+	folks-internal \
 	folks-telepathy \
 	gee-1.0 \
 	gio-2.0 \
@@ -53,6 +54,7 @@ telepathy_la_LIBADD = \
 	$(GLIB_LIBS) \
 	$(GEE_LIBS) \
 	$(top_builddir)/folks/libfolks.la \
+	$(top_builddir)/folks/libfolks-internal.la \
 	$(TP_GLIB_LIBS) \
 	lib/libfolks-telepathy.la \
 	$(NULL)
diff --git a/backends/telepathy/lib/tpf-persona-store.vala b/backends/telepathy/lib/tpf-persona-store.vala
index a0089b0..6e667db 100644
--- a/backends/telepathy/lib/tpf-persona-store.vala
+++ b/backends/telepathy/lib/tpf-persona-store.vala
@@ -425,6 +425,8 @@ public class Tpf.PersonaStore : Folks.PersonaStore
    */
   public override async void prepare () throws GLib.Error
     {
+      Internal.profiling_start ("preparing Tpf.PersonaStore (ID: %s)", this.id);
+
       lock (this._is_prepared)
         {
           if (this._is_prepared || this._prepare_pending)
@@ -489,18 +491,24 @@ public class Tpf.PersonaStore : Folks.PersonaStore
                     }
                 });
 
+              Internal.profiling_point ("created account manager in " +
+                  "Tpf.PersonaStore (ID: %s)", this.id);
+
               this._favourite_ids.clear ();
               this._logger = new Logger (this.id);
               this._logger.invalidated.connect (
                   this._logger_invalidated_cb);
               this._logger.favourite_contacts_changed.connect (
                   this._favourite_contacts_changed_cb);
+              Internal.profiling_start ("initialising favourite contacts in " +
+                  "Tpf.PersonaStore (ID: %s)", this.id);
               this._initialise_favourite_contacts.begin ((o, r) =>
                 {
-                  debug ("FAVOURITE INIT DONE");
                   try
                     {
                       this._initialise_favourite_contacts.end (r);
+                      Internal.profiling_end ("initialising favourite " +
+                          "contacts in Tpf.PersonaStore (ID: %s)", this.id);
                     }
                   catch (GLib.Error e)
                     {
@@ -510,6 +518,9 @@ public class Tpf.PersonaStore : Folks.PersonaStore
                     }
                 });
 
+              Internal.profiling_point ("created logger in Tpf.PersonaStore " +
+                  "(ID: %s)", this.id);
+
               this.account.notify["connection"].connect (
                   this._notify_connection_cb);
 
@@ -527,6 +538,9 @@ public class Tpf.PersonaStore : Folks.PersonaStore
                   this._force_quiescent ();
                 }
 
+              Internal.profiling_point ("loaded cache in Tpf.PersonaStore " +
+                  "(ID: %s)", this.id);
+
               this._is_prepared = true;
               this.notify_property ("is-prepared");
             }
@@ -535,6 +549,8 @@ public class Tpf.PersonaStore : Folks.PersonaStore
               this._prepare_pending = false;
             }
         }
+
+      Internal.profiling_end ("preparing Tpf.PersonaStore (ID: %s)", this.id);
     }
 
   private void _account_manager_invalidated_cb (uint domain, int code,
@@ -678,6 +694,9 @@ public class Tpf.PersonaStore : Folks.PersonaStore
       debug ("_notify_connection_cb_async() for Tpf.PersonaStore %p ('%s').",
           this, this.id);
 
+      Internal.profiling_start ("notify connection for Tpf.PersonaStore " +
+          "(ID: %s)", this.id);
+
       /* Ensure the connection is prepared as necessary. */
       yield this.account.connection.prepare_async ({
           TelepathyGLib.Connection.get_feature_quark_contact_list (),
@@ -774,6 +793,9 @@ public class Tpf.PersonaStore : Folks.PersonaStore
 
       this._conn.notify["contact-list-state"].connect (this._contact_list_state_changed_cb);
       this._contact_list_state_changed_cb (this._conn, null);
+
+      Internal.profiling_end ("notify connection for Tpf.PersonaStore " +
+          "(ID: %s)", this.id);
     }
 
   private void _marshall_supported_fields ()
diff --git a/backends/telepathy/tp-backend.vala b/backends/telepathy/tp-backend.vala
index 5e03949..e0a3293 100644
--- a/backends/telepathy/tp-backend.vala
+++ b/backends/telepathy/tp-backend.vala
@@ -87,6 +87,8 @@ public class Folks.Backends.Tp.Backend : Folks.Backend
    */
   public override async void prepare () throws GLib.Error
     {
+      Internal.profiling_start ("preparing Tp.Backend");
+
       lock (this._is_prepared)
         {
           if (this._is_prepared || this._prepare_pending)
@@ -121,6 +123,8 @@ public class Folks.Backends.Tp.Backend : Folks.Backend
               this._prepare_pending = false;
             }
         }
+
+      Internal.profiling_end ("preparing Tp.Backend");
     }
 
   /**
diff --git a/backends/tracker/Makefile.am b/backends/tracker/Makefile.am
index 88aa79a..e99c34c 100644
--- a/backends/tracker/Makefile.am
+++ b/backends/tracker/Makefile.am
@@ -22,6 +22,7 @@ tracker_la_SOURCES = \
 
 tracker_deps = \
 	folks \
+	folks-internal \
 	folks-tracker \
 	gee-1.0 \
 	gio-2.0 \
@@ -54,6 +55,7 @@ tracker_la_LIBADD = \
 	$(GLIB_LIBS) \
 	$(GEE_LIBS) \
 	$(top_builddir)/folks/libfolks.la \
+	$(top_builddir)/folks/libfolks-internal.la \
 	$(TRACKER_SPARQL_LIBS) \
 	$(top_builddir)/backends/tracker/lib/libfolks-tracker.la \
 	$(NULL)
diff --git a/backends/tracker/lib/Makefile.am b/backends/tracker/lib/Makefile.am
index fab3218..c43885b 100644
--- a/backends/tracker/lib/Makefile.am
+++ b/backends/tracker/lib/Makefile.am
@@ -25,6 +25,7 @@ libfolks_tracker_la_VALAFLAGS = \
 	--vapidir=. \
 	--vapidir=$(top_srcdir)/folks \
 	--pkg folks \
+	--pkg folks-internal \
 	--pkg gobject-2.0 \
 	--pkg gio-2.0 \
 	--pkg gee-1.0 \
@@ -65,6 +66,7 @@ libfolks_tracker_la_LIBADD = \
 	$(GLIB_LIBS) \
 	$(GEE_LIBS) \
 	$(top_builddir)/folks/libfolks.la \
+	$(top_builddir)/folks/libfolks-internal.la \
 	$(TRACKER_SPARQL_LIBS) \
 	$(NULL)
 
diff --git a/backends/tracker/lib/trf-persona-store.vala b/backends/tracker/lib/trf-persona-store.vala
index 2441bfb..1972fe1 100644
--- a/backends/tracker/lib/trf-persona-store.vala
+++ b/backends/tracker/lib/trf-persona-store.vala
@@ -1067,6 +1067,8 @@ public class Trf.PersonaStore : Folks.PersonaStore
    */
   public override async void prepare () throws GLib.Error
     {
+      Internal.profiling_start ("preparing Trf.PersonaStore (ID: %s)", this.id);
+
       lock (this._is_prepared)
         {
           if (this._is_prepared || this._prepare_pending)
@@ -1083,9 +1085,19 @@ public class Trf.PersonaStore : Folks.PersonaStore
                   this._connection =
                     yield Tracker.Sparql.Connection.get_async ();
 
+                  Internal.profiling_point ("got connection in " +
+                      "Trf.PersonaStore (ID: %s)", this.id);
+
                   yield this._build_predicates_table ();
+
+                  Internal.profiling_point ("build predicates table in " +
+                      "Trf.PersonaStore (ID: %s)", this.id);
+
                   yield this._do_add_contacts (this._INITIAL_QUERY.printf (""));
 
+                  Internal.profiling_point ("added contacts in " +
+                      "Trf.PersonaStore (ID: %s)", this.id);
+
                   /* Don't add a match rule for all signals from Tracker but
                    * only for GraphUpdated with the specific class we need. We
                    * don't want to be woken up for irrelevent updates on the
@@ -1103,6 +1115,9 @@ public class Trf.PersonaStore : Folks.PersonaStore
                       Trf.OntologyDefs.PERSON_CLASS, GLib.DBusSignalFlags.NONE,
                       this._graph_updated_cb);
 
+                  Internal.profiling_point ("got resources proxy in " +
+                      "Trf.PersonaStore (ID: %s)", this.id);
+
                   this._is_prepared = true;
                   this.notify_property ("is-prepared");
 
@@ -1138,6 +1153,8 @@ public class Trf.PersonaStore : Folks.PersonaStore
               this._prepare_pending = false;
             }
         }
+
+      Internal.profiling_end ("preparing Trf.PersonaStore (ID: %s)", this.id);
     }
 
   public int get_favorite_id ()
diff --git a/backends/tracker/tr-backend.vala b/backends/tracker/tr-backend.vala
index 996e2a6..5cbdc2b 100644
--- a/backends/tracker/tr-backend.vala
+++ b/backends/tracker/tr-backend.vala
@@ -93,6 +93,8 @@ public class Folks.Backends.Tr.Backend : Folks.Backend
    */
   public override async void prepare () throws GLib.Error
     {
+      Internal.profiling_start ("preparing Tr.Backend");
+
       lock (this._is_prepared)
         {
           if (this._is_prepared || this._prepare_pending)
@@ -117,6 +119,8 @@ public class Folks.Backends.Tr.Backend : Folks.Backend
               this._prepare_pending = false;
             }
         }
+
+      Internal.profiling_end ("preparing Tr.Backend");
     }
 
   /**
diff --git a/configure.ac b/configure.ac
index d1ee61d..8d44bcd 100644
--- a/configure.ac
+++ b/configure.ac
@@ -512,6 +512,17 @@ AC_SUBST([ERROR_INTROSPECTION_SCANNER_ARGS])
 AC_SUBST([ERROR_VALAFLAGS])
 
 # -----------------------------------------------------------
+# Profiling
+# -----------------------------------------------------------
+
+AC_ARG_ENABLE([profiling],
+              AS_HELP_STRING([--enable-profiling],
+                             [Enable building profiling points]),
+              [enable_profiling=$enableval],
+              [enable_profiling=no])
+AM_CONDITIONAL([ENABLE_PROFILING], [test "$enable_profiling" = "yes"])
+
+# -----------------------------------------------------------
 # Final output
 # -----------------------------------------------------------
 
diff --git a/folks/Makefile.am b/folks/Makefile.am
index 336efd9..4bcc042 100644
--- a/folks/Makefile.am
+++ b/folks/Makefile.am
@@ -24,10 +24,15 @@ libfolks_internal_la_VALAFLAGS = \
 	--library=folks-internal \
 	--vapidir=. \
 	--pkg gobject-2.0 \
+	--pkg gio-2.0 \
 	--pkg gee-1.0 \
+	--pkg posix \
 	--vapi folks-internal.vapi \
 	-H folks-internal.h \
 	$(NULL)
+if ENABLE_PROFILING
+libfolks_internal_la_VALAFLAGS += --define=ENABLE_PROFILING
+endif
 
 libfolks_internal_la_CFLAGS = \
 	$(AM_CFLAGS) \
diff --git a/folks/backend-store.vala b/folks/backend-store.vala
index cad02fe..0f08de7 100644
--- a/folks/backend-store.vala
+++ b/folks/backend-store.vala
@@ -254,14 +254,18 @@ public class Folks.BackendStore : Object {
    */
   public async void prepare ()
     {
+      Internal.profiling_start ("preparing BackendStore");
+
       /* (re-)load the list of disabled backends */
       yield this._load_disabled_backend_names ();
 
-      if (this._is_prepared == true)
-        return;
-      this._is_prepared = true;
+      if (this._is_prepared == false)
+        {
+          this._is_prepared = true;
+          this.notify_property ("is-prepared");
+        }
 
-      this.notify_property ("is-prepared");
+      Internal.profiling_end ("preparing BackendStore");
     }
 
   /**
@@ -277,6 +281,8 @@ public class Folks.BackendStore : Object {
     {
       assert (Module.supported());
 
+      Internal.profiling_start ("loading backends in BackendStore");
+
       yield this.prepare ();
 
       /* unload backends that have been disabled since they were loaded */
@@ -285,6 +291,8 @@ public class Folks.BackendStore : Object {
           yield this._backend_unload_if_needed (backend_existing);
         }
 
+      Internal.profiling_point ("unloaded backends in BackendStore");
+
       string? _path = Environment.get_variable ("FOLKS_BACKEND_PATH");
       string path;
 
@@ -336,15 +344,39 @@ public class Folks.BackendStore : Object {
             }
         }
 
+      Internal.profiling_point ("found modules in BackendStore");
+
       /* this will load any new modules found in the backends dir and will
        * prepare and unprepare backends such that they match the state in the
        * backend store key file */
       foreach (var module in modules.values)
         this._load_module_from_file (module);
 
+      Internal.profiling_point ("loaded modules in BackendStore");
+
       /* this is populated indirectly from _load_module_from_file(), above */
+      var backends_remaining = 1;
       foreach (var backend in this._backend_hash.values)
-        yield this._backend_load_if_needed (backend);
+        {
+          backends_remaining++;
+          this._backend_load_if_needed.begin (backend, (o, r) =>
+            {
+              this._backend_load_if_needed.end (r);
+              backends_remaining--;
+
+              if (backends_remaining == 0)
+                {
+                  this.load_backends.callback ();
+                }
+            });
+        }
+      backends_remaining--;
+      if (backends_remaining > 0)
+        {
+          yield;
+        }
+
+      Internal.profiling_end ("loading backends in BackendStore");
     }
 
   private async void _backend_load_if_needed (Backend backend)
diff --git a/folks/individual-aggregator.vala b/folks/individual-aggregator.vala
index 9cec0fb..91fa813 100644
--- a/folks/individual-aggregator.vala
+++ b/folks/individual-aggregator.vala
@@ -496,6 +496,8 @@ public class Folks.IndividualAggregator : Object
    */
   public async void prepare () throws GLib.Error
     {
+      Internal.profiling_start ("preparing IndividualAggregator");
+
       /* Once this async function returns, all the { link Backend}s will have
        * been prepared (though no { link PersonaStore}s are guaranteed to be
        * available yet). This last guarantee is new as of version 0.2.0. */
@@ -544,6 +546,8 @@ public class Folks.IndividualAggregator : Object
               this._prepare_pending = false;
             }
         }
+
+      Internal.profiling_end ("preparing IndividualAggregator");
     }
 
   /**
@@ -867,6 +871,9 @@ public class Folks.IndividualAggregator : Object
           return;
         }
 
+      Internal.profiling_point ("emitting " +
+          "IndividualAggregator::individuals-changed");
+
       _added = (added != null) ? (!) added : new HashSet<Individual> ();
       _removed = (removed != null) ? (!) removed : new HashSet<Individual> ();
 
@@ -1475,6 +1482,9 @@ public class Folks.IndividualAggregator : Object
                   this._configured_primary_store_id);
             }
 
+          Internal.profiling_point ("reached quiescence in " +
+              "IndividualAggregator");
+
           this._is_quiescent = true;
           this.notify_property ("is-quiescent");
 
diff --git a/folks/internal.vala b/folks/internal.vala
index 41cf7f2..78866ab 100644
--- a/folks/internal.vala
+++ b/folks/internal.vala
@@ -18,7 +18,9 @@
  *       Raul Gutierrez Segales <raul gutierrez segales collabora co uk>
  */
 
+using GLib;
 using Gee;
+using Posix;
 
 namespace Folks.Internal
 {
@@ -35,4 +37,74 @@ namespace Folks.Internal
 
       return true;
     }
+
+#if ENABLE_PROFILING
+  /* See: http://people.gnome.org/~federico/news-2006-03.html#timeline-tools */
+  private static void profiling_markv (string format, va_list args)
+    {
+      var formatted = format.vprintf (args);
+      var str = "MARK: %s-%p: %s".printf (Environment.get_prgname (), Thread.self<void> (), formatted);
+      access (str, F_OK);
+    }
+#endif
+
+  /**
+   * Emit a profiling point.
+   *
+   * This emits a profiling point with the given message (printf-style), which
+   * can be picked up by profiling tools and timing information extracted.
+   *
+   * @param format printf-style message format
+   * @param ... message arguments
+   * @since UNRELEASED
+   */
+  public static void profiling_point (string format, ...)
+    {
+#if ENABLE_PROFILING
+      var args = va_list ();
+      Internal.profiling_markv (format, args);
+#endif
+    }
+
+  /**
+   * Start a profiling block.
+   *
+   * This emits a profiling start point with the given message (printf-style),
+   * which can be picked up by profiling tools and timing information extracted.
+   *
+   * This is typically used in a pair with { link Internal.profiling_end} to
+   * delimit blocks of processing which need timing.
+   *
+   * @param format printf-style message format
+   * @param ... message arguments
+   * @since UNRELEASED
+   */
+  public static void profiling_start (string format, ...)
+    {
+#if ENABLE_PROFILING
+      var args = va_list ();
+      Internal.profiling_markv ("START: " + format, args);
+#endif
+    }
+
+  /**
+   * End a profiling block.
+   *
+   * This emits a profiling end point with the given message (printf-style),
+   * which can be picked up by profiling tools and timing information extracted.
+   *
+   * This is typically used in a pair with { link Internal.profiling_start} to
+   * delimit blocks of processing which need timing.
+   *
+   * @param format printf-style message format
+   * @param ... message arguments
+   * @since UNRELEASED
+   */
+  public static void profiling_end (string format, ...)
+    {
+#if ENABLE_PROFILING
+      var args = va_list ();
+      Internal.profiling_markv ("END: " + format, args);
+#endif
+    }
 }
diff --git a/folks/persona-store.vala b/folks/persona-store.vala
index 6fa0130..7019cde 100644
--- a/folks/persona-store.vala
+++ b/folks/persona-store.vala
@@ -423,6 +423,9 @@ public abstract class Folks.PersonaStore : Object
           _removed = new HashSet<Persona> ();
         }
 
+      Internal.profiling_point ("emitting PersonaStore::personas-changed " +
+          "(ID: %s)", this.id);
+
       // We've now guaranteed that both _added and _removed are non-null.
       this.personas_changed (((!) _added).read_only_view,
           ((!) _removed).read_only_view, message, actor, reason);



[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]