diff --git a/backends/p4tools/common/CMakeLists.txt b/backends/p4tools/common/CMakeLists.txt index 058fba4620..9e5c86f763 100644 --- a/backends/p4tools/common/CMakeLists.txt +++ b/backends/p4tools/common/CMakeLists.txt @@ -24,6 +24,7 @@ set( lib/arch_spec.cpp lib/format_int.cpp lib/gen_eq.cpp + lib/logging.cpp lib/model.cpp lib/namespace_context.cpp lib/symbolic_env.cpp diff --git a/backends/p4tools/common/lib/constants.h b/backends/p4tools/common/lib/constants.h index cbef133edd..3319b25b97 100644 --- a/backends/p4tools/common/lib/constants.h +++ b/backends/p4tools/common/lib/constants.h @@ -1,8 +1,6 @@ #ifndef BACKENDS_P4TOOLS_COMMON_LIB_CONSTANTS_H_ #define BACKENDS_P4TOOLS_COMMON_LIB_CONSTANTS_H_ -#include "ir/ir.h" - namespace P4Tools { class P4Constants { diff --git a/backends/p4tools/common/lib/logging.cpp b/backends/p4tools/common/lib/logging.cpp new file mode 100644 index 0000000000..bd24676b95 --- /dev/null +++ b/backends/p4tools/common/lib/logging.cpp @@ -0,0 +1,60 @@ +#include "backends/p4tools/common/lib/logging.h" + +#include +#include + +#include "lib/log.h" +#include "lib/timer.h" + +namespace P4Tools { + +void enableInformationLogging() { ::Log::addDebugSpec("test_info:4"); } + +void enablePerformanceLogging() { ::Log::addDebugSpec("performance:4"); } + +void printPerformanceReport(const std::optional &basePath) { + // Do not emit a report if performance logging is not enabled. + if (!Log::fileLogLevelIsAtLeast("performance", 4)) { + return; + } + printFeature("performance", 4, "============ Timers ============"); + using TimerData = std::unordered_map; + std::vector timerList; + for (const auto &c : Util::getTimers()) { + TimerData timerData; + timerData["time"] = std::to_string(c.milliseconds); + if (c.timerName.empty()) { + printFeature("performance", 4, "Total: %i ms", c.milliseconds); + timerData["pct"] = "100"; + timerData["name"] = "total"; + } else { + timerData["pct"] = std::to_string(c.relativeToParent * 100); + printFeature("performance", 4, "%s: %i ms (%0.2f %% of parent)", c.timerName, + c.milliseconds, c.relativeToParent * 100); + auto prunedName = c.timerName; + prunedName.erase(remove_if(prunedName.begin(), prunedName.end(), isspace), + prunedName.end()); + timerData["name"] = prunedName; + } + timerList.emplace_back(timerData); + } + // Write the report to the file, if one was provided. + if (basePath.has_value()) { + auto perfFilePath = basePath.value(); + perfFilePath.concat("_perf"); + perfFilePath.replace_extension(".csv"); + auto perfFile = std::ofstream(perfFilePath, std::ios::out | std::ios::app); + if (!perfFile.is_open()) { + ::error("Failed to open the performance report file %1%", perfFilePath.c_str()); + return; + } + + perfFile << "Timer,Total Time,Percentage\n"; + for (const auto &timerData : timerList) { + perfFile << timerData.at("name") << "," << timerData.at("time") << "," + << timerData.at("pct") << "\n"; + } + perfFile.close(); + } +} +} // namespace P4Tools diff --git a/backends/p4tools/common/lib/logging.h b/backends/p4tools/common/lib/logging.h new file mode 100644 index 0000000000..39d57788de --- /dev/null +++ b/backends/p4tools/common/lib/logging.h @@ -0,0 +1,31 @@ +#ifndef BACKENDS_P4TOOLS_COMMON_LIB_LOGGING_H_ +#define BACKENDS_P4TOOLS_COMMON_LIB_LOGGING_H_ + +#include +#include +#include + +#include "backends/p4tools/common/lib/util.h" + +namespace P4Tools { + +/// Helper functions that prints strings associated with basic test generation information., for +/// example the covered nodes or tests number. +template +void printInfo(const std::string &fmt, Arguments &&...args) { + printFeature("test_info", 4, fmt, std::forward(args)...); +} + +/// Enable the printing of basic run information. +void enableInformationLogging(); + +/// Enable printing of timing reports. +void enablePerformanceLogging(); + +/// Print a performance report if performance logging is enabled. +/// If a file is provided, it will be written to the file. +void printPerformanceReport(const std::optional &basePath = std::nullopt); + +} // namespace P4Tools + +#endif /* BACKENDS_P4TOOLS_COMMON_LIB_LOGGING_H_ */ diff --git a/backends/p4tools/modules/testgen/lib/logging.cpp b/backends/p4tools/modules/testgen/lib/logging.cpp index 972689dd4b..ba1ab354fa 100644 --- a/backends/p4tools/modules/testgen/lib/logging.cpp +++ b/backends/p4tools/modules/testgen/lib/logging.cpp @@ -5,14 +5,10 @@ namespace P4Tools::P4Testgen { -void enableTraceLogging() { Log::addDebugSpec("test_traces:4"); } +void enableTraceLogging() { ::Log::addDebugSpec("test_traces:4"); } -void enableInformationLogging() { Log::addDebugSpec("test_info:4"); } +void enableStepLogging() { ::Log::addDebugSpec("small_step:4"); } -void enableStepLogging() { Log::addDebugSpec("small_step:4"); } - -void enableCoverageLogging() { Log::addDebugSpec("coverage:4"); } - -void enablePerformanceLogging() { Log::addDebugSpec("performance:4"); } +void enableCoverageLogging() { ::Log::addDebugSpec("coverage:4"); } } // namespace P4Tools::P4Testgen diff --git a/backends/p4tools/modules/testgen/lib/logging.h b/backends/p4tools/modules/testgen/lib/logging.h index 43ba6a7515..fd6b6cba50 100644 --- a/backends/p4tools/modules/testgen/lib/logging.h +++ b/backends/p4tools/modules/testgen/lib/logging.h @@ -4,6 +4,7 @@ #include #include +#include "backends/p4tools/common/lib/logging.h" // IWYU pragma: export #include "backends/p4tools/common/lib/util.h" namespace P4Tools::P4Testgen { @@ -15,29 +16,15 @@ void printTraces(const std::string &fmt, Arguments &&...args) { printFeature("test_traces", 4, fmt, std::forward(args)...); } -/// Helper functions that prints strings associated with basic test generation information., for -/// example the covered nodes or tests number. -template -void printInfo(const std::string &fmt, Arguments &&...args) { - printFeature("test_info", 4, fmt, std::forward(args)...); -} - /// Enable trace printing. void enableTraceLogging(); -/// Enable the printing of basic test case generation information, for example the covered -/// nodes or test number. -void enableInformationLogging(); - /// Enable printing of the individual program node steps of the interpreter. void enableStepLogging(); /// Enable printing of the statement coverage statistics the interpreter collects. void enableCoverageLogging(); -/// Enable printing of timing reports. -void enablePerformanceLogging(); - } // namespace P4Tools::P4Testgen #endif /* BACKENDS_P4TOOLS_MODULES_TESTGEN_LIB_LOGGING_H_ */ diff --git a/backends/p4tools/modules/testgen/lib/test_backend.cpp b/backends/p4tools/modules/testgen/lib/test_backend.cpp index c36b37d51c..f8fc92d71c 100644 --- a/backends/p4tools/modules/testgen/lib/test_backend.cpp +++ b/backends/p4tools/modules/testgen/lib/test_backend.cpp @@ -1,6 +1,5 @@ #include "backends/p4tools/modules/testgen/lib/test_backend.h" -#include #include #include "backends/p4tools/common/core/z3_solver.h" @@ -85,7 +84,7 @@ bool TestBackEnd::run(const FinalState &state) { auto concolicOptState = state.computeConcolicState(*resolvedConcolicVariables); if (!concolicOptState.has_value()) { testCount++; - printPerformanceReport(false); + printPerformanceReport(std::nullopt); return needsToTerminate(testCount); } auto replacedState = concolicOptState.value().get(); @@ -106,7 +105,7 @@ bool TestBackEnd::run(const FinalState &state) { abort = printTestInfo(executionState, testInfo, outputPortExpr); if (abort) { testCount++; - printPerformanceReport(false); + printPerformanceReport(std::nullopt); return needsToTerminate(testCount); } const auto *testSpec = createTestSpec(executionState, &finalModel, testInfo); @@ -142,7 +141,7 @@ bool TestBackEnd::run(const FinalState &state) { printTraces("============ End Test %1% ============\n", testCount); testCount++; P4::Coverage::printCoverageReport(coverableNodes, visitedNodes); - printPerformanceReport(false); + printPerformanceReport(std::nullopt); // If MAX_NODE_COVERAGE is enabled, terminate early if we hit max node coverage already. if (testgenOptions.stopMetric == "MAX_NODE_COVERAGE" && coverage == 1.0) { @@ -238,10 +237,6 @@ bool TestBackEnd::printTestInfo(const ExecutionState * /*executionState*/, const return false; } -void TestBackEnd::printPerformanceReport(bool write) const { - testWriter->printPerformanceReport(write); -} - int64_t TestBackEnd::getTestCount() const { return testCount; } float TestBackEnd::getCoverage() const { return coverage; } diff --git a/backends/p4tools/modules/testgen/lib/test_backend.h b/backends/p4tools/modules/testgen/lib/test_backend.h index 0b2ac9b1fa..f716de6d1b 100644 --- a/backends/p4tools/modules/testgen/lib/test_backend.h +++ b/backends/p4tools/modules/testgen/lib/test_backend.h @@ -114,11 +114,6 @@ class TestBackEnd { /// The callback that is executed by the symbolic executor. virtual bool run(const FinalState &state); - /// Print out some performance numbers if logging feature "performance" is enabled. - /// Also log performance numbers to a separate file in the test folder if @param write is - /// enabled. - void printPerformanceReport(bool write) const; - /// Returns test count. [[nodiscard]] int64_t getTestCount() const; diff --git a/backends/p4tools/modules/testgen/lib/test_framework.cpp b/backends/p4tools/modules/testgen/lib/test_framework.cpp index 71ed0a3585..cdba51e100 100644 --- a/backends/p4tools/modules/testgen/lib/test_framework.cpp +++ b/backends/p4tools/modules/testgen/lib/test_framework.cpp @@ -1,62 +1,12 @@ #include "backends/p4tools/modules/testgen/lib/test_framework.h" -#include -#include #include -#include #include -#include "backends/p4tools/common/lib/util.h" -#include "inja/inja.hpp" -#include "lib/log.h" -#include "lib/timer.h" - namespace P4Tools::P4Testgen { TestFramework::TestFramework(std::filesystem::path basePath, std::optional seed = std::nullopt) : basePath(std::move(basePath)), seed(seed) {} -void TestFramework::printPerformanceReport(bool write) const { - // Do not emit a report if performance logging is not enabled. - if (!Log::fileLogLevelIsAtLeast("performance", 4)) { - return; - } - printFeature("performance", 4, "============ Timers ============"); - inja::json dataJson; - inja::json timerList = inja::json::array(); - for (const auto &c : Util::getTimers()) { - inja::json timerData; - timerData["time"] = c.milliseconds; - if (c.timerName.empty()) { - printFeature("performance", 4, "Total: %i ms", c.milliseconds); - timerData["pct"] = "100"; - timerData["name"] = "total"; - } else { - timerData["pct"] = c.relativeToParent * 100; - printFeature("performance", 4, "%s: %i ms (%0.2f %% of parent)", c.timerName, - c.milliseconds, c.relativeToParent * 100); - auto prunedName = c.timerName; - prunedName.erase(remove_if(prunedName.begin(), prunedName.end(), isspace), - prunedName.end()); - timerData["name"] = prunedName; - } - timerList.emplace_back(timerData); - } - if (write) { - dataJson["timers"] = timerList; - static const std::string TEST_CASE(R"""(Timer,Total Time,Percentage -## for timer in timers -{{timer.name}},{{timer.time}},{{timer.pct}} -## endfor -)"""); - auto perfFilePath = basePath; - perfFilePath.concat("_perf"); - perfFilePath.replace_extension(".csv"); - auto perfFile = std::ofstream(perfFilePath); - inja::render_to(perfFile, TEST_CASE, dataJson); - perfFile.flush(); - } -} - } // namespace P4Tools::P4Testgen diff --git a/backends/p4tools/modules/testgen/lib/test_framework.h b/backends/p4tools/modules/testgen/lib/test_framework.h index 4061711df8..fb61b28242 100644 --- a/backends/p4tools/modules/testgen/lib/test_framework.h +++ b/backends/p4tools/modules/testgen/lib/test_framework.h @@ -3,20 +3,16 @@ #include #include -#include #include -#include #include #include #include #include -#include #include #include "backends/p4tools/common/lib/format_int.h" #include "backends/p4tools/common/lib/trace_event.h" -#include "ir/ir.h" #include "lib/cstring.h" #include "backends/p4tools/modules/testgen/lib/test_object.h" @@ -145,11 +141,6 @@ class TestFramework { // attaches arbitrary string data to the test preamble. virtual void outputTest(const TestSpec *spec, cstring selectedBranches, size_t testIdx, float currentCoverage) = 0; - - /// Print out some performance numbers if logging feature "performance" is enabled. - /// Also log performance numbers to a separate file in the test folder if @param write is - /// enabled. - void printPerformanceReport(bool write) const; }; } // namespace P4Tools::P4Testgen diff --git a/backends/p4tools/modules/testgen/options.cpp b/backends/p4tools/modules/testgen/options.cpp index e22f4ff8d4..3966963647 100644 --- a/backends/p4tools/modules/testgen/options.cpp +++ b/backends/p4tools/modules/testgen/options.cpp @@ -341,7 +341,7 @@ TestgenOptions::TestgenOptions() registerOption( "--print-performance-report", nullptr, [](const char *) { - P4Testgen::enablePerformanceLogging(); + enablePerformanceLogging(); return true; }, "Print timing report summary at the end of the program."); diff --git a/backends/p4tools/modules/testgen/testgen.cpp b/backends/p4tools/modules/testgen/testgen.cpp index 7f457ac175..d57794e292 100644 --- a/backends/p4tools/modules/testgen/testgen.cpp +++ b/backends/p4tools/modules/testgen/testgen.cpp @@ -75,7 +75,7 @@ int generateAbstractTests(const TestgenOptions &testgenOptions, const ProgramInf symbex.run(callBack); // Emit a performance report, if desired. - testBackend->printPerformanceReport(true); + printPerformanceReport(testPath); // Do not print this warning if assertion mode is enabled. if (testBackend->getTestCount() == 0 && !testgenOptions.assertionModeEnabled) {