diff --git a/src/drt/src/TritonRoute.cpp b/src/drt/src/TritonRoute.cpp index 4231ab8a3df..4e5b0f12f4e 100644 --- a/src/drt/src/TritonRoute.cpp +++ b/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; } diff --git a/src/gpl/src/nesterovPlace.cpp b/src/gpl/src/nesterovPlace.cpp index 90707177b7a..71ea722bcb5 100644 --- a/src/gpl/src/nesterovPlace.cpp +++ b/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_) { diff --git a/src/grt/src/GlobalRouter.cpp b/src/grt/src/GlobalRouter.cpp index aa08cc2be12..9f68ece3bef 100644 --- a/src/grt/src/GlobalRouter.cpp +++ b/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, diff --git a/src/mpl2/src/rtl_mp.cpp b/src/mpl2/src/rtl_mp.cpp index c254a4e987a..47812d32e52 100644 --- a/src/mpl2/src/rtl_mp.cpp +++ b/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); diff --git a/src/rsz/src/Resizer.cc b/src/rsz/src/Resizer.cc index 175d9fd3b28..1c38b9986bc 100644 --- a/src/rsz/src/Resizer.cc +++ b/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, diff --git a/src/utl/include/utl/timer.h b/src/utl/include/utl/timer.h index 0397748c6c3..c9a018dd8e1 100644 --- a/src/utl/include/utl/timer.h +++ b/src/utl/include/utl/timer.h @@ -36,6 +36,8 @@ #pragma once #include +#include +#include #include #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 diff --git a/src/utl/src/timer.cpp b/src/utl/src/timer.cpp index ef5a30b944a..ed0fa832822 100644 --- a/src/utl/src/timer.cpp +++ b/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 +#include + +#if defined(__APPLE__) && defined(__MACH__) +#include + +#elif (defined(_AIX) || defined(__TOS__AIX__)) \ + || (defined(__sun__) || defined(__sun) \ + || defined(sun) && (defined(__SVR4) || defined(__svr4__))) +#include +#include + +#elif defined(__linux__) || defined(__linux) || defined(linux) \ + || defined(__gnu_linux__) +#include +#include +#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 diff --git a/src/utl/test/regression_tests.tcl b/src/utl/test/regression_tests.tcl index 2d158a48c85..745fe12fdb9 100644 --- a/src/utl/test/regression_tests.tcl +++ b/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 diff --git a/src/utl/test/test_statistics.ok b/src/utl/test/test_statistics.ok new file mode 100644 index 00000000000..e7c76ecec8d --- /dev/null +++ b/src/utl/test/test_statistics.ok @@ -0,0 +1 @@ +Passed: Statistics are logged. diff --git a/src/utl/test/test_statistics.py b/src/utl/test/test_statistics.py new file mode 100644 index 00000000000..0890efe23e2 --- /dev/null +++ b/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() + diff --git a/test/regression.tcl b/test/regression.tcl index 33d7b2f9d3e..23d36217bd4 100755 --- a/test/regression.tcl +++ b/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"