From 5907468088678982af52a33bee041c352dc7f0a0 Mon Sep 17 00:00:00 2001 From: Martin Pitt Date: Wed, 3 Mar 2010 21:20:00 +0100 Subject: [PATCH] =?utf8?q?Bug=2026725=20=E2=80=94=20add=20profiling?= MIME-Version: 1.0 Content-Type: text/plain; charset=utf8 Content-Transfer-Encoding: 8bit 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 | 6 ++++++ src/daemon.c | 15 +++++++++++++++ src/device.c | 25 +++++++++++++++++++++++++ src/main.c | 9 +++++++++ src/profile.h | 53 +++++++++++++++++++++++++++++++++++++++++++++++++++++ 5 files changed, 108 insertions(+) create mode 100644 src/profile.h diff --git a/configure.ac b/configure.ac index a231fc6..be9562c 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=$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} " diff --git a/src/daemon.c b/src/daemon.c index 49497be..40e7d2e 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 26af69f..d2e89b5 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 @@ -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 */ diff --git a/src/main.c b/src/main.c index 3f0c8ab..6b6326b 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..b3322ef --- /dev/null +++ b/src/profile.h @@ -0,0 +1,53 @@ +/* -*- mode: C; c-file-style: "gnu"; indent-tabs-mode: nil; -*- + * + * 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" + +#include + +/* 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: " 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 */ + -- 2.7.4