| 1 | #!/usr/bin/env python2
|
| 2 | """
|
| 3 | time.py -- Replacement for coreutils 'time'.
|
| 4 |
|
| 5 | TODO:
|
| 6 | (Must be Python 3 because it's used before a Python 2 WEDGE can be installed.)
|
| 7 |
|
| 8 | The interface of this program is modelled after:
|
| 9 |
|
| 10 | /usr/bin/time --append --output foo.txt --format '%x %e'
|
| 11 |
|
| 12 | Why we're not using /usr/bin/time:
|
| 13 | - We need to print extra TSV fields at the end of the row, but it prints a newline
|
| 14 | - It prints extraneous output: 'Command exited with non-zero status 1'
|
| 15 | - Elapsed time only has 2 digits of precision. Apparently it uses times()
|
| 16 | rather than getrusage()? https://unix.stackexchange.com/questions/70653/increase-e-precision-with-usr-bin-time-shell-command
|
| 17 |
|
| 18 | Problems with resource.getrusage() in Python:
|
| 19 |
|
| 20 | The memory usage of dash and bash get obscured by Python! Because
|
| 21 | subprocess.call() does a fork(), which includes Python's address space.
|
| 22 | # https://stackoverflow.com/questions/13880724/python-getrusage-with-rusage-children-behaves-stangely
|
| 23 |
|
| 24 | Problems with bash time builtin
|
| 25 | - has no way to get the exit code
|
| 26 | - writes to stderr, so you it's annoying to get both process stderr and the
|
| 27 | timing
|
| 28 |
|
| 29 | This program also writes CSV and TSV directly.
|
| 30 | - CSV values get escaped
|
| 31 | - TSV values can't have tabs
|
| 32 |
|
| 33 | So we use a tiny C program time-helper.c to do it, and not /usr/bin/time.
|
| 34 | """
|
| 35 | from __future__ import print_function
|
| 36 |
|
| 37 | import csv
|
| 38 | try:
|
| 39 | import hashlib # PY3
|
| 40 | except ImportError:
|
| 41 | hashlib = None
|
| 42 | import md5
|
| 43 |
|
| 44 | import optparse
|
| 45 | import os
|
| 46 | import sys
|
| 47 | import subprocess
|
| 48 | import time
|
| 49 |
|
| 50 | THIS_DIR = os.path.dirname(os.path.abspath(sys.argv[0]))
|
| 51 |
|
| 52 | time1 = os.path.abspath(os.path.join(THIS_DIR, '../_devbuild/bin/time-helper'))
|
| 53 |
|
| 54 | # Pre-built ones, for CI images - I guess some of them don't have compilers
|
| 55 | rel_path = 'time-helper/2023-02-28/time-helper'
|
| 56 | time2 = os.path.join(THIS_DIR, '../../oils.DEPS/wedge', rel_path)
|
| 57 | time3 = os.path.join('/wedge/oils-for-unix.org/pkg', rel_path)
|
| 58 |
|
| 59 | if os.path.exists(time1):
|
| 60 | TIME_HELPER = time1
|
| 61 | elif os.path.exists(time2):
|
| 62 | TIME_HELPER = time2
|
| 63 | elif os.path.exists(time3):
|
| 64 | TIME_HELPER = time3
|
| 65 | else:
|
| 66 | raise AssertionError('time-helper not found')
|
| 67 |
|
| 68 | def log(msg, *args):
|
| 69 | if args:
|
| 70 | msg = msg % args
|
| 71 | print(msg, file=sys.stderr)
|
| 72 |
|
| 73 |
|
| 74 | def Options():
|
| 75 | """Returns an option parser instance."""
|
| 76 | p = optparse.OptionParser('time.py [options] ARGV...')
|
| 77 | p.add_option('--tsv',
|
| 78 | dest='tsv',
|
| 79 | default=False,
|
| 80 | action='store_true',
|
| 81 | help='Write output in TSV format')
|
| 82 | p.add_option(
|
| 83 | '--rusage',
|
| 84 | dest='rusage',
|
| 85 | default=False,
|
| 86 | action='store_true',
|
| 87 | help='Also show user time, system time, and max resident set size')
|
| 88 | p.add_option('--rusage-2',
|
| 89 | dest='rusage_2',
|
| 90 | default=False,
|
| 91 | action='store_true',
|
| 92 | help='Also show page faults, context switches, etc.')
|
| 93 | p.add_option('--time-span',
|
| 94 | dest='time_span',
|
| 95 | default=False,
|
| 96 | action='store_true',
|
| 97 | help='Also show start_time and end_time')
|
| 98 | p.add_option('-o',
|
| 99 | '--output',
|
| 100 | dest='output',
|
| 101 | default=None,
|
| 102 | help='Name of output file to write to to')
|
| 103 | p.add_option('-a',
|
| 104 | '--append',
|
| 105 | dest='append',
|
| 106 | default=False,
|
| 107 | action='store_true',
|
| 108 | help='Append to the file instead of overwriting it')
|
| 109 | p.add_option(
|
| 110 | '--field',
|
| 111 | dest='fields',
|
| 112 | default=[],
|
| 113 | action='append',
|
| 114 | help='A string to append to each row, after the exit code and status')
|
| 115 | p.add_option('--time-fmt',
|
| 116 | dest='time_fmt',
|
| 117 | default='%.4f',
|
| 118 | help='sprintf format for elapsed seconds (float)')
|
| 119 | p.add_option(
|
| 120 | '--stdout',
|
| 121 | dest='stdout',
|
| 122 | default=None,
|
| 123 | help='Save stdout to this file, and add a column for its md5 checksum')
|
| 124 | p.add_option(
|
| 125 | '--print-header',
|
| 126 | dest='print_header',
|
| 127 | default=False,
|
| 128 | action='store_true',
|
| 129 | help=
|
| 130 | 'Print an XSV header, respecting --time-span, --rusage, --rusage-2, --stdout, --field, and --tsv'
|
| 131 | )
|
| 132 | return p
|
| 133 |
|
| 134 |
|
| 135 | def MakeTableOutput(f, tsv):
|
| 136 | if tsv: # TSV output.
|
| 137 | out = csv.writer(f,
|
| 138 | delimiter='\t',
|
| 139 | lineterminator='\n',
|
| 140 | doublequote=False,
|
| 141 | quoting=csv.QUOTE_NONE)
|
| 142 | else:
|
| 143 | out = csv.writer(f)
|
| 144 | return out
|
| 145 |
|
| 146 |
|
| 147 | def main(argv):
|
| 148 | (opts, child_argv) = Options().parse_args(argv[1:])
|
| 149 |
|
| 150 | # Used only for 'time' format string. For --field, we use our own.
|
| 151 | sep = '\t' if opts.tsv else ','
|
| 152 |
|
| 153 | if opts.print_header:
|
| 154 | if child_argv:
|
| 155 | raise RuntimeError('No arguments allowed with --print-header')
|
| 156 | names = ['status', 'elapsed_secs']
|
| 157 | if opts.time_span:
|
| 158 | names.extend(['start_time', 'end_time'])
|
| 159 | if opts.rusage:
|
| 160 | names.extend(['user_secs', 'sys_secs', 'max_rss_KiB'])
|
| 161 | if opts.rusage_2:
|
| 162 | names.extend([
|
| 163 | 'minor_faults', 'major_faults', 'swaps', 'in_block',
|
| 164 | 'out_block', 'signals', 'voluntary_ctx', 'involuntary_ctx'
|
| 165 | ])
|
| 166 | if opts.stdout:
|
| 167 | names.append('stdout_md5sum')
|
| 168 | names.extend(opts.fields)
|
| 169 |
|
| 170 | if opts.output:
|
| 171 | f = open(opts.output, 'w')
|
| 172 | else:
|
| 173 | f = sys.stdout
|
| 174 | table_out = MakeTableOutput(f, opts.tsv)
|
| 175 | table_out.writerow(names)
|
| 176 | return 0
|
| 177 |
|
| 178 | if not child_argv:
|
| 179 | raise RuntimeError('Expected a command')
|
| 180 |
|
| 181 | # built by build/dev.sh all
|
| 182 | time_argv = [TIME_HELPER, '-d', sep]
|
| 183 |
|
| 184 | if opts.append:
|
| 185 | time_argv.append('-a')
|
| 186 |
|
| 187 | if opts.output:
|
| 188 | time_argv.extend(['-o', opts.output])
|
| 189 | else:
|
| 190 | pass
|
| 191 | # Somehow this doesn't work? Getting binary data?
|
| 192 | # time_argv.extend(['-o', '/dev/stdout'])
|
| 193 |
|
| 194 | # %x: exit status
|
| 195 | # %e: elapsed
|
| 196 | time_argv.extend(['-x', '-e'])
|
| 197 | if opts.time_span:
|
| 198 | # begin and end time
|
| 199 | time_argv.extend(['-y', '-z'])
|
| 200 | if opts.rusage:
|
| 201 | # %U: user time
|
| 202 | # %S: sys time
|
| 203 | # %M: Max RSS
|
| 204 | time_argv.extend(['-U', '-S', '-M'])
|
| 205 | if opts.rusage_2:
|
| 206 | time_argv.extend(['-m'])
|
| 207 |
|
| 208 | time_argv.append('--')
|
| 209 | time_argv.extend(child_argv)
|
| 210 | #log('time_argv %s', time_argv)
|
| 211 |
|
| 212 | start_time = time.time()
|
| 213 | try:
|
| 214 | if opts.stdout:
|
| 215 | # We don't want to intermingle 'time' stdout with the program's stdout
|
| 216 | if not opts.output:
|
| 217 | raise RuntimeError('Flag -o is required when --stdout')
|
| 218 | with open(opts.stdout, 'w') as f:
|
| 219 | exit_code = subprocess.call(time_argv, stdout=f)
|
| 220 | else:
|
| 221 | exit_code = subprocess.call(time_argv)
|
| 222 | except OSError as e:
|
| 223 | log('Error executing %s: %s', time_argv, e)
|
| 224 | return 1
|
| 225 |
|
| 226 | if opts.stdout:
|
| 227 | if hashlib:
|
| 228 | m = hashlib.md5() # PY3
|
| 229 | else:
|
| 230 | m = md5.new() # PY2
|
| 231 | with open(opts.stdout, 'rb') as f:
|
| 232 | while True:
|
| 233 | chunk = f.read(4096)
|
| 234 | if not chunk:
|
| 235 | break
|
| 236 | m.update(chunk)
|
| 237 | maybe_stdout = [m.hexdigest()]
|
| 238 | else:
|
| 239 | maybe_stdout = [] # no field
|
| 240 |
|
| 241 | more_cells = maybe_stdout + opts.fields
|
| 242 |
|
| 243 | if opts.output:
|
| 244 | with open(opts.output, 'a') as f: # append
|
| 245 | if more_cells:
|
| 246 | f.write(sep) # tab or comma for more cells
|
| 247 | table_out = MakeTableOutput(f, opts.tsv)
|
| 248 | table_out.writerow(more_cells)
|
| 249 | else:
|
| 250 | f.write('\n') # end the row
|
| 251 | else:
|
| 252 | if more_cells:
|
| 253 | log("More cells that -o would have written: %s", more_cells)
|
| 254 |
|
| 255 | # Preserve the command's exit code. (This means you can't distinguish
|
| 256 | # between a failure of time.py and the command, but that's better than
|
| 257 | # swallowing the error.)
|
| 258 | return exit_code
|
| 259 |
|
| 260 |
|
| 261 | if __name__ == '__main__':
|
| 262 | try:
|
| 263 | status = main(sys.argv)
|
| 264 | except KeyboardInterrupt as e:
|
| 265 | print('%s: interrupted with Ctrl-C' % sys.argv[0], file=sys.stderr)
|
| 266 | sys.exit(1)
|
| 267 | except RuntimeError as e:
|
| 268 | log('time_.py: %s', e)
|
| 269 | status = 2
|
| 270 | sys.exit(status)
|