15d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)# Copyright 2013 The Chromium Authors. All rights reserved.
25d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)# Use of this source code is governed by a BSD-style license that can be
35d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)# found in the LICENSE file.
45d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
55d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)"""This script reports time spent by setup.exe in each install/update phase.
65d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
75d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)It does so by probing for InstallerExtraCode1 changes in the registry and can
85d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)run besides any setup.exe. It's best to launch it before setup.exe itself
95d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)starts, but can also time remaining stages if launched half-way through.
105d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
115d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)Refer to InstallerStage in chrome/installer/util/util_constants.h for a brief
125d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)description of each stage.
135d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
145d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)Note that the stages are numbered in the order they were added to setup's
155d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)implementation, not in the order they are meant to occur.
165d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
175d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)This script never ends, it will endlessly report stage timings until killed.
185d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)"""
195d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
205d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)import _winreg
215d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)import json
225d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)import optparse
235d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)import sys
245d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)import time
255d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
265d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
275d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)def TimeSetupStages(hive_str, state_key, product_guid, observed_code):
285d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  """Observes setup.exe and reports about timings for each install/update stage.
295d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
305d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  Does so by observing the registry value |observed_code| in the key at:
315d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  |hive_str_|\|state_key|\|product_guid|.
325d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  """
335d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  hive = (_winreg.HKEY_LOCAL_MACHINE if hive_str == 'HKLM' else
345d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)          _winreg.HKEY_CURRENT_USER)
355d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  key = 0
365d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  try:
375d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    key = _winreg.OpenKey(hive, state_key + product_guid, 0, _winreg.KEY_READ)
385d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  except WindowsError as e:
395d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    print 'Error opening %s\\%s\\%s: %s' % (hive_str, state_key, product_guid,
405d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                                            e)
415d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    return
425d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
435d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  timings = []
445d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  start_time = 0
455d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  saw_start = False
465d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  current_stage = 0
475d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  try:
485d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    current_stage, value_type = _winreg.QueryValueEx(key, observed_code)
495d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    assert value_type == _winreg.REG_DWORD
505d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    print 'Starting in already ongoing stage %u' % current_stage
515d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    start_time = time.clock()
525d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  except WindowsError:
535d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    print 'No ongoing stage, waiting for next install/update cycle...'
545d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
555d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  while True:
565d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    new_stage = 0
575d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    try:
585d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      new_stage, value_type = _winreg.QueryValueEx(key, observed_code)
595d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      assert value_type == _winreg.REG_DWORD
605d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    except WindowsError:
615d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      # Handle the non-existant case by simply leaving |new_stage == 0|.
625d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      pass
635d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    if current_stage == new_stage:
645d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      # Keep probing until a change is seen.
655d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      time.sleep(0.01)
665d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      continue
675d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
685d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    if current_stage != 0:
695d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      # Round elapsed time to 2 digits precision; anything beyond that would be
705d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      # bogus given the above polling loop's precision.
715d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      elapsed_time = round(time.clock() - start_time, 2)
725d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      if saw_start:
735d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)        print '%s: Stage %u took %.2f seconds.' % (
745d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)            time.strftime("%x %X", time.localtime()), current_stage,
755d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)            elapsed_time)
765d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)        timings.append({'stage': current_stage, 'time': elapsed_time})
775d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      else:
785d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)        print '%s: The remainder of stage %u took %.2f seconds.' % (
795d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)            time.strftime("%x %X", time.localtime()), current_stage,
805d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)            elapsed_time)
815d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)        # Log this timing, but mark that it was already ongoing when this script
825d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)        # started timing it.
835d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)        timings.append({'stage': current_stage, 'time': elapsed_time,
845d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                        'status': 'missed_start'})
855d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
865d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    if new_stage != 0:
875d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      print '%s: Starting stage %u...' % (
885d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)          time.strftime("%x %X", time.localtime()), new_stage)
895d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      saw_start = True
905d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    else:
915d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      print '%s: Install/update complete, stages timings:' % (
925d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)          time.strftime("%x %X", time.localtime()))
935d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      print json.dumps(timings, indent=2, sort_keys=True)
945d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      timings = []
955d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)      print '%s: No more stages, waiting for next install/update cycle...' % (
965d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)          time.strftime("%x %X", time.localtime()))
975d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
985d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    current_stage = new_stage
995d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)    start_time = time.clock()
1005d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
1015d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
1025d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)def main():
1035d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  usage = 'usage: %prog [options]'
1045d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  parser = optparse.OptionParser(usage,
1055d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                                 description="Times Chrome's installer stages.")
1065d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  parser.add_option('--hive', default='HKLM',
1075d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                    help='The hive to observe: "HKLM" for system-level '
1085d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                         'installs, "HKCU" for user-level installs, defaults '
1095d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                         'to HKLM.')
1105d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  parser.add_option('--state-key',
1115d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                    default='Software\\Google\\Update\\ClientState\\',
1125d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                    help="The client state key to observe, defaults to Google "
1135d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                         "Update's.")
1145d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  parser.add_option('--product-guid',
1155d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                    default='{4DC8B4CA-1BDA-483e-B5FA-D3C12E15B62D}',
1165d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                    help="The GUID of the product to observe: defaults to "
1175d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                         "the GUID for the Google Chrome Binaries which is the "
1185d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                         "one being written to on updates.")
1195d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  parser.add_option('--observed-code', default='InstallerExtraCode1',
1205d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                    help='The installer code to observe under '
1215d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                         '|state_key|\\|product_guid|, defaults to '
1225d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                         'InstallerExtraCode1.')
1235d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  options, _ = parser.parse_args()
1245d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
1255d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  TimeSetupStages(options.hive, options.state_key, options.product_guid,
1265d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)                  options.observed_code)
1275d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
1285d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)
1295d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)if __name__ == '__main__':
1305d1f7b1de12d16ceb2c938c56701a3e8bfa558f7Torne (Richard Coles)  sys.exit(main())
131