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.
@@ -917,6 +918,7 @@ void TritonRoute::sendDesignUpdates(const std::string& globals_path)
 
 int TritonRoute::main()
 {
+  utl::ScopedStatistics stat(logger_);
   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;
@@ -62,6 +63,7 @@ NesterovPlace::NesterovPlace(const NesterovPlaceVars& npVars,
                              utl::Logger* log)
     : NesterovPlace()
 {
+  utl::ScopedStatistics stat(log);
   npVars_ = npVars;
   pbc_ = pbc;
   nbc_ = nbc;

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_);
   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_);
   hier_rtlmp_->setClusterSize(
       max_num_macro, min_num_macro, max_num_inst, min_num_inst);
   hier_rtlmp_->setClusterSizeTolerance(tolerance);

src/rsz/src/RepairDesign.cc

@@ -51,6 +51,7 @@
 #include "sta/Search.hh"
 #include "sta/SearchPred.hh"
 #include "sta/Units.hh"
+#include "utl/timer.h"
 
 namespace rsz {
 
@@ -93,6 +94,7 @@ void RepairDesign::repairDesign(double max_wire_length,
                                 bool verbose)
 {
   init();
+  utl::ScopedStatistics stat(logger_);
   int repaired_net_count, slew_violations, cap_violations;
   int fanout_violations, length_violations;
   repairDesign(max_wire_length,

src/rsz/src/RepairHold.cc

@@ -55,6 +55,7 @@
 #include "sta/TimingArc.hh"
 #include "sta/Units.hh"
 #include "utl/Logger.h"
+#include "utl/timer.h"
 
 namespace rsz {
 
@@ -93,6 +94,7 @@ void RepairHold::repairHold(
     const bool verbose)
 {
   init();
+  utl::ScopedStatistics stat(logger_);
   sta_->checkSlewLimitPreamble();
   sta_->checkCapacitanceLimitPreamble();
   LibertyCell* buffer_cell = findHoldBuffer();
@@ -132,6 +134,7 @@ void RepairHold::repairHold(const Pin* end_pin,
                             const int max_passes)
 {
   init();
+  utl::ScopedStatistics stat(logger_);
   sta_->checkSlewLimitPreamble();
   sta_->checkCapacitanceLimitPreamble();
   LibertyCell* buffer_cell = findHoldBuffer();

src/utl/include/utl/timer.h

@@ -35,6 +35,8 @@
 
 #pragma once
 
+#include <unistd.h>
+
 #include <chrono>
 #include <iostream>
 
@@ -78,4 +80,15 @@ class DebugScopedTimer : public Timer
 
 std::ostream& operator<<(std::ostream& os, const Timer& t);
 
+class ScopedStatistics : public Timer
+{
+ public:
+  ScopedStatistics(utl::Logger* logger);
+  ~ScopedStatistics() override;
+
+ private:
+  size_t getPeakMemoryUsage();
+  utl::Logger* logger_;
+};
+
 }  // namespace utl

src/utl/src/timer.cpp

@@ -35,6 +35,8 @@
 
 #include "utl/timer.h"
 
+#include <sys/resource.h>
+
 namespace utl {
 
 void Timer::reset()
@@ -74,4 +76,23 @@ DebugScopedTimer::~DebugScopedTimer()
   debugPrint(logger_, tool_, group_.c_str(), level_, msg_, *this);
 }
 
+ScopedStatistics::ScopedStatistics(utl::Logger* logger)
+    : Timer(), logger_(logger)
+{
+}
+
+size_t ScopedStatistics::getPeakMemoryUsage()
+{
+  struct rusage rusage;
+  getrusage(RUSAGE_SELF, &rusage);
+  return (size_t) (rusage.ru_maxrss * 1024L);
+}
+
+ScopedStatistics::~ScopedStatistics()
+{
+  logger_->report("Runtime {} seconds, memory used {} KB.",
+                  Timer::elapsed(),
+                  getPeakMemoryUsage());
+}
+
 }  // 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,42 @@
+import os
+import subprocess
+import re
+
+def run_regression_script(regression_script_path, argument):
+    try:
+        subprocess.run([regression_script_path, argument], check=True)
+    except subprocess.CalledProcessError as e:
+        print(f"Error running regression script: {e}")
+        return False
+    return True
+
+def check_log_file(log_path):
+    pattern = re.compile(r"Runtime\s+\d+\.\d+\s+seconds,\s+memory used\s+\d+\s+KB")
+    runtime_count = 0
+
+    with open(log_path, 'r') as log_file:
+        for line in log_file:
+            if pattern.search(line):
+                runtime_count += 1
+    if runtime_count == 2:
+        print("Passed: Statistics are logged.")
+        exit(0)
+    else:
+        print("Statistics are not logged enough times.")
+        exit(1)
+
+def main():
+    script_dir = os.path.dirname(os.path.abspath(__file__))
+    base_dir = os.path.abspath(os.path.join(script_dir, "../../rsz/test"))
+    log_path = os.path.join(base_dir, "results", "repair_design4-tcl.log")
+    regression_script_path = os.path.join(base_dir, "regression")
+
+    if not os.path.exists(log_path):
+        if not run_regression_script(regression_script_path, "repair_design4"):
+            exit(1)
+
+    check_log_file(log_path)
+
+if __name__ == "__main__":
+    main()
+

test/regression.tcl

@@ -230,14 +230,30 @@ proc run_test_lang { test lang } {
             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"
-              append_failure $test
-              incr errors(fail)
+
+            # 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 {/Runtime.*seconds.*memory.*used.*KB.*/d} \
+		    $log_file > $tmp_log_file} sed_error]
+            if {$sed_result != 0} {
+                puts "Error running sed"
+                puts "Error message: $sed_error"
+                incr errors(fail)
             } else {
-              puts " pass$error_msg"
+              # Proceed with the diff operation
+              set result [catch {exec diff $diff_options $ok_file $tmp_log_file >> $diff_file}]
+              if {$result != 0} {
+                exec cat $diff_file
+                puts " *FAIL*$error_msg"
+                append_failure $test
+                incr errors(fail)
+              } else {
+                puts " pass$error_msg"
+              }
             }
+            # Clean up the temporary filtered log file.
+            file delete -force $tmp_log_file
           } else {
             puts " *NO OK FILE*$error_msg"
             append_failure $test