P4Testgen logging cleanups. (p4lang#4684)

* Some logging fixes. Signed-off-by: fruffy <[email protected]> * Return when the logging level does not match. Signed-off-by: fruffy <[email protected]> --------- Signed-off-by: fruffy <[email protected]>
komaljai · Jul 2, 2024 · a484745 · a484745
1 parent 061cb5a
commit a484745
Show file tree

Hide file tree

Showing 4 changed files with 53 additions and 48 deletions.
diff --git a/backends/p4tools/common/lib/logging.cpp b/backends/p4tools/common/lib/logging.cpp
@@ -3,33 +3,34 @@
 #include <fstream>
 #include <unordered_map>
 
+#include "lib/error.h"
 #include "lib/log.h"
 #include "lib/timer.h"
 
 namespace P4Tools {
 
-void enableInformationLogging() { ::Log::addDebugSpec("test_info:4"); }
+void enableInformationLogging() { ::Log::addDebugSpec("tools_info:4"); }
 
-void enablePerformanceLogging() { ::Log::addDebugSpec("performance:4"); }
+void enablePerformanceLogging() { ::Log::addDebugSpec("tools_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)) {
+    if (!Log::fileLogLevelIsAtLeast("tools_performance", 4)) {
         return;
     }
-    printFeature("performance", 4, "============ Timers ============");
+    printFeature("tools_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);
+            printFeature("tools_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,
+            printFeature("tools_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),

diff --git a/backends/p4tools/common/lib/logging.h b/backends/p4tools/common/lib/logging.h
@@ -2,18 +2,53 @@
 #define BACKENDS_P4TOOLS_COMMON_LIB_LOGGING_H_
 
 #include <filesystem>
+#include <optional>
 #include <string>
 #include <utility>
 
-#include "backends/p4tools/common/lib/util.h"
+#include <boost/format.hpp>
+
+#include "lib/log.h"
 
 namespace P4Tools {
 
-/// Helper functions that prints strings associated with basic test generation information., for
-/// example the covered nodes or tests number.
+/// Helper function for @printFeature
+inline std::string logHelper(boost::format &f) { return f.str(); }
+
+/// Helper function for @printFeature
+template <class T, class... Args>
+std::string logHelper(boost::format &f, T &&t, Args &&...args) {
+    return logHelper(f % std::forward<T>(t), std::forward<Args>(args)...);
+}
+
+/// A helper function that allows us to configure logging for a particular feature. This code is
+/// taken from
+// https://stackoverflow.com/a/25859856
+template <typename... Arguments>
+void printFeature(const std::string &label, int level, const std::string &fmt,
+                  Arguments &&...args) {
+    // Do not print logging messages when logging is not enabled.
+    if (!Log::fileLogLevelIsAtLeast(label.c_str(), level)) {
+        return;
+    }
+
+    boost::format f(fmt);
+    LOG_FEATURE(label.c_str(), level, logHelper(f, std::forward<Arguments>(args)...));
+}
+
+/// Helper functions that prints strings associated with basic tool information.
+/// For example, the seed, status of test case generation, etc.
 template <typename... Arguments>
 void printInfo(const std::string &fmt, Arguments &&...args) {
-    printFeature("test_info", 4, fmt, std::forward<Arguments>(args)...);
+    printFeature("tools_info", 4, fmt, std::forward<Arguments>(args)...);
+}
+
+/// Convenience function for printing debug information.
+/// Easier to use then LOG(XX) since we only need one specific log-level across all files.
+/// Can be invoked with "-T tools_debug:4".
+template <typename... Arguments>
+void printDebug(const std::string &fmt, Arguments &&...args) {
+    printFeature("tools_debug", 4, fmt, std::forward<Arguments>(args)...);
 }
 
 /// Enable the printing of basic run information.

diff --git a/backends/p4tools/common/lib/util.h b/backends/p4tools/common/lib/util.h
@@ -7,41 +7,14 @@
 #include <optional>
 #include <ostream>
 #include <string>
-#include <utility>
 #include <vector>
 
-#include <boost/format.hpp>
 #include <boost/random/mersenne_twister.hpp>
 
 #include "ir/ir.h"
-#include "lib/big_int_util.h"
-#include "lib/cstring.h"
-#include "lib/log.h"
 
 namespace P4Tools {
 
-/// Helper function for @printFeature
-inline std::string logHelper(boost::format &f) { return f.str(); }
-
-/// Helper function for @printFeature
-template <class T, class... Args>
-std::string logHelper(boost::format &f, T &&t, Args &&...args) {
-    return logHelper(f % std::forward<T>(t), std::forward<Args>(args)...);
-}
-
-/// A helper function that allows us to configure logging for a particular feature. This code is
-/// taken from
-// https://stackoverflow.com/a/25859856
-template <typename... Arguments>
-void printFeature(const std::string &label, int level, const std::string &fmt,
-                  Arguments &&...args) {
-    boost::format f(fmt);
-
-    auto result = logHelper(f, std::forward<Arguments>(args)...);
-
-    LOG_FEATURE(label.c_str(), level, result);
-}
-
 /// General utility functions that are not present in the compiler framework.
 class Utils {
     /* =========================================================================================

diff --git a/backends/p4tools/modules/testgen/lib/test_backend.cpp b/backends/p4tools/modules/testgen/lib/test_backend.cpp
@@ -72,8 +72,7 @@ bool TestBackEnd::run(const FinalState &state) {
             if (!executionState->getProperty<bool>("assertionTriggered"_cs)) {
                 return needsToTerminate(testCount);
             }
-            printFeature("test_info", 4,
-                         "AssertionMode: Found an input that triggers an assertion.");
+            printInfo("AssertionMode: Found an input that triggers an assertion.");
         }
 
         // For long-running tests periodically reset the solver state to free up memory.
@@ -142,18 +141,16 @@ bool TestBackEnd::run(const FinalState &state) {
         testCount++;
         const P4::Coverage::CoverageSet &visitedNodes = symbex.getVisitedNodes();
         if (!testgenOptions.hasCoverageTracking) {
-            printFeature("test_info", 4, "============ Test %1% ============", testCount);
+            printInfo("============ Test %1% ============", testCount);
         } else if (coverableNodes.empty()) {
-            printFeature("test_info", 4,
-                         "============ Test %1%: No coverable nodes ============", testCount);
+            printInfo("============ Test %1%: No coverable nodes ============", testCount);
             // All 0 nodes covered.
             coverage = 1.0;
         } else {
             coverage =
                 static_cast<float>(visitedNodes.size()) / static_cast<float>(coverableNodes.size());
-            printFeature("test_info", 4,
-                         "============ Test %1%: Nodes covered: %2% (%3%/%4%) ============",
-                         testCount, coverage, visitedNodes.size(), coverableNodes.size());
+            printInfo("============ Test %1%: Nodes covered: %2% (%3%/%4%) ============", testCount,
+                      coverage, visitedNodes.size(), coverableNodes.size());
             P4::Coverage::logCoverage(coverableNodes, visitedNodes, executionState->getVisited());
         }
 
@@ -240,9 +237,8 @@ bool TestBackEnd::printTestInfo(const ExecutionState * /*executionState*/, const
     printTraces("=======================================");
     // We have no control over the test, if the output port is tainted. So we abort.
     if (Taint::hasTaint(outputPortExpr)) {
-        printFeature(
-            "test_info", 4,
-            "============ Test %1%: Output port tainted - Aborting Test ============", testCount);
+        printInfo("============ Test %1%: Output port tainted - Aborting Test ============",
+                  testCount);
         return true;
     }
     printTraces("Input packet size: %1%", inputPacketSize);