From 6136b9fb4811ee44ec16f3ad9f4306d0798419b1 Mon Sep 17 00:00:00 2001 From: Vladimir 'phcoder' Serbinenko 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 - remove get_endpoint_descriptor and change all functions needing + Implement boot time analysis framework. + +2013-03-19 Vladimir Serbinenko + + 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 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 . + */ + +#include +#include +#include +#include + +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 + +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