Add initial infrastructure for Profiling

The EosProfileProbe API allows defining profiling probes that can be
used to efficiently measure the time spent in a critical section.

The Profiling API is meant to collect samples and generate a report
at the end of the lifetime of the process, either by printing out the
results once the process terminates; or by saving the raw data in a
binary file that can be loaded at a later date.

This profiling API is meant to be as close as possible to a zero cost
abstraction:

 - probes are only allocated if profiling is enabled
 - all profiling API is a no-op if profiling isn't enabled
 - the C API is meant to be easily tied to a scope, through the
   use of auto-cleanup macros provided by GLib

This allows projects using the Endless SDK to keep the profiling probes
in place, instead of conditionally compile them in.

https://phabricator.endlessm.com/T18514

1 files changed, 610 insertions, 0 deletions

diff --git a/endless/eosprofile.c b/endless/eosprofile.c
new file mode 100644
index 0000000..1f104d9
--- /dev/null
+++ b/endless/eosprofile.c
@@ -0,0 +1,610 @@
+/* Copyright 2017 Endless Mobile, Inc. */
+
+#include "config.h"
+
+#include "eosprofile-private.h"
+
+#include <stdlib.h>
+#include <string.h>
+#include <sys/types.h>
+#include <unistd.h>
+#include <termios.h>
+#include <fcntl.h>
+#include <sys/ioctl.h>
+#include <math.h>
+
+#include "gvdb/gvdb-builder.h"
+
+/**
+ * SECTION:profiling
+ * @Title: Profiling
+ * @Short_description: Profiling tools for applications
+ *
+ * The profiling API provided by the Endless SDK is a simple tool for defining
+ * profiling probes and collecting data over multiple calls.
+ *
+ * ### Enabling profiling
+ *
+ * Profile probes try to be as close to zero-cost as possible; they are only
+ * enabled if the `EOS_PROFILE` environment variable is set. This means that
+ * you can leave the profile probes in your code, and they will be inert until
+ * the environment is set up for profiling.
+ *
+ * ### Using profiling probes
+ *
+ * Typically, you want to declare a profiling probe at the beginning of the
+ * section of the code you wish to measure, and stop it at the end.
+ *
+ * The profiling probes are identified by a unique name, typically expressed
+ * as a path, like `/com/example/ExampleProbe`; this allows creating a tree of
+ * probes.
+ *
+ * If you are using the C API and a GCC-compatible compiler, you will want to
+ * use the `g_autoptr()` macro to declare the profiling probe, and have it
+ * automatically collected at the end of the scope, for instance:
+ *
+ * |[<!-- language="C" -->
+ * static void
+ * some_function (SomeObject *obj)
+ * {
+ *   some_set_up (obj);
+ *
+ *   // Here begins the section we wish to profile
+ *   g_autoptr(EosProfileProbe) outer = EOS_PROFILE ("/com/example/some-function");
+ *
+ *   some_expensive_computation (obj);
+ *   some_additional_work (obj);
+ *
+ *   if (some_state (obj))
+ *     {
+ *       g_autoptr(EosProfileProbe) inner = EOS_PROFILE ("/com/example/some-function/state");
+ *
+ *       some_more_computation (obj);
+ *     }
+ * }
+ * ]|
+ *
+ * In the example above, the `outer` probe is created after we performed some
+ * operation; since we are not interested into its cost, we are going to
+ * ignore it. Additionally, the `inner` probe is created conditionally on some
+ * state, so we can also gather information on the actual number of times the
+ * inner function is called. In either cases, both the `outer` and `inner`
+ * probes are automatically stopped once they get out of scope.
+ *
+ * ### Capturing profiling data
+ *
+ * By default, when the `EOS_PROFILE` environment variable is set, you will
+ * get a summary at the end of the process, sent to the standard output.
+ *
+ * It is also possible to redirect the profiling data to a capture file, by
+ * setting the `EOS_PROFILE` environment variable to the `capture` value. In
+ * that case, the profiling data will be stored in a binary format at the
+ * end of the process, and you can use the `eos-profile` tool to extract the
+ * probes, timings, and generate a summary. The default filename for the
+ * captured data is based on the name of the binary and the process ID, and
+ * it's saved under the `$XDG_CACHE_HOME` directory (see: g_get_user_cache_dir()).
+ *
+ * You can also specify the name of the capture file, by setting the
+ * `EOS_PROFILE` environment variable to `capture:/path/to/file`.
+ */
+
+static int
+sample_compare (gconstpointer a,
+                gconstpointer b)
+{
+  const ProfileSample *sample_a = a;
+  const ProfileSample *sample_b = b;
+
+  /* Times are monotonic, so this is always positive */
+  gint64 delta_a = sample_a->end_time - sample_a->start_time;
+  gint64 delta_b = sample_b->end_time - sample_b->start_time;
+
+  if (delta_a < delta_b)
+    return -1;
+
+  if (delta_a > delta_b)
+    return 1;
+
+  return 0;
+}
+
+#define N_SAMPLES       64
+
+struct _EosProfileProbe {
+  volatile int ref_count;
+
+  char *file;
+  gint32 line;
+  char *function;
+  char *name;
+
+  GArray *samples;
+
+  GMutex probe_lock;
+};
+
+static EosProfileProbe eos_profile_dummy_probe;
+
+static EosProfileProbe *
+eos_profile_probe_new (const char *file,
+                       gsize       line,
+                       const char *function,
+                       const char *name)
+{
+  EosProfileProbe *res = g_new0 (EosProfileProbe, 1);
+
+  res->ref_count = 1;
+
+  res->name = g_strdup (name);
+  res->function = g_strdup (function);
+  res->file = g_strdup (file);
+  res->line = line;
+
+  res->samples = g_array_sized_new (FALSE, FALSE, sizeof (ProfileSample), N_SAMPLES);
+
+  g_mutex_init (&res->probe_lock);
+
+  return res;
+}
+
+static void
+eos_profile_probe_destroy (gpointer data)
+{
+  EosProfileProbe *probe = data;
+
+  g_hash_table_remove (profile_state->probes, probe->name);
+
+  g_array_unref (probe->samples);
+  g_free (probe->name);
+  g_free (probe->function);
+  g_free (probe->file);
+
+  g_free (probe);
+}
+
+static EosProfileProbe *
+eos_profile_probe_copy (EosProfileProbe *probe)
+{
+  return probe;
+}
+
+static void
+eos_profile_probe_free (EosProfileProbe *probe)
+{
+  /* no-op */
+}
+
+G_DEFINE_BOXED_TYPE (EosProfileProbe, eos_profile_probe,
+                     eos_profile_probe_copy,
+                     eos_profile_probe_free)
+
+/**
+ * eos_profile_probe_start:
+ * @file: the source file for the probe, typically represented by %__FILE__
+ * @line: the line in the source @file, typically represented by %__LINE__
+ * @function: the function for the probe, typically represented by %G_STRFUNC
+ * @name: a unique name for the probe
+ *
+ * Starts a profiling probe for @name, creating it if necessary.
+ *
+ * Returns: (transfer none): a profile probe identifier; use eos_profile_probe_stop()
+ *   to stop the profiling on the returned probe
+ *
+ * Since: 0.6
+ */
+EosProfileProbe *
+eos_profile_probe_start (const char *file,
+                         gsize       line,
+                         const char *function,
+                         const char *name)
+{
+  /* Don't measure the lock */
+  gint64 sample_time = g_get_monotonic_time ();
+
+  /* We can take this out of the lock because by the time we reach
+   * eos_profile_probe_stop() the profile state is guaranteed to
+   * either always exist, or not
+   */
+  if (profile_state == NULL)
+    return &eos_profile_dummy_probe;
+
+  G_LOCK (profile_state);
+
+  EosProfileProbe *res = g_hash_table_lookup (profile_state->probes, name);
+  if (res == NULL)
+    {
+      res = eos_profile_probe_new (file, line, function, name);
+
+      g_hash_table_insert (profile_state->probes, res->name, res);
+    }
+
+  g_array_append_vals (res->samples,
+                       &(ProfileSample) {
+                         .start_time = sample_time,
+                         .end_time = -1
+                       },
+                       1);
+
+  G_UNLOCK (profile_state);
+
+  return (EosProfileProbe *) res;
+}
+
+/**
+ * eos_profile_probe_stop:
+ * @probe: a #EosProfileProbe
+ *
+ * Stops a profiling probe started using eos_profile_probe_start().
+ *
+ * Since: 0.6
+ */
+void
+eos_profile_probe_stop (EosProfileProbe *probe)
+{
+  if (probe == &eos_profile_dummy_probe)
+    return;
+
+  /* Don't measure the lock */
+  gint64 sample_time = g_get_monotonic_time ();
+
+  g_autoptr(GMutexLocker) locker = g_mutex_locker_new (&probe->probe_lock);
+
+  /* Ideally, we just want to update the sample we just created, which means
+   * picking the last slot in the samples array; in practice, this is what
+   * should happen most of the time, unless we end up recursing. In that case
+   * we end up with creating a sample while the outer sample is still in
+   * flight.
+   *
+   * If we just recorded the inner samples, we'd end up with a skewed capture,
+   * as those samples would inevitably be masking the timing of the outer
+   * samples.
+   *
+   * The easiest approach is to discard the inner samples until we reach the
+   * outermost live sample
+   */
+  int first_in_flight = probe->samples->len - 1;
+  for (int i = probe->samples->len - 1; i >= 0; i--)
+    {
+      const ProfileSample *sample = &g_array_index (probe->samples, ProfileSample, i);
+
+      if (sample->end_time > 0)
+        break;
+
+      first_in_flight = i;
+    }
+
+  ProfileSample *sample = &g_array_index (probe->samples, ProfileSample, first_in_flight);
+
+  sample->end_time = sample_time;
+
+  if (first_in_flight != probe->samples->len - 1)
+    {
+      int range = probe->samples->len - first_in_flight - 1;
+
+      g_array_remove_range (probe->samples, first_in_flight + 1, range);
+    }
+}
+
+void
+eos_profile_state_init (void)
+{
+  static gboolean profile_state_inited;
+
+  if (profile_state_inited)
+    return;
+
+  profile_state_inited = TRUE;
+
+  const char *str = getenv ("EOS_PROFILE");
+  if (str != NULL)
+    {
+      profile_state = g_new0 (ProfileState, 1);
+      profile_state->probes = g_hash_table_new_full (g_str_hash, g_str_equal,
+                                                     NULL,
+                                                     eos_profile_probe_destroy);
+
+      int capture_prefix_len = strlen ("capture");
+
+      if (g_ascii_strncasecmp (str, "capture", capture_prefix_len) == 0)
+        {
+          profile_state->capture = TRUE;
+
+          const char *filename = str + capture_prefix_len;
+          if (*filename == ':')
+            {
+              filename += 1;
+
+              if (*filename != '\0')
+                profile_state->capture_file = g_strdup (filename);
+            }
+
+          if (profile_state->capture_file == NULL || *profile_state->capture_file == '\0')
+            {
+              g_autofree char *capture_dir = g_build_filename (g_get_user_cache_dir (),
+                                                               "com.endlessm.Sdk.Profile",
+                                                               NULL);
+
+              if (g_mkdir_with_parents (capture_dir, 0700) < 0)
+                capture_dir = g_get_current_dir ();
+
+              profile_state->capture_file = g_strdup_printf ("%s%s%s.db",
+                                                             capture_dir,
+                                                             G_DIR_SEPARATOR_S,
+                                                             g_get_prgname ());
+            }
+        }
+    }
+}
+
+static const double
+scale_val (double val)
+{
+  if (val >= G_USEC_PER_SEC)
+    return val / G_USEC_PER_SEC;
+
+  if (val >= 1000)
+    return val / 1000.0;
+
+  return val;
+}
+
+static const char *
+unit_for (double val)
+{
+  enum {
+    SECONDS,
+    MILLISECONDS,
+    MICROSECONDS
+  };
+
+  const char *units[] = {
+    [SECONDS] = "s",
+    [MILLISECONDS] = "ms",
+    [MICROSECONDS] = "µs",
+  };
+
+  if (val >= G_USEC_PER_SEC)
+    return units[SECONDS];
+
+  if (val >= 1000)
+    return units[MILLISECONDS];
+
+  return units[MICROSECONDS];
+}
+
+static void
+profile_state_dump_to_console (void)
+{
+  gushort max_columns = 256;
+
+  if (isatty (STDOUT_FILENO))
+    {
+      struct winsize w;
+
+      ioctl (STDOUT_FILENO, TIOCGWINSZ, &w);
+
+      max_columns = w.ws_col;
+    }
+
+  GHashTableIter iter;
+  gpointer value;
+
+  g_hash_table_iter_init (&iter, profile_state->probes);
+  while (g_hash_table_iter_next (&iter, NULL, &value))
+    {
+      EosProfileProbe *probe = value;
+
+      /* Take ownership of the samples in order to sort them; we want to
+       * pre-sort so that we can easily discard the outliers when doing
+       * our analysis, later on
+       */
+      GArray *sorted_samples = g_steal_pointer (&probe->samples);
+      g_array_sort (sorted_samples, sample_compare);
+
+      gint64 min_sample = G_MAXINT64, max_sample = 0;
+      gint64 total = 0;
+
+      g_autoptr(GArray) valid_samples = g_array_new (FALSE, FALSE, sizeof (guint));
+
+      for (int i = 0; i < sorted_samples->len; i++)
+        {
+          const ProfileSample *sample = &g_array_index (sorted_samples, ProfileSample, i);
+
+          gint64 delta = sample->end_time - sample->start_time;
+
+          /* If the probe never got stopped we need to skip this sample */
+          if (delta < 0)
+            continue;
+
+          g_array_append_val (valid_samples, i);
+
+          if (delta < min_sample)
+            min_sample = delta;
+          if (delta > max_sample)
+            max_sample = delta;
+
+          total += delta;
+        }
+
+      g_autofree char *msg = NULL;
+
+      if (valid_samples->len > 1)
+        {
+          double avg = total / (double) valid_samples->len;
+          double s = 0;
+          double s_part = 0;
+
+          for (int i = 1; i < valid_samples->len - 1; i++)
+            {
+              guint idx = g_array_index (valid_samples, guint, i);
+              const ProfileSample *sample = &g_array_index (sorted_samples, ProfileSample, idx);
+
+              gint64 delta = sample->end_time - sample->start_time;
+              g_assert (delta >= 0);
+
+              double deviation = delta - avg;
+              s_part += (deviation * deviation);
+            }
+
+          if (valid_samples->len > 1)
+            s = sqrt (s_part / (double) valid_samples->len - 1);
+          else
+            s = 0.0;
+
+          g_autofree char *stddev = g_strdup_printf (", σ:%g", s);
+
+          msg =
+            g_strdup_printf ("%d samples: avg:%g %s, min:%d %s, max:%d %s%s)",
+                             valid_samples->len,
+                             scale_val (avg), unit_for (avg),
+                             (int) scale_val (min_sample), unit_for (min_sample),
+                             (int) scale_val (max_sample), unit_for (max_sample),
+                             s == 0.0 ? "" : stddev);
+        }
+      else
+        {
+          msg = g_strdup ("not enough valid samples found");
+        }
+
+      g_autofree char *probe_name = NULL;
+
+      int probe_len = strlen (probe->name);
+      int msg_len = strlen (msg);
+      if (probe_len + msg_len >= (int) max_columns - 2)
+        {
+          gsize name_len = MAX ((int) max_columns - msg_len, 2);
+          probe_name = g_strndup (probe->name, name_len);
+          probe_name[name_len - 1] = '~';
+        }
+      else
+        probe_name = g_strdup (probe->name);
+
+      g_print ("%s%*c%s\n",
+               probe_name,
+               max_columns - strlen (probe_name) - msg_len, ' ',
+               msg);
+      g_print ("  %s at %s:%d\n\n",
+               probe->function,
+               probe->file, probe->line);
+    }
+}
+
+/* Get the immediate parent table in the GVDB table, using the
+ * key separator '/' to determine the nesting level. If needed,
+ * this function will create the intermediate tables
+ */
+static GvdbItem *
+get_parent (GHashTable *table,
+            char       *key,
+            int         length)
+{
+  GvdbItem *grandparent, *parent;
+
+  if (length == 1)
+    return NULL;
+
+  while (key[--length - 1] != '/')
+    ;
+
+  key[length] = '\0';
+
+  parent = g_hash_table_lookup (table, key);
+
+  if (parent == NULL)
+    {
+      parent = gvdb_hash_table_insert (table, key);
+
+      grandparent = get_parent (table, key, length);
+
+      if (grandparent != NULL)
+        gvdb_item_set_parent (parent, grandparent);
+    }
+
+  return parent;
+}
+
+void
+eos_profile_state_dump (void)
+{
+  if (profile_state == NULL)
+    return;
+
+  if (!profile_state->capture)
+    {
+      profile_state_dump_to_console ();
+      return;
+    }
+
+  g_autoptr(GHashTable) db_table = gvdb_hash_table_new (NULL, NULL);
+
+  /* Metadata for the DB */
+  g_autofree char *version_key = g_strdup (PROBE_DB_META_VERSION_KEY);
+  gsize version_key_len = strlen (version_key);
+  GvdbItem *meta = gvdb_hash_table_insert (db_table, PROBE_DB_META_VERSION_KEY);
+  gvdb_item_set_parent (meta, get_parent (db_table, version_key, version_key_len));
+  gvdb_item_set_value (meta, g_variant_new_int32 (PROBE_DB_VERSION));
+
+  /* Iterate over the probes */
+  GHashTableIter iter;
+  gpointer value;
+  g_hash_table_iter_init (&iter, profile_state->probes);
+  while (g_hash_table_iter_next (&iter, NULL, &value))
+    {
+      EosProfileProbe *probe = value;
+
+      g_autofree char *key = g_strdup (probe->name);
+      gsize key_len = strlen (probe->name);
+
+      GvdbItem *item = gvdb_hash_table_insert (db_table, key);
+      gvdb_item_set_parent (item, get_parent (db_table, key, key_len));
+
+      GVariantBuilder builder;
+
+      g_variant_builder_init (&builder, G_VARIANT_TYPE ("(sssuua(xx))"));
+
+      g_variant_builder_add (&builder, "s", probe->name);
+      g_variant_builder_add (&builder, "s", probe->function);
+      g_variant_builder_add (&builder, "s", probe->file);
+      g_variant_builder_add (&builder, "u", probe->line);
+
+      g_variant_builder_add (&builder, "u", probe->samples->len);
+
+      /* Take ownership of the samples in order to sort them; we want to
+       * pre-sort so that we can easily discard the outliers when doing
+       * our analysis, later on
+       */
+      GArray *sorted_samples = g_steal_pointer (&(probe->samples));
+      g_array_sort (sorted_samples, sample_compare);
+
+      g_variant_builder_open (&builder, G_VARIANT_TYPE ("a(xx)"));
+
+      for (int i = 0; i < sorted_samples->len; i++)
+        {
+          const ProfileSample *sample = &g_array_index (sorted_samples, ProfileSample, i);
+
+          g_variant_builder_open (&builder, G_VARIANT_TYPE ("(xx)"));
+          g_variant_builder_add (&builder, "x", sample->start_time);
+          g_variant_builder_add (&builder, "x", sample->end_time);
+          g_variant_builder_close (&builder);
+        }
+
+      g_variant_builder_close (&builder);
+
+      g_array_free (sorted_samples, TRUE);
+
+      gvdb_item_set_value (item, g_variant_builder_end (&builder));
+    }
+
+  /* Clean up */
+  g_hash_table_unref (profile_state->probes);
+  g_free (profile_state->capture_file);
+  g_free (profile_state);
+
+  g_autoptr(GError) error = NULL;
+  gvdb_table_write_contents (db_table, profile_state->capture_file,
+                             G_BYTE_ORDER != G_LITTLE_ENDIAN,
+                             &error);
+
+  if (error != NULL)
+    g_printerr ("PROFILE: %s\n", error->message);
+}