Commit 3deab10a authored by Philip Withnall's avatar Philip Withnall
Browse files

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.
parent 93d2f1b9
......@@ -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.
......@@ -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:
......
......@@ -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) \
......
......@@ -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");
}
/**
......
......@@ -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)
......
......@@ -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 = \
......
......@@ -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");
}
/**
......
......@@ -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);
}
/**
......
......@@ -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)
......
......@@ -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)
......
......@@ -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");
}
/**
......
......@@ -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)
......
......@@ -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 ()
......
......@@ -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");
}
/**
......
......@@ -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)
......
......@@ -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)
......
......@@ -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 ()
......
......@@ -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");
}
/**
......
......@@ -511,6 +511,17 @@ m4_if(folks_released, [1], [],
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
# -----------------------------------------------------------
......
......@@ -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) \
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment