[ESI][Runtime] Logging API

The ESI logging API is intended to be agnostic of the application's
logging framework. In other words, it can be adapted to the
application's logging method with ease -- users must only extend one
class. It also comes with a simple text logger.

It is also designed to enable debug logging in Release builds with
(very) minimal performance overhead if the user does not set the log
level to debug.

This PR introduces the API, but doesn't use it much. More plumbing will
be required to actually use it. In the interest of keeping this PR
small, this is left for future work.

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,160 @@
+//===- 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 logger that writes to a C++ std::ostream.
+class StreamLogger : public Logger {
+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)
+      : Logger(minLevel == Level::Debug), minLevel(minLevel), outStream(out),
+        errorStream(error) {}
+  /// Create a stream logger that logs to stdout, stderr.
+  StreamLogger(Level minLevel);
+  void log(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;
+
+  /// Mutex to protect the stream from interleaved logging writes.
+  std::mutex mutex;
+  /// 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;