Added long running commands runtime to log files.

src/drt/src/TritonRoute.cpp

@@ -57,6 +57,7 @@
 #include "sta/StaMain.hh"
 #include "stt/SteinerTreeBuilder.h"
 #include "ta/FlexTA.h"
+#include "utl/timer.h"
 
 namespace sta {
 // Tcl files encoded into strings.
@@ -923,6 +924,7 @@ void TritonRoute::sendDesignUpdates(const std::string& globals_path)
 
 int TritonRoute::main()
 {
+  utl::ScopedStatistics stat(logger_, "detailed_route");
   if (DBPROCESSNODE == "GF14_13M_3Mx_2Cx_4Kx_2Hx_2Gx_LB") {
     USENONPREFTRACKS = false;
   }

src/gpl/src/nesterovPlace.cpp

@@ -46,6 +46,7 @@
 #include "routeBase.h"
 #include "timingBase.h"
 #include "utl/Logger.h"
+#include "utl/timer.h"
 
 namespace gpl {
 using utl::GPL;
@@ -299,6 +300,7 @@ void NesterovPlace::reset()
 
 int NesterovPlace::doNesterovPlace(int start_iter)
 {
+  utl::ScopedStatistics stat(log_, "global_place");
   // if replace diverged in init() function,
   // replace must be skipped.
   if (isDiverged_) {

src/grt/src/GlobalRouter.cpp

@@ -72,6 +72,7 @@
 #include "stt/SteinerTreeBuilder.h"
 #include "utl/Logger.h"
 #include "utl/algorithms.h"
+#include "utl/timer.h"
 
 namespace grt {
 
@@ -248,6 +249,7 @@ void GlobalRouter::globalRoute(bool save_guides,
                                bool start_incremental,
                                bool end_incremental)
 {
+  utl::ScopedStatistics stat(logger_, "global_route");
   if (start_incremental && end_incremental) {
     logger_->error(GRT,
                    251,

src/mpl2/src/rtl_mp.cpp

@@ -37,6 +37,7 @@
 #include "hier_rtlmp.h"
 #include "object.h"
 #include "odb/db.h"
+#include "utl/timer.h"
 
 namespace mpl2 {
 using odb::dbDatabase;
@@ -94,6 +95,7 @@ bool MacroPlacer2::place(const int num_threads,
                          const bool bus_planning_on,
                          const char* report_directory)
 {
+  utl::ScopedStatistics stat(logger_, "rtl_macro_placer");
   hier_rtlmp_->setClusterSize(
       max_num_macro, min_num_macro, max_num_inst, min_num_inst);
   hier_rtlmp_->setClusterSizeTolerance(tolerance);

src/rsz/src/Resizer.cc

@@ -66,6 +66,7 @@
 #include "sta/TimingModel.hh"
 #include "sta/Units.hh"
 #include "utl/Logger.h"
+#include "utl/timer.h"
 
 // http://vlsicad.eecs.umich.edu/BK/Slots/cache/dropzone.tamu.edu/~zhuoli/GSRC/fast_buffer_insertion.html
 
@@ -2528,6 +2529,7 @@ void Resizer::repairDesign(double max_wire_length,
                            double cap_margin,
                            bool verbose)
 {
+  utl::ScopedStatistics stat(logger_, "repair_design");
   resizePreamble();
   if (parasitics_src_ == ParasiticsSrc::global_routing) {
     opendp_->initMacrosAndGrid();
@@ -2717,6 +2719,7 @@ void Resizer::repairHold(
     int max_passes,
     bool verbose)
 {
+  utl::ScopedStatistics stat(logger_, "repair_timing");
   resizePreamble();
   if (parasitics_src_ == ParasiticsSrc::global_routing) {
     opendp_->initMacrosAndGrid();
@@ -2736,6 +2739,7 @@ void Resizer::repairHold(const Pin* end_pin,
                          float max_buffer_percent,
                          int max_passes)
 {
+  utl::ScopedStatistics stat(logger_, "repair_timing");
   resizePreamble();
   repair_hold_->repairHold(end_pin,
                            setup_margin,

src/utl/include/utl/timer.h

@@ -36,6 +36,8 @@
 #pragma once
 
 #include <chrono>
+#include <cmath>
+#include <ctime>
 #include <iostream>
 
 #include "utl/Logger.h"
@@ -78,4 +80,20 @@ class DebugScopedTimer : public Timer
 
 std::ostream& operator<<(std::ostream& os, const Timer& t);
 
+class ScopedStatistics : public Timer
+{
+ public:
+  ScopedStatistics(utl::Logger* logger, std::string msg);
+  ~ScopedStatistics() override;
+
+ private:
+  size_t getStartRSZ();
+  size_t getPeakRSZ();
+
+  std::string msg_;
+  size_t start_rsz_;
+  utl::Logger* logger_;
+  clock_t cpu_start_;
+};
+
 }  // namespace utl

src/utl/src/timer.cpp

@@ -35,7 +35,30 @@
 
 #include "utl/timer.h"
 
+#if defined(__unix__) || defined(__unix) || defined(unix) \
+    || (defined(__APPLE__) && defined(__MACH__))
+#include <sys/resource.h>
+#include <unistd.h>
+
+#if defined(__APPLE__) && defined(__MACH__)
+#include <mach/mach.h>
+
+#elif (defined(_AIX) || defined(__TOS__AIX__)) \
+    || (defined(__sun__) || defined(__sun)     \
+        || defined(sun) && (defined(__SVR4) || defined(__svr4__)))
+#include <fcntl.h>
+#include <procfs.h>
+
+#elif defined(__linux__) || defined(__linux) || defined(linux) \
+    || defined(__gnu_linux__)
+#include <cstdint>
+#include <cstdio>
+#endif
+
+#endif
+
 namespace utl {
+const size_t kFactor = 1024;
 
 void Timer::reset()
 {
@@ -74,4 +97,86 @@ DebugScopedTimer::~DebugScopedTimer()
   debugPrint(logger_, tool_, group_.c_str(), level_, msg_, *this);
 }
 
+ScopedStatistics::ScopedStatistics(utl::Logger* logger, std::string msg)
+    : Timer(),
+      msg_(std::move(msg)),
+      start_rsz_(getStartRSZ()),
+      logger_(logger),
+      cpu_start_(clock())
+{
+}
+
+size_t ScopedStatistics::getStartRSZ()
+{
+#if defined(__APPLE__) && defined(__MACH__)
+  struct mach_task_basic_info info;
+  mach_msg_type_number_t info_count = MACH_TASK_BASIC_INFO_COUNT;
+  if (task_info(mach_task_self(), MACH_TASK_BASIC_INFO,
+                (task_info_t) &info, &info_count) {
+    return (size_t) 0L;
+  }
+  return (size_t) info.resident_size / kFactor;
+#elif defined(__linux__) || defined(__linux) || defined(linux) \
+    || defined(__gnu_linux__)
+  int64_t rss = 0L;
+  FILE* fp = fopen("/proc/self/statm", "r");
+  if (fp == nullptr) {
+    return (size_t) 0L;
+  }
+  if (fscanf(fp, "%*s%ld", &rss) != 1) {
+    fclose(fp);
+    return (size_t) 0L;
+  }
+  fclose(fp);
+  return (size_t) rss * (size_t) sysconf(_SC_PAGESIZE) / (kFactor * kFactor);
+#else
+  return (size_t) 0L; /* Unsupported. */
+#endif
+}
+
+size_t ScopedStatistics::getPeakRSZ()
+{
+#if (defined(_AIX) || defined(__TOS__AIX__)) \
+    || (defined(__sun__) || defined(__sun)   \
+        || defined(sun) && (defined(__SVR4) || defined(__svr4__)))
+  struct psinfo psinfo;
+  int fd = -1;
+  if ((fd = open("/proc/self/psinfo", O_RDONLY)) == -1)
+    return (size_t) 0L; /* Can't open? */
+  if (read(fd, &psinfo, sizeof(psinfo)) != sizeof(psinfo)) {
+    close(fd);
+    return (size_t) 0L; /* Can't read? */
+  }
+  close(fd);
+  return (size_t) (psinfo.pr_rssize * kFactor);
+#elif defined(__unix__) || defined(__unix) || defined(unix) \
+    || (defined(__APPLE__) && defined(__MACH__))
+  struct rusage rsg;
+  if (getrusage(RUSAGE_SELF, &rsg) != 0) {
+    return (size_t) 0L;
+  }
+#elif defined(__APPLE__) && defined(__MACH__)
+  return ((size_t) rsg.ru_maxrss) / (kFactor * kFactor);
+#else
+  return (size_t) rsg.ru_maxrss / kFactor;
+#endif
+  return (size_t) 0L; /* Unsupported. */
+}
+
+ScopedStatistics::~ScopedStatistics()
+{
+  auto ts_elapsed = Timer::elapsed();
+  int hour = ts_elapsed / 3600;
+  int min = (((int) ts_elapsed % 3600) / 60);
+  int sec = (int) ts_elapsed % 60;
+
+  auto ts_cpu = (clock() - cpu_start_) / CLOCKS_PER_SEC;
+  int chour = ts_cpu / 3600;
+  int cmin = (ts_cpu % 3600) / 60;
+  int csec = ts_cpu % 60;
+
+  logger_->report(msg_ + ": cpu time = {:02}:{:02}:{:02}, elapsed time = {:02}:{:02}:{:02}, memory = {} MB, peak = {} MB",
+      chour, cmin, csec, hour, min, sec, start_rsz_, getPeakRSZ());
+}
+
 }  // namespace utl

src/utl/test/regression_tests.tcl

@@ -3,6 +3,7 @@ record_tests {
     test_error
     test_suppress_message
     test_metrics
+    test_statistics
     #utl_man_tcl_check
     #utl_readme_msgs_check
     #test_error_exception

src/utl/test/test_statistics.ok

@@ -0,0 +1 @@
+Passed: Statistics are logged.

src/utl/test/test_statistics.py

@@ -0,0 +1,41 @@
+import os
+import re
+from openroad import Tech, Design
+
+def check_log_file(log_path):
+    pattern = re.compile(r"global.*route.*cpu.*time.*elapsed.*time.*memory.*peak.*")
+    match_count = 0
+
+    with open(log_path, 'r') as log_file:
+        for line in log_file:
+            if pattern.search(line):
+                match_count += 1
+
+    return match_count == 1
+
+def main():
+    test_path = os.path.abspath(os.path.dirname(__file__))
+
+    tech = Tech()
+    tech.readLef(os.path.join(test_path, "../../../test/Nangate45/Nangate45.lef"))
+
+    design = Design(tech)
+    gcddef = os.path.abspath(os.path.join(test_path, "../../grt/test/gcd.def"))
+    design.readDef(gcddef)
+
+    gr = design.getGlobalRouter()
+    gr.globalRoute(True)
+
+    log_path = os.path.join(test_path, "results", "test_statistics-py.log")
+    if check_log_file(log_path):
+        with open(log_path, 'w') as log_file:
+            log_file.write("Passed: Statistics are logged.\n")
+        exit(0)
+    else:
+        with open(log_path, 'w') as log_file:
+            log_file.write("Failed: Statistics are not logged.\n")
+        exit(1)
+
+if __name__ == "__main__":
+    main()
+

test/regression.tcl

@@ -180,6 +180,40 @@ proc run_test { test } {
   }
 }
 
+proc log_comparer {test log_file ok_file diff_file diff_options error_msg} {
+    global result_dir errors
+
+    # Filter dos '/r's from log file.
+    set tmp_file [file join $result_dir $test.tmp]
+    exec tr -d "\r" < $log_file > $tmp_file
+    file rename -force $tmp_file $log_file
+
+    # Create a temporary filtered log file that ignores lines with the specific pattern
+    set tmp_log_file [file join $result_dir "${test}_log.tmp"]
+
+    set sed_result [catch \
+	    {exec sed {/.*cpu.*time.*.*elapsed.*time.*memory.*peak.*/d} \
+            $log_file > $tmp_log_file} sed_error]
+    if {$sed_result != 0} {
+        puts "Error running sed"
+        puts "Error message: $sed_error"
+        incr errors(fail)
+        return 1
+    } else {
+        # Proceed with the diff operation
+        set result [catch {exec diff $diff_options $ok_file $tmp_log_file >> $diff_file}]
+        if {$result != 0} {
+            puts " *FAIL log_and_ok*$error_msg"
+            return 1
+        } else {
+            puts " pass$error_msg"
+            return 0
+        }
+    }
+    # Clean up the temporary filtered log file.
+    file delete -force $tmp_log_file
+}
+
 proc run_test_lang { test lang } {
   global result_dir diff_file errors diff_options
 
@@ -226,17 +260,11 @@ proc run_test_lang { test lang } {
       switch [test_pass_criteria $test] {
         compare_logfile {
           if { [file exists $ok_file] } {
-            # Filter dos '/r's from log file.
-            set tmp_file [file join $result_dir $test.tmp]
-            exec tr -d "\r" < $log_file > $tmp_file
-            file rename -force $tmp_file $log_file
-            if [catch [concat exec diff $diff_options $ok_file $log_file \
-                         >> $diff_file]] {
-              puts " *FAIL*$error_msg"
+            set compare_result [log_comparer $test $log_file $ok_file \
+		    $diff_file $diff_options $error_msg]
+            if {$compare_result != 0} {
               append_failure $test
               incr errors(fail)
-            } else {
-              puts " pass$error_msg"
             }
           } else {
             puts " *NO OK FILE*$error_msg"