From: Philip Withnall Date: Sun, 24 Jun 2012 16:55:43 +0000 (+0100) Subject: core: Add a profiling API and implement some profiling points X-Git-Tag: FOLKS_0_7_2~12 X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=3deab10a238fb77a68f96fb74ce75a4f37c347a8;p=platform%2Fupstream%2Ffolks.git 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. --- 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/ .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 (); /* 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 (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 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 (); _removed = (removed != null) ? (!) removed : new HashSet (); @@ -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 */ +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 (), 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 (); } + 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);