test/option/debug-time.py

   1 #!/usr/bin/env python
   2 #
   3 # __COPYRIGHT__
   4 #
   5 # Permission is hereby granted, free of charge, to any person obtaining
   6 # a copy of this software and associated documentation files (the
   7 # "Software"), to deal in the Software without restriction, including
   8 # without limitation the rights to use, copy, modify, merge, publish,
   9 # distribute, sublicense, and/or sell copies of the Software, and to
  10 # permit persons to whom the Software is furnished to do so, subject to
  11 # the following conditions:
  12 #
  13 # The above copyright notice and this permission notice shall be included
  14 # in all copies or substantial portions of the Software.
  15 #
  16 # THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY
  17 # KIND, EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE
  18 # WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
  19 # NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
  20 # LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
  21 # OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
  22 # WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
  23 #
  24
  25 __revision__ = "__FILE__ __REVISION__ __DATE__ __DEVELOPER__"
  26
  27 import TestSCons
  28 import sys
  29 import string
  30 import re
  31 import time
  32
  33 _python_ = TestSCons._python_
  34
  35 test = TestSCons.TestSCons()
  36
  37 test.write('sleep_cat.py', """\
  38 import sys
  39 import time
  40 time.sleep(int(sys.argv[1]))
  41 fp = open(sys.argv[2], 'wb')
  42 for arg in sys.argv[3:]:
  43     fp.write(open(arg, 'rb').read())
  44 fp.close()
  45 sys.exit(0)
  46 """)
  47
  48 test.write('SConstruct', """
  49 env = Environment(PYTHON = r'%(_python_)s',
  50                   SLEEP_CAT = r'sleep_cat.py',
  51                   CATCOM = '$PYTHON $SLEEP_CAT $SECONDS $TARGET $SOURCES',
  52                   SECONDS = ARGUMENTS.get('SLEEP', '0'))
  53 f1 = env.Command('f1.out', 'f1.in', '$CATCOM')
  54 f2 = env.Command('f2.out', 'f2.in', '$CATCOM')
  55 f3 = env.Command('f3.out', 'f3.in', '$CATCOM')
  56 f4 = env.Command('f4.out', 'f4.in', '$CATCOM')
  57 env.Command('output', [f1, f2, f3, f4], '$CATCOM')
  58 """ % locals())
  59
  60 test.write('f1.in', "f1.in\n")
  61 test.write('f2.in', "f2.in\n")
  62 test.write('f3.in', "f3.in\n")
  63 test.write('f4.in', "f4.in\n")
  64
  65
  66
  67 def num(s, match):
  68     return float(re.search(match, s).group(1))
  69
  70 def within_tolerance(expected, actual, tolerance):
  71     return abs((expected-actual)/actual) <= tolerance
  72
  73
  74
  75 # Try to make our results a little more accurate and repeatable by
  76 # measuring Python overhead executing a minimal file, and reading the
  77 # scons.py script itself from disk so that it's already been cached.
  78 test.write('pass.py', "pass\n")
  79 test.read(test.program)
  80
  81 start_time = time.time()
  82 test.run(program=TestSCons.python, arguments=test.workpath('pass.py'))
  83 overhead = time.time() - start_time
  84
  85
  86
  87 start_time = time.time()
  88 test.run(arguments = "-j1 --debug=time . SLEEP=0")
  89 complete_time = time.time() - start_time
  90
  91
  92
  93 expected_total_time = complete_time - overhead
  94
  95 pattern = r'Command execution time: (\d+\.\d+) seconds'
  96 times = map(float, re.findall(pattern, test.stdout()))
  97 expected_command_time = reduce(lambda x, y: x + y, times, 0.0)
  98
  99
 100 stdout = test.stdout()
 101
 102 total_time      = num(stdout, r'Total build time: (\d+\.\d+) seconds')
 103 sconscript_time = num(stdout, r'Total SConscript file execution time: (\d+\.\d+) seconds')
 104 scons_time      = num(stdout, r'Total SCons execution time: (\d+\.\d+) seconds')
 105 command_time    = num(stdout, r'Total command execution time: (\d+\.\d+) seconds')
 106
 107 failures = []
 108
 109 if not within_tolerance(expected_command_time, command_time, 0.01):
 110     failures.append("""\
 111 SCons -j1 reported a total command execution time of %(command_time)s,
 112 but command execution times really totalled %(expected_command_time)s,
 113 outside of the 1%% tolerance.
 114 """ % locals())
 115
 116 added_times = sconscript_time+scons_time+command_time
 117 if not within_tolerance(total_time, added_times, 0.01):
 118     failures.append("""\
 119 SCons -j1 reported a total build time of %(total_time)s,
 120 but the various execution times actually totalled %(added_times)s,
 121 outside of the 1%% tolerance.
 122 """ % locals())
 123
 124 if not within_tolerance(total_time, expected_total_time, 0.15):
 125     failures.append("""\
 126 SCons -j1 reported total build time of %(total_time)s,
 127 but the actual measured build time was %(expected_total_time)s
 128 (end-to-end time of %(complete_time)s less Python overhead of %(overhead)s),
 129 outside of the 15%% tolerance.
 130 """ % locals())
 131
 132 if failures:
 133     print string.join([test.stdout()] + failures, '\n')
 134     test.fail_test(1)
 135
 136
 137
 138 test.run(arguments = "-c")
 139
 140 test.run(arguments = "-j4 --debug=time . SLEEP=1")
 141
 142
 143
 144 stdout = test.stdout()
 145
 146 total_time      = num(stdout, r'Total build time: (\d+\.\d+) seconds')
 147 sconscript_time = num(stdout, r'Total SConscript file execution time: (\d+\.\d+) seconds')
 148 scons_time      = num(stdout, r'Total SCons execution time: (\d+\.\d+) seconds')
 149 command_time    = num(stdout, r'Total command execution time: (\d+\.\d+) seconds')
 150
 151 failures = []
 152
 153 added_times = sconscript_time+scons_time+command_time
 154 if not within_tolerance(total_time, added_times, 0.01):
 155     failures.append("""\
 156 SCons -j4 reported a total build time of %(total_time)s,
 157 but the various execution times actually totalled %(added_times)s,
 158 outside of the 1%% tolerance.
 159 """ % locals())
 160
 161 if failures:
 162     print string.join([test.stdout()] + failures, '\n')
 163     test.fail_test(1)
 164
 165
 166 test.pass_test()