From e51ff447105528e09002f9b3cd509df39f2e6e0e Mon Sep 17 00:00:00 2001
From: Ganesh Gore <goreganesh007@gmail.com>
Date: Wed, 21 Aug 2019 11:08:47 -0600
Subject: [PATCH] Added execution time information in logs

---
 openfpga_flow/scripts/run_fpga_task.py | 43 +++++++++++++++++++-------
 1 file changed, 31 insertions(+), 12 deletions(-)

diff --git a/openfpga_flow/scripts/run_fpga_task.py b/openfpga_flow/scripts/run_fpga_task.py
index 4ff388cd2..6009ad22b 100644
--- a/openfpga_flow/scripts/run_fpga_task.py
+++ b/openfpga_flow/scripts/run_fpga_task.py
@@ -2,6 +2,7 @@ import os
 import sys
 import shutil
 import time
+from datetime import timedelta
 import shlex
 import argparse
 from configparser import ConfigParser, ExtendedInterpolation
@@ -13,6 +14,10 @@ import csv
 from string import Template
 import run_fpga_flow
 import pprint
+import importlib
+
+if importlib.util.find_spec("humanize"):
+    import humanize
 
 # = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = =
 # Configure logging system
@@ -35,6 +40,8 @@ parser.add_argument('--test_run', action="store_true",
                     help="Dummy run shows final generated VPR commands")
 parser.add_argument('--debug', action="store_true",
                     help="Run script in debug mode")
+parser.add_argument('--skip_tread_logs', action="store_true",
+                    help="Skips logs from running thread")
 args = parser.parse_args()
 
 # = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = =
@@ -220,9 +227,13 @@ def create_run_command(curr_job_dir, archfile, benchmark_obj, task_conf):
         command += ["--vpr_fpga_spice"]
     if task_conf.getboolean("GENERAL", "verilog_output", fallback=False):
         command += ["--vpr_fpga_verilog"]
+        command += ["--vpr_fpga_verilog_dir", "."]
+        command += ["--vpr_fpga_x2p_rename_illegal_port"]
 
     # Add other paramters to pass
     for key, values in task_conf["SCRIPT_PARAM"].items():
+        command += ["--"+key, values] if values else ["--"+key]
+
     if args.debug:
         command += ["--debug"]
     return command
@@ -234,23 +245,31 @@ def run_single_script(s, eachJob):
         logger.debug("Running OpenFPGA flow with " +
                      " ".join(eachJob["commands"]))
         name = threading.currentThread().getName()
+        eachJob["starttime"] = time.time()
         try:
             logfile = "%s_out.log" % name
             with open(logfile, 'w+') as output:
-                process = subprocess.run(["python3.5",
-                                          gc["script_default"]] +
-                                         eachJob["commands"],
-                                         check=True,
-                                         stdout=subprocess.PIPE,
-                                         stderr=subprocess.PIPE,
-                                         universal_newlines=True)
-                output.write(process.stdout)
+                process = subprocess.Popen(["python3.5",
+                                            gc["script_default"]] +
+                                           eachJob["commands"],
+                                           stdout=subprocess.PIPE,
+                                           stderr=subprocess.STDOUT,
+                                           universal_newlines=True)
+                for line in process.stdout:
+                    if not args.skip_tread_logs:
+                        logging.info(line[:-1])
+                    sys.stdout.buffer.flush()
+                    output.write(line)
+                process.wait()
                 eachJob["status"] = True
         except:
-            logger.error("Failed to execute openfpga flow - " +
-                         eachJob["name"])
-            # logger.exception("Failed to launch openfpga flow")
-        logger.info("%s Finished " % name)
+            logger.exception("Failed to execute openfpga flow - " +
+                             eachJob["name"])
+        eachJob["endtime"] = time.time()
+        timediff = timedelta(seconds=(eachJob["endtime"]-eachJob["starttime"]))
+        timestr = humanize.naturaldelta(timediff) if "humanize" in sys.modules \
+            else str(timediff)
+        logger.info("%s Finished, Time Taken %s " % (name, timestr))
 
 
 def run_actions(job_run_list):