From 1fb71cf6fc68add2f4b1ff3446c0eb6ae650747b Mon Sep 17 00:00:00 2001 From: Joe Hamman Date: Thu, 28 Jul 2016 12:13:15 -0700 Subject: [PATCH] VIC 5 performance profiling (#560) * add profiling tests and also print timing table from end of std out when profiling -- usefull when understanding the runtime along side the call graph --- .gitignore | 6 + ci/requirements.yml | 2 + tests/profiling/README.md | 4 + tests/profiling/run_gprof.bash | 58 +++++++++ tests/run_profiling.py | 221 +++++++++++++++++++++++++++++++++ 5 files changed, 291 insertions(+) create mode 100644 tests/profiling/README.md create mode 100755 tests/profiling/run_gprof.bash create mode 100755 tests/run_profiling.py diff --git a/.gitignore b/.gitignore index 674f2d010..5c0ef4d1f 100644 --- a/.gitignore +++ b/.gitignore @@ -28,6 +28,12 @@ vic_classic.exe vic_image.exe liblnd.a _vic.py +vic_timing_*txt +massif.out.* +vic_call_graph_* + +vic_call_graph* +gmon.out .DS_Store TAGS diff --git a/ci/requirements.yml b/ci/requirements.yml index 6e97212fb..cbc696634 100644 --- a/ci/requirements.yml +++ b/ci/requirements.yml @@ -10,8 +10,10 @@ dependencies: - configobj - xarray - bottleneck + - psutil - pip: - git+https://github.com/UW-Hydro/tonic.git - engarde - pytest-faulthandler - pytest-xdist + - gprof2dot diff --git a/tests/profiling/README.md b/tests/profiling/README.md new file mode 100644 index 000000000..ffa974bba --- /dev/null +++ b/tests/profiling/README.md @@ -0,0 +1,4 @@ +VIC Profiling Tests +======= + +These tests quantify the performance of VIC in terms of CPU/wall time and memory usage. diff --git a/tests/profiling/run_gprof.bash b/tests/profiling/run_gprof.bash new file mode 100755 index 000000000..a813acd37 --- /dev/null +++ b/tests/profiling/run_gprof.bash @@ -0,0 +1,58 @@ +#!/usr/bin/env bash +set -e +# set -x + +# A POSIX variable +OPTIND=1 # Reset in case getopts has been used previously in the shell. + +# Initialize our own variables: +vic_exe="" +vic_global="" + +function usage { + echo "Usage: `basename $0` -e vic_executable -g vic_global -h for help"; +} + + +while getopts "h?e::g::" opt; do + case "$opt" in + h|\?) + usage + exit 0 + ;; + e) vic_exe=$OPTARG ;; + g) vic_global=$OPTARG ;; + esac +done + +shift $((OPTIND-1)) + +[ "$1" = "--" ] && shift + +GIT_VERSION=$(git describe --abbrev=4 --dirty --always --tags) + +echo "----------------------- START VIC GPROF PROFILING -----------------------" +echo "" +echo "Date : $(date)" +echo "Machine : $HOSTNAME" +echo "User : $USER" +echo "VIC Test Git Version : $GIT_VERSION" +echo "VIC Executable : $vic_exe" +echo "VIC Global Parameter File : $vic_global" +echo "" + +echo "VIC Executable Version Info" +echo "---------------------------" +$vic_exe -v +echo "" + +$vic_exe -g $vic_global 2>&1 | tail -n 55 + +now=`date +"%y%m%d"` +gprof $vic_exe | gprof2dot | dot -Tpng -o vic_call_graph_$now.png + +echo "" +echo "------------------------ END VIC GPROF PROFILING ------------------------" +exit 0 + +# End of file diff --git a/tests/run_profiling.py b/tests/run_profiling.py new file mode 100755 index 000000000..796fe3be9 --- /dev/null +++ b/tests/run_profiling.py @@ -0,0 +1,221 @@ +#!/usr/bin/env python +'''VIC testing command line interface''' + +from __future__ import print_function +import os +import argparse +from collections import namedtuple +import psutil +import string +import subprocess +from subprocess import check_call +import datetime +import getpass +import socket +import time + +import numpy as np + +from tonic.models.vic.vic import VIC + +host_config = namedtuple('host_config', + ('max_cores', 'template', 'submit', 'mpiexec')) + +table_header = '''----------------- START VIC SCALING PROFILE ----------------- + +Date : $date +Machine : $hostname +User : $user +VIC Test Git Version : $git_version +VIC Executable : $vic_exe +VIC Global Parameter File : $vic_global +Test Maximum MPI Cores : $max_cores + +VIC Executable Version Info +--------------------------- +$vic_version +Cores | Time (Seconds) +---------------------- +''' + + +hosts = { + 'local': host_config(max_cores=psutil.cpu_count(), submit=None, template=None, + mpiexec=os.getenv('MPIEXEC', 'mpiexec')), + 'hydra': host_config(max_cores=64, submit='qsub', mpiexec='mpiexec', + template='''#!/bin/bash +# +#$ -N VIC_scaling_test_$np +#$ -cwd +#$ -j y +#$ -S /bin/bash +#$ -m be +#$ -pe orte $np + +# Qsub template for UW's Hydra Cluster +# Scheduler: SGE +# Valid values for np 1-64 +if [ "$np" -gt "64" ] + echo "$np exceeds maximum number of processes on Hydra" + exit 1 +fi + +START=$(date +%s) +mpiexec -np $np $vic_exe -g $vic_global +END=$(date +%s) +DIFF=$(echo "$END - $START" | bc) +printf "%5s | %f" $np $DIFF >> $timing_table_file'''), + } + +OUTPUT_WIDTH = 100 + +description = ''' + VIC Test Suite +------------------------------------------------------------------------------- +This is the VIC Profiling Test Suite. There are 2 main test types: + + 1. Gprof Profiling: This test will generate a profiling call graph using + gprof. This test requires building your VIC executable with the flags `-pg`. + 2. Scaling: This test will generate a MPI scaling timing table. +------------------------------------------------------------------------------- +''' + +epilog = ''' +------------------------------------------------------------------------------- +For questions about the development or use of VIC or use of this test module, +please email the VIC users list serve at vic_users@u.washington.edu. +------------------------------------------------------------------------------- +''' + + +class CustomFormatter(argparse.ArgumentDefaultsHelpFormatter, + argparse.RawDescriptionHelpFormatter): + pass + + +def main(): + ''' ''' + # dates and times + starttime = datetime.datetime.now() + ymd = starttime.strftime('%Y%m%d') + + # parse command line options + parser = argparse.ArgumentParser(description=description, epilog=epilog, + formatter_class=CustomFormatter) + + parser.add_argument('vic_exe', type=str, + help='VIC executable to test') + parser.add_argument('--kind', type=str, + help='Specify which type of test should be run', + choices=['scaling', 'profile'], + default='scaling') + parser.add_argument('--host', type=str, + help='Host machine to run test on, if not specified, ' + 'test will be run locally', + choices=list(hosts.keys()), + default='local') + parser.add_argument('--global_param', '-g', type=str, + help='global parameter file to test') + parser.add_argument('--timing', '-t', type=str, + default='vic_timing_{}.txt'.format(ymd), + help='path to timing file') + parser.add_argument('--clean', action='store_true', help='Clean up run files') + parser.add_argument('--test', action='store_true', + help='Test the setup but do not run VIC') + + args = parser.parse_args() + + if args.global_param is None: + raise ValueError('Global Parameter option is required') + + if args.kind == 'scaling': + run_scaling(args) + elif args.kind == 'profile': + run_profiling(args) + else: + raise ValueError('Unknown test kind %s' % args.kind) + + +def run_profiling(args): + '''wrapper function for profiling tests''' + cmd = './profiling/run_gprof.bash -e {vic_exe} -g {vic_global}'.format( + vic_exe=args.vic_exe, vic_global=args.global_param) + check_call(cmd, shell=True) + + +def run_scaling(args): + '''wrapper function for scaling tests''' + config = hosts[args.host] + vic_exe = VIC(args.vic_exe) + + # write timing file header + header = string.Template(table_header) + header_kwargs = get_header_info(args.vic_exe, args.global_param, + config.max_cores) + header = header.safe_substitute(**header_kwargs) + with open(args.timing, 'w') as f: + f.write(header) + + for n in log2_range(config.max_cores).astype(np.int): + if config.template: + # run on a cluster of some kind + # start by printing the template + print('-'.ljust(OUTPUT_WIDTH, '-')) + print('{host} template'.format(host=args.host).center(OUTPUT_WIDTH)) + print('-'.ljust(OUTPUT_WIDTH, '-')) + print(config.template) + print('-'.ljust(OUTPUT_WIDTH, '-')) + template = string.Template(config.template) + + run_string = template.safe_substitute(np=n, vic_exe=args.vic_exe, + vic_global=args.global_param, + timing_table_file=args.timing) + run_file = 'vic_{host}_{n}.sh'.format(host=args.host, n=n) + with open(run_file, 'w') as f: + f.write(run_string) + + cmd = '{submit} {run_file}'.format(submit=config.submit, + run_file=run_file) + print(cmd) + if not args.test: + check_call(cmd, shell=True) + + if args.clean: + os.remove(run_file) + else: + # run locally + print('Running {} with {} processors'.format(args.vic_exe, n)) + if not args.test: + start = time.time() + vic_exe.run(args.global_param, mpi_proc=int(n)) + end = time.time() + diff = end - start + with open(args.timing, 'a') as f: + f.write('%5s | %.2f\n' % (n, diff)) + + print('See %s for scaling table' % args.timing) + + +def log2_range(m): + '''make an array of integers that increase by 2^n with maximum value of m''' + n = int(np.floor(np.log2(m))) + 1 + return np.exp2(np.arange(n)).astype(np.int) + + +def get_header_info(vic_exe, vic_global, max_cores): + '''get info for timing table headers''' + header_kwargs = {} + header_kwargs['date'] = datetime.datetime.now() + header_kwargs['hostname'] = socket.gethostname() + header_kwargs['user'] = getpass.getuser() + header_kwargs['git_version'] = subprocess.check_output( + ['git', 'describe', '--abbrev=4', '--dirty', '--always', '--tags']).decode() + header_kwargs['vic_exe'] = vic_exe + header_kwargs['vic_global'] = vic_global + header_kwargs['max_cores'] = max_cores + header_kwargs['vic_version'] = subprocess.check_output([vic_exe, '-v']).decode() + return header_kwargs + + +if __name__ == '__main__': + main()