From 4eb811a009dd1d7d8a12d81b8535ef5383ccbf69 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=98yvind=20Harboe?= Date: Wed, 17 Apr 2024 00:14:22 +0200 Subject: [PATCH] makefile: print out maximum memory usage in elapsed MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Øyvind Harboe --- flow/test/test_genElapsedTime.py | 58 +++++++++++++----------------- flow/util/genElapsedTime.py | 62 +++++++++++++++++++------------- 2 files changed, 63 insertions(+), 57 deletions(-) diff --git a/flow/test/test_genElapsedTime.py b/flow/test/test_genElapsedTime.py index ab9bcadd00..543ee178fe 100755 --- a/flow/test/test_genElapsedTime.py +++ b/flow/test/test_genElapsedTime.py @@ -7,12 +7,14 @@ import sys import os import tempfile -import importlib # module reloading # make sure the working dir is flow/ -sys.path.append(os.path.join(os.path.dirname(os.path.abspath(__file__)), '..', 'util')) +sys.path.append(os.path.join(os.path.dirname(os.path.abspath(__file__)), + '..', 'util')) os.chdir(os.path.join(os.path.dirname(os.path.abspath(__file__)))) +import genElapsedTime + class TestElapsedTime(unittest.TestCase): def setUp(self): self.tmp_dir = tempfile.TemporaryDirectory() @@ -24,14 +26,12 @@ def test_elapsed_time(self, mock_stdout): # create a log file with elapsed time with open(self.log_file, "w") as f: f.write("Some log entry\n") - f.write("Elapsed time: 01:30:00[h:]min:sec.\n") + f.write("Elapsed time: 01:30:00[h:]min:sec. Peak memory: 9667132KB.\n") # call the script with the test log file - sys.argv = ["./genElapsedTime.py", "--logDir", str(self.tmp_dir.name), - "--noHeader"] - with patch.object(sys, 'argv', sys.argv): - module = importlib.import_module(self.module_name) + genElapsedTime.scan_logs(["--logDir", str(self.tmp_dir.name), + "--noHeader"]) # check if output is correct - expected_output = self.tmp_dir.name + "\n1_test 5400\nTotal 5400\n" + expected_output = self.tmp_dir.name + "\n1_test 5400 9667132\nTotal 5400 9667132\n" self.assertEqual(mock_stdout.getvalue(), expected_output) @patch("sys.stdout", new_callable=StringIO) @@ -39,14 +39,12 @@ def test_zero_time(self, mock_stdout): # create a log file with elapsed time with open(self.log_file, "w") as f: f.write("Some log entry\n") - f.write("Elapsed time: 00:00:74[h:]min:sec.\n") + f.write("Elapsed time: 00:00:74[h:]min:sec. Peak memory: 9667132KB.\n") # call the script with the test log file - sys.argv = ["./genElapsedTime.py", "--logDir", str(self.tmp_dir.name), - "--noHeader"] - with patch.object(sys, 'argv', sys.argv): - module = importlib.import_module(self.module_name) - # check if output is correct - self.assertEqual(mock_stdout.getvalue(), "") + genElapsedTime.scan_logs(["--logDir", str(self.tmp_dir.name), + "--noHeader"]) + expected_output = self.tmp_dir.name + "\n1_test 74 9667132\nTotal 74 9667132\n" + self.assertEqual(mock_stdout.getvalue(), expected_output) @patch("sys.stdout", new_callable=StringIO) def test_elapsed_time_longer_duration(self, mock_stdout): @@ -55,36 +53,30 @@ def test_elapsed_time_longer_duration(self, mock_stdout): f.write("Some log entry\n") f.write("Elapsed time: 12:24.14[h:]min:sec. CPU time: user 5081.82 sys 170.18 (705%). Peak memory: 9667132KB.\n") # call the script with the test log file - sys.argv = ["util/genElapsedTime.py", "--logDir", str(self.tmp_dir.name), - "--noHeader"] - with patch.object(sys, 'argv', sys.argv): - module = importlib.import_module(self.module_name) - importlib.reload(module) + genElapsedTime.scan_logs(["--logDir", str(self.tmp_dir.name), + "--noHeader"]) # check if output is correct - expected_output = self.tmp_dir.name + "\n1_test 744\nTotal 744\n" + expected_output = (self.tmp_dir.name + + "\n1_test 744 9667132\nTotal 744 9667132\n") self.assertEqual(mock_stdout.getvalue(), expected_output) def test_missing_arg(self): with self.assertRaises(SystemExit): with patch('sys.stderr', new=StringIO()) as fake_err_output: - with patch('sys.argv', ["util/genElapsedTime.py"]): - module = importlib.import_module(self.module_name) - importlib.reload(module) + genElapsedTime.scan_logs(["util/genElapsedTime.py"]) self.assertIn('--logDir', fake_err_output.getvalue()) - def test_no_elapsed_time(self): + @patch("sys.stderr", new_callable=StringIO) + def test_no_elapsed_time(self, fake_err_output): with open(self.log_file, "w") as f: f.write('Other log message') - with patch('sys.argv', ["util/genElapsedTime.py", - "--logDir", str(self.tmp_dir.name), - "--noHeader"]): - with patch('sys.stderr', new=StringIO()) as fake_err_output: - module = importlib.import_module(self.module_name) - importlib.reload(module) - self.assertIn('No elapsed time found in', fake_err_output.getvalue()) + genElapsedTime.scan_logs(["--logDir", str(self.tmp_dir.name), + "--noHeader"]) + self.assertIn('No elapsed time found in', fake_err_output.getvalue()) def tearDown(self): - self.tmp_dir.cleanup() + self.tmp_dir.cleanup() + if __name__ == '__main__': unittest.main() diff --git a/flow/util/genElapsedTime.py b/flow/util/genElapsedTime.py index 4b40fdd0ec..3295604a02 100755 --- a/flow/util/genElapsedTime.py +++ b/flow/util/genElapsedTime.py @@ -11,24 +11,12 @@ # Parse and validate arguments # ============================================================================== -parser = argparse.ArgumentParser( - description='Print elapsed time for every step in the flow') -parser.add_argument('--logDir', '-d', required=True, nargs='+', - help='Log files directories') -parser.add_argument('--noHeader', action='store_true', - help='Skip the header') -args = parser.parse_args() - -if not args.logDir: - print('[ERROR] Please add a logDir' - '-d/--logDir.', file=sys.stderr) - parser.print_help() - sys.exit(1) - - -def print_log_dir_times(logdir): + + +def print_log_dir_times(logdir, args): first = True totalElapsed = 0 + total_max_memory = 0 print(logdir) # Loop on all log files in the directory @@ -39,8 +27,11 @@ def print_log_dir_times(logdir): with open(str(f)) as logfile: found = False for line in logfile: - elapsedTime = 0 + elapsedTime = None + peak_memory = None + # Example line: + # Elapsed time: 0:04.26[h:]min:sec. CPU time: user 4.08 sys 0.17 (99%). Peak memory: 671508KB. if 'Elapsed time' in line: found = True # Extract the portion that has the time @@ -61,23 +52,46 @@ def print_log_dir_times(logdir): else: print('Elapsed time not understood in', str(line), file=sys.stderr) + # Find Peak Memory + peak_memory = line.split('Peak memory: ')[1].split('KB')[0] if not found: print('No elapsed time found in', str(f), file=sys.stderr) continue # Print the name of the step and the corresponding elapsed time - if elapsedTime != 0: + format_str = "%-25s %20s %14s" + if elapsedTime is not None and peak_memory is not None: if first and not args.noHeader: - print("%-25s %10s" % ("Log", "Elapsed seconds")) + print(format_str % + ("Log", "Elapsed seconds", "Peak Memory/KB")) first = False - print('%-25s %10s' % (os.path.splitext( - os.path.basename(str(f)))[0], elapsedTime)) + print(format_str % (os.path.splitext( + os.path.basename(str(f)))[0], elapsedTime, peak_memory)) totalElapsed += elapsedTime + total_max_memory = max(total_max_memory, int(peak_memory)) if totalElapsed != 0: - print("%-25s %10s" % ("Total", totalElapsed)) + print(format_str % ("Total", totalElapsed, total_max_memory)) + + +def scan_logs(args): + parser = argparse.ArgumentParser(description='Print elapsed time for every step in the flow') + parser.add_argument('--logDir', '-d', required=True, nargs='+', + help='Log files directories') + parser.add_argument('--noHeader', action='store_true', + help='Skip the header') + args = parser.parse_args(args) + + if not args.logDir: + print('[ERROR] Please add a logDir' + '-d/--logDir.', file=sys.stderr) + parser.print_help() + sys.exit(1) + + for log_dir in args.logDir: + print_log_dir_times(log_dir, args) -for log_dir in args.logDir: - print_log_dir_times(log_dir) +if __name__ == '__main__': + scan_logs(sys.argv[1:])