setup_timer.py revision 5d1f7b1de12d16ceb2c938c56701a3e8bfa558f7 
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
7It does so by probing for InstallerExtraCode1 changes in the registry and can
8run besides any setup.exe. It's best to launch it before setup.exe itself
9starts, but can also time remaining stages if launched half-way through.
10
11Refer to InstallerStage in chrome/installer/util/util_constants.h for a brief
12description of each stage.
13
14Note that the stages are numbered in the order they were added to setup's
15implementation, not in the order they are meant to occur.
16
17This script never ends, it will endlessly report stage timings until killed.
18"""
19
20import _winreg
21import json
22import optparse
23import sys
24import time
25
26
27def 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
102def 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
129if __name__ == '__main__':
130  sys.exit(main())
131