feat(core): implement tracing

core/CMakeLists.txt

@@ -30,6 +30,7 @@ set(CUBOS_CORE_SOURCE
 
 	"src/tel/logging.cpp"
 	"src/tel/metrics.cpp"
+	"src/tel/tracing.cpp"
 
 	"src/thread/pool.cpp"
 	"src/thread/task.cpp"

core/include/cubos/core/tel/logging.hpp

@@ -8,6 +8,7 @@
 
 #include <cubos/core/memory/buffer_stream.hpp>
 #include <cubos/core/reflection/reflect.hpp>
+#include <cubos/core/tel/tracing.hpp>
 
 /// @addtogroup core-tel
 /// @{
@@ -298,10 +299,11 @@ namespace cubos::core::tel
         /// @brief Data created by a call to @ref log.
         struct Entry
         {
-            Level level;         ///< Level.
-            Timestamp timestamp; ///< Timestamp;
-            Location location;   ///< Code location which originated the log message.
-            std::string message; ///< Message.
+            Level level;             ///< Level.
+            Timestamp timestamp;     ///< Timestamp;
+            Location location;       ///< Code location which originated the log message.
+            std::string message;     ///< Message.
+            SpanManager::Span* span; ///< Span.
         };
 
         /// @brief Deleted constructor.

core/include/cubos/core/tel/tracing.hpp

@@ -0,0 +1,104 @@
+/// @file
+/// @brief Tracing macros.
+/// @ingroup core-tel
+
+#pragma once
+
+#include <chrono>
+#include <string>
+#include <thread>
+
+namespace cubos::core::tel
+{
+    class SpanManager
+    {
+    public:
+        class Span
+        {
+        public:
+            /// @brief Construct a new Span inside the SpanManager.
+            Span(const std::string& name, std::size_t level, const std::string& file, std::size_t line);
+
+            /// @brief Deconstruct the Span. Will get removed from the SpanManager and a new metric will be stored.
+            ~Span();
+
+            /// @brief Get Span name.
+            std::string name();
+
+        private:
+            std::thread::id mId;                                                ///< Thread id where span was invoked.
+            std::string mName;                                                  ///< The name of the scope.
+            std::string mFile;                                                  ///< The file from where it was invoked.
+            std::size_t mLine;                                                  ///< The line from where it was invoked.
+            std::chrono::time_point<std::chrono::high_resolution_clock> mStart; ///< Start time when constructed.
+            std::size_t mLevel;                                                 ///< Debug level
+        };
+
+        /// @brief Gets the current active span.
+        /// @return Span* Pointer to the current active span.
+        static Span* current();
+
+        /// @brief Decides next span name.
+        /// @example If current span is `foo` and a `bar` was invoked, this returns "foo:bar`.
+        /// @return Returns span name.
+        static std::string nextName(std::string name);
+
+        /// @brief Gets the count of active spans.
+        /// @return Span count.
+        static std::size_t count();
+
+        /// @brief Enters a new span.
+        /// @param s Pointer to the span to be entered.
+        static void enter(Span* s);
+
+        /// @brief Exits the current active span.
+        static void exit();
+
+    private:
+        SpanManager() = default;
+    };
+} // namespace cubos::core::tel
+
+#define SPAN(a, b) SPAN_INNER(a, b)
+#define SPAN_INNER(a, b) a##b
+
+/// @addtogroup core-tel
+/// @{
+
+/// @brief Trace span level.
+/// @sa CUBOS_SPAN_LEVEL
+#define CUBOS_SPAN_LEVEL_TRACE 0
+
+/// @brief Debug span level.
+/// @sa CUBOS_SPAN_LEVEL
+#define CUBOS_SPAN_LEVEL_DEBUG 1
+
+/// @brief Information log level.
+/// @sa CUBOS_SPAN_LEVEL
+#define CUBOS_SPAN_LEVEL_INFO 2
+
+/// @brief Constructs a new info span.
+/// @param name Span name.
+#define CUBOS_SPAN_INFO(name)                                                                                          \
+    cubos::core::tel::SpanManager::Span SPAN(info_span_, __COUNTER__)                                                  \
+    {                                                                                                                  \
+        name, CUBOS_SPAN_LEVEL_INFO, __FILE__, __LINE__                                                                \
+    }
+
+/// @brief Constructs a new debug span.
+/// @param name Span name.
+#define CUBOS_SPAN_DEBUG(name)                                                                                         \
+    cubos::core::tel::SpanManager::Span SPAN(trace_span_, __COUNTER__)                                                 \
+    {                                                                                                                  \
+        name, CUBOS_SPAN_LEVEL_DEBUG, __FILE__, __LINE__                                                               \
+    }
+
+/// @brief Constructs a new trace span.
+/// @param name Span name.
+#define CUBOS_SPAN_TRACE(name)                                                                                         \
+    cubos::core::tel::SpanManager::Span SPAN(trace_span_, __COUNTER__)                                                 \
+    {                                                                                                                  \
+        name, CUBOS_SPAN_LEVEL_TRACE, __FILE__, __LINE__                                                               \
+    }
+
+/// @}

core/src/tel/logging.cpp

@@ -196,21 +196,21 @@ void Logger::write(Level level, Location location, std::string message)
     // Print to file if opened
     if (state().logFileStream != nullptr)
     {
-        state().logFileStream->printf("[{}] [{}] {}: {}\n", timestamp.string(), location.string(),
-                                      toLower(EnumTrait::toString(level)), message);
+        state().logFileStream->printf("[{}] [{}] [{}] {}: {}\n", timestamp.string(), location.string(),
+                                      SpanManager::current()->name(), toLower(EnumTrait::toString(level)), message);
     }
 
     // Print the message to stderr.
-    memory::Stream::stdErr.printf("{}[{}] [{}] {}: {}{}\n", levelColor(level), timestamp.string(), location.string(),
+    memory::Stream::stdErr.printf("{}[{}] [{}] [{}] {}: {}{}\n", levelColor(level), timestamp.string(),
+                                  location.string(), SpanManager::current()->name(),
                                   toLower(EnumTrait::toString(level)), message, ColorResetCode);
 
     // Store the log entry.
-    state().entries.emplace_back(Entry{
-        .level = level,
-        .timestamp = timestamp,
-        .location = std::move(location),
-        .message = std::move(message),
-    });
+    state().entries.emplace_back(Entry{.level = level,
+                                       .timestamp = timestamp,
+                                       .location = std::move(location),
+                                       .message = std::move(message),
+                                       .span = SpanManager::current()});
 }
 
 bool Logger::read(std::size_t& cursor, Entry& entry)

core/src/tel/tracing.cpp

@@ -0,0 +1,84 @@
+#include <stack>
+
+#include <cubos/core/tel/metrics.hpp>
+#include <cubos/core/tel/tracing.hpp>
+
+using cubos::core::tel::SpanManager;
+
+namespace
+{
+    /// @brief Private type which stores the state of the span tracer.
+    struct State
+    {
+        std::stack<SpanManager::Span*> spans;
+    };
+} // namespace
+
+/// @brief Span tracer state singleton. Guarantees it is initialized exactly once, per thread, when needed.
+/// @return Tracer state.
+static State& state()
+{
+    static thread_local State state{};
+    return state;
+}
+
+SpanManager::Span::Span(const std::string& name, std::size_t level, const std::string& file, std::size_t line)
+    : mId(std::this_thread::get_id())
+    , mName(SpanManager::nextName(name))
+    , mFile(file)
+    , mLine(line)
+    , mStart(std::chrono::time_point<std::chrono::high_resolution_clock>::clock::now())
+    , mLevel(level)
+{
+    SpanManager::enter(this);
+}
+
+SpanManager::Span::~Span()
+{
+    auto now = std::chrono::time_point<std::chrono::high_resolution_clock>::clock::now();
+    std::chrono::duration<double, std::milli> elapsed = now - mStart;
+    Metrics::metric(mName, elapsed.count());
+
+    (void)mLevel; // TODO use this
+    (void)mLine;  // TODO use this
+    SpanManager::exit();
+}
+
+std::string SpanManager::Span::name()
+{
+    return mName;
+}
+
+SpanManager::Span* SpanManager::current()
+{
+    return state().spans.empty() ? nullptr : state().spans.top();
+}
+
+std::string SpanManager::nextName(std::string name)
+{
+    if (current() != nullptr)
+    {
+        name = current()->name() + ":" + name;
+    }
+
+    return name;
+}
+
+std::size_t SpanManager::count()
+{
+    return state().spans.size();
+}
+
+void SpanManager::enter(Span* s)
+{
+    state().spans.push(s);
+}
+
+void SpanManager::exit()
+{
+    if (!state().spans.empty())
+    {
+        state().spans.pop();
+        // TODO: remove name
+    }
+}