From 01b28420a5ad67fbc1cdd6ffc119941dfebc4f50 Mon Sep 17 00:00:00 2001 From: Martin Pitt Date: Thu, 25 Feb 2010 13:00:04 +0100 Subject: [PATCH] add profiling Add a profile() function (src/profile.h) which, when building with --enable-profiling, adds fake access() calls that can be analyzed with strace -e access -ttt. http://people.gnome.org/~federico/news-2006-03.html#login-time-2 describes how to turn these strace logs into a nice graph: # strace -ttt -e access -f -o /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 | 5 +++++ src/daemon.c | 15 +++++++++++++++ src/device.c | 25 +++++++++++++++++++++++++ src/main.c | 9 +++++++++ src/profile.h | 48 ++++++++++++++++++++++++++++++++++++++++++++++++ 5 files changed, 102 insertions(+), 0 deletions(-) create mode 100644 src/profile.h diff --git a/configure.ac b/configure.ac index 71ee3dc..8bf003c 100644 --- a/configure.ac +++ b/configure.ac @@ -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=no) + +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 diff --git a/src/daemon.c b/src/daemon.c index 49497be..251ab88 100644 --- a/src/daemon.c +++ b/src/daemon.c @@ -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; } diff --git a/src/device.c b/src/device.c index e23241d..d48ad63 100644 --- a/src/device.c +++ b/src/device.c @@ -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 @@ -4717,6 +4721,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; } @@ -4970,6 +4975,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); @@ -4981,6 +4988,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); @@ -4988,6 +4996,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); @@ -4998,10 +5007,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; } @@ -5313,6 +5324,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; @@ -5508,6 +5520,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) @@ -5618,6 +5632,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; } @@ -9537,6 +9552,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; @@ -9584,8 +9601,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) @@ -9617,9 +9636,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); @@ -9627,6 +9648,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) @@ -9636,6 +9658,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 @@ -9654,6 +9677,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; @@ -9711,6 +9735,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 */ diff --git a/src/main.c b/src/main.c index 3f0c8ab..bdf4e84 100644 --- a/src/main.c +++ b/src/main.c @@ -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 index 0000000..904d747 --- /dev/null +++ b/src/profile.h @@ -0,0 +1,48 @@ +/* -*- mode: C; c-file-style: "gnu"; indent-tabs-mode: nil; -*- + * + * Copyright (C) 2007 Federico Mena-Quintero + * Copyright (C) 2010 Martin Pitt + * + * 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" + +#ifdef PROFILING +static void +profile (const char *format, ...) +{ + va_list args; + char *formatted, *str; + + va_start (args, format); + formatted = g_strdup_vprintf (format, args); + va_end (args); + + str = g_strdup_printf ("MARK: %s: %s", g_get_prgname(), formatted); + g_free (formatted); + + access (str, F_OK); + g_free (str); +} +#else +# define profile(...) {} +#endif + +#endif /* __PROFILE_H */ -- 1.7.0