makefile: print out maximum memory usage in elapsed

Signed-off-by: Øyvind Harboe <[email protected]>

Author: oharboe

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,29 +26,25 @@ 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)
     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()

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:])