chrome/installer/tools/setup_timer.py

   1 # Copyright 2013 The Chromium Authors. All rights reserved.
   2 # Use of this source code is governed by a BSD-style license that can be
   3 # found in the LICENSE file.
   4
   5 """This script reports time spent by setup.exe in each install/update phase.
   6
   7 It does so by probing for InstallerExtraCode1 changes in the registry and can
   8 run besides any setup.exe. It's best to launch it before setup.exe itself
   9 starts, but can also time remaining stages if launched half-way through.
  10
  11 Refer to InstallerStage in chrome/installer/util/util_constants.h for a brief
  12 description of each stage.
  13
  14 Note that the stages are numbered in the order they were added to setup's
  15 implementation, not in the order they are meant to occur.
  16
  17 This script never ends, it will endlessly report stage timings until killed.
  18 """
  19
  20 import _winreg
  21 import json
  22 import optparse
  23 import sys
  24 import time
  25
  26
  27 def TimeSetupStages(hive_str, state_key, product_guid, observed_code):
  28   """Observes setup.exe and reports about timings for each install/update stage.
  29
  30   Does so by observing the registry value |observed_code| in the key at:
  31   |hive_str_|\|state_key|\|product_guid|.
  32   """
  33   hive = (_winreg.HKEY_LOCAL_MACHINE if hive_str == 'HKLM' else
  34           _winreg.HKEY_CURRENT_USER)
  35   key = 0
  36   try:
  37     key = _winreg.OpenKey(hive, state_key + product_guid, 0, _winreg.KEY_READ)
  38   except WindowsError as e:
  39     print 'Error opening %s\\%s\\%s: %s' % (hive_str, state_key, product_guid,
  40                                             e)
  41     return
  42
  43   timings = []
  44   start_time = 0
  45   saw_start = False
  46   current_stage = 0
  47   try:
  48     current_stage, value_type = _winreg.QueryValueEx(key, observed_code)
  49     assert value_type == _winreg.REG_DWORD
  50     print 'Starting in already ongoing stage %u' % current_stage
  51     start_time = time.clock()
  52   except WindowsError:
  53     print 'No ongoing stage, waiting for next install/update cycle...'
  54
  55   while True:
  56     new_stage = 0
  57     try:
  58       new_stage, value_type = _winreg.QueryValueEx(key, observed_code)
  59       assert value_type == _winreg.REG_DWORD
  60     except WindowsError:
  61       # Handle the non-existant case by simply leaving |new_stage == 0|.
  62       pass
  63     if current_stage == new_stage:
  64       # Keep probing until a change is seen.
  65       time.sleep(0.01)
  66       continue
  67
  68     if current_stage != 0:
  69       # Round elapsed time to 2 digits precision; anything beyond that would be
  70       # bogus given the above polling loop's precision.
  71       elapsed_time = round(time.clock() - start_time, 2)
  72       if saw_start:
  73         print '%s: Stage %u took %.2f seconds.' % (
  74             time.strftime("%x %X", time.localtime()), current_stage,
  75             elapsed_time)
  76         timings.append({'stage': current_stage, 'time': elapsed_time})
  77       else:
  78         print '%s: The remainder of stage %u took %.2f seconds.' % (
  79             time.strftime("%x %X", time.localtime()), current_stage,
  80             elapsed_time)
  81         # Log this timing, but mark that it was already ongoing when this script
  82         # started timing it.
  83         timings.append({'stage': current_stage, 'time': elapsed_time,
  84                         'status': 'missed_start'})
  85
  86     if new_stage != 0:
  87       print '%s: Starting stage %u...' % (
  88           time.strftime("%x %X", time.localtime()), new_stage)
  89       saw_start = True
  90     else:
  91       print '%s: Install/update complete, stages timings:' % (
  92           time.strftime("%x %X", time.localtime()))
  93       print json.dumps(timings, indent=2, sort_keys=True)
  94       timings = []
  95       print '%s: No more stages, waiting for next install/update cycle...' % (
  96           time.strftime("%x %X", time.localtime()))
  97
  98     current_stage = new_stage
  99     start_time = time.clock()
 100
 101
 102 def main():
 103   usage = 'usage: %prog [options]'
 104   parser = optparse.OptionParser(usage,
 105                                  description="Times Chrome's installer stages.")
 106   parser.add_option('--hive', default='HKLM',
 107                     help='The hive to observe: "HKLM" for system-level '
 108                          'installs, "HKCU" for user-level installs, defaults '
 109                          'to HKLM.')
 110   parser.add_option('--state-key',
 111                     default='Software\\Google\\Update\\ClientState\\',
 112                     help="The client state key to observe, defaults to Google "
 113                          "Update's.")
 114   parser.add_option('--product-guid',
 115                     default='{4DC8B4CA-1BDA-483e-B5FA-D3C12E15B62D}',
 116                     help="The GUID of the product to observe: defaults to "
 117                          "the GUID for the Google Chrome Binaries which is the "
 118                          "one being written to on updates.")
 119   parser.add_option('--observed-code', default='InstallerExtraCode1',
 120                     help='The installer code to observe under '
 121                          '|state_key|\\|product_guid|, defaults to '
 122                          'InstallerExtraCode1.')
 123   options, _ = parser.parse_args()
 124
 125   TimeSetupStages(options.hive, options.state_key, options.product_guid,
 126                   options.observed_code)
 127
 128
 129 if __name__ == '__main__':
 130   sys.exit(main())