From 4df9e2e0e52dc39e0b7cea296f17f04d71f51cf2 Mon Sep 17 00:00:00 2001 From: Wilson Snyder Date: Mon, 25 Mar 2024 07:03:17 -0400 Subject: [PATCH] Add printing summary reports (#4909) (#5018) --- Changes | 1 + bin/verilator | 4 + docs/guide/exe_sim.rst | 5 ++ docs/guide/exe_verilator.rst | 9 +++ docs/guide/simulating.rst | 54 ++++++++++++++ docs/guide/verilating.rst | 75 +++++++++++++++++++ examples/make_tracing_c/sim_main.cpp | 3 + include/verilated.cpp | 49 +++++++++++++ include/verilated.h | 20 ++++- include/verilatedos.h | 40 ++++++++++ include/verilatedos_c.h | 101 ++++++++++++++++++++++++++ src/V3EmitCMain.cpp | 4 + src/V3Options.cpp | 5 ++ src/V3Options.h | 6 +- src/V3Os.cpp | 30 +------- src/V3Os.h | 3 +- src/V3Stats.h | 12 +++ src/V3StatsReport.cpp | 43 ++++++++++- src/Verilator.cpp | 20 +++++ test_regress/t/t_flag_quiet_stats.pl | 22 ++++++ test_regress/t/t_flag_quiet_stats.v | 12 +++ test_regress/t/t_flag_quiet_stats2.pl | 24 ++++++ test_regress/t/t_flag_quiet_stats3.pl | 24 ++++++ test_regress/t/t_runflag_quiet.pl | 35 +++++++++ test_regress/t/t_runflag_quiet.v | 16 ++++ 25 files changed, 585 insertions(+), 32 deletions(-) create mode 100644 include/verilatedos_c.h create mode 100755 test_regress/t/t_flag_quiet_stats.pl create mode 100644 test_regress/t/t_flag_quiet_stats.v create mode 100755 test_regress/t/t_flag_quiet_stats2.pl create mode 100755 test_regress/t/t_flag_quiet_stats3.pl create mode 100755 test_regress/t/t_runflag_quiet.pl create mode 100644 test_regress/t/t_runflag_quiet.v diff --git a/Changes b/Changes index 27fabd22e..9dfb5a866 100644 --- a/Changes +++ b/Changes @@ -13,6 +13,7 @@ Verilator 5.023 devel **Major:** +* Add printing summary reports, use `--quiet` or `+verilator+quiet` to suppress (#4909). * Support 1800-2023 keywords, and parsing with UNDEFINED warnings. * Support 1800-2023 preprocessor ifdef expressions. * Support 1800-2023 DPI headers, svGetTime/svgGetTimeUnit/svGetTimePrecision methods. diff --git a/bin/verilator b/bin/verilator index 01b97b249..253981f18 100755 --- a/bin/verilator +++ b/bin/verilator @@ -58,6 +58,7 @@ if (! GetOptions( # Switches "gdb!" => \$opt_gdb, "gdbbt!" => \$opt_gdbbt, + "quiet!" => \$opt_quiet_exit, # As -quiet implies -quiet-exit "quiet-exit!" => \$opt_quiet_exit, "rr!" => \$opt_rr, "unlimited-stack!" => \$opt_unlimited_stack, @@ -423,7 +424,9 @@ detailed descriptions of these arguments. --public-params Mark all parameters as public_flat --public-flat-rw Mark all variables, etc as public_flat_rw -pvalue+= Overwrite toplevel parameter + --quiet Minimize additional printing --quiet-exit Don't print the command on failure + --quiet-stats Don't print statistics --relative-includes Resolve includes relative to current file --reloop-limit Minimum iterations for forming loops --report-unoptflat Extra diagnostics for UNOPTFLAT @@ -515,6 +518,7 @@ description of these arguments. +verilator+prof+exec+start+ Set execution profile starting point +verilator+prof+exec+window+ Set execution profile duration +verilator+prof+vlt+file+ Set PGO profile filename + +verilator+quiet Minimize additional printing +verilator+rand+reset+ Set random reset technique +verilator+seed+ Set random seed +verilator+V Show verbose version and config diff --git a/docs/guide/exe_sim.rst b/docs/guide/exe_sim.rst index d396c96d2..b0867ae9f 100644 --- a/docs/guide/exe_sim.rst +++ b/docs/guide/exe_sim.rst @@ -92,6 +92,11 @@ Summary: profile-guided optimization data runtime filename to dump to. Defaults to :file:`profile.vlt`. +.. option:: +verilator+quiet + + Disable printing the simulation summary report, see :ref:`Simulation + Summary Report`. + .. option:: +verilator+rand+reset+ When a model was Verilated using diff --git a/docs/guide/exe_verilator.rst b/docs/guide/exe_verilator.rst index 44c86b7b2..02b2adee1 100644 --- a/docs/guide/exe_verilator.rst +++ b/docs/guide/exe_verilator.rst @@ -1163,11 +1163,20 @@ Summary: Overwrites the given parameter(s) of the top-level module. See :vlopt:`-G <-G>` for a detailed description. +.. option:: --quiet + + Alias for :vlopt:`--quiet-exit` :vlopt:`--quiet-stats`. + .. option:: --quiet-exit When exiting due to an error, do not display the "Exiting due to Errors" nor "Command Failed" messages. +.. option:: --quiet-stats + + Disable printing the Verilation statistics report, see :ref:`Verilation + Summary Report`. + .. option:: --relative-includes When a file references an include file, resolve the filename relative to diff --git a/docs/guide/simulating.rst b/docs/guide/simulating.rst index 47a35df1a..bb2f6e002 100644 --- a/docs/guide/simulating.rst +++ b/docs/guide/simulating.rst @@ -12,6 +12,60 @@ Verilated model's executable. For the runtime arguments to a simulated model, see :ref:`Simulation Runtime Arguments`. +.. _Simulation Summary Report: + +Simulation Summary Report +========================= + +When simulation finishes, it will print a report to stdout summarizing the +simulation. This requires the model being Verilated with :vlopt:`--main`. +The report may be disabled with :vlopt:`+verilator+quiet`. + +For example: + +.. code-block:: + + - S i m u l a t i o n R e p o r t: Verilator ... + - Verilator: End at simtime 123 ns; walltime 1234.001 s; speed 123 ns/s + - Verilator: cpu 22.001 s on 4 threads; alloced 123 MB + +The information in this report is: + +.. describe:: "Verilator ..." + + Program version. + +.. describe:: "End at simtime 123 ns" + + Verilog $time at which the model finished or stopped. + +.. describe:: "walltime 1234.001 s" + + Real elapsed wall time in seconds. + +.. describe:: "speed 123.1 ns/s" + + Simulated time (if non-zero) divided by wall time. e.g. `123 ns/s` means + 123 simulated nanoseconds took 1 second of wall time; for a model with + only a 1 GHz clock that would be equivalent to 123.1 cycles per + second. The units are automatically selected to give a number between 1 + and 1000. The wall time includes initialization, initial and final + process blocks, so indicates a slower speed than if the model had a + longer runtime. + +.. describe:: "cpu 22 s" + + CPU time used total across all CPU threads in seconds. + +.. describe:: "4 threads" + + Number of simultaneous threads used. + +.. describe:: "alloced 123 MB" + + Total memory used during simulation in megabytes. + + .. _Benchmarking & Optimization: Benchmarking & Optimization diff --git a/docs/guide/verilating.rst b/docs/guide/verilating.rst index 2a22d3e37..00346eb98 100644 --- a/docs/guide/verilating.rst +++ b/docs/guide/verilating.rst @@ -498,3 +498,78 @@ The search paths can be configured by setting some variables: Sets the installation prefix of an installed SystemC library. (Same as SYSTEMC_ROOT). + + +.. _Verilation Summary Report: + +Verilation Summary Report +========================= + +When Verilator generates code, unless :vlopt:`--quiet-stats` is used, it +will print a report to stdout summarizing the build. For example: + +.. code-block:: + + - V e r i l a t i o n R e p o r t: Verilator .... + - Verilator: Built from 354 MB sources in 247 modules, + into 74 MB in 89 C++ files needing 0.192 MB + - Verilator: Walltime 26.580 s (elab=2.096, cvt=18.268, + bld=2.100); cpu 26.548 s on 1 threads; alloced 2894.672 MB + +The information in this report is: + +.. describe:: "Verilator ..." + + Program version. + +.. describe:: "234 MB sources" + + Characters of post-preprocessed text in all input + Verilog and Verilator Control files in megabytes. + +.. describe:: "247 modules" + + Number of interfaces/modules/classes/packages in design before + elaboration. + +.. describe:: "into 74 MB" + + Characters of output C++ code, including comments in megabytes. + +.. describe:: "89 C++ files" + + Number of .cpp files created. + +.. describe:: "needing 192MB" + + Verilation-time minimum-bound estimate of memory needed to run model in + megabytes. (Expect to need significantly more.) + +.. describe:: "Walltime 26.580 s" + + Real elapsed wall time for Verilation and build. + +.. describe:: "elab=2.096" + + Wall time to read in files and complete elaboration. + +.. describe:: "cvt=18.268" + + Wall time for Verilator to process and write output. + +.. describe:: "bld=2.1" + + Wall time to compile gcc/clang (if using :vlopt:`--build`). + +.. describe:: "cpu 22.548 s" + + CPU time used, total across all CPU threads. + +.. describe:: "4 threads" + + Number of simultaneous threads used. + +.. describe:: "alloced 123 MB" + + Total memory used during build by Verilator executable (excludes + :vlopt:`--build` compiler's usage) in megabytes. diff --git a/examples/make_tracing_c/sim_main.cpp b/examples/make_tracing_c/sim_main.cpp index 69f99cae2..1e21a8b71 100644 --- a/examples/make_tracing_c/sim_main.cpp +++ b/examples/make_tracing_c/sim_main.cpp @@ -117,6 +117,9 @@ int main(int argc, char** argv) { contextp->coveragep()->write("logs/coverage.dat"); #endif + // Final simulation summary + contextp->printStatsSummary(); + // Return good completion status // Don't use exit() or destructor won't get called return 0; diff --git a/include/verilated.cpp b/include/verilated.cpp index 50ba5d8a7..3390e421b 100644 --- a/include/verilated.cpp +++ b/include/verilated.cpp @@ -2565,6 +2565,29 @@ std::string VerilatedContext::profVltFilename() const VL_MT_SAFE { const VerilatedLockGuard lock{m_mutex}; return m_ns.m_profVltFilename; } + +void VerilatedContext::printStatsSummary() VL_MT_UNSAFE { + if (quiet()) return; + VL_PRINTF("- S i m u l a t i o n R e p o r t: %s %s\n", Verilated::productName(), + Verilated::productVersion()); + const std::string endwhy = gotError() ? "$stop" : gotFinish() ? "$finish" : "end"; + const double simtimeInUnits = VL_TIME_Q() * vl_time_multiplier(timeunit()) + * vl_time_multiplier(timeprecision() - timeunit()); + const std::string simtime = vl_timescaled_double(simtimeInUnits); + const double walltime = statWallTimeSinceStart(); + const double cputime = statCpuTimeSinceStart(); + const std::string simtimePerf + = vl_timescaled_double((cputime != 0.0) ? (simtimeInUnits / cputime) : 0, "%0.3f %s"); + VL_PRINTF("- Verilator: %s at %s; walltime %0.3f s; speed %s/s\n", endwhy.c_str(), + simtime.c_str(), walltime, simtimePerf.c_str()); + const double modelMB = VlOs::memUsageBytes() / 1024.0 / 1024.0; + VL_PRINTF("- Verilator: cpu %0.3f s on %d threads; alloced %0.0f MB\n", cputime, + modelThreads(), modelMB); +} +void VerilatedContext::quiet(bool flag) VL_MT_SAFE { + const VerilatedLockGuard lock{m_mutex}; + m_s.m_quiet = flag; +} void VerilatedContext::randReset(int val) VL_MT_SAFE { const VerilatedLockGuard lock{m_mutex}; m_s.m_randReset = val; @@ -2632,8 +2655,16 @@ void VerilatedContext::internalsDump() const VL_MT_SAFE { } void VerilatedContext::addModel(VerilatedModel* modelp) { + if (!quiet()) { + // CPU time isn't read as starting point until model creation, so that quiet() is set + // Thus if quiet(), avoids slow OS read affecting some usages that make many models + const VerilatedLockGuard lock{m_mutex}; + m_ns.m_cpuTimeStart.start(); + m_ns.m_wallTimeStart.start(); + } threadPoolp(); // Ensure thread pool is created, so m_threads cannot change any more + m_modelThreads += modelp->threads(); if (VL_UNLIKELY(modelp->threads() > m_threads)) { std::ostringstream msg; msg << "VerilatedContext has " << m_threads << " threads but model '" @@ -2762,6 +2793,8 @@ void VerilatedContextImp::commandArgVl(const std::string& arg) { profExecFilename(str); } else if (commandArgVlString(arg, "+verilator+prof+vlt+file+", str)) { profVltFilename(str); + } else if (arg == "+verilator+quiet") { + quiet(true); } else if (commandArgVlUint64(arg, "+verilator+rand+reset+", u64, 0, 2)) { randReset(static_cast(u64)); } else if (commandArgVlUint64(arg, "+verilator+seed+", u64, 1, @@ -2839,6 +2872,18 @@ uint64_t VerilatedContextImp::randSeedDefault64() const VL_MT_SAFE { } } +//====================================================================== +// VerilatedContext:: Statistics + +double VerilatedContext::statCpuTimeSinceStart() const VL_MT_SAFE_EXCLUDES(m_mutex) { + const VerilatedLockGuard lock{m_mutex}; + return m_ns.m_cpuTimeStart.deltaTime(); +} +double VerilatedContext::statWallTimeSinceStart() const VL_MT_SAFE_EXCLUDES(m_mutex) { + const VerilatedLockGuard lock{m_mutex}; + return m_ns.m_wallTimeStart.deltaTime(); +} + //====================================================================== // VerilatedContext:: Methods - scopes @@ -3321,3 +3366,7 @@ void VlDeleter::deleteAll() VL_EXCLUDES(m_mutex) VL_EXCLUDES(m_deleteMutex) VL_M } //=========================================================================== +// OS functions (last, so we have minimal OS dependencies above) + +#define VL_ALLOW_VERILATEDOS_C +#include "verilatedos_c.h" diff --git a/include/verilated.h b/include/verilated.h index 06c873309..a31a90bb6 100644 --- a/include/verilated.h +++ b/include/verilated.h @@ -354,13 +354,14 @@ protected: struct Serialized final { // All these members serialized/deserialized // No std::strings or pointers or will serialize badly! // Fast path + uint64_t m_time = 0; // Current $time (unscaled), 0=at zero, or legacy bool m_assertOn = true; // Assertions are enabled bool m_calcUnusedSigs = false; // Waves file on, need all signals calculated bool m_fatalOnError = true; // Fatal on $stop/non-fatal error bool m_fatalOnVpiError = true; // Fatal on vpi error/unsupported bool m_gotError = false; // A $finish statement executed bool m_gotFinish = false; // A $finish or $stop statement executed - uint64_t m_time = 0; // Current $time (unscaled), 0=at zero, or legacy + bool m_quiet = false; // Quiet, no summary report // Slow path int8_t m_timeunit; // Time unit as 0..15 int8_t m_timeprecision; // Time precision as 0..15 @@ -390,6 +391,8 @@ protected: std::string m_coverageFilename; // +coverage+file filename std::string m_profExecFilename; // +prof+exec+file filename std::string m_profVltFilename; // +prof+vlt filename + VlOs::DeltaCpuTime m_cpuTimeStart{false}; // CPU time, starts when create first model + VlOs::DeltaWallTime m_wallTimeStart{false}; // Wall time, starts when create first model } m_ns; mutable VerilatedMutex m_argMutex; // Protect m_argVec, m_argVecLoaded @@ -405,6 +408,8 @@ protected: const std::unique_ptr m_impdatap; // Number of threads to use for simulation (size of m_threadPool + 1 for main thread) unsigned m_threads = std::thread::hardware_concurrency(); + // Number of threads in added models + unsigned m_modelThreads = 0; // The thread pool shared by all models added to this context std::unique_ptr m_threadPool; // The execution profiler shared by all models added to this context @@ -489,6 +494,12 @@ public: void gotFinish(bool flag) VL_MT_SAFE; /// Return if got a $finish or $stop/error bool gotFinish() const VL_MT_SAFE { return m_s.m_gotFinish; } + /// Print statistics summary (if not quiet) + void printStatsSummary() VL_MT_UNSAFE; + /// Enable quiet (also prevents need for OS calls to get CPU time) + void quiet(bool flag) VL_MT_SAFE; + /// Return if quiet enabled + bool quiet() const VL_MT_SAFE { return m_s.m_quiet; } /// Select initial value of otherwise uninitialized signals. /// 0 = Set to zeros /// 1 = Set all bits to one @@ -501,6 +512,11 @@ public: /// Set default random seed, 0 = seed it automatically int randSeed() const VL_MT_SAFE { return m_s.m_randSeed; } + /// Return statistic: CPU time delta from model created until now + double statCpuTimeSinceStart() const VL_MT_SAFE_EXCLUDES(m_mutex); + /// Return statistic: Wall time delta from model created until now + double statWallTimeSinceStart() const VL_MT_SAFE_EXCLUDES(m_mutex); + // Time handling /// Returns current simulation time in units of timeprecision(). /// @@ -544,6 +560,8 @@ public: /// Get number of threads used for simulation (including the main thread) unsigned threads() const { return m_threads; } + /// Get number of threads in added models (for statistical use only) + unsigned modelThreads() const { return m_modelThreads; } /// Set number of threads used for simulation (including the main thread) /// Can only be called before the thread pool is created (before first model is added). void threads(unsigned n); diff --git a/include/verilatedos.h b/include/verilatedos.h index 435b57df7..2bbfbb69a 100644 --- a/include/verilatedos.h +++ b/include/verilatedos.h @@ -343,6 +343,7 @@ extern "C" void __gcov_dump(); #include #include #include +#include #ifndef VL_NO_LEGACY using vluint8_t = uint8_t; ///< 8-bit unsigned type (backward compatibility) @@ -610,6 +611,45 @@ static inline double VL_ROUND(double n) { #define VL_OFFSETOF(type, field) \ (reinterpret_cast(&(reinterpret_cast(0x10000000)->field)) - 0x10000000) +//========================================================================= +// Time and performance + +namespace VlOs { + +extern uint64_t memUsageBytes(); ///< Return memory usage in bytes, or 0 if not implemented + +// Internal: Record CPU time, starting point on construction, and current delta from that +class DeltaCpuTime final { + double m_start{}; // Time constructed at + static double gettime(); + +public: + // Construct, and if startit is true, start() timer + explicit DeltaCpuTime(bool startit) { + if (startit) start(); + } + void start() { m_start = gettime(); } // Start timer; record current time + double deltaTime() const { // Return time between now and start() + return (m_start == 0.0) ? 0.0 : gettime() - m_start; + } +}; +// Internal: Record wall time, starting point on construction, and current delta from that +class DeltaWallTime final { + double m_start{}; // Time constructed at + static double gettime(); + +public: + // Construct, and if startit is true, start() timer + explicit DeltaWallTime(bool startit) { + if (startit) start(); + } + void start() { m_start = gettime(); } // Start timer; record current time + double deltaTime() const { // Return time between now and start() + return (m_start == 0.0) ? 0.0 : gettime() - m_start; + } +}; +} //namespace VlOs + //========================================================================= // Conversions diff --git a/include/verilatedos_c.h b/include/verilatedos_c.h new file mode 100644 index 000000000..2178984f4 --- /dev/null +++ b/include/verilatedos_c.h @@ -0,0 +1,101 @@ +// -*- mode: C++; c-file-style: "cc-mode" -*- +//************************************************************************* +// +// Code available from: https://verilator.org +// +// Copyright 2003-2024 by Wilson Snyder. This program is free software; you can +// redistribute it and/or modify it under the terms of either the GNU +// Lesser General Public License Version 3 or the Perl Artistic License +// Version 2.0. +// SPDX-License-Identifier: LGPL-3.0-only OR Artistic-2.0 +// +//************************************************************************* +/// +/// \file +/// \brief Verilated/Verilator common implementation for OS portability +/// +/// This is compiled as part of other .cpp files to reduce compile time +/// and as such is a .h file rather than .cpp file. +/// +//************************************************************************* + +#ifndef VL_ALLOW_VERILATEDOS_C +#error "This file should be included only from V3Os.cpp/Verilated.cpp" +#endif + +#include "verilatedos.h" + +// clang-format off +#if defined(_WIN32) || defined(__MINGW32__) +# include // LONG for bcrypt.h on MINGW +# include // GetProcessTimes +# include // GetProcessMemoryInfo +#endif +// clang-format on + +namespace VlOs { + +//========================================================================= +// VlOs::VlGetCpuTime/VlGetWallTime implementation + +double DeltaCpuTime::gettime() { +#if defined(_WIN32) || defined(__MINGW32__) + FILETIME lpCreationTime, lpExitTime, lpKernelTime, lpUserTime; + if (0 + != GetProcessTimes(GetCurrentProcess(), &lpCreationTime, &lpExitTime, &lpKernelTime, + &lpUserTime)) { + return static_cast(static_cast(lpUserTime.dwLowDateTime) + | static_cast(lpUserTime.dwHighDateTime) << 32ULL) + * 1e-7; + } +#else + // NOLINTNEXTLINE(cppcoreguidelines-pro-type-member-init) + timespec ts; + if (0 != clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &ts)) return ts.tv_sec + ts.tv_nsec * 1e-9; +#endif + return 0.0; +} +double DeltaWallTime::gettime() { +#if defined(_WIN32) || defined(__MINGW32__) + FILETIME ft; // contains number of 0.1us intervals since the beginning of 1601 UTC. + GetSystemTimeAsFileTime(&ft); + const uint64_t tenthus + = ((static_cast(ft.dwHighDateTime) << 32) + ft.dwLowDateTime + 5ULL); + return static_cast(tenthus) * 1e-7; +#else + // NOLINTNEXTLINE(cppcoreguidelines-pro-type-member-init) + timespec ts; + if (0 == clock_gettime(CLOCK_MONOTONIC, &ts)) return ts.tv_sec + ts.tv_nsec * 1e-9; + return 0.0; +#endif +} + +//========================================================================= +// VlOs::memUsageBytes implementation + +uint64_t memUsageBytes() { +#if defined(_WIN32) || defined(__MINGW32__) + const HANDLE process = GetCurrentProcess(); + PROCESS_MEMORY_COUNTERS pmc; + if (GetProcessMemoryInfo(process, &pmc, sizeof(pmc))) { + // The best we can do using simple Windows APIs is to get the size of the working set. + return pmc.WorkingSetSize; + } + return 0; +#else + // Highly unportable. Sorry + const char* const statmFilename = "/proc/self/statm"; + FILE* const fp = fopen(statmFilename, "r"); + if (!fp) return 0; + uint64_t size, resident, share, text, lib, data, dt; // All in pages + const int items = fscanf( + fp, "%" SCNu64 " %" SCNu64 " %" SCNu64 " %" SCNu64 " %" SCNu64 " %" SCNu64 " %" SCNu64, + &size, &resident, &share, &text, &lib, &data, &dt); + fclose(fp); + if (VL_UNCOVERABLE(7 != items)) return 0; + return (text + data) * getpagesize(); +#endif +} + +//========================================================================= +} //namespace VlOs diff --git a/src/V3EmitCMain.cpp b/src/V3EmitCMain.cpp index 4adbab1e6..9e8e0b163 100644 --- a/src/V3EmitCMain.cpp +++ b/src/V3EmitCMain.cpp @@ -110,6 +110,10 @@ private: puts("\n"); } + puts("// Print statistical summary report\n"); + puts("contextp->printStatsSummary();\n"); + puts("\n"); + puts("return 0;\n"); puts("}\n"); diff --git a/src/V3Options.cpp b/src/V3Options.cpp index 1dc36c7c9..c1d6eb217 100644 --- a/src/V3Options.cpp +++ b/src/V3Options.cpp @@ -1415,7 +1415,12 @@ void V3Options::parseOptsList(FileLine* fl, const string& optdir, int argc, m_public_params = flag; v3Global.dpi(true); }); + DECL_OPTION("-quiet", CbOnOff, [this](bool flag) { + m_quietExit = flag; + m_quietStats = flag; + }); DECL_OPTION("-quiet-exit", OnOff, &m_quietExit); + DECL_OPTION("-quiet-stats", OnOff, &m_quietStats); DECL_OPTION("-relative-includes", OnOff, &m_relativeIncludes); DECL_OPTION("-reloop-limit", CbVal, [this, fl](const char* valp) { diff --git a/src/V3Options.h b/src/V3Options.h index ef0a7b627..a2d7cf67d 100644 --- a/src/V3Options.h +++ b/src/V3Options.h @@ -271,8 +271,9 @@ private: bool m_publicFlatRW = false; // main switch: --public-flat-rw bool m_public_params = false; // main switch: --public-params bool m_quietExit = false; // main switch: --quiet-exit - bool m_relativeIncludes = false; // main switch: --relative-includes - bool m_reportUnoptflat = false; // main switch: --report-unoptflat + bool m_quietStats = false; // main switch: --quiet-stats + bool m_relativeIncludes = false; // main switch: --relative-includes + bool m_reportUnoptflat = false; // main switch: --report-unoptflat bool m_savable = false; // main switch: --savable bool m_std = true; // main switch: --std bool m_structsPacked = false; // main switch: --structs-packed @@ -524,6 +525,7 @@ public: bool lintOnly() const VL_MT_SAFE { return m_lintOnly; } bool ignc() const { return m_ignc; } bool quietExit() const VL_MT_SAFE { return m_quietExit; } + bool quietStats() const VL_MT_SAFE { return m_quietStats; } bool reportUnoptflat() const { return m_reportUnoptflat; } bool verilate() const { return m_verilate; } bool vpi() const { return m_vpi; } diff --git a/src/V3Os.cpp b/src/V3Os.cpp index 92413b62a..41508f43b 100644 --- a/src/V3Os.cpp +++ b/src/V3Os.cpp @@ -61,7 +61,6 @@ VL_DEFINE_DEBUG_FUNCTIONS; # include # include // mkdir # include // open, read, write, close -# include // GetProcessMemoryInfo # include // These macros taken from gdbsupport/gdb_wait.h in binutils-gdb # ifndef WIFEXITED @@ -80,6 +79,9 @@ VL_DEFINE_DEBUG_FUNCTIONS; #endif // clang-format on +#define VL_ALLOW_VERILATEDOS_C +#include "verilatedos_c.h" + //###################################################################### // Environment @@ -397,7 +399,7 @@ uint64_t V3Os::timeUsecs() { FILETIME ft; // contains number of 0.1us intervals since the beginning of 1601 UTC. GetSystemTimeAsFileTime(&ft); - uint64_t us + const uint64_t us = ((static_cast(ft.dwHighDateTime) << 32) + ft.dwLowDateTime + 5ULL) / 10ULL; return us - EPOCH_DIFFERENCE_USECS; #else @@ -408,30 +410,6 @@ uint64_t V3Os::timeUsecs() { #endif } -uint64_t V3Os::memUsageBytes() { -#if defined(_WIN32) || defined(__MINGW32__) - const HANDLE process = GetCurrentProcess(); - PROCESS_MEMORY_COUNTERS pmc; - if (GetProcessMemoryInfo(process, &pmc, sizeof(pmc))) { - // The best we can do using simple Windows APIs is to get the size of the working set. - return pmc.WorkingSetSize; - } - return 0; -#else - // Highly unportable. Sorry - const char* const statmFilename = "/proc/self/statm"; - FILE* const fp = fopen(statmFilename, "r"); - if (!fp) return 0; - uint64_t size, resident, share, text, lib, data, dt; // All in pages - const int items = fscanf( - fp, "%" SCNu64 " %" SCNu64 " %" SCNu64 " %" SCNu64 " %" SCNu64 " %" SCNu64 " %" SCNu64, - &size, &resident, &share, &text, &lib, &data, &dt); - fclose(fp); - if (VL_UNCOVERABLE(7 != items)) return 0; - return (text + data) * getpagesize(); -#endif -} - void V3Os::u_sleep(int64_t usec) { #if defined(_WIN32) || defined(__MINGW32__) std::this_thread::sleep_for(std::chrono::microseconds(usec)); diff --git a/src/V3Os.h b/src/V3Os.h index d9858c878..6232b2647 100644 --- a/src/V3Os.h +++ b/src/V3Os.h @@ -71,11 +71,10 @@ public: static uint64_t rand64(std::array& stater); static string trueRandom(size_t size) VL_MT_SAFE; - // METHODS (time & performance) + // METHODS (time & performance) (See also VlOs methods) static void u_sleep(int64_t usec); ///< Sleep for a given number of microseconds. /// Return wall time since epoch in microseconds, or 0 if not implemented static uint64_t timeUsecs(); - static uint64_t memUsageBytes(); ///< Return memory usage in bytes, or 0 if not implemented // METHODS (sub command) /// Run system command, returns the exit code of the child process. diff --git a/src/V3Stats.h b/src/V3Stats.h index 33f100723..a516df343 100644 --- a/src/V3Stats.h +++ b/src/V3Stats.h @@ -109,9 +109,14 @@ public: // Symbolic names for some statistics that are later read by summaryReport() static constexpr const char* STAT_CPP_CHARS = "Output, C++ bytes written"; static constexpr const char* STAT_CPP_FILES = "Output, C++ files written"; + static constexpr const char* STAT_CPUTIME = "CPU time, Total (sec)"; static constexpr const char* STAT_MODEL_SIZE = "Size prediction, Model total (bytes)"; static constexpr const char* STAT_SOURCE_CHARS = "Input, Verilog bytes read"; static constexpr const char* STAT_SOURCE_MODULES = "Input, Verilog modules read"; + static constexpr const char* STAT_WALLTIME = "Wall time, Total (sec)"; + static constexpr const char* STAT_WALLTIME_BUILD = "Wall time, Build (sec)"; + static constexpr const char* STAT_WALLTIME_CVT = "Wall time, Conversion (sec)"; + static constexpr const char* STAT_WALLTIME_ELAB = "Wall time, Elaboration (sec)"; static void addStat(const V3Statistic&); static void addStat(const string& stage, const string& name, double value, @@ -126,6 +131,11 @@ public: static void addStatPerf(const string& name, double value) { addStat(V3Statistic{"*", name, value, 6, true, true}); } + /// Return value of statistic, or zero if not found + static double getStatSum(const string& name); + static uint64_t getStatSumQ(const string& name) { + return static_cast(getStatSum(name)); + } /// Called each stage static void statsStage(const string& name); /// Called by the top level to collect statistics @@ -135,6 +145,8 @@ public: static void statsReport(); /// Called by debug dumps static void infoHeader(std::ofstream& os, const string& prefix); + /// Called for final build report + static void summaryReport(); }; #endif // Guard diff --git a/src/V3StatsReport.cpp b/src/V3StatsReport.cpp index bb5ac347e..8b83c501f 100644 --- a/src/V3StatsReport.cpp +++ b/src/V3StatsReport.cpp @@ -162,6 +162,17 @@ public: // METHODS static void addStat(const V3Statistic& stat) { s_allStats.push_back(stat); } + static double getStatSum(const string& name) { + // O(n^2) if called a lot; present assumption is only a small call count + for (auto& itr : s_allStats) { + const V3Statistic* const repp = &itr; + if (repp->name() == name) return repp->value(); + } + return 0.0; + } + + static void calculate() { sumit(); } + // CONSTRUCTORS explicit StatsReport(std::ofstream* aofp) : os(*aofp) { // Need () or GCC 4.8 false warning @@ -189,6 +200,8 @@ void V3Statistic::dump(std::ofstream& os) const { void V3Stats::addStat(const V3Statistic& stat) { StatsReport::addStat(stat); } +double V3Stats::getStatSum(const string& name) { return StatsReport::getStatSum(name); } + void V3Stats::statsStage(const string& name) { static double lastWallTime = -1; static int fileNumber = 0; @@ -202,7 +215,7 @@ void V3Stats::statsStage(const string& name) { V3Stats::addStatPerf("Stage, Elapsed time (sec), " + digitName, wallTimeDelta); V3Stats::addStatPerf("Stage, Elapsed time (sec), TOTAL", wallTimeDelta); - const double memory = V3Os::memUsageBytes() / 1024.0 / 1024.0; + const double memory = VlOs::memUsageBytes() / 1024.0 / 1024.0; V3Stats::addStatPerf("Stage, Memory (MB), " + digitName, memory); } @@ -229,3 +242,31 @@ void V3Stats::statsReport() { ofp->close(); VL_DO_DANGLING(delete ofp, ofp); } + +void V3Stats::summaryReport() { + StatsReport::calculate(); + std::cout << "- V e r i l a t i o n R e p o r t: " << V3Options::version() << "\n"; + + std::cout << std::setprecision(3) << std::fixed; + const double sourceCharsMB = V3Stats::getStatSumQ(STAT_SOURCE_CHARS) / 1024.0 / 1024.0; + const double cppCharsMB = V3Stats::getStatSumQ(STAT_CPP_CHARS) / 1024.0 / 1024.0; + const uint64_t sourceModules = V3Stats::getStatSumQ(STAT_SOURCE_MODULES); + const uint64_t cppFiles = V3Stats::getStatSumQ(STAT_CPP_FILES); + const double modelMB = V3Stats::getStatSum(STAT_MODEL_SIZE) / 1024.0 / 1024.0; + std::cout << "- Verilator: Built from " << sourceCharsMB << " MB sources in " << sourceModules + << " modules, into " << cppCharsMB << " MB in " << cppFiles << " C++ files needing " + << modelMB << " MB\n"; + + const double walltime = V3Stats::getStatSum(STAT_WALLTIME); + const double walltimeElab = V3Stats::getStatSum(STAT_WALLTIME_ELAB); + const double walltimeCvt = V3Stats::getStatSum(STAT_WALLTIME_CVT); + const double walltimeBuild = V3Stats::getStatSum(STAT_WALLTIME_BUILD); + const double cputime = V3Stats::getStatSum(STAT_CPUTIME); + std::cout << "- Verilator: Walltime " << walltime << " s (elab=" << walltimeElab + << ", cvt=" << walltimeCvt << ", bld=" << walltimeBuild << "); cpu " << cputime + << " s on " << std::max(v3Global.opt.verilateJobs(), v3Global.opt.buildJobs()) + << " threads"; + const double memory = VlOs::memUsageBytes() / 1024.0 / 1024.0; + if (VL_UNCOVERABLE(memory != 0.0)) std::cout << "; alloced " << memory << " MB"; + std::cout << "\n"; +} diff --git a/src/Verilator.cpp b/src/Verilator.cpp index 6b6aff6dc..1882b9afa 100644 --- a/src/Verilator.cpp +++ b/src/Verilator.cpp @@ -136,6 +136,8 @@ static void emitXmlOrJson() VL_MT_DISABLED { static void process() { { const V3MtDisabledLockGuard mtDisabler{v3MtDisabledLock()}; + VlOs::DeltaWallTime elabWallTime{true}; + // Sort modules by level so later algorithms don't need to care V3LinkLevel::modSortByLevel(); V3Error::abortIfErrors(); @@ -209,6 +211,10 @@ static void process() { v3Global.assertDTypesResolved(true); v3Global.widthMinUsage(VWidthMinUsage::MATCHES_WIDTH); + // End of elaboration + V3Stats::addStatPerf(V3Stats::STAT_WALLTIME_ELAB, elabWallTime.deltaTime()); + VlOs::DeltaWallTime cvtWallTime{true}; + // Coverage insertion // Before we do dead code elimination and inlining, or we'll lose it. if (v3Global.opt.coverage()) V3Coverage::coverage(v3Global.rootp()); @@ -582,6 +588,9 @@ static void process() { } else if (v3Global.opt.dpiHdrOnly()) { V3EmitC::emitcSyms(true); } + + // End of conversion + V3Stats::addStatPerf(V3Stats::STAT_WALLTIME_CVT, cvtWallTime.deltaTime()); } if (!v3Global.opt.serializeOnly() && !v3Global.opt.dpiHdrOnly()) { // Unfortunately we have some lint checks in emitcImp. @@ -778,11 +787,14 @@ static void execBuildJob() { UASSERT(v3Global.opt.build(), "--build is not specified."); UASSERT(v3Global.opt.gmake(), "--build requires GNU Make."); UASSERT(!v3Global.opt.cmake(), "--build cannot use CMake."); + VlOs::DeltaWallTime buildWallTime{true}; UINFO(1, "Start Build\n"); const string cmdStr = buildMakeCmd(v3Global.opt.prefix() + ".mk", ""); V3Os::filesystemFlushBuildDir(v3Global.opt.hierTopDataDir()); const int exit_code = V3Os::system(cmdStr); + V3Stats::addStatPerf(V3Stats::STAT_WALLTIME_BUILD, buildWallTime.deltaTime()); + if (exit_code != 0) { v3error(cmdStr << " exited with " << exit_code << std::endl); std::exit(exit_code); @@ -807,6 +819,8 @@ static void execHierVerilation() { int main(int argc, char** argv) { // General initialization std::ios::sync_with_stdio(); + VlOs::DeltaWallTime wallTimeTotal{true}; + VlOs::DeltaCpuTime cpuTimeTotal{true}; time_t randseed; time(&randseed); @@ -855,5 +869,11 @@ int main(int argc, char** argv) { FileLine::deleteAllRemaining(); } + if (!v3Global.opt.quietStats() && !v3Global.opt.preprocOnly()) { + V3Stats::addStatPerf(V3Stats::STAT_CPUTIME, cpuTimeTotal.deltaTime()); + V3Stats::addStatPerf(V3Stats::STAT_WALLTIME, wallTimeTotal.deltaTime()); + V3Stats::summaryReport(); + } + UINFO(1, "Done, Exiting...\n"); } diff --git a/test_regress/t/t_flag_quiet_stats.pl b/test_regress/t/t_flag_quiet_stats.pl new file mode 100755 index 000000000..eb7961c00 --- /dev/null +++ b/test_regress/t/t_flag_quiet_stats.pl @@ -0,0 +1,22 @@ +#!/usr/bin/env perl +if (!$::Driver) { use FindBin; exec("$FindBin::Bin/bootstrap.pl", @ARGV, $0); die; } +# DESCRIPTION: Verilator: Verilog Test driver/expect definition +# +# Copyright 2008 by Wilson Snyder. This program is free software; you +# can redistribute it and/or modify it under the terms of either the GNU +# Lesser General Public License Version 3 or the Perl Artistic License +# Version 2.0. +# SPDX-License-Identifier: LGPL-3.0-only OR Artistic-2.0 + +scenarios(vlt => 1); + +compile( + verilator_flags2 => ['--quiet-stats'], + verilator_make_gcc => 0, + logfile => $Self->{run_log_filename}, + ); + +file_grep_not($Self->{obj_dir}.'/vlt_compile.log', qr/V e r i l a t/i,); + +ok(1); +1; diff --git a/test_regress/t/t_flag_quiet_stats.v b/test_regress/t/t_flag_quiet_stats.v new file mode 100644 index 000000000..f4b6f7852 --- /dev/null +++ b/test_regress/t/t_flag_quiet_stats.v @@ -0,0 +1,12 @@ +// DESCRIPTION: Verilator: Verilog Test module +// +// This file ONLY is placed under the Creative Commons Public Domain, for +// any use, without warranty, 2008 by Wilson Snyder. +// SPDX-License-Identifier: CC0-1.0 + +module t (/*AUTOARG*/); + initial begin + $write("*-* All Finished *-*\n"); + $finish; + end +endmodule diff --git a/test_regress/t/t_flag_quiet_stats2.pl b/test_regress/t/t_flag_quiet_stats2.pl new file mode 100755 index 000000000..5a87e9df8 --- /dev/null +++ b/test_regress/t/t_flag_quiet_stats2.pl @@ -0,0 +1,24 @@ +#!/usr/bin/env perl +if (!$::Driver) { use FindBin; exec("$FindBin::Bin/bootstrap.pl", @ARGV, $0); die; } +# DESCRIPTION: Verilator: Verilog Test driver/expect definition +# +# Copyright 2008 by Wilson Snyder. This program is free software; you +# can redistribute it and/or modify it under the terms of either the GNU +# Lesser General Public License Version 3 or the Perl Artistic License +# Version 2.0. +# SPDX-License-Identifier: LGPL-3.0-only OR Artistic-2.0 + +scenarios(vlt => 1); + +top_filename("t/t_flag_quiet_stats.v"); + +compile( + verilator_flags2 => ['--quiet'], + verilator_make_gcc => 0, + logfile => $Self->{run_log_filename}, + ); + +file_grep_not($Self->{obj_dir}.'/vlt_compile.log', qr/V e r i l a t/i,); + +ok(1); +1; diff --git a/test_regress/t/t_flag_quiet_stats3.pl b/test_regress/t/t_flag_quiet_stats3.pl new file mode 100755 index 000000000..f7e7580a5 --- /dev/null +++ b/test_regress/t/t_flag_quiet_stats3.pl @@ -0,0 +1,24 @@ +#!/usr/bin/env perl +if (!$::Driver) { use FindBin; exec("$FindBin::Bin/bootstrap.pl", @ARGV, $0); die; } +# DESCRIPTION: Verilator: Verilog Test driver/expect definition +# +# Copyright 2008 by Wilson Snyder. This program is free software; you +# can redistribute it and/or modify it under the terms of either the GNU +# Lesser General Public License Version 3 or the Perl Artistic License +# Version 2.0. +# SPDX-License-Identifier: LGPL-3.0-only OR Artistic-2.0 + +scenarios(vlt => 1); + +top_filename("t/t_flag_quiet_stats.v"); + +compile( + verilator_flags2 => ['--quiet --no-quiet-stats'], + verilator_make_gcc => 0, + logfile => $Self->{run_log_filename}, + ); + +file_grep($Self->{obj_dir}.'/vlt_compile.log', qr/V e r i l a t/i,); + +ok(1); +1; diff --git a/test_regress/t/t_runflag_quiet.pl b/test_regress/t/t_runflag_quiet.pl new file mode 100755 index 000000000..bfaab429e --- /dev/null +++ b/test_regress/t/t_runflag_quiet.pl @@ -0,0 +1,35 @@ +#!/usr/bin/env perl +if (!$::Driver) { use FindBin; exec("$FindBin::Bin/bootstrap.pl", @ARGV, $0); die; } +# DESCRIPTION: Verilator: Verilog Test driver/expect definition +# +# Copyright 2003 by Wilson Snyder. This program is free software; you +# can redistribute it and/or modify it under the terms of either the GNU +# Lesser General Public License Version 3 or the Perl Artistic License +# Version 2.0. +# SPDX-License-Identifier: LGPL-3.0-only OR Artistic-2.0 + +scenarios(vlt_all => 1); + +compile( + verilator_flags2 => ["--binary --quiet"], + ); + +execute( + all_run_flags => ["+verilator+quiet"], + logfile => "$Self->{obj_dir}/sim__quiet.log", + ); + +file_grep_not("$Self->{obj_dir}/sim__quiet.log", qr/S i m u l a t/i,); + +#--- + +execute( + all_run_flags => [""], + logfile => "$Self->{obj_dir}/sim__noquiet.log", + ); + +file_grep("$Self->{obj_dir}/sim__noquiet.log", qr/S i m u l a t/i,); + +ok(1); + +1; diff --git a/test_regress/t/t_runflag_quiet.v b/test_regress/t/t_runflag_quiet.v new file mode 100644 index 000000000..1c62e1b40 --- /dev/null +++ b/test_regress/t/t_runflag_quiet.v @@ -0,0 +1,16 @@ +// DESCRIPTION: Verilator: Verilog Test module +// +// This file ONLY is placed under the Creative Commons Public Domain, for +// any use, without warranty, 2019 by Wilson Snyder. +// SPDX-License-Identifier: CC0-1.0 + +timeunit 1us; +timeprecision 1ns; + +module t; + initial begin + #10; + $write("*-* All Finished *-*\n"); + $finish; + end +endmodule