]> git.ipfire.org Git - thirdparty/grub.git/commitdiff
Implement boot time analysis framework.
authorVladimir 'phcoder' Serbinenko <phcoder@gmail.com>
Tue, 19 Mar 2013 19:25:09 +0000 (20:25 +0100)
committerVladimir 'phcoder' Serbinenko <phcoder@gmail.com>
Tue, 19 Mar 2013 19:25:09 +0000 (20:25 +0100)
14 files changed:
ChangeLog
config.h.in
configure.ac
grub-core/Makefile.core.def
grub-core/bus/usb/ehci.c
grub-core/bus/usb/usb.c
grub-core/bus/usb/usbhub.c
grub-core/commands/boottime.c [new file with mode: 0644]
grub-core/disk/usbms.c
grub-core/kern/dl.c
grub-core/kern/main.c
grub-core/kern/misc.c
grub-core/normal/main.c
include/grub/misc.h

index a544fbf37fd1bfeb121264cd4fcf9b0f7a46dd0e..94dd5bb6f1d19dca436c59aee9543f4ae84350c3 100644 (file)
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,6 +1,10 @@
 2013-03-19  Vladimir Serbinenko  <phcoder@gmail.com>
 
-       remove get_endpoint_descriptor and change all functions needing
+       Implement boot time analysis framework.
+
+2013-03-19  Vladimir Serbinenko  <phcoder@gmail.com>
+
+       Remove get_endpoint_descriptor and change all functions needing
        descriptor to just receive it as argument rather than endpoint
        address.
 
index 621742caee9ec7da84ee87112bfcd062ebe384de..2e1f4590928f4ce61925203dc228a45cb083358c 100644 (file)
@@ -8,6 +8,7 @@
 
 /* Define to 1 to enable disk cache statistics.  */
 #define DISK_CACHE_STATS @DISK_CACHE_STATS@
+#define BOOT_TIME_STATS @BOOT_TIME_STATS@
 
 #if defined (GRUB_UTIL) || !defined (GRUB_MACHINE)
 #include <config-util.h>
index 038f429077fc3e4fed014bc0d612566904b46ad6..a39a025fef04e0e91d7f21e02d2ee6f0cbeb8ca6 100644 (file)
@@ -798,6 +798,17 @@ else
 fi
 AC_SUBST([DISK_CACHE_STATS])
 
+AC_ARG_ENABLE([boot-time],
+             AS_HELP_STRING([--enable-boot-time],
+                             [enable boot time statistics collection]))
+
+if test x$enable_boot_time = xyes; then
+  BOOT_TIME_STATS=1
+else
+  BOOT_TIME_STATS=0
+fi
+AC_SUBST([BOOT_TIME_STATS])
+
 AC_ARG_ENABLE([grub-emu-usb],
              [AS_HELP_STRING([--enable-grub-emu-usb],
                              [build and install the `grub-emu' debugging utility with USB support (default=guessed)])])
@@ -1159,6 +1170,7 @@ AM_CONDITIONAL([COND_GRUB_PE2ELF], [test x$TARGET_OBJ2ELF != x])
 AM_CONDITIONAL([COND_APPLE_CC], [test x$TARGET_APPLE_CC = x1])
 AM_CONDITIONAL([COND_ENABLE_EFIEMU], [test x$enable_efiemu = xyes])
 AM_CONDITIONAL([COND_ENABLE_CACHE_STATS], [test x$DISK_CACHE_STATS = x1])
+AM_CONDITIONAL([COND_ENABLE_BOOT_TIME_STATS], [test x$BOOT_TIME_STATS = x1])
 
 AM_CONDITIONAL([COND_HAVE_ASM_USCORE], [test x$HAVE_ASM_USCORE = x1])
 AM_CONDITIONAL([COND_CYGWIN], [test x$host_os = xcygwin])
@@ -1231,6 +1243,13 @@ echo With disk cache statistics: Yes
 else
 echo With disk cache statistics: No
 fi
+
+if [ x"$enable_boot_time" = xyes ]; then
+echo With boot time statistics: Yes
+else
+echo With boot time statistics: No
+fi
+
 if [ x"$efiemu_excuse" = x ]; then
 echo efiemu runtime: Yes
 else
index 3bcf66232ff0469c3efb7a76f94a6f43017dd71b..5c15f32413aadafd1ee39fb7874412e27e974646 100644 (file)
@@ -1868,6 +1868,12 @@ module = {
   condition = COND_ENABLE_CACHE_STATS;
 };
 
+module = {
+  name = boottime;
+  common = commands/boottime.c;
+  condition = COND_ENABLE_BOOT_TIME_STATS;
+};
+
 module = {
   name = adler32;
   common = lib/adler32.c;
index c60873d606a10f39a2e7c65410df7cb6ded32fcb..a5a24afb6feaeb4ba0d27c467fde9dc3601bab8c 100644 (file)
@@ -715,6 +715,7 @@ grub_ehci_pci_iter (grub_pci_device_t dev, grub_pci_id_t pciid,
       usblegsup = grub_pci_read (pciaddr_eecp);
       if (usblegsup & GRUB_EHCI_BIOS_OWNED)
        {
+         grub_boot_time ("Taking ownership of EHCI port");
          grub_dprintf ("ehci",
                        "EHCI grub_ehci_pci_iter: EHCI owned by: BIOS\n");
          /* Ownership change - set OS_OWNED bit */
@@ -741,6 +742,7 @@ grub_ehci_pci_iter (grub_pci_device_t dev, grub_pci_id_t pciid,
              /* Ensure PCI register is written */
              grub_pci_read (pciaddr_eecp);
            }
+         grub_boot_time ("Ownership of EHCI port taken");
        }
       else if (usblegsup & GRUB_EHCI_OS_OWNED)
        /* XXX: What to do in this case - nothing ? Can it happen ? */
@@ -1706,10 +1708,12 @@ grub_ehci_portstatus (grub_usb_controller_t dev,
   /* Reset RESET bit and wait for the end of reset */
   grub_ehci_port_resbits (e, port, GRUB_EHCI_PORT_RESET);
   endtime = grub_get_time_ms () + 1000;
+  grub_boot_time ("Resetting port %d", port);
   while (grub_ehci_port_read (e, port) & GRUB_EHCI_PORT_RESET)
     if (grub_get_time_ms () > endtime)
       return grub_error (GRUB_ERR_IO,
                         "portstatus: EHCI Timed out - reset port");
+  grub_boot_time ("Port %d reset", port);
   /* Remember "we did the reset" - needed by detect_dev */
   e->reset |= (1 << port);
   /* Test if port enabled, i.e. HIGH speed device connected */
@@ -1911,8 +1915,11 @@ GRUB_MOD_INIT (ehci)
 {
   COMPILE_TIME_ASSERT (sizeof (struct grub_ehci_td) == 64);
   COMPILE_TIME_ASSERT (sizeof (struct grub_ehci_qh) == 96);
+  grub_boot_time ("Initing EHCI hardware");
   grub_ehci_inithw ();
+  grub_boot_time ("Registering EHCI driver");
   grub_usb_controller_dev_register (&usb_controller);
+  grub_boot_time ("EHCI driver registered");
   grub_loader_register_preboot_hook (grub_ehci_fini_hw, grub_ehci_restore_hw,
                                     GRUB_LOADER_PREBOOT_HOOK_PRIO_DISK);
 }
index 7a517f80b0bd97f1571f659ebbfeadb1b49467a6..108c69b3c29c719911c89d18212edf72a012c5a0 100644 (file)
@@ -262,8 +262,13 @@ void grub_usb_device_attach (grub_usb_device_t dev)
        continue;
 
       for (desc = attach_hooks; desc; desc = desc->next)
-       if (interf->class == desc->class && desc->hook (dev, 0, i))
-         dev->config[0].interf[i].attached = 1;
+       if (interf->class == desc->class)
+         {
+           grub_boot_time ("Probing USB device driver class %x", desc->class);
+           if (desc->hook (dev, 0, i))
+             dev->config[0].interf[i].attached = 1;
+           grub_boot_time ("Probed USB device driver class %x", desc->class);
+         }
 
       if (dev->config[0].interf[i].attached)
        continue;
index 7e7dc8ceeac4690064f06064e11e75e29e6639a6..f95a567883a23860a1f20b7232f443fec42ddb8b 100644 (file)
@@ -52,6 +52,8 @@ grub_usb_hub_add_dev (grub_usb_controller_t controller,
   int i;
   grub_usb_err_t err;
 
+  grub_boot_time ("Attaching USB device");
+
   dev = grub_zalloc (sizeof (struct grub_usb_device));
   if (! dev)
     return NULL;
@@ -108,8 +110,12 @@ grub_usb_hub_add_dev (grub_usb_controller_t controller,
 
   /* Wait "recovery interval", spec. says 2ms */
   grub_millisleep (2);
+
+  grub_boot_time ("Probing USB device driver");
   
   grub_usb_device_attach (dev);
+
+  grub_boot_time ("Attached USB device");
   
   return dev;
 }
@@ -194,6 +200,8 @@ attach_root_port (struct grub_usb_hub *hub, int portno,
   grub_usb_speed_t current_speed = GRUB_USB_SPEED_NONE;
   int changed=0;
 
+  grub_boot_time ("detect_dev USB root portno=%d\n", portno);
+
 #if 0
 /* Specification does not say about disabling of port when device
  * connected. If disabling is really necessary for some devices,
@@ -203,6 +211,9 @@ attach_root_port (struct grub_usb_hub *hub, int portno,
   if (err)
     return;
 #endif
+
+  grub_boot_time ("Before the stable power wait portno=%d", portno);
+
   /* Wait for completion of insertion and stable power (USB spec.)
    * Should be at least 100ms, some devices requires more...
    * There is also another thing - some devices have worse contacts
@@ -239,6 +250,8 @@ attach_root_port (struct grub_usb_hub *hub, int portno,
   /* If the device is a Hub, scan it for more devices.  */
   if (dev->descdev.class == 0x09)
     grub_usb_add_hub (dev);
+
+  grub_boot_time ("Attached root port");
 }
 
 grub_usb_err_t
@@ -248,6 +261,8 @@ grub_usb_root_hub (grub_usb_controller_t controller)
   struct grub_usb_hub *hub;
   int changed=0;
 
+  grub_boot_time ("Registering USB root hub");
+
   hub = grub_malloc (sizeof (*hub));
   if (!hub)
     return GRUB_USB_ERR_INTERNAL;
@@ -287,6 +302,8 @@ grub_usb_root_hub (grub_usb_controller_t controller)
         }
     }
 
+  grub_boot_time ("USB root hub registered");
+
   return GRUB_USB_ERR_NONE;
 }
 
@@ -407,12 +424,13 @@ poll_nonroot_hub (grub_usb_device_t dev)
          /* Connected and status of connection changed ? */
          if (status & GRUB_USB_HUB_STATUS_PORT_CONNECTED)
            {
+             grub_boot_time ("Before the stable power wait portno=%d", i);
              /* A device is actually connected to this port. */
-  /* Wait for completion of insertion and stable power (USB spec.)
-   * Should be at least 100ms, some devices requires more...
-   * There is also another thing - some devices have worse contacts
-   * and connected signal is unstable for some time - we should handle
-   * it - but prevent deadlock in case when device is too faulty... */
+             /* Wait for completion of insertion and stable power (USB spec.)
+              * Should be at least 100ms, some devices requires more...
+              * There is also another thing - some devices have worse contacts
+              * and connected signal is unstable for some time - we should handle
+              * it - but prevent deadlock in case when device is too faulty... */
               for (total = j = 0; (j < 250) && (total < 2000); j++, total++)
                 {
                   grub_millisleep (1);
@@ -432,6 +450,9 @@ poll_nonroot_hub (grub_usb_device_t dev)
                   if (!(current_status & GRUB_USB_HUB_STATUS_PORT_CONNECTED))
                     j = 0;
                 }
+
+             grub_boot_time ("After the stable power wait portno=%d", i);
+
               grub_dprintf ("usb", "(non-root) total=%d\n", total);
               if (total >= 2000)
                 continue;
@@ -443,6 +464,8 @@ poll_nonroot_hub (grub_usb_device_t dev)
                                    GRUB_USB_REQ_SET_FEATURE,
                                    GRUB_USB_HUB_FEATURE_PORT_RESET,
                                    i, 0, 0);
+             grub_boot_time ("Resetting port %d", i);
+
              rescan = 1;
              /* We cannot reset more than one device at the same time !
               * Resetting more devices together results in very bad
@@ -464,6 +487,8 @@ poll_nonroot_hub (grub_usb_device_t dev)
                                GRUB_USB_REQ_CLEAR_FEATURE,
                                GRUB_USB_HUB_FEATURE_C_PORT_RESET, i, 0, 0);
 
+         grub_boot_time ("Port %d reset", i);
+
          if (status & GRUB_USB_HUB_STATUS_PORT_CONNECTED)
            {
              grub_usb_speed_t speed;
diff --git a/grub-core/commands/boottime.c b/grub-core/commands/boottime.c
new file mode 100644 (file)
index 0000000..cd7f70a
--- /dev/null
@@ -0,0 +1,66 @@
+/* cacheinfo.c - disk cache statistics  */
+/*
+ *  GRUB  --  GRand Unified Bootloader
+ *  Copyright (C) 2008,2010  Free Software Foundation, Inc.
+ *
+ *  GRUB 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 3 of the License, or
+ *  (at your option) any later version.
+ *
+ *  GRUB 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 GRUB.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+#include <grub/dl.h>
+#include <grub/misc.h>
+#include <grub/command.h>
+#include <grub/i18n.h>
+
+GRUB_MOD_LICENSE ("GPLv3+");
+
+
+static grub_err_t
+grub_cmd_boottime (struct grub_command *cmd __attribute__ ((unused)),
+                  int argc __attribute__ ((unused)),
+                  char *argv[] __attribute__ ((unused)))
+{
+  struct grub_boot_time *cur;
+  grub_uint64_t last_time = 0, start_time = 0;
+  if (!grub_boot_time_head)
+    {
+      grub_puts_ (N_("No boot time statistics is available\n"));
+      return 0;
+    }
+  start_time = last_time = grub_boot_time_head->tp;
+  for (cur = grub_boot_time_head; cur; cur = cur->next)
+    {
+      grub_uint32_t tmabs = cur->tp - start_time;
+      grub_uint32_t tmrel = cur->tp - last_time;
+      last_time = cur->tp;
+
+      grub_printf ("%3d.%03ds %2d.%03ds %s:%d %s\n", 
+                  tmabs / 1000, tmabs % 1000, tmrel / 1000, tmrel % 1000, cur->file, cur->line,
+                  cur->msg);
+    }
+ return 0;
+}
+
+static grub_command_t cmd_boottime;
+
+GRUB_MOD_INIT(boottime)
+{
+  cmd_boottime =
+    grub_register_command ("boottime", grub_cmd_boottime,
+                          0, N_("Get boot time statistics."));
+}
+
+GRUB_MOD_FINI(boottime)
+{
+  grub_unregister_command (cmd_boottime);
+}
index dd35bff35563ee2f866371f7a1d67f4b946c3cc3..2cfc537112d5fbca9881a68fc8c59ea763c0e092 100644 (file)
@@ -151,6 +151,8 @@ grub_usbms_attach (grub_usb_device_t usbdev, int configno, int interfno)
   unsigned curnum;
   grub_usb_err_t err = GRUB_ERR_NONE;
 
+  grub_boot_time ("Attaching USB mass storage");
+
   if (first_available_slot == ARRAY_SIZE (grub_usbms_devices))
     return 0;
 
@@ -246,6 +248,8 @@ grub_usbms_attach (grub_usb_device_t usbdev, int configno, int interfno)
 
   usbdev->config[configno].interf[interfno].detach_hook = grub_usbms_detach;
 
+  grub_boot_time ("Attached USB mass storage");
+
 #if 0 /* All this part should be probably deleted.
        * This make trouble on some devices if they are not in
        * Phase Error state - and there they should be not in such state...
index 5b0aa65820e92de3ff0b276ca873bd10587da469..d06b6aef2267c48363c032d215bb3b623265bd5b 100644 (file)
@@ -648,7 +648,10 @@ grub_dl_load_core (void *addr, grub_size_t size)
 
   grub_dprintf ("modules", "module name: %s\n", mod->name);
   grub_dprintf ("modules", "init function: %p\n", mod->init);
+
+  grub_boot_time ("Initing module %s", mod->name);
   grub_dl_call_init (mod);
+  grub_boot_time ("Module %s inited", mod->name);
 
   if (grub_dl_add (mod))
     {
index e1a200166735eb30f3c29bd3e16936de33a77190..19dc9885af9903eaad4ebf70ad2d344c55af3b42 100644 (file)
@@ -254,6 +254,8 @@ grub_main (void)
   /* First of all, initialize the machine.  */
   grub_machine_init ();
 
+  grub_boot_time ("After machine init.");
+
   /* Hello.  */
   grub_setcolorstate (GRUB_TERM_COLOR_HIGHLIGHT);
   grub_printf ("Welcome to GRUB!\n\n");
@@ -261,6 +263,8 @@ grub_main (void)
 
   grub_load_config ();
 
+  grub_boot_time ("Before loading embedded modules.");
+
   /* Load pre-loaded modules and free the space.  */
   grub_register_exported_symbols ();
 #ifdef GRUB_LINKER_HAVE_INIT
@@ -268,6 +272,8 @@ grub_main (void)
 #endif  
   grub_load_modules ();
 
+  grub_boot_time ("After loading embedded modules.");
+
   /* It is better to set the root device as soon as possible,
      for convenience.  */
   grub_set_prefix_and_root ();
@@ -277,11 +283,17 @@ grub_main (void)
   /* Reclaim space used for modules.  */
   reclaim_module_space ();
 
+  grub_boot_time ("After reclaiming module space.");
+
   grub_register_core_commands ();
 
+  grub_boot_time ("Before execution of embedded config.");
+
   if (load_config)
     grub_parser_execute (load_config);
 
+  grub_boot_time ("After execution of embedded config. Attempt to go to normal mode");
+
   grub_load_normal_mode ();
   grub_rescue_run ();
 }
index 6cb8f0e67dd6b209dfc1803412ba87665f05b8e5..94b88a386d7b45988083e6caa9c5fa0f019290d7 100644 (file)
@@ -1130,3 +1130,42 @@ void __deregister_frame_info (void)
 }
 #endif
 
+#if BOOT_TIME_STATS
+
+#include <grub/time.h>
+
+struct grub_boot_time *grub_boot_time_head;
+static struct grub_boot_time **boot_time_last = &grub_boot_time_head;
+
+void
+grub_real_boot_time (const char *file,
+                    const int line,
+                    const char *fmt, ...)
+{
+  struct grub_boot_time *n;
+  va_list args;
+
+  grub_error_push ();
+  n = grub_malloc (sizeof (*n));
+  if (!n)
+    {
+      grub_errno = 0;
+      grub_error_pop ();
+      return;
+    }
+  n->file = file;
+  n->line = line;
+  n->tp = grub_get_time_ms ();
+  n->next = 0;
+
+  va_start (args, fmt);
+  n->msg = grub_xvasprintf (fmt, args);    
+  va_end (args);
+
+  *boot_time_last = n;
+  boot_time_last = &n->next;
+
+  grub_errno = 0;
+  grub_error_pop ();
+}
+#endif
index 07f337ddc8e50d33724d04c3a17581d2752d5e65..9aaa3b29f369c2a7b8a4328758b97d079efed61d 100644 (file)
@@ -296,6 +296,8 @@ grub_normal_execute (const char *config, int nested, int batch)
       grub_register_variable_hook ("prefix", NULL, read_lists_hook);
     }
 
+  grub_boot_time ("Executing config file");
+
   if (config)
     {
       menu = read_config_file (config);
@@ -304,10 +306,14 @@ grub_normal_execute (const char *config, int nested, int batch)
       grub_errno = GRUB_ERR_NONE;
     }
 
+  grub_boot_time ("Executed config file");
+
   if (! batch)
     {
       if (menu && menu->size)
        {
+
+         grub_boot_time ("Entering menu");
          grub_show_menu (menu, nested, 0);
          if (nested)
            grub_normal_free_menu (menu);
@@ -319,12 +325,15 @@ grub_normal_execute (const char *config, int nested, int batch)
 void
 grub_enter_normal_mode (const char *config)
 {
+  grub_boot_time ("Entering normal mode");
   nested_level++;
   grub_normal_execute (config, 0, 0);
+  grub_boot_time ("Entering shell");
   grub_cmdline_run (0);
   nested_level--;
   if (grub_normal_exit_level)
     grub_normal_exit_level--;
+  grub_boot_time ("Exiting normal mode");
 }
 
 /* Enter normal mode from rescue mode.  */
@@ -504,6 +513,8 @@ GRUB_MOD_INIT(normal)
 {
   unsigned i;
 
+  grub_boot_time ("Preparing normal module");
+
   /* Previously many modules depended on gzio. Be nice to user and load it.  */
   grub_dl_load ("gzio");
   grub_errno = 0;
@@ -556,6 +567,8 @@ GRUB_MOD_INIT(normal)
   grub_env_export ("grub_cpu");
   grub_env_set ("grub_platform", GRUB_PLATFORM);
   grub_env_export ("grub_platform");
+
+  grub_boot_time ("Normal module prepared");
 }
 
 GRUB_MOD_FINI(normal)
index 11eeb22a83969df005e494d09a3db0986e3e8f4b..f0ecaec3d1a164eb9f7b6debe1620252ed983286 100644 (file)
@@ -458,4 +458,24 @@ grub_error_load (const struct grub_error_saved *save)
   grub_errno = save->grub_errno;
 }
 
+#if BOOT_TIME_STATS
+struct grub_boot_time
+{
+  struct grub_boot_time *next;
+  grub_uint64_t tp;
+  const char *file;
+  int line;
+  char *msg;
+};
+
+extern struct grub_boot_time *EXPORT_VAR(grub_boot_time_head);
+
+void EXPORT_FUNC(grub_real_boot_time) (const char *file,
+                                      const int line,
+                                      const char *fmt, ...) __attribute__ ((format (printf, 3, 4)));
+#define grub_boot_time(fmt, args...) grub_real_boot_time(GRUB_FILE, __LINE__, fmt, ## args)
+#else
+#define grub_boot_time(fmt, args...) 
+#endif
+
 #endif /* ! GRUB_MISC_HEADER */