Bug 26725 — add profiling
authorMartin Pitt <martin.pitt@ubuntu.com>
Wed, 3 Mar 2010 20:20:00 +0000 (21:20 +0100)
committerMartin Pitt <martin.pitt@ubuntu.com>
Wed, 3 Mar 2010 21:02:57 +0000 (22:02 +0100)
Add a PROFILE() macro (src/profile.h) which, when building with
--enable-profiling, adds fake access() calls as trace points for startup speed
profiling.

http://people.gnome.org/~federico/news-2006-03.html#login-time-2 describes how
to use strace and turn its output into a nice graph:

  # strace -tttfo /tmp/trace src/udisks-daemon
  [...]
  $ plot-timeline.py -o /tmp/trace.png /tmp/trace

Instrument the most important/complex methods in daemon.c and device.c, and
main().

configure.ac
src/daemon.c
src/device.c
src/main.c
src/profile.h [new file with mode: 0644]

index a231fc6..be9562c 100644 (file)
@@ -22,6 +22,11 @@ m4_ifdef([AM_SILENT_RULES], [AM_SILENT_RULES([yes])])
 AC_ARG_ENABLE(ansi,             [  --enable-ansi           enable -ansi -pedantic gcc flags],enable_ansi=$enableval,enable_ansi=no)
 AC_ARG_ENABLE(verbose-mode,     [  --enable-verbose-mode   support verbose debug mode],enable_verbose_mode=$enableval,enable_verbose_mode=$USE_MAINTAINER_MODE)
 AC_ARG_ENABLE(man-pages,        [  --enable-man-pages      build manual pages],enable_man_pages=$enableval,enable_man_pages=yes)
+AC_ARG_ENABLE(profiling,        [  --enable-profiling      add tracing instrumentation for plot-timeline.py], enable_profiling=$enableval,enable_profiling=$USE_MAINTAINER_MODE)
+
+if test "x$enable_profiling" = "xyes"; then
+  AC_DEFINE(PROFILING, 1, [Define to 1 if profiling is enabled ])
+fi
 
 if test "${enable_man_page}" != no; then
 dnl
@@ -251,6 +256,7 @@ echo "
         Remote Access:              ${remote_access}
 
         Maintainer mode:            ${USE_MAINTAINER_MODE}
+        Profiling:                  ${enable_profiling}
         Building api docs:          ${enable_gtk_doc}
         Building man pages:         ${enable_man_pages}
 "
index 49497be..40e7d2e 100644 (file)
@@ -74,6 +74,8 @@
 #include "daemon-glue.h"
 #include "marshal.h"
 
+#include "profile.h"
+
 /*--------------------------------------------------------------------------------------------------------------*/
 
 enum
@@ -1848,8 +1850,11 @@ daemon_new (void)
   Device *device;
   GHashTableIter device_iter;
 
+  PROFILE ("daemon_new(): start");
+
   daemon = DAEMON (g_object_new (TYPE_DAEMON, NULL));
 
+  PROFILE ("daemon_new(): register_disks_daemon");
   if (!register_disks_daemon (DAEMON (daemon)))
     {
       g_object_unref (daemon);
@@ -1857,6 +1862,7 @@ daemon_new (void)
     }
 
   /* process storage adapters */
+  PROFILE ("daemon_new(): storage adapters");
   devices = g_udev_client_query_by_subsystem (daemon->priv->gudev_client, "pci");
   for (l = devices; l != NULL; l = l->next)
     {
@@ -1867,6 +1873,7 @@ daemon_new (void)
   g_list_free (devices);
 
   /* process ATA ports */
+  PROFILE ("daemon_new(): ATA ports");
   devices = g_udev_client_query_by_subsystem (daemon->priv->gudev_client, "scsi_host");
   for (l = devices; l != NULL; l = l->next)
     {
@@ -1877,6 +1884,7 @@ daemon_new (void)
   g_list_free (devices);
 
   /* process SAS Expanders */
+  PROFILE ("daemon_new(): SAS Expanders");
   devices = g_udev_client_query_by_subsystem (daemon->priv->gudev_client, "sas_expander");
   for (l = devices; l != NULL; l = l->next)
     {
@@ -1887,6 +1895,7 @@ daemon_new (void)
   g_list_free (devices);
 
   /* process SAS PHYs */
+  PROFILE ("daemon_new(): process SAS PHYs");
   devices = g_udev_client_query_by_subsystem (daemon->priv->gudev_client, "sas_phy");
   for (l = devices; l != NULL; l = l->next)
     {
@@ -1901,6 +1910,7 @@ daemon_new (void)
    * TODO: ideally there would be a way to properly traverse a whole subtree using gudev
    * so we could visit everything in the proper order.
    */
+  PROFILE ("daemon_new(): reprocess SAS expanders");
   devices = g_udev_client_query_by_subsystem (daemon->priv->gudev_client, "sas_expander");
   for (l = devices; l != NULL; l = l->next)
     {
@@ -1911,6 +1921,7 @@ daemon_new (void)
   g_list_free (devices);
 
   /* process block devices (disks and partitions) */
+  PROFILE ("daemon_new(): block devices");
   devices = g_udev_client_query_by_subsystem (daemon->priv->gudev_client, "block");
   for (l = devices; l != NULL; l = l->next)
     {
@@ -1923,6 +1934,7 @@ daemon_new (void)
   /* now refresh data for all devices just added to get slave/holder relationships
    * properly initialized
    */
+  PROFILE ("daemon_new(): refresh");
   g_hash_table_iter_init (&device_iter, daemon->priv->map_object_path_to_device);
   while (g_hash_table_iter_next (&device_iter, NULL, (gpointer) & device))
     {
@@ -1932,6 +1944,7 @@ daemon_new (void)
   /* clean stale directories in /media as well as stale
    * entries in /var/lib/udisks/mtab
    */
+  PROFILE ("daemon_new(): clean up stale locks and mount points");
   l = g_hash_table_get_values (daemon->priv->map_native_path_to_device);
   mount_file_clean_stale (l);
   g_list_free (l);
@@ -1943,9 +1956,11 @@ daemon_new (void)
                                                                     (GSourceFunc) refresh_ata_smart_data,
                                                                     daemon);
 
+  PROFILE ("daemon_new(): end");
   return daemon;
 
  error:
+  PROFILE ("daemon_new(): existing with error");
   return NULL;
 }
 
index 26af69f..d2e89b5 100644 (file)
@@ -62,6 +62,8 @@
 #include "adapter.h"
 #include "port.h"
 
+#include "profile.h"
+
 /*--------------------------------------------------------------------------------------------------------------*/
 #include "device-glue.h"
 
@@ -4296,6 +4298,8 @@ update_info (Device *device)
 
   ret = FALSE;
 
+  PROFILE ("update_info(device=%s) start", device->priv->native_path);
+
   g_print ("**** UPDATING %s\n", device->priv->native_path);
 
   /* need the slaves/holders to synthesize 'change' events if a device goes away (since the kernel
@@ -4724,6 +4728,7 @@ update_info (Device *device)
   g_list_foreach (cur_holders_objpath, (GFunc) g_free, NULL);
   g_list_free (cur_holders_objpath);
 
+  PROFILE ("update_info(device=%s) end", device->priv->native_path);
   return ret;
 }
 
@@ -4977,6 +4982,8 @@ device_new (Daemon *daemon,
       || g_str_has_prefix (native_path, "/sys/devices/virtual/block/loop"))
     goto out;
 
+  PROFILE ("device_new(native_path=%s): start", native_path);
+
   device = DEVICE (g_object_new (TYPE_DEVICE, NULL));
   device->priv->d = g_object_ref (d);
   device->priv->daemon = g_object_ref (daemon);
@@ -4988,6 +4995,7 @@ device_new (Daemon *daemon,
    */
   device->priv->device_detection_time = (guint64) time (NULL);
 
+  PROFILE ("device_new(native_path=%s): update_info", native_path);
   if (!update_info (device))
     {
       g_object_unref (device);
@@ -4995,6 +5003,7 @@ device_new (Daemon *daemon,
       goto out;
     }
 
+  PROFILE ("device_new(native_path=%s): register_disks_device", native_path);
   if (!register_disks_device (DEVICE (device)))
     {
       g_object_unref (device);
@@ -5005,10 +5014,12 @@ device_new (Daemon *daemon,
   /* if just added, update the smart data if applicable */
   if (device->priv->drive_ata_smart_is_available)
     {
+      PROFILE ("device_new(native_path=%s): refresh ATA SMART DATA", native_path);
       gchar *ata_smart_refresh_data_options[] = { NULL };
       device_drive_ata_smart_refresh_data (device, ata_smart_refresh_data_options, NULL);
     }
 
+  PROFILE ("device_new(native_path=%s): end", native_path);
  out:
   return device;
 }
@@ -5320,6 +5331,7 @@ job_child_watch_cb (GPid pid,
       g_free (buf);
     }
 
+  PROFILE ("job finish (id=%s, pid=%i, device=%s)", job->job_id, job->pid, job->device ? job->device->priv->device_file : "none");
   g_print ("helper(pid %5d): completed with exit code %d\n", job->pid, WEXITSTATUS (status));
 
   job->status = status;
@@ -5515,6 +5527,8 @@ job_new (DBusGMethodInvocation *context,
   ret = FALSE;
   job = NULL;
 
+  PROFILE ("job_new(id=%s, device=%s): start", job_id ? job_id : argv[0], device ? device->priv->device_file : "none");
+
   if (device != NULL)
     {
       if (device->priv->job != NULL || device->priv->job_in_progress)
@@ -5625,6 +5639,7 @@ job_new (DBusGMethodInvocation *context,
  out:
   if (!ret && job != NULL)
     job_free (job);
+  PROFILE ("job_new(id=%s, device=%s): end", job_id, device ? device->priv->device_file : "none");
   return ret;
 }
 
@@ -9545,6 +9560,8 @@ drive_ata_smart_refresh_data_completed_cb (DBusGMethodInvocation *context,
   time_t time_collected;
   SkSmartOverall overall;
 
+  PROFILE ("drive_ata_smart_refresh_data_completed_cb(device=%s) start", device->priv->native_path);
+
   d = NULL;
   blob = NULL;
 
@@ -9592,8 +9609,10 @@ drive_ata_smart_refresh_data_completed_cb (DBusGMethodInvocation *context,
       goto out;
     }
 
+  PROFILE ("drive_ata_smart_refresh_data_completed_cb(device=%s) decode blob", device->priv->native_path);
   blob = (gchar *) g_base64_decode (stdout, &blob_size);
 
+  PROFILE ("drive_ata_smart_refresh_data_completed_cb(device=%s) set blob", device->priv->native_path);
   if (blob == NULL)
     {
       if (context != NULL)
@@ -9625,9 +9644,11 @@ drive_ata_smart_refresh_data_completed_cb (DBusGMethodInvocation *context,
       goto out;
     }
 
+  PROFILE ("drive_ata_smart_refresh_data_completed_cb(device=%s) time collected", device->priv->native_path);
   time_collected = time (NULL);
   device_set_drive_ata_smart_time_collected (device, time_collected);
 
+  PROFILE ("drive_ata_smart_refresh_data_completed_cb(device=%s) overall smart status", device->priv->native_path);
   if (sk_disk_smart_get_overall (d, &overall) != 0)
     overall = -1;
   device_set_drive_ata_smart_status (device, overall);
@@ -9635,6 +9656,7 @@ drive_ata_smart_refresh_data_completed_cb (DBusGMethodInvocation *context,
   blob = NULL;
 
   /* emit change event since we've updated the smart data */
+  PROFILE ("drive_ata_smart_refresh_data_completed_cb(device=%s) drain pending changes", device->priv->native_path);
   drain_pending_changes (device, FALSE);
 
   if (context != NULL)
@@ -9644,6 +9666,7 @@ drive_ata_smart_refresh_data_completed_cb (DBusGMethodInvocation *context,
   g_free (blob);
   if (d != NULL)
     sk_disk_free (d);
+  PROFILE ("drive_ata_smart_refresh_data_completed_cb(device=%s) end", device->priv->native_path);
 }
 
 static void
@@ -9662,6 +9685,7 @@ device_drive_ata_smart_refresh_data_authorized_cb (Daemon *daemon,
   gboolean nowakeup;
   uid_t caller_uid;
 
+  PROFILE ("device_drive_ata_smart_refresh_data_authorized_cb(device=%s) start", device->priv->native_path);
   daemon_local_get_uid (device->priv->daemon, &caller_uid, context);
 
   simuldata = NULL;
@@ -9719,6 +9743,7 @@ device_drive_ata_smart_refresh_data_authorized_cb (Daemon *daemon,
 
  out:
   ;
+  PROFILE ("device_drive_ata_smart_refresh_data_authorized_cb(device=%s) end", device->priv->native_path);
 }
 
 /* may be called with context==NULL */
index 3f0c8ab..6b6326b 100644 (file)
@@ -45,6 +45,8 @@
 #include "poller.h"
 #include "daemon.h"
 
+#include "profile.h"
+
 #define NAME_TO_CLAIM "org.freedesktop.UDisks"
 
 static GMainLoop *loop;
@@ -148,6 +150,8 @@ main (int argc,
          &helper_dir, "Directory for helper tools",  NULL },
       { NULL } };
 
+  PROFILE ("main(): start");
+
   ret = 1;
   error = NULL;
 
@@ -184,6 +188,8 @@ main (int argc,
     }
   g_free (path);
 
+  PROFILE ("main(): basic initialization done");
+
   bus = dbus_g_bus_get (DBUS_BUS_SYSTEM, &error);
   if (bus == NULL)
     {
@@ -205,6 +211,8 @@ main (int argc,
       goto out;
     }
 
+  PROFILE ("main(): D-Bus initialization done");
+
   g_debug ("Starting daemon version %s", VERSION);
 
   daemon = daemon_new ();
@@ -214,6 +222,7 @@ main (int argc,
       goto out;
     }
 
+  PROFILE ("main(): starting main loop");
   loop = g_main_loop_new (NULL, FALSE);
 
   g_main_loop_run (loop);
diff --git a/src/profile.h b/src/profile.h
new file mode 100644 (file)
index 0000000..b3322ef
--- /dev/null
@@ -0,0 +1,53 @@
+/* -*- mode: C; c-file-style: "gnu"; indent-tabs-mode: nil; -*-
+ *
+ * Copyright (C) 2010 Martin Pitt <martin.pitt@ubuntu.com>
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
+ *
+ */
+
+#ifndef __PROFILE_H
+#define __PROFILE_H
+
+#include "config.h"
+
+#include <glib.h>
+
+/* Define a macro PROFILE(format, ...) which adds a trace point for profiling
+ * startup speed. This executes an access() call to a fake file name 
+ * "MARK: <description>" which can easily be evaluated with strace -t.
+ *
+ * http://people.gnome.org/~federico/news-2006-03.html#login-time-2 describes
+ * how to turn these strace logs into a nice graph:
+ *
+ *   # strace -tttfo /tmp/trace src/udisks-daemon
+ *   [...]
+ *   $ plot-timeline.py -o /tmp/trace.png /tmp/trace
+ *
+ * If profiling is not enabled, this macro is a no-op.
+ */
+
+#ifdef PROFILING
+# define PROFILE(format, ...) { \
+        char *str = g_strdup_printf ("MARK: %s: " format, g_get_prgname(), ##__VA_ARGS__); \
+        access (str, F_OK); \
+        g_free (str); \
+}
+#else
+# define PROFILE(...) {}
+#endif
+
+#endif /* __PROFILE_H */
+