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_, "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;
@@ -62,6 +63,7 @@ NesterovPlace::NesterovPlace(const NesterovPlaceVars& npVars,
                              utl::Logger* log)
     : NesterovPlace()
 {
+  utl::ScopedStatistics stat(log, "global_place");
   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_, "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/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_, "repair_design");
   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_, "repair_timing");
   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_, "repair_timing");
   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,23 @@ 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 getMemoryUsage(const char* tag);
+  size_t getStartRSZ();
+  size_t getPeakRSZ();
+  size_t getStartVSZ();
+  size_t getPeakVSZ();
+
+  std::string msg_;
+  size_t start_rsz_;
+  size_t start_vsz_;
+  utl::Logger* logger_;
+};
+
 }  // namespace utl

src/utl/src/timer.cpp

@@ -33,8 +33,13 @@
 //
 ///////////////////////////////////////////////////////////////////////////////
 
+#define _GNU_SOURCE
 #include "utl/timer.h"
 
+#include <sys/resource.h>
+
+#include <fstream>
+
 namespace utl {
 
 void Timer::reset()
@@ -74,4 +79,70 @@ DebugScopedTimer::~DebugScopedTimer()
   debugPrint(logger_, tool_, group_.c_str(), level_, msg_, *this);
 }
 
+ScopedStatistics::ScopedStatistics(utl::Logger* logger, std::string msg)
+    : Timer(),
+      msg_(msg),
+      start_rsz_(getStartRSZ()),
+      start_vsz_(getStartVSZ()),
+      logger_(logger)
+{
+}
+
+size_t ScopedStatistics::getMemoryUsage(const char* tag)
+{
+  FILE* file = fopen("/proc/self/status", "r");
+  if (file == NULL) {
+    perror("Failed to open /proc/self/status");
+    exit(EXIT_FAILURE);
+  }
+
+  size_t result = (size_t) -1;
+  char line[128];
+  size_t tagLength = strlen(tag);
+
+  while (fgets(line, sizeof(line), file) != NULL) {
+    if (strncmp(line, tag, tagLength) == 0) {
+      const char* p = line;
+      while (*p < '0' || *p > '9')
+        p++;
+      result = (size_t) atoi(p);
+      break;
+    }
+  }
+
+  fclose(file);
+  if (result == (size_t) -1) {
+    fprintf(stderr, "%s not found in /proc/self/status\n", tag);
+    exit(EXIT_FAILURE);
+  }
+
+  return result / 1024;
+}
+
+size_t ScopedStatistics::getStartVSZ()
+{
+  return getMemoryUsage("VmSize:");
+}
+
+size_t ScopedStatistics::getPeakVSZ()
+{
+  return getMemoryUsage("VmPeak:");
+}
+
+size_t ScopedStatistics::getStartRSZ()
+{
+  return getMemoryUsage("VmRSS:");
+}
+
+size_t ScopedStatistics::getPeakRSZ()
+{
+  return getMemoryUsage("VmHWM:");
+}
+
+ScopedStatistics::~ScopedStatistics()
+{
+  logger_->report(msg_ + ": runtime {} seconds, usage: rsz = {} MB, vsz = {} MB, peak: rsz = {} MB, vsz = {} MB", static_cast<int>(Timer::elapsed()), (getPeakRSZ() - start_rsz_),
+    (getPeakVSZ() - start_vsz_), (getPeakRSZ()), (getPeakVSZ()));
+}
+
 }  // 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"repair_design: runtime.*seconds.*usage.*rsz.*MB.*vsz.*MB.*peak.*rsz.*vsz.*")
+    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

@@ -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 {/.*runtime.*seconds.*usage.*rsz.*MB.*vsz.*MB.*peak.*rsz.*vsz.*/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"