From f3bd693165af430175484be3e69a263e99b84f5d Mon Sep 17 00:00:00 2001 From: Joel Smith <140545543+joelsmithTT@users.noreply.github.com> Date: Thu, 28 Nov 2024 11:11:48 -0600 Subject: [PATCH] Introduce a real logging library (#290) ### Issue Follow on from https://github.com/tenstorrent/tt-umd/pull/176 https://github.com/tenstorrent/tt-umd/issues/160 https://github.com/tenstorrent/tt-umd/issues/140 ### Description * Adds a real logging library [spdlog](https://github.com/gabime/spdlog) to replace the homegrown logger.hpp * Lazy initializes * Supports logging to console (stderr) and/or disk * Not integrated yet (does not yet replace logger.hpp) -- want feedback from the team prior to replacing existing log statements ### List of the changes * Introduces new logging API * Adds tests and performance characterization code ### Testing * Unit tests ### API Changes There are no public API changes in this PR. --- cmake/dependencies.cmake | 37 +++--- common/CMakeLists.txt | 2 + common/logger_.cpp | 49 ++++++++ common/logger_.hpp | 90 +++++++++++++++ common/timestamp.hpp | 61 ++++++++++ device/CMakeLists.txt | 1 + tests/CMakeLists.txt | 2 +- tests/misc/CMakeLists.txt | 12 +- tests/misc/test_logger.cpp | 225 +++++++++++++++++++++++++++++++++++++ 9 files changed, 460 insertions(+), 19 deletions(-) create mode 100644 common/logger_.cpp create mode 100644 common/logger_.hpp create mode 100644 common/timestamp.hpp create mode 100644 tests/misc/test_logger.cpp diff --git a/cmake/dependencies.cmake b/cmake/dependencies.cmake index 96ebbaf5..86152401 100644 --- a/cmake/dependencies.cmake +++ b/cmake/dependencies.cmake @@ -8,9 +8,9 @@ function(fetch_dependencies) include(${PROJECT_SOURCE_DIR}/cmake/CPM.cmake) - ############################################################################################################################ + #################################################################################################################### # google test - ############################################################################################################################ + #################################################################################################################### CPMAddPackage( NAME googletest GITHUB_REPOSITORY google/googletest @@ -20,9 +20,9 @@ function(fetch_dependencies) "INSTALL_GTEST OFF" ) - ############################################################################################################################ + #################################################################################################################### # yaml-cpp - ############################################################################################################################ + #################################################################################################################### CPMAddPackage( NAME yaml-cpp GITHUB_REPOSITORY jbeder/yaml-cpp @@ -42,15 +42,15 @@ function(fetch_dependencies) ) endif() - ############################################################################################################################ + ################################################################################################################### # boost::interprocess - ############################################################################################################################ + ################################################################################################################### include(${PROJECT_SOURCE_DIR}/cmake/fetch_boost.cmake) fetch_boost_library(interprocess) - ############################################################################################################################ + ################################################################################################################### # Nanomsg - ############################################################################################################################ + ################################################################################################################### CPMAddPackage( NAME nanomsg GITHUB_REPOSITORY nanomsg/nng @@ -61,9 +61,9 @@ function(fetch_dependencies) "NNG_TOOLS OFF" ) - ############################################################################################################################ + ################################################################################################################### # Flatbuffers - ############################################################################################################################ + ################################################################################################################### CPMAddPackage( NAME flatbuffers GITHUB_REPOSITORY google/flatbuffers @@ -94,22 +94,27 @@ function(fetch_dependencies) set(FBS_GENERATED_HEADER ${FBS_GENERATED_HEADER} PARENT_SCOPE) endfunction() - ############################################################################################################################ + ################################################################################################################### # libuv (for process management) - ############################################################################################################################ + ################################################################################################################### CPMAddPackage(NAME libuv GITHUB_REPOSITORY libuv/libuv GIT_TAG v1.48.0 OPTIONS "LIBUV_BUILD_TESTS OFF") - ############################################################################################################################ + ################################################################################################################### # fmt : https://github.com/fmtlib/fmt - ############################################################################################################################ + ################################################################################################################### CPMAddPackage(NAME fmt GITHUB_REPOSITORY fmtlib/fmt GIT_TAG 11.0.1) - ############################################################################################################################ + ################################################################################################################### # nanobench (for uBenchmarking) - ############################################################################################################################ + ################################################################################################################### if(MASTER_PROJECT) CPMAddPackage(NAME nanobench GITHUB_REPOSITORY martinus/nanobench GIT_TAG v4.3.11) endif() + + #################################################################################################################### + # spdlog + #################################################################################################################### + CPMAddPackage(NAME spdlog GITHUB_REPOSITORY gabime/spdlog GIT_TAG v1.14.1 VERSION v1.14.1) endfunction() fetch_dependencies() diff --git a/common/CMakeLists.txt b/common/CMakeLists.txt index 69a6eef6..d1a3f16d 100644 --- a/common/CMakeLists.txt +++ b/common/CMakeLists.txt @@ -8,6 +8,8 @@ target_sources( backtrace.hpp gtest_initializer.hpp # FIXME: this should be tucked away with the tests logger.hpp + logger_.hpp # FIXME: replace old logger, see issue #315 + logger_.cpp ) target_include_directories(umd_common INTERFACE .) diff --git a/common/logger_.cpp b/common/logger_.cpp new file mode 100644 index 00000000..0a604e6f --- /dev/null +++ b/common/logger_.cpp @@ -0,0 +1,49 @@ +/* + * SPDX-FileCopyrightText: (c) 2024 Tenstorrent Inc. + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include "logger_.hpp" // TODO: rename after logger.hpp is removed + +#include +#include +#include + +#include + +namespace tt::umd::logger { + +void initialize(const Options& options) { + static std::mutex mutex; + std::scoped_lock lock{mutex}; + + if (detail::is_initialized.load(std::memory_order_relaxed)) { + return; + } + + std::vector sinks; + + if (options.log_to_stderr) { + auto stderr_sink = std::make_shared(); + sinks.push_back(stderr_sink); + } + + if (!options.filename.empty()) { + auto file_sink = std::make_shared(options.filename); + sinks.push_back(file_sink); + } + + auto logger = std::make_shared("UMD", sinks.begin(), sinks.end()); + logger->set_level(options.log_level); + logger->set_pattern(options.pattern); + + spdlog::set_default_logger(logger); + detail::is_initialized.store(true, std::memory_order_release); +} + +namespace detail { +std::atomic_bool is_initialized = false; +} + +} // namespace tt::umd::logger diff --git a/common/logger_.hpp b/common/logger_.hpp new file mode 100644 index 00000000..047611ad --- /dev/null +++ b/common/logger_.hpp @@ -0,0 +1,90 @@ +/* + * SPDX-FileCopyrightText: (c) 2024 Tenstorrent Inc. + * + * SPDX-License-Identifier: Apache-2.0 + * + */ + +#pragma once + +#include + +#define SPDLOG_FMT_EXTERNAL +#include + +namespace tt::umd::logger { + +/** + * Parameters controlling the behavior of the logger. + */ +struct Options { + bool log_to_stderr{true}; + std::string filename{}; + std::string pattern{"[%Y-%m-%d %H:%M:%S.%e] [%l] [%s:%#] %v"}; + spdlog::level::level_enum log_level{spdlog::level::debug}; + + // TODO: this can be augmented as needed (log rotation, flush policy...) +}; + +/** + * One-time initialization of the logger. + * + * If you don't call it, the logger will be initialized with default options the + * first time a message is logged. + */ +void initialize(const Options& options = Options{}); + +/** + * Macros for using the logger. + */ +#define UMD_TRACE(...) \ + do { \ + ::tt::umd::logger::detail::ensure_initialized(); \ + SPDLOG_TRACE(__VA_ARGS__); \ + } while (0) + +#define UMD_DEBUG(...) \ + do { \ + ::tt::umd::logger::detail::ensure_initialized(); \ + SPDLOG_DEBUG(__VA_ARGS__); \ + } while (0) + +#define UMD_INFO(...) \ + do { \ + ::tt::umd::logger::detail::ensure_initialized(); \ + SPDLOG_INFO(__VA_ARGS__); \ + } while (0) + +#define UMD_WARN(...) \ + do { \ + ::tt::umd::logger::detail::ensure_initialized(); \ + SPDLOG_WARN(__VA_ARGS__); \ + } while (0) + +#define UMD_ERROR(...) \ + do { \ + ::tt::umd::logger::detail::ensure_initialized(); \ + SPDLOG_ERROR(__VA_ARGS__); \ + } while (0) + +#define UMD_CRITICAL(...) \ + do { \ + ::tt::umd::logger::detail::ensure_initialized(); \ + SPDLOG_CRITICAL(__VA_ARGS__); \ + } while (0) + +/** + * This is not part of the API. + */ +namespace detail { +extern std::atomic_bool is_initialized; + +inline void ensure_initialized() { + if (!is_initialized.load(std::memory_order_acquire)) { + initialize(); + } +} + +} // namespace detail + +} // namespace tt::umd::logger diff --git a/common/timestamp.hpp b/common/timestamp.hpp new file mode 100644 index 00000000..055827e3 --- /dev/null +++ b/common/timestamp.hpp @@ -0,0 +1,61 @@ +/* + * SPDX-FileCopyrightText: (c) 2024 Tenstorrent Inc. + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#pragma once + +#include + +#include +#include + +namespace tt::umd::util { + +class Timestamp { + std::chrono::steady_clock::time_point start; + +public: + Timestamp() : start(std::chrono::steady_clock::now()) {} + + void reset() { start = std::chrono::steady_clock::now(); } + + uint64_t nanoseconds() const { + auto now = std::chrono::steady_clock::now(); + return std::chrono::duration_cast(now - start).count(); + } + + uint64_t microseconds() const { + auto now = std::chrono::steady_clock::now(); + return std::chrono::duration_cast(now - start).count(); + } + + uint64_t milliseconds() const { + auto now = std::chrono::steady_clock::now(); + return std::chrono::duration_cast(now - start).count(); + } + + uint64_t seconds() const { + auto now = std::chrono::steady_clock::now(); + return std::chrono::duration_cast(now - start).count(); + } + + std::string to_string() const { + auto ns = nanoseconds(); + if (ns < 1000) { + return fmt::format("{} ns", ns); + } + auto us = microseconds(); + if (us < 1000) { + return fmt::format("{} μs", us); + } + auto ms = milliseconds(); + if (ms < 1000) { + return fmt::format("{} ms", ms); + } + return fmt::format("{} s", seconds()); + } +}; + +} // namespace tt::umd::util diff --git a/device/CMakeLists.txt b/device/CMakeLists.txt index 9f0d0738..592de0e4 100644 --- a/device/CMakeLists.txt +++ b/device/CMakeLists.txt @@ -54,6 +54,7 @@ target_link_libraries( hwloc rt Boost::interprocess + spdlog::spdlog_header_only fmt::fmt-header-only yaml-cpp::yaml-cpp ${CMAKE_CURRENT_SOURCE_DIR}/libs/${CMAKE_SYSTEM_PROCESSOR}/libcreate_ethernet_map.a diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index f37d1718..bfb6057f 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -62,8 +62,8 @@ if(MASTER_PROJECT) add_subdirectory(${CMAKE_CURRENT_SOURCE_DIR}/microbenchmark) endif() add_subdirectory(${CMAKE_CURRENT_SOURCE_DIR}/api) -add_subdirectory(${CMAKE_CURRENT_SOURCE_DIR}/pcie) add_subdirectory(${CMAKE_CURRENT_SOURCE_DIR}/misc) +add_subdirectory(${CMAKE_CURRENT_SOURCE_DIR}/pcie) add_subdirectory(${CMAKE_CURRENT_SOURCE_DIR}/simulation) if($ENV{ARCH_NAME} STREQUAL "wormhole_b0") add_subdirectory(${CMAKE_CURRENT_SOURCE_DIR}/wormhole) diff --git a/tests/misc/CMakeLists.txt b/tests/misc/CMakeLists.txt index fbde42df..4f34dd5b 100644 --- a/tests/misc/CMakeLists.txt +++ b/tests/misc/CMakeLists.txt @@ -1,7 +1,15 @@ -set(UMD_MISC_TESTS_SRCS test_semver.cpp) +set(UMD_MISC_TESTS_SRCS + test_semver.cpp + test_logger.cpp +) add_executable(umd_misc_tests ${UMD_MISC_TESTS_SRCS}) -target_link_libraries(umd_misc_tests PRIVATE test_common) +target_link_libraries( + umd_misc_tests + PRIVATE + test_common + spdlog::spdlog_header_only +) set_target_properties( umd_misc_tests PROPERTIES diff --git a/tests/misc/test_logger.cpp b/tests/misc/test_logger.cpp new file mode 100644 index 00000000..1ed54ac2 --- /dev/null +++ b/tests/misc/test_logger.cpp @@ -0,0 +1,225 @@ +/* + * SPDX-FileCopyrightText: (c) 2024 Tenstorrent Inc. + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include + +#include +#include +#include + +#include "common/logger_.hpp" +#include "common/timestamp.hpp" + +using namespace tt::umd::util; + +class LoggerTest : public ::testing::Test { +protected: + std::filesystem::path temp_dir; + std::filesystem::path log_file; + + void SetUp() override { + // A bit of a hack - logger is only intended to be initialized once per + // process, but we need to reset it for each test. + tt::umd::logger::detail::is_initialized.store(false); + + std::string tmpl = (std::filesystem::temp_directory_path() / "logger_test_XXXXXX").string(); + int fd = mkstemp(tmpl.data()); + if (fd == -1) { + throw std::runtime_error("Failed to create temporary file"); + } + close(fd); + log_file = tmpl; + temp_dir = log_file.parent_path(); + } + + void TearDown() override { + std::filesystem::remove_all(log_file); + spdlog::shutdown(); + } + + // Helper to read entire file content + std::string read_log_file() { + std::ifstream file(log_file); + std::stringstream buf; + buf << file.rdbuf(); + return buf.str(); + } +}; + +TEST_F(LoggerTest, BasicLogging) { + // Initialize logger with our test configuration + tt::umd::logger::Options options; + options.log_to_stderr = true; + options.filename = log_file.string(); + options.pattern = "%v"; // Simple pattern for easier testing + tt::umd::logger::initialize(options); + + // Write some test messages + UMD_INFO("Test message 1"); + UMD_INFO("Test message 2"); + UMD_INFO("Test message 4"); + UMD_INFO("Test message 3"); + + // Force flush by destroying the logger + spdlog::drop_all(); + + auto log_content = read_log_file(); + + // Verify log content + EXPECT_TRUE(log_content.find("Test message 1") != std::string::npos); + EXPECT_TRUE(log_content.find("Test message 2") != std::string::npos); + EXPECT_TRUE(log_content.find("Test message 3") != std::string::npos); + EXPECT_TRUE(log_content.find("Test message 4") != std::string::npos); +} + +TEST_F(LoggerTest, LogLevels) { + tt::umd::logger::Options options; + options.log_to_stderr = true; + options.filename = log_file.string(); + options.pattern = "%v"; + options.log_level = spdlog::level::info; // Set to INFO level + tt::umd::logger::initialize(options); + + UMD_DEBUG("Debug message"); // Shouldn't appear + UMD_INFO("Info message"); // Should appear + UMD_ERROR("Error message"); // Should appear + + spdlog::drop_all(); + + auto log_content = read_log_file(); + + EXPECT_EQ(log_content.find("Debug message"), std::string::npos); + EXPECT_TRUE(log_content.find("Info message") != std::string::npos); + EXPECT_TRUE(log_content.find("Error message") != std::string::npos); +} + +TEST_F(LoggerTest, FormatPatterns) { + tt::umd::logger::Options options; + options.log_to_stderr = false; + options.filename = log_file.string(); + options.pattern = "[%l] %v"; // Level and message + tt::umd::logger::initialize(options); + + UMD_INFO("Test message"); + + spdlog::drop_all(); + + auto log_content = read_log_file(); + + EXPECT_TRUE(log_content.find("[info] Test message") != std::string::npos); +} + +TEST_F(LoggerTest, MultipleInitialization) { + tt::umd::logger::Options options; + options.log_to_stderr = false; + options.filename = log_file.string(); + options.pattern = "%v"; + + // Initialize multiple times - should use first initialization only + tt::umd::logger::initialize(options); + + UMD_INFO("First message"); + + options.pattern = "DIFFERENT: %v"; + tt::umd::logger::initialize(options); // Should be ignored + + UMD_INFO("Second message"); + + spdlog::drop_all(); + + auto log_content = read_log_file(); + + EXPECT_TRUE(log_content.find("First message") != std::string::npos); + EXPECT_TRUE(log_content.find("Second message") != std::string::npos); + EXPECT_EQ(log_content.find("DIFFERENT:"), std::string::npos); +} + +/** + * The next few tests aren't really unit tests - just a mechanism to understand + * the performance of the logger. A log message that isn't printed (i.e. the + * log level suppresses it) is a single-digit nanosecond penalty in a release + * build on EPYC 7713 -- so pretty cheap. + */ +TEST_F(LoggerTest, DiskPerformance) { + const size_t num_messages = 10; + tt::umd::logger::Options options; + options.log_to_stderr = false; + options.filename = log_file.string(); + options.log_level = spdlog::level::info; + tt::umd::logger::initialize(options); + + // Actually logged + { + Timestamp ts; + for (size_t i = 0; i < num_messages; i++) { + UMD_INFO("Test message"); + } + std::cout << ts.to_string() << " for " << num_messages << " messages to disk" << std::endl; + } + + // Not logged - should be faster + { + Timestamp ts; + for (size_t i = 0; i < num_messages; i++) { + UMD_TRACE("Shouldn't be logged"); + } + std::cout << ts.to_string() << " for " << num_messages << " messages below level threshold" << std::endl; + } +} + +TEST_F(LoggerTest, StderrPerformance) { + const size_t num_messages = 10; + tt::umd::logger::Options options; + options.log_to_stderr = true; + options.filename = ""; + options.log_level = spdlog::level::info; + tt::umd::logger::initialize(options); + + // Actually logged + { + Timestamp ts; + for (size_t i = 0; i < num_messages; i++) { + UMD_INFO("Test message"); + } + std::cout << ts.to_string() << " for " << num_messages << " messages to stderr" << std::endl; + } + + // Not logged - should be faster + { + Timestamp ts; + for (size_t i = 0; i < num_messages; i++) { + UMD_TRACE("Shouldn't be logged"); + } + std::cout << ts.to_string() << " for " << num_messages << " messages below level threshold" << std::endl; + } +} + +TEST_F(LoggerTest, StderrAndDiskPerformance) { + const size_t num_messages = 10; + tt::umd::logger::Options options; + options.log_to_stderr = true; + options.filename = log_file.string(); + options.log_level = spdlog::level::info; + tt::umd::logger::initialize(options); + + // Actually logged + { + Timestamp ts; + for (size_t i = 0; i < num_messages; i++) { + UMD_INFO("Test message"); + } + std::cout << ts.to_string() << " for " << num_messages << " messages to disk & stderr" << std::endl; + } + + // Not logged - should be faster + { + Timestamp ts; + for (size_t i = 0; i < num_messages; i++) { + UMD_TRACE("Shouldn't be logged"); + } + std::cout << ts.to_string() << " for " << num_messages << " messages below level threshold" << std::endl; + } +}