Merge pull request #1648 from callumfare/callum/tracing_logger

callumfare · web-flow · commit d5166d52b10f · 2024-05-24T13:48:42.000+01:00
Add ability to log from the tracing layer directly rather than use XPTI
diff --git a/scripts/core/INTRO.rst b/scripts/core/INTRO.rst
@@ -182,6 +182,8 @@ Unified Runtime loader implements tracing support through the `XPTI framework <h
        | **user_data**: A pointer to `function_with_args_t` object, that includes function ID, name, arguments, and return value.
      - None
 
+The Unified Runtime tracing layer also supports logging tracing output directly, rather than using XPTI. Use the `UR_LOG_TRACING` environment variable to control this output. See the `Logging`_ section below for details of the syntax. All traces are logged at the *info* log level.
+
 Sanitizers
 ---------------------
 
@@ -318,6 +320,10 @@ Specific environment variables can be set to control the behavior of unified run
 
    Holds parameters for setting Unified Runtime validation logging. The syntax is described in the Logging_ section.
 
+.. envvar:: UR_LOG_TRACING
+
+   Holds parameters for setting Unified Runtime tracing logging. The syntax is described in the Logging_ section.
+
 .. envvar:: UR_ADAPTERS_FORCE_LOAD
 
    Holds a comma-separated list of library paths used by the loader for adapter discovery. By setting this value you can
diff --git a/scripts/templates/trcddi.cpp.mako b/scripts/templates/trcddi.cpp.mako
@@ -45,10 +45,16 @@ namespace ur_tracing_layer
         ${th.make_pfncb_param_type(n, tags, obj)} params = { &${",&".join(th.make_param_lines(n, tags, obj, format=["name"]))} };
         uint64_t instance = context.notify_begin(${th.make_func_etor(n, tags, obj)}, "${th.make_func_name(n, tags, obj)}", &params);
 
+        context.logger.info("---> ${th.make_func_name(n, tags, obj)}");
+
         ${x}_result_t result = ${th.make_pfn_name(n, tags, obj)}( ${", ".join(th.make_param_lines(n, tags, obj, format=["name"]))} );
 
         context.notify_end(${th.make_func_etor(n, tags, obj)}, "${th.make_func_name(n, tags, obj)}", &params, &result, instance);
 
+        std::ostringstream args_str;
+        ur::extras::printFunctionParams(args_str, ${th.make_func_etor(n, tags, obj)}, &params);
+        context.logger.info("({}) -> {};\n", args_str.str(), result);
+
         return result;
     }
     %if 'condition' in obj:
@@ -112,6 +118,10 @@ namespace ur_tracing_layer
             return result;
         }
 
+        // Recreate the logger in case env variables have been modified between
+        // program launch and the call to `urLoaderInit`
+        logger = logger::create_logger("tracing", true, true);
+
         ur_tracing_layer::context.codelocData = codelocData;
 
     %for tbl in th.get_pfntables(specs, meta, n, tags):
diff --git a/source/common/logger/ur_logger.hpp b/source/common/logger/ur_logger.hpp
@@ -14,7 +14,8 @@
 
 namespace logger {
 
-Logger create_logger(std::string logger_name, bool skip_prefix = false);
+Logger create_logger(std::string logger_name, bool skip_prefix = false,
+                     bool skip_linebreak = false);
 
 inline Logger &get_logger(std::string name = "common") {
     static Logger logger = create_logger(std::move(name));
@@ -105,7 +106,8 @@ template <typename T> inline std::string toHex(T t) {
 ///             - flush level: error, meaning that only error messages are guaranteed
 ///                            to be printed immediately as they occur
 ///             - output: stderr
-inline Logger create_logger(std::string logger_name, bool skip_prefix) {
+inline Logger create_logger(std::string logger_name, bool skip_prefix,
+                            bool skip_linebreak) {
     std::transform(logger_name.begin(), logger_name.end(), logger_name.begin(),
                    ::toupper);
     std::stringstream env_var_name;
@@ -121,7 +123,7 @@ inline Logger create_logger(std::string logger_name, bool skip_prefix) {
         auto map = getenv_to_map(env_var_name.str().c_str());
         if (!map.has_value()) {
             return Logger(std::make_unique<logger::StderrSink>(
-                std::move(logger_name), skip_prefix));
+                std::move(logger_name), skip_prefix, skip_linebreak));
         }
 
         auto kv = map->find("level");
@@ -150,19 +152,20 @@ inline Logger create_logger(std::string logger_name, bool skip_prefix) {
                       << map->begin()->first
                       << "'. Default logger options are set.";
             return Logger(std::make_unique<logger::StderrSink>(
-                std::move(logger_name), skip_prefix));
+                std::move(logger_name), skip_prefix, skip_linebreak));
         }
 
-        sink =
-            values.size() == 2
-                ? sink_from_str(logger_name, values[0], values[1], skip_prefix)
-                : sink_from_str(logger_name, values[0], "", skip_prefix);
+        sink = values.size() == 2
+                   ? sink_from_str(logger_name, values[0], values[1],
+                                   skip_prefix, skip_linebreak)
+                   : sink_from_str(logger_name, values[0], "", skip_prefix,
+                                   skip_linebreak);
     } catch (const std::invalid_argument &e) {
         std::cerr << "Error when creating a logger instance from the '"
                   << env_var_name.str() << "' environment variable:\n"
                   << e.what() << std::endl;
         return Logger(std::make_unique<logger::StderrSink>(
-            std::move(logger_name), skip_prefix));
+            std::move(logger_name), skip_prefix, skip_linebreak));
     }
     sink->setFlushLevel(flush_level);
 
diff --git a/source/common/logger/ur_logger_details.hpp b/source/common/logger/ur_logger_details.hpp
@@ -25,6 +25,7 @@ class Logger {
     Logger(logger::Level level, std::unique_ptr<logger::Sink> sink)
         : level(level), sink(std::move(sink)) {}
 
+    Logger &operator=(Logger &&) = default;
     ~Logger() = default;
 
     void setLevel(logger::Level level) { this->level = level; }
diff --git a/source/common/logger/ur_sinks.hpp b/source/common/logger/ur_sinks.hpp
@@ -39,8 +39,10 @@ class Sink {
     std::ostream *ostream;
     logger::Level flush_level;
 
-    Sink(std::string logger_name, bool skip_prefix = false)
-        : logger_name(std::move(logger_name)), skip_prefix(skip_prefix) {
+    Sink(std::string logger_name, bool skip_prefix = false,
+         bool skip_linebreak = false)
+        : logger_name(std::move(logger_name)), skip_prefix(skip_prefix),
+          skip_linebreak(skip_linebreak) {
         ostream = nullptr;
         flush_level = logger::Level::ERR;
     }
@@ -56,6 +58,7 @@ class Sink {
   private:
     std::string logger_name;
     bool skip_prefix;
+    bool skip_linebreak;
     std::mutex output_mutex;
     const char *error_prefix = "Log message syntax error: ";
 
@@ -83,7 +86,9 @@ class Sink {
                 }
             }
         }
-        buffer << "\n";
+        if (!skip_linebreak) {
+            buffer << "\n";
+        }
     }
 
     template <typename Arg, typename... Args>
@@ -129,14 +134,15 @@ class Sink {
 
 class StdoutSink : public Sink {
   public:
-    StdoutSink(std::string logger_name, bool skip_prefix = false)
-        : Sink(std::move(logger_name), skip_prefix) {
+    StdoutSink(std::string logger_name, bool skip_prefix = false,
+               bool skip_linebreak = false)
+        : Sink(std::move(logger_name), skip_prefix, skip_linebreak) {
         this->ostream = &std::cout;
     }
 
     StdoutSink(std::string logger_name, Level flush_lvl,
-               bool skip_prefix = false)
-        : StdoutSink(std::move(logger_name), skip_prefix) {
+               bool skip_prefix = false, bool skip_linebreak = false)
+        : StdoutSink(std::move(logger_name), skip_prefix, skip_linebreak) {
         this->flush_level = flush_lvl;
     }
 
@@ -145,13 +151,15 @@ class StdoutSink : public Sink {
 
 class StderrSink : public Sink {
   public:
-    StderrSink(std::string logger_name, bool skip_prefix = false)
-        : Sink(std::move(logger_name), skip_prefix) {
+    StderrSink(std::string logger_name, bool skip_prefix = false,
+               bool skip_linebreak = false)
+        : Sink(std::move(logger_name), skip_prefix, skip_linebreak) {
         this->ostream = &std::cerr;
     }
 
-    StderrSink(std::string logger_name, Level flush_lvl, bool skip_prefix)
-        : StderrSink(std::move(logger_name), skip_prefix) {
+    StderrSink(std::string logger_name, Level flush_lvl, bool skip_prefix,
+               bool skip_linebreak)
+        : StderrSink(std::move(logger_name), skip_prefix, skip_linebreak) {
         this->flush_level = flush_lvl;
     }
 
@@ -161,8 +169,8 @@ class StderrSink : public Sink {
 class FileSink : public Sink {
   public:
     FileSink(std::string logger_name, filesystem::path file_path,
-             bool skip_prefix = false)
-        : Sink(std::move(logger_name), skip_prefix) {
+             bool skip_prefix = false, bool skip_linebreak = false)
+        : Sink(std::move(logger_name), skip_prefix, skip_linebreak) {
         ofstream = std::ofstream(file_path);
         if (!ofstream.good()) {
             std::stringstream ss;
@@ -174,8 +182,10 @@ class FileSink : public Sink {
     }
 
     FileSink(std::string logger_name, filesystem::path file_path,
-             Level flush_lvl, bool skip_prefix = false)
-        : FileSink(std::move(logger_name), std::move(file_path), skip_prefix) {
+             Level flush_lvl, bool skip_prefix = false,
+             bool skip_linebreak = false)
+        : FileSink(std::move(logger_name), std::move(file_path), skip_prefix,
+                   skip_linebreak) {
         this->flush_level = flush_lvl;
     }
 
@@ -188,14 +198,17 @@ class FileSink : public Sink {
 inline std::unique_ptr<Sink> sink_from_str(std::string logger_name,
                                            std::string name,
                                            filesystem::path file_path = "",
-                                           bool skip_prefix = false) {
+                                           bool skip_prefix = false,
+                                           bool skip_linebreak = false) {
     if (name == "stdout" && file_path.empty()) {
-        return std::make_unique<logger::StdoutSink>(logger_name, skip_prefix);
+        return std::make_unique<logger::StdoutSink>(logger_name, skip_prefix,
+                                                    skip_linebreak);
     } else if (name == "stderr" && file_path.empty()) {
-        return std::make_unique<logger::StderrSink>(logger_name, skip_prefix);
+        return std::make_unique<logger::StderrSink>(logger_name, skip_prefix,
+                                                    skip_linebreak);
     } else if (name == "file" && !file_path.empty()) {
         return std::make_unique<logger::FileSink>(logger_name, file_path,
-                                                  skip_prefix);
+                                                  skip_prefix, skip_linebreak);
     }
 
     throw std::invalid_argument(
diff --git a/source/loader/layers/tracing/ur_tracing_layer.cpp b/source/loader/layers/tracing/ur_tracing_layer.cpp
@@ -27,7 +27,7 @@ constexpr auto STREAM_VER_MINOR = UR_MINOR_VERSION(UR_API_VERSION_CURRENT);
 static thread_local xpti_td *activeEvent;
 
 ///////////////////////////////////////////////////////////////////////////////
-context_t::context_t() {
+context_t::context_t() : logger(logger::create_logger("tracing", true, true)) {
     xptiFrameworkInitialize();
 
     call_stream_id = xptiRegisterStream(CALL_STREAM_NAME);
@@ -37,7 +37,7 @@ context_t::context_t() {
                    streamv.str().data());
 }
 
-bool context_t::isAvailable() const { return xptiTraceEnabled(); }
+bool context_t::isAvailable() const { return true; }
 
 void context_t::notify(uint16_t trace_type, uint32_t id, const char *name,
                        void *args, ur_result_t *resultp, uint64_t instance) {
diff --git a/source/loader/layers/tracing/ur_tracing_layer.hpp b/source/loader/layers/tracing/ur_tracing_layer.hpp
@@ -13,6 +13,7 @@
 #ifndef UR_TRACING_LAYER_H
 #define UR_TRACING_LAYER_H 1
 
+#include "logger/ur_logger.hpp"
 #include "ur_ddi.h"
 #include "ur_proxy_layer.hpp"
 #include "ur_util.hpp"
@@ -25,6 +26,7 @@ class __urdlllocal context_t : public proxy_layer_context_t {
   public:
     ur_dditable_t urDdiTable = {};
     codeloc_data codelocData;
+    logger::Logger logger;
 
     context_t();
     ~context_t();
diff --git a/source/loader/layers/tracing/ur_trcddi.cpp b/source/loader/layers/tracing/ur_trcddi.cpp
diff --git a/test/layers/tracing/CMakeLists.txt b/test/layers/tracing/CMakeLists.txt
diff --git a/test/layers/tracing/hello_world.out.logged.match b/test/layers/tracing/hello_world.out.logged.match
