| 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 | # Pre-built one
|
| 54 | time2 = '/wedge/oils-for-unix.org/pkg/time-helper/2023-02-28/time-helper'
|
| 55 |
|
| 56 | if os.path.exists(time1):
|
| 57 | TIME_HELPER = time1
|
| 58 | elif os.path.exists(time2):
|
| 59 | TIME_HELPER = time2
|
| 60 | else:
|
| 61 | raise AssertionError('time-helper not found')
|
| 62 |
|
| 63 |
|
| 64 | def log(msg, *args):
|
| 65 | if args:
|
| 66 | msg = msg % args
|
| 67 | print(msg, file=sys.stderr)
|
| 68 |
|
| 69 |
|
| 70 | def Options():
|
| 71 | """Returns an option parser instance."""
|
| 72 | p = optparse.OptionParser('time.py [options] ARGV...')
|
| 73 | p.add_option('--tsv',
|
| 74 | dest='tsv',
|
| 75 | default=False,
|
| 76 | action='store_true',
|
| 77 | help='Write output in TSV format')
|
| 78 | p.add_option(
|
| 79 | '--rusage',
|
| 80 | dest='rusage',
|
| 81 | default=False,
|
| 82 | action='store_true',
|
| 83 | help='Also show user time, system time, and max resident set size')
|
| 84 | p.add_option('--time-span',
|
| 85 | dest='time_span',
|
| 86 | default=False,
|
| 87 | action='store_true',
|
| 88 | help='Also show start_time and end_time')
|
| 89 | p.add_option('-o',
|
| 90 | '--output',
|
| 91 | dest='output',
|
| 92 | default=None,
|
| 93 | help='Name of output file to write to to')
|
| 94 | p.add_option('-a',
|
| 95 | '--append',
|
| 96 | dest='append',
|
| 97 | default=False,
|
| 98 | action='store_true',
|
| 99 | help='Append to the file instead of overwriting it')
|
| 100 | p.add_option(
|
| 101 | '--field',
|
| 102 | dest='fields',
|
| 103 | default=[],
|
| 104 | action='append',
|
| 105 | help='A string to append to each row, after the exit code and status')
|
| 106 | p.add_option('--time-fmt',
|
| 107 | dest='time_fmt',
|
| 108 | default='%.4f',
|
| 109 | help='sprintf format for elapsed seconds (float)')
|
| 110 | p.add_option(
|
| 111 | '--stdout',
|
| 112 | dest='stdout',
|
| 113 | default=None,
|
| 114 | help='Save stdout to this file, and add a column for its md5 checksum')
|
| 115 | p.add_option(
|
| 116 | '--print-header',
|
| 117 | dest='print_header',
|
| 118 | default=False,
|
| 119 | action='store_true',
|
| 120 | help=
|
| 121 | 'Print an XSV header, respecting --time-span, --rusage, --stdout, --field, and --tsv'
|
| 122 | )
|
| 123 | return p
|
| 124 |
|
| 125 |
|
| 126 | def MakeTableOutput(f, tsv):
|
| 127 | if tsv: # TSV output.
|
| 128 | out = csv.writer(f,
|
| 129 | delimiter='\t',
|
| 130 | lineterminator='\n',
|
| 131 | doublequote=False,
|
| 132 | quoting=csv.QUOTE_NONE)
|
| 133 | else:
|
| 134 | out = csv.writer(f)
|
| 135 | return out
|
| 136 |
|
| 137 |
|
| 138 | def main(argv):
|
| 139 | (opts, child_argv) = Options().parse_args(argv[1:])
|
| 140 |
|
| 141 | # Used only for 'time' format string. For --field, we use our own.
|
| 142 | sep = '\t' if opts.tsv else ','
|
| 143 |
|
| 144 | if opts.print_header:
|
| 145 | if child_argv:
|
| 146 | raise RuntimeError('No arguments allowed with --print-header')
|
| 147 | names = ['status', 'elapsed_secs']
|
| 148 | if opts.time_span:
|
| 149 | names.extend(['start_time', 'end_time'])
|
| 150 | if opts.rusage:
|
| 151 | names.extend(['user_secs', 'sys_secs', 'max_rss_KiB'])
|
| 152 | if opts.stdout:
|
| 153 | names.append('stdout_md5sum')
|
| 154 | names.extend(opts.fields)
|
| 155 |
|
| 156 | if opts.output:
|
| 157 | f = open(opts.output, 'w')
|
| 158 | else:
|
| 159 | f = sys.stdout
|
| 160 | table_out = MakeTableOutput(f, opts.tsv)
|
| 161 | table_out.writerow(names)
|
| 162 | return 0
|
| 163 |
|
| 164 | if not child_argv:
|
| 165 | raise RuntimeError('Expected a command')
|
| 166 |
|
| 167 | # built by build/dev.sh all
|
| 168 | time_argv = [TIME_HELPER, '-d', sep]
|
| 169 |
|
| 170 | if opts.append:
|
| 171 | time_argv.append('-a')
|
| 172 |
|
| 173 | if opts.output:
|
| 174 | time_argv.extend(['-o', opts.output])
|
| 175 |
|
| 176 | # %x: exit status
|
| 177 | # %e: elapsed
|
| 178 | time_argv.extend(['-x', '-e'])
|
| 179 | if opts.time_span:
|
| 180 | # begin and end time
|
| 181 | time_argv.extend(['-y', '-z'])
|
| 182 | if opts.rusage:
|
| 183 | # %U: user time
|
| 184 | # %S: sys time
|
| 185 | # %M: Max RSS
|
| 186 | time_argv.extend(['-U', '-S', '-M'])
|
| 187 |
|
| 188 | time_argv.append('--')
|
| 189 | time_argv.extend(child_argv)
|
| 190 | #log('time_argv %s', time_argv)
|
| 191 |
|
| 192 | start_time = time.time()
|
| 193 | try:
|
| 194 | if opts.stdout:
|
| 195 | # We don't want to intermingle 'time' stdout with the program's stdout
|
| 196 | if not opts.output:
|
| 197 | raise RuntimeError('Flag -o is required when --stdout')
|
| 198 | with open(opts.stdout, 'w') as f:
|
| 199 | exit_code = subprocess.call(time_argv, stdout=f)
|
| 200 | else:
|
| 201 | exit_code = subprocess.call(time_argv)
|
| 202 | except OSError as e:
|
| 203 | log('Error executing %s: %s', time_argv, e)
|
| 204 | return 1
|
| 205 |
|
| 206 | elapsed = time.time() - start_time
|
| 207 | if opts.stdout:
|
| 208 | if hashlib:
|
| 209 | m = hashlib.md5() # PY3
|
| 210 | else:
|
| 211 | m = md5.new() # PY2
|
| 212 | with open(opts.stdout, 'rb') as f:
|
| 213 | while True:
|
| 214 | chunk = f.read(4096)
|
| 215 | if not chunk:
|
| 216 | break
|
| 217 | m.update(chunk)
|
| 218 | maybe_stdout = [m.hexdigest()]
|
| 219 | else:
|
| 220 | maybe_stdout = [] # no field
|
| 221 |
|
| 222 | more_cells = maybe_stdout + opts.fields
|
| 223 |
|
| 224 | if opts.output:
|
| 225 | with open(opts.output, 'a') as f: # append
|
| 226 | if more_cells:
|
| 227 | f.write(sep) # tab or comma for more cells
|
| 228 | table_out = MakeTableOutput(f, opts.tsv)
|
| 229 | table_out.writerow(more_cells)
|
| 230 | else:
|
| 231 | f.write('\n') # end the row
|
| 232 | else:
|
| 233 | if more_cells:
|
| 234 | log("More cells that -o would have written: %s", more_cells)
|
| 235 |
|
| 236 | # Preserve the command's exit code. (This means you can't distinguish
|
| 237 | # between a failure of time.py and the command, but that's better than
|
| 238 | # swallowing the error.)
|
| 239 | return exit_code
|
| 240 |
|
| 241 |
|
| 242 | if __name__ == '__main__':
|
| 243 | try:
|
| 244 | status = main(sys.argv)
|
| 245 | except KeyboardInterrupt as e:
|
| 246 | print('%s: interrupted with Ctrl-C' % sys.argv[0], file=sys.stderr)
|
| 247 | sys.exit(1)
|
| 248 | except RuntimeError as e:
|
| 249 | log('time_.py: %s', e)
|
| 250 | status = 2
|
| 251 | sys.exit(status)
|