From 2a854c3dcdbf5f2877e60fd7177a78ab21d0b4bd Mon Sep 17 00:00:00 2001 From: John Demme Date: Tue, 3 Sep 2024 03:16:38 +0000 Subject: [PATCH] [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 | 4 + .../test_software/esi_test.py | 2 + lib/Dialect/ESI/runtime/CMakeLists.txt | 1 + .../ESI/runtime/cpp/include/esi/Accelerator.h | 1 + .../ESI/runtime/cpp/include/esi/Common.h | 3 + .../ESI/runtime/cpp/include/esi/Context.h | 22 ++- .../ESI/runtime/cpp/include/esi/Logging.h | 160 ++++++++++++++++++ .../ESI/runtime/cpp/lib/Accelerator.cpp | 38 ++++- lib/Dialect/ESI/runtime/cpp/lib/Common.cpp | 17 ++ lib/Dialect/ESI/runtime/cpp/lib/Logging.cpp | 98 +++++++++++ .../ESI/runtime/cpp/tools/esitester.cpp | 18 +- .../runtime/python/esiaccel/esiCppAccel.cpp | 13 +- 12 files changed, 363 insertions(+), 14 deletions(-) create mode 100644 lib/Dialect/ESI/runtime/cpp/include/esi/Logging.h create mode 100644 lib/Dialect/ESI/runtime/cpp/lib/Logging.cpp diff --git a/frontends/PyCDE/integration_test/esitester.py b/frontends/PyCDE/integration_test/esitester.py index e390ffe0d86a..c763cdf48a88 100644 --- a/frontends/PyCDE/integration_test/esitester.py +++ b/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) diff --git a/frontends/PyCDE/integration_test/test_software/esi_test.py b/frontends/PyCDE/integration_test/test_software/esi_test.py index 605d27a1dec1..c9d6e45b45bc 100644 --- a/frontends/PyCDE/integration_test/test_software/esi_test.py +++ b/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]) diff --git a/lib/Dialect/ESI/runtime/CMakeLists.txt b/lib/Dialect/ESI/runtime/CMakeLists.txt index b14555cd9153..99d220788b52 100644 --- a/lib/Dialect/ESI/runtime/CMakeLists.txt +++ b/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 diff --git a/lib/Dialect/ESI/runtime/cpp/include/esi/Accelerator.h b/lib/Dialect/ESI/runtime/cpp/include/esi/Accelerator.h index e80d2600a7a4..8713cd275120 100644 --- a/lib/Dialect/ESI/runtime/cpp/include/esi/Accelerator.h +++ b/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(); diff --git a/lib/Dialect/ESI/runtime/cpp/include/esi/Common.h b/lib/Dialect/ESI/runtime/cpp/include/esi/Common.h index a47e2c0e76dd..6169054daa87 100644 --- a/lib/Dialect/ESI/runtime/cpp/include/esi/Common.h +++ b/lib/Dialect/ESI/runtime/cpp/include/esi/Common.h @@ -119,6 +119,9 @@ class MessageData { return MessageData(reinterpret_cast(&t), sizeof(T)); } + /// Convert the data to a hex string. + std::string toHex() const; + private: std::vector data; }; diff --git a/lib/Dialect/ESI/runtime/cpp/include/esi/Context.h b/lib/Dialect/ESI/runtime/cpp/include/esi/Context.h index 9616dcf4670a..3f446ac022e1 100644 --- a/lib/Dialect/ESI/runtime/cpp/include/esi/Context.h +++ b/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 @@ -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()) {} + Context(std::unique_ptr logger) : logger(std::move(logger)) {} + + /// Create a context with a specific logger type. + template + static Context withLogger(Args &&...args) { + return Context(std::make_unique(args...)); + } + /// Resolve a type id to the type. std::optional getType(Type::ID id) const { if (auto f = types.find(id); f != types.end()) @@ -44,6 +53,17 @@ class Context { std::unique_ptr connect(std::string backend, std::string connection); + /// Register a logger with the accelerator. Assumes ownership of the logger. + void setLogger(std::unique_ptr 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; + private: using TypeCache = std::map>; TypeCache types; diff --git a/lib/Dialect/ESI/runtime/cpp/include/esi/Logging.h b/lib/Dialect/ESI/runtime/cpp/include/esi/Logging.h new file mode 100644 index 000000000000..ef0bde1e179a --- /dev/null +++ b/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 +#include +#include +#include +#include +#include + +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 *details = nullptr) = 0; + + /// Report an error. + virtual void error(const std::string &subsystem, const std::string &msg, + const std::map *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 *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 *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 *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> &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 *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> &details)> + debugFunc) { + if (!debugEnabled) + return; + std::string subsystem; + std::string msg; + std::unique_ptr> 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 *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 *) 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 diff --git a/lib/Dialect/ESI/runtime/cpp/lib/Accelerator.cpp b/lib/Dialect/ESI/runtime/cpp/lib/Accelerator.cpp index 9f94d784489d..9df78be3f4e3 100644 --- a/lib/Dialect/ESI/runtime/cpp/lib/Accelerator.cpp +++ b/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 /// libBackend.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 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); } diff --git a/lib/Dialect/ESI/runtime/cpp/lib/Common.cpp b/lib/Dialect/ESI/runtime/cpp/lib/Common.cpp index 909cf3b8cafc..50b4308cff7b 100644 --- a/lib/Dialect/ESI/runtime/cpp/lib/Common.cpp +++ b/lib/Dialect/ESI/runtime/cpp/lib/Common.cpp @@ -17,6 +17,23 @@ #include #include +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(data[i]); + } + return ss.str(); +} + std::string esi::toHex(uint32_t val) { std::ostringstream ss; ss << std::hex << val; diff --git a/lib/Dialect/ESI/runtime/cpp/lib/Logging.cpp b/lib/Dialect/ESI/runtime/cpp/lib/Logging.cpp new file mode 100644 index 000000000000..3ad650a4e728 --- /dev/null +++ b/lib/Dialect/ESI/runtime/cpp/lib/Logging.cpp @@ -0,0 +1,98 @@ +//===- Logging.cpp - ESI logging system API implementation ----------------===// +// +// 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 +// +//===----------------------------------------------------------------------===// +// +// DO NOT EDIT! +// This file is distributed as part of an ESI package. The source for this file +// should always be modified within CIRCT (lib/dialect/ESI/runtime/cpp/). +// +//===----------------------------------------------------------------------===// + +#include "esi/Logging.h" +#include "esi/Common.h" + +#include +#include + +using namespace esi; + +// Necessary in some versions of the c++ standard library to avoid warnings +// about scoped_lock deduction guides. +struct allow_ctad_t; +namespace std { +scoped_lock(allow_ctad_t) -> scoped_lock; +lock_guard(allow_ctad_t) -> lock_guard; +} // namespace std + +StreamLogger::StreamLogger(Level minLevel) + : Logger(minLevel == Level::Debug), minLevel(minLevel), + outStream(std::cout), errorStream(std::cerr) {} + +void StreamLogger::log(Level level, const std::string &subsystem, + const std::string &msg, + const std::map *details) { + std::scoped_lock lock(mutex); + std::ostream &os = level == Level::Error ? errorStream : outStream; + unsigned indentSpaces = 0; + + switch (level) { + case Level::Error: + os << "[ERROR] "; + indentSpaces = 8; + break; + case Level::Warning: + os << "[WARNING] "; + indentSpaces = 10; + break; + case Level::Info: + os << "[INFO] "; + indentSpaces = 7; + break; + case Level::Debug: + os << "[DEBUG] "; + indentSpaces = 8; + break; + } + + if (!subsystem.empty()) { + os << "[" << subsystem << "] "; + indentSpaces += subsystem.size() + 3; + } + os << msg << std::endl; + + if (!details) + return; + std::string indent(indentSpaces, ' '); + for (const auto &detail : *details) + os << indent << detail.first << ": " << toString(detail.second) << "\n"; +} + +std::string esi::toString(const std::any &value) { + if (value.type() == typeid(std::string)) + return std::any_cast(value); + if (value.type() == typeid(int)) + return std::to_string(std::any_cast(value)); + if (value.type() == typeid(long)) + return std::to_string(std::any_cast(value)); + if (value.type() == typeid(unsigned)) + return std::to_string(std::any_cast(value)); + if (value.type() == typeid(unsigned long)) + return std::to_string(std::any_cast(value)); + if (value.type() == typeid(bool)) + return std::any_cast(value) ? "true" : "false"; + if (value.type() == typeid(double)) + return std::to_string(std::any_cast(value)); + if (value.type() == typeid(float)) + return std::to_string(std::any_cast(value)); + if (value.type() == typeid(const char *)) + return std::string(std::any_cast(value)); + if (value.type() == typeid(char)) + return std::string(1, std::any_cast(value)); + if (value.type() == typeid(MessageData)) + return std::any_cast(value).toHex(); + return ""; +} diff --git a/lib/Dialect/ESI/runtime/cpp/tools/esitester.cpp b/lib/Dialect/ESI/runtime/cpp/tools/esitester.cpp index d2563616d645..52aa456504b2 100644 --- a/lib/Dialect/ESI/runtime/cpp/tools/esitester.cpp +++ b/lib/Dialect/ESI/runtime/cpp/tools/esitester.cpp @@ -29,7 +29,7 @@ using namespace esi; -static void registerCallbacks(Accelerator *); +static void registerCallbacks(AcceleratorConnection *, Accelerator *); int main(int argc, const char *argv[]) { // TODO: find a command line parser library rather than doing this by hand. @@ -46,14 +46,14 @@ int main(int argc, const char *argv[]) { cmd = argv[3]; try { - Context ctxt; + Context ctxt = Context::withLogger(Logger::Level::Debug); std::unique_ptr acc = ctxt.connect(backend, conn); const auto &info = *acc->getService(); Manifest manifest(ctxt, info.getJsonManifest()); Accelerator *accel = manifest.buildAccelerator(*acc); acc->getServiceThread()->addPoll(*accel); - registerCallbacks(accel); + registerCallbacks(acc.get(), accel); if (cmd == "loop") { while (true) { @@ -73,14 +73,22 @@ int main(int argc, const char *argv[]) { } } -void registerCallbacks(Accelerator *accel) { +void registerCallbacks(AcceleratorConnection *conn, Accelerator *accel) { auto ports = accel->getPorts(); auto f = ports.find(AppID("PrintfExample")); if (f != ports.end()) { auto callPort = f->second.getAs(); if (callPort) callPort->connect( - [](const MessageData &data) -> MessageData { + [conn](const MessageData &data) -> MessageData { + conn->getLogger().debug( + [&](std::string &subsystem, std::string &msg, + std::unique_ptr> &details) { + subsystem = "ESITESTER"; + msg = "Received PrintfExample message"; + details = std::make_unique>(); + details->emplace("data", data); + }); std::cout << "PrintfExample: " << *data.as() << std::endl; return MessageData(); }, diff --git a/lib/Dialect/ESI/runtime/python/esiaccel/esiCppAccel.cpp b/lib/Dialect/ESI/runtime/python/esiaccel/esiCppAccel.cpp index 145e468b2899..cf873c971b37 100644 --- a/lib/Dialect/ESI/runtime/python/esiaccel/esiCppAccel.cpp +++ b/lib/Dialect/ESI/runtime/python/esiaccel/esiCppAccel.cpp @@ -180,6 +180,14 @@ PYBIND11_MODULE(esiCppAccel, m) { return os.str(); }); + py::enum_(m, "LogLevel") + .value("Debug", Logger::Level::Debug) + .value("Info", Logger::Level::Info) + .value("Warning", Logger::Level::Warning) + .value("Error", Logger::Level::Error) + .export_values(); + py::class_(m, "Logger"); + py::class_(m, "Service"); py::class_(m, "SysInfo") @@ -339,7 +347,10 @@ PYBIND11_MODULE(esiCppAccel, m) { py::class_(m, "Context") .def(py::init<>()) - .def("connect", &Context::connect); + .def("connect", &Context::connect) + .def("set_stdio_logger", [](Context &ctxt, Logger::Level level) { + ctxt.setLogger(std::make_unique(level)); + }); accConn.def(py::init(®istry::connect)) .def(