[P4Testgen] Move P4Testgen's logging function into the common library.

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

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 {

backends/p4tools/common/lib/logging.cpp

@@ -0,0 +1,60 @@
+#include "backends/p4tools/common/lib/logging.h"
+
+#include <fstream>
+#include <unordered_map>
+
+#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<std::filesystem::path> &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::string, std::string>;
+    std::vector<TimerData> 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

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 <filesystem>
+#include <string>
+#include <utility>
+
+#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 <typename... Arguments>
+void printInfo(const std::string &fmt, Arguments &&...args) {
+    printFeature("test_info", 4, fmt, std::forward<Arguments>(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<std::filesystem::path> &basePath = std::nullopt);
+
+}  // namespace P4Tools
+
+#endif /* BACKENDS_P4TOOLS_COMMON_LIB_LOGGING_H_ */

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

backends/p4tools/modules/testgen/lib/logging.h

@@ -4,6 +4,7 @@
 #include <string>
 #include <utility>
 
+#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<Arguments>(args)...);
 }
 
-/// Helper functions that prints strings associated with basic test generation information., for
-/// example the covered nodes or tests number.
-template <typename... Arguments>
-void printInfo(const std::string &fmt, Arguments &&...args) {
-    printFeature("test_info", 4, fmt, std::forward<Arguments>(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_ */

backends/p4tools/modules/testgen/lib/test_backend.cpp

@@ -1,6 +1,5 @@
 #include "backends/p4tools/modules/testgen/lib/test_backend.h"
 
-#include <iostream>
 #include <optional>
 
 #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; }

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;
 

backends/p4tools/modules/testgen/lib/test_framework.cpp

@@ -1,62 +1,12 @@
 #include "backends/p4tools/modules/testgen/lib/test_framework.h"
 
-#include <algorithm>
-#include <cctype>
 #include <optional>
-#include <ostream>
 #include <utility>
 
-#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<unsigned int> 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

backends/p4tools/modules/testgen/lib/test_framework.h

@@ -3,20 +3,16 @@
 
 #include <cstddef>
 #include <filesystem>
-#include <functional>
 #include <iosfwd>
-#include <list>
 #include <map>
 #include <optional>
 #include <string>
 #include <utility>
-#include <vector>
 
 #include <inja/inja.hpp>
 
 #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

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.");

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) {