From 6136b9fb4811ee44ec16f3ad9f4306d0798419b1 Mon Sep 17 00:00:00 2001

From: Vladimir 'phcoder' Serbinenko <phcoder@gmail.com>

Date: Tue, 19 Mar 2013 20:25:09 +0100

Subject: [PATCH 212/364] 	Implement boot time analysis framework.

---

 ChangeLog                     |  6 +++-

 config.h.in                   |  1 +

 configure.ac                  | 19 +++++++++++++

 grub-core/Makefile.core.def   |  6 ++++

 grub-core/bus/usb/ehci.c      |  7 +++++

 grub-core/bus/usb/usb.c       |  9 ++++--

 grub-core/bus/usb/usbhub.c    | 35 +++++++++++++++++++----

 grub-core/commands/boottime.c | 66 +++++++++++++++++++++++++++++++++++++++++++

 grub-core/disk/usbms.c        |  4 +++

 grub-core/kern/dl.c           |  3 ++

 grub-core/kern/main.c         | 12 ++++++++

 grub-core/kern/misc.c         | 39 +++++++++++++++++++++++++

 grub-core/normal/main.c       | 13 +++++++++

 include/grub/misc.h           | 20 +++++++++++++

 14 files changed, 232 insertions(+), 8 deletions(-)

 create mode 100644 grub-core/commands/boottime.c

diff --git a/ChangeLog b/ChangeLog

index a544fbf..94dd5bb 100644

--- 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.

diff --git a/config.h.in b/config.h.in

index 621742c..2e1f459 100644

--- a/config.h.in

+++ b/config.h.in

@@ -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>

diff --git a/configure.ac b/configure.ac

index 038f429..a39a025 100644

--- a/configure.ac

+++ b/configure.ac

@@ -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

diff --git a/grub-core/Makefile.core.def b/grub-core/Makefile.core.def

index 3bcf662..5c15f32 100644

--- a/grub-core/Makefile.core.def

+++ b/grub-core/Makefile.core.def

@@ -1869,6 +1869,12 @@ module = {

 };

 module = {

+  name = boottime;

+  common = commands/boottime.c;

+  condition = COND_ENABLE_BOOT_TIME_STATS;

+};

+

+module = {

   name = adler32;

   common = lib/adler32.c;

 };

diff --git a/grub-core/bus/usb/ehci.c b/grub-core/bus/usb/ehci.c

index c60873d..a5a24af 100644

--- a/grub-core/bus/usb/ehci.c

+++ b/grub-core/bus/usb/ehci.c

@@ -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);

 }

diff --git a/grub-core/bus/usb/usb.c b/grub-core/bus/usb/usb.c

index 7a517f8..108c69b 100644

--- a/grub-core/bus/usb/usb.c

+++ b/grub-core/bus/usb/usb.c

@@ -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;

diff --git a/grub-core/bus/usb/usbhub.c b/grub-core/bus/usb/usbhub.c

index 7e7dc8c..f95a567 100644

--- a/grub-core/bus/usb/usbhub.c

+++ b/grub-core/bus/usb/usbhub.c

@@ -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

index 0000000..cd7f70a

--- /dev/null

+++ b/grub-core/commands/boottime.c

@@ -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);

+}

diff --git a/grub-core/disk/usbms.c b/grub-core/disk/usbms.c

index dd35bff..2cfc537 100644

--- a/grub-core/disk/usbms.c

+++ b/grub-core/disk/usbms.c

@@ -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...

diff --git a/grub-core/kern/dl.c b/grub-core/kern/dl.c

index 5b0aa65..d06b6ae 100644

--- a/grub-core/kern/dl.c

+++ b/grub-core/kern/dl.c

@@ -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))

     {

diff --git a/grub-core/kern/main.c b/grub-core/kern/main.c

index e1a2001..19dc988 100644

--- a/grub-core/kern/main.c

+++ b/grub-core/kern/main.c

@@ -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 ();

 }

diff --git a/grub-core/kern/misc.c b/grub-core/kern/misc.c

index 6cb8f0e..94b88a3 100644

--- a/grub-core/kern/misc.c

+++ b/grub-core/kern/misc.c

@@ -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

diff --git a/grub-core/normal/main.c b/grub-core/normal/main.c

index 07f337d..9aaa3b2 100644

--- a/grub-core/normal/main.c

+++ b/grub-core/normal/main.c

@@ -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)

diff --git a/include/grub/misc.h b/include/grub/misc.h

index 11eeb22..f0ecaec 100644

--- a/include/grub/misc.h

+++ b/include/grub/misc.h

@@ -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 */

-- 

1.8.1.4