[ESI][Runtime] Logging API

frontends/PyCDE/integration_test/esitester.py

@@ -29,6 +29,8 @@
 
 import sys
 
+# CHECK: [INFO] [CONNECT] connecting to backend
+
 
 class PrintfExample(Module):
   """Call a printf function on the host once at startup."""
@@ -38,6 +40,8 @@ class PrintfExample(Module):
 
   @generator
   def construct(ports):
+    # CHECK: [DEBUG] [ESITESTER] Received PrintfExample message
+    # CHECK:                     data: 7000
     # CHECK: PrintfExample: 7
     arg_data = UInt(32)(7)
 

frontends/PyCDE/integration_test/test_software/esi_test.py

@@ -4,6 +4,8 @@
 import sys
 import time
 
+esi.accelerator.ctxt.set_stdio_logger(esi.accelerator.cpp.LogLevel.Debug)
+
 platform = sys.argv[1]
 acc = esi.AcceleratorConnection(platform, sys.argv[2])
 

lib/Dialect/ESI/runtime/CMakeLists.txt

@@ -100,6 +100,7 @@ set(ESICppRuntimeSources
   ${CMAKE_CURRENT_SOURCE_DIR}/cpp/lib/Context.cpp
   ${CMAKE_CURRENT_SOURCE_DIR}/cpp/lib/Common.cpp
   ${CMAKE_CURRENT_SOURCE_DIR}/cpp/lib/Design.cpp
+  ${CMAKE_CURRENT_SOURCE_DIR}/cpp/lib/Logging.cpp
   ${CMAKE_CURRENT_SOURCE_DIR}/cpp/lib/Manifest.cpp
   ${CMAKE_CURRENT_SOURCE_DIR}/cpp/lib/Services.cpp
   ${CMAKE_CURRENT_SOURCE_DIR}/cpp/lib/Ports.cpp

lib/Dialect/ESI/runtime/cpp/include/esi/Accelerator.h

@@ -80,6 +80,7 @@ class AcceleratorConnection {
   AcceleratorConnection(Context &ctxt);
   virtual ~AcceleratorConnection();
   Context &getCtxt() const { return ctxt; }
+  Logger &getLogger() const { return ctxt.getLogger(); }
 
   /// Disconnect from the accelerator cleanly.
   virtual void disconnect();

lib/Dialect/ESI/runtime/cpp/include/esi/Common.h

@@ -119,6 +119,9 @@ class MessageData {
     return MessageData(reinterpret_cast<const uint8_t *>(&t), sizeof(T));
   }
 
+  /// Convert the data to a hex string.
+  std::string toHex() const;
+
 private:
   std::vector<uint8_t> data;
 };

lib/Dialect/ESI/runtime/cpp/include/esi/Context.h

@@ -16,6 +16,7 @@
 #ifndef ESI_CONTEXT_H
 #define ESI_CONTEXT_H
 
+#include "esi/Logging.h"
 #include "esi/Types.h"
 
 #include <exception>
@@ -28,8 +29,16 @@ class AcceleratorConnection;
 /// AcceleratorConnections, Accelerators, and Manifests must all share a
 /// context. It owns all the types, uniquifying them.
 class Context {
-
 public:
+  Context() : logger(std::make_unique<NullLogger>()) {}
+  Context(std::unique_ptr<Logger> logger) : logger(std::move(logger)) {}
+
+  /// Create a context with a specific logger type.
+  template <typename T, typename... Args>
+  static Context withLogger(Args &&...args) {
+    return Context(std::make_unique<T>(args...));
+  }
+
   /// Resolve a type id to the type.
   std::optional<const Type *> getType(Type::ID id) const {
     if (auto f = types.find(id); f != types.end())
@@ -44,6 +53,17 @@ class Context {
   std::unique_ptr<AcceleratorConnection> connect(std::string backend,
                                                  std::string connection);
 
+  /// Register a logger with the accelerator. Assumes ownership of the logger.
+  void setLogger(std::unique_ptr<Logger> logger) {
+    if (!logger)
+      throw std::invalid_argument("logger must not be null");
+    this->logger = std::move(logger);
+  }
+  inline Logger &getLogger() { return *logger; }
+
+private:
+  std::unique_ptr<Logger> logger;
+
 private:
   using TypeCache = std::map<Type::ID, std::unique_ptr<Type>>;
   TypeCache types;

lib/Dialect/ESI/runtime/cpp/include/esi/Logging.h

@@ -0,0 +1,180 @@
+//===- Logging.h - ESI Runtime logging --------------------------*- C++ -*-===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+//
+// ESI runtime logging is very simple but very flexible. Rather than mandating a
+// particular logging library, it allows users to hook into their existing
+// logging system by implementing a simple interface.
+//
+//===----------------------------------------------------------------------===//
+//
+// DO NOT EDIT!
+// This file is distributed as part of an ESI package. The source for this file
+// should always be modified within CIRCT.
+//
+//===----------------------------------------------------------------------===//
+
+// NOLINTNEXTLINE(llvm-header-guard)
+#ifndef ESI_LOGGING_H
+#define ESI_LOGGING_H
+
+#include <any>
+#include <functional>
+#include <iosfwd>
+#include <map>
+#include <memory>
+#include <string>
+
+namespace esi {
+
+class Logger {
+public:
+  enum class Level {
+    Error,   // Many errors will be followed by exceptions which may get caught.
+    Warning, // May indicate a problem.
+    Info,    // General information, like connecting to an accelerator.
+    Debug,   // Everything and the kitchen sink, possibly including _all_
+             // messages written and read.
+  };
+  Logger(bool debugEnabled) : debugEnabled(debugEnabled) {}
+  virtual ~Logger() = default;
+  bool getDebugEnabled() { return debugEnabled; }
+
+  /// Report a log message.
+  /// Arguments:
+  ///   level: The log level as defined by the 'Level' enum above.
+  ///   subsystem: The subsystem that generated the log message.
+  ///   msg: The log message.
+  ///   details: Optional additional structured details to include in the log
+  ///            message. If there are no details, this should be nullptr.
+  virtual void
+  log(Level level, const std::string &subsystem, const std::string &msg,
+      const std::map<std::string, std::any> *details = nullptr) = 0;
+
+  /// Report an error.
+  virtual void error(const std::string &subsystem, const std::string &msg,
+                     const std::map<std::string, std::any> *details = nullptr) {
+    log(Level::Error, subsystem, msg, details);
+  }
+  /// Report a warning.
+  virtual void
+  warning(const std::string &subsystem, const std::string &msg,
+          const std::map<std::string, std::any> *details = nullptr) {
+    log(Level::Warning, subsystem, msg, details);
+  }
+  /// Report an informational message.
+  virtual void info(const std::string &subsystem, const std::string &msg,
+                    const std::map<std::string, std::any> *details = nullptr) {
+    log(Level::Info, subsystem, msg, details);
+  }
+
+  /// Report a debug message. This is not virtual so that it can be inlined to
+  /// minimize performance impact that debug messages have, allowing debug
+  /// messages in Release builds.
+  inline void debug(const std::string &subsystem, const std::string &msg,
+                    const std::map<std::string, std::any> *details = nullptr) {
+    if (debugEnabled)
+      debugImpl(subsystem, msg, details);
+  }
+  /// Call the debug function callback only if debug is enabled then log a debug
+  /// message. Allows users to run heavy weight debug message generation code
+  /// only when debug is enabled, which in turns allows users to provide
+  /// fully-featured debug messages in Release builds with minimal performance
+  /// impact. Not virtual so that it can be inlined.
+  inline void
+  debug(std::function<
+        void(std::string &subsystem, std::string &msg,
+             std::unique_ptr<std::map<std::string, std::any>> &details)>
+            debugFunc) {
+    if (debugEnabled)
+      debugImpl(debugFunc);
+  }
+
+protected:
+  /// Overrideable version of debug. Only gets called if debug is enabled.
+  virtual void debugImpl(const std::string &subsystem, const std::string &msg,
+                         const std::map<std::string, std::any> *details) {
+    log(Level::Debug, subsystem, msg, details);
+  }
+  /// Overrideable version of debug. Only gets called if debug is enabled.
+  virtual void
+  debugImpl(std::function<
+            void(std::string &subsystem, std::string &msg,
+                 std::unique_ptr<std::map<std::string, std::any>> &details)>
+                debugFunc) {
+    if (!debugEnabled)
+      return;
+    std::string subsystem;
+    std::string msg;
+    std::unique_ptr<std::map<std::string, std::any>> details = nullptr;
+    debugFunc(subsystem, msg, details);
+    debugImpl(subsystem, msg, details.get());
+  }
+
+  /// Enable or disable debug messages.
+  bool debugEnabled = false;
+};
+
+/// A thread-safe logger which calls functions implemented by subclasses. Only
+/// protects the `log` method. If subclasses override other methods and need to
+/// protect them, they need to do that themselves.
+class TSLogger : public Logger {
+public:
+  using Logger::Logger;
+
+  /// Grabs the lock and calls logImpl.
+  void log(Level level, const std::string &subsystem, const std::string &msg,
+           const std::map<std::string, std::any> *details) override final;
+
+protected:
+  /// Subclasses must implement this method to log messages.
+  virtual void logImpl(Level level, const std::string &subsystem,
+                       const std::string &msg,
+                       const std::map<std::string, std::any> *details) = 0;
+
+  /// Mutex to protect the stream from interleaved logging writes.
+  std::mutex mutex;
+};
+
+/// A logger that writes to a C++ std::ostream.
+class StreamLogger : public TSLogger {
+public:
+  /// Create a stream logger that logs to the given output stream and error
+  /// output stream.
+  StreamLogger(Level minLevel, std::ostream &out, std::ostream &error)
+      : TSLogger(minLevel == Level::Debug), minLevel(minLevel), outStream(out),
+        errorStream(error) {}
+  /// Create a stream logger that logs to stdout, stderr.
+  StreamLogger(Level minLevel);
+  void logImpl(Level level, const std::string &subsystem,
+               const std::string &msg,
+               const std::map<std::string, std::any> *details) override;
+
+private:
+  /// The minimum log level to emit.
+  Level minLevel;
+
+  /// Everything except errors goes here.
+  std::ostream &outStream;
+  /// Just for errors.
+  std::ostream &errorStream;
+};
+
+/// A logger that does nothing.
+class NullLogger : public Logger {
+public:
+  NullLogger() : Logger(false) {}
+  void log(Level, const std::string &, const std::string &,
+           const std::map<std::string, std::any> *) override {}
+};
+
+/// 'Stringify' a std::any. This is used to log std::any values by some loggers.
+std::string toString(const std::any &a);
+
+} // namespace esi
+
+#endif // ESI_LOGGING_H

lib/Dialect/ESI/runtime/cpp/lib/Accelerator.cpp

@@ -116,7 +116,8 @@ static std::filesystem::path getLibPath() {
 /// Load a backend plugin dynamically. Plugins are expected to be named
 /// lib<BackendName>Backend.so and located in one of 1) CWD, 2) in the same
 /// directory as the application, or 3) in the same directory as this library.
-static void loadBackend(std::string backend) {
+static void loadBackend(Context &ctxt, std::string backend) {
+  Logger &logger = ctxt.getLogger();
   backend[0] = toupper(backend[0]);
 
   // Get the file name we are looking for.
@@ -135,15 +136,24 @@ static void loadBackend(std::string backend) {
   // First, try the current directory.
   std::filesystem::path backendPath = backendFileName;
   std::string backendPathStr;
+  logger.debug("CONNECT",
+               "trying to load backend plugin: " + backendPath.string());
   if (!std::filesystem::exists(backendPath)) {
     // Next, try the directory of the executable.
     backendPath = getExePath().parent_path().append(backendFileName);
+    logger.debug("CONNECT",
+                 "trying to load backend plugin: " + backendPath.string());
     if (!std::filesystem::exists(backendPath)) {
       // Finally, try the directory of the library.
       backendPath = getLibPath().parent_path().append(backendFileName);
-      if (!std::filesystem::exists(backendPath))
+      logger.debug("CONNECT",
+                   "trying to load backend plugin: " + backendPath.string());
+      if (!std::filesystem::exists(backendPath)) {
         // If all else fails, just try the name.
         backendPathStr = backendFileName;
+        logger.debug("CONNECT",
+                     "trying to load backend plugin: " + backendPathStr);
+      }
     }
   }
   // If the path was found, convert it to a string.
@@ -158,9 +168,13 @@ static void loadBackend(std::string backend) {
     // Attempt to load it.
 #ifdef __linux__
   void *handle = dlopen(backendPathStr.c_str(), RTLD_NOW | RTLD_GLOBAL);
-  if (!handle)
+  if (!handle) {
+    std::string error(dlerror());
+    logger.error("CONNECT",
+                 "while attempting to load backend plugin: " + error);
     throw std::runtime_error("While attempting to load backend plugin: " +
-                             std::string(dlerror()));
+                             error);
+  }
 #elif _WIN32
   // Set the DLL directory to the same directory as the backend DLL in case it
   // has transitive dependencies.
@@ -175,15 +189,21 @@ static void loadBackend(std::string backend) {
   HMODULE handle = LoadLibraryA(backendPathStr.c_str());
   if (!handle) {
     DWORD error = GetLastError();
-    if (error == ERROR_MOD_NOT_FOUND)
+    if (error == ERROR_MOD_NOT_FOUND) {
+      logger.error("CONNECT", "while attempting to load backend plugin: " +
+                                  backendPathStr + " not found");
       throw std::runtime_error("While attempting to load backend plugin: " +
                                backendPathStr + " not found");
+    }
+    logger.error("CONNECT", "while attempting to load backend plugin: " +
+                                std::to_string(error));
     throw std::runtime_error("While attempting to load backend plugin: " +
                              std::to_string(error));
   }
 #else
 #eror "Unsupported platform"
 #endif
+  logger.info("CONNECT", "loaded backend plugin: " + backendPathStr);
 }
 
 namespace registry {
@@ -215,11 +235,15 @@ std::unique_ptr<AcceleratorConnection> connect(Context &ctxt,
   auto f = registry.find(backend);
   if (f == registry.end()) {
     // If it's not already found in the registry, try to load it dynamically.
-    loadBackend(backend);
+    loadBackend(ctxt, backend);
     f = registry.find(backend);
-    if (f == registry.end())
+    if (f == registry.end()) {
+      ctxt.getLogger().error("CONNECT", "backend '" + backend + "' not found");
       throw std::runtime_error("Backend '" + backend + "' not found");
+    }
   }
+  ctxt.getLogger().info("CONNECT", "connecting to backend " + backend +
+                                       " via '" + connection + "'");
   return f->second(ctxt, connection);
 }
 

lib/Dialect/ESI/runtime/cpp/lib/Common.cpp

@@ -17,6 +17,23 @@
 #include <iostream>
 #include <sstream>
 
+using namespace esi;
+
+std::string MessageData::toHex() const {
+  std::ostringstream ss;
+  ss << std::hex;
+  for (size_t i = 0, e = data.size(); i != e; ++i) {
+    // Add spaces every 8 bytes.
+    if (i % 8 == 0 && i != 0)
+      ss << ' ';
+    // Add an extra space every 64 bytes.
+    if (i % 64 == 0 && i != 0)
+      ss << ' ';
+    ss << static_cast<unsigned>(data[i]);
+  }
+  return ss.str();
+}
+
 std::string esi::toHex(uint32_t val) {
   std::ostringstream ss;
   ss << std::hex << val;