[tools] add unified runtime tracing tool

.github/workflows/cmake.yml

@@ -35,7 +35,7 @@ jobs:
 
     - name: Test
       working-directory: ${{github.workspace}}/build
-      run: ctest -C ${{env.BUILD_TYPE}} --output-on-failure -L "python|uma|loader|validation|tracing|unit"
+      run: ctest -C ${{env.BUILD_TYPE}} --output-on-failure -L "python|uma|loader|validation|tracing|unit|urtrace"
 
   windows-build:
     name: Build - Windows
@@ -62,4 +62,4 @@ jobs:
 
     - name: Test
       working-directory: ${{github.workspace}}/build
-      run: ctest -C ${{env.BUILD_TYPE}} --output-on-failure -L "python|uma|loader|validation|tracing|unit"
+      run: ctest -C ${{env.BUILD_TYPE}} --output-on-failure -L "python|uma|loader|validation|tracing|unit|urtrace"

CMakeLists.txt

@@ -27,6 +27,7 @@ option(UR_USE_MSAN "enable MemorySanitizer" OFF)
 option(UMA_BUILD_SHARED_LIBRARY "Build UMA as shared library" OFF)
 option(UR_ENABLE_TRACING "enable api tracing through xpti" OFF)
 option(VAL_USE_LIBBACKTRACE_BACKTRACE "enable libbacktrace validation backtrace for linux" OFF)
+option(UR_BUILD_TOOLS "build ur tools" ON)
 
 set(CMAKE_LIBRARY_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR}/lib)
 set(CMAKE_ARCHIVE_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR}/lib)
@@ -181,6 +182,9 @@ add_subdirectory(examples)
 if(UR_BUILD_TESTS)
     add_subdirectory(test)
 endif()
+if(UR_BUILD_TOOLS)
+    add_subdirectory(tools)
+endif()
 
 # Add the list of installed targets to the install. This includes the namespace
 # which all installed targets will be prefixed with, e.g. for the headers

README.md

@@ -98,6 +98,7 @@ List of options provided by CMake:
 | UR_USE_UBSAN | Enable UndefinedBehavior Sanitizer | ON/OFF | OFF |
 | UR_USE_MSAN | Enable MemorySanitizer (clang only) | ON/OFF | OFF |
 | UR_ENABLE_TRACING | Enable XPTI-based tracing layer | ON/OFF | OFF |
+| UR_BUILD_TOOLS | Build tools | ON/OFF | ON |
 
 **General**:
 

cmake/match.cmake

@@ -6,6 +6,8 @@
 # with a known good match file.
 #
 
+find_package(Python3 COMPONENTS Interpreter)
+
 if(NOT DEFINED TEST_FILE)
     message(FATAL_ERROR "TEST_FILE needs to be defined")
 endif()
@@ -15,23 +17,30 @@ endif()
 
 set(TEST_OUT "_matchtmpfile")
 
+if(NOT DEFINED TEST_ARGS) # easier than ifdefing the rest of the code
+    set(TEST_ARGS "")
+endif()
+
+string(REPLACE "\"" "" TEST_ARGS "${TEST_ARGS}")
+separate_arguments(TEST_ARGS)
+
 execute_process(
-    COMMAND ${TEST_FILE}
+    COMMAND ${TEST_FILE} ${TEST_ARGS}
     OUTPUT_FILE ${TEST_OUT}
     RESULT_VARIABLE TEST_RESULT
 )
 
 if(TEST_RESULT)
-    message(FATAL_ERROR "Failed: Test ${TEST_FILE} returned non-zero (${TEST_ERROR}).")
+    message(FATAL_ERROR "Failed: Test ${TEST_FILE} ${TEST_ARGS} returned non-zero (${TEST_RESULT}).")
 endif()
 
 execute_process(
-    COMMAND ${CMAKE_COMMAND} -E compare_files ${TEST_OUT} ${MATCH_FILE}
+    COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_LIST_DIR}/match.py ${TEST_OUT} ${MATCH_FILE}
     RESULT_VARIABLE TEST_RESULT
 )
 
 if(TEST_RESULT)
-    message(FATAL_ERROR "Failed: The output of ${TEST_FILE} (stored in ${TEST_OUT}) does not match ${MATCH_FILE}")
+    message(FATAL_ERROR "Failed: The output of ${TEST_FILE} (stored in ${TEST_OUT}) does not match ${MATCH_FILE} (${TEST_RESULT})")
 elseif()
     message("Passed: The output of ${TEST_FILE} matches ${MATCH_FILE}")
 endif()

cmake/match.py

@@ -0,0 +1,41 @@
+#!/usr/bin/env python
+
+# Copyright (C) 2023 Intel Corporation
+# SPDX-License-Identifier: MIT
+
+# check if all lines match in a file
+# lines in a match file can contain regex inside of double curly braces {{}}
+
+import sys
+import re
+
+if len(sys.argv) != 3:
+    print("Usage: python match.py <input_file> <match_file>")
+    sys.exit(1)
+
+input_file = sys.argv[1]
+match_file = sys.argv[2]
+
+with open(input_file, 'r') as input, open(match_file, 'r') as match:
+    input_lines = input.readlines()
+    match_lines = match.readlines()
+
+if len(match_lines) != len(input_lines):
+    sys.exit(f"Line count doesn't match (is: {len(input_lines)}, expected: {len(match_lines)})")
+
+for i, match_line in enumerate(match_lines):
+    # split into parts at {{ }}
+    match_parts = re.split(r'\{{(.*?)\}}', match_line.strip())
+    pattern = ""
+    for j, part in enumerate(match_parts):
+        if j % 2 == 0:
+            pattern += re.escape(part)
+        else:
+            pattern += part
+
+    input_line = input_lines[i].strip()
+    if not re.fullmatch(pattern, input_line):
+        print(f"Line {i+1} does not match".format(i+1))
+        print("is:       " + input_line)
+        print("expected: " + match_line.strip())
+        sys.exit(1)

examples/hello_world/hello_world.cpp

@@ -70,7 +70,7 @@ int main(int argc, char *argv[]) {
             goto out;
         }
         for (auto d : devices) {
-            ur_device_type_t device_type;
+            ur_device_type_t device_type = UR_DEVICE_TYPE_ALL;
             status = urDeviceGetInfo(
                 d, UR_DEVICE_INFO_TYPE, sizeof(ur_device_type_t),
                 static_cast<void *>(&device_type), nullptr);

source/common/logger/ur_logger.hpp

@@ -12,7 +12,7 @@
 
 namespace logger {
 
-Logger create_logger(std::string logger_name);
+Logger create_logger(std::string logger_name, bool skip_prefix = false);
 
 inline Logger &get_logger(std::string name = "common") {
     static Logger logger = create_logger(name);
@@ -66,7 +66,7 @@ inline void setFlushLevel(logger::Level level) {
 ///             - 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) {
+inline Logger create_logger(std::string logger_name, bool skip_prefix) {
     std::transform(logger_name.begin(), logger_name.end(), logger_name.begin(),
                    ::toupper);
     std::stringstream env_var_name;
@@ -80,7 +80,8 @@ inline Logger create_logger(std::string logger_name) {
     env_var_name << "UR_LOG_" << logger_name;
     auto map = getenv_to_map(env_var_name.str().c_str());
     if (!map.has_value()) {
-        return Logger(std::make_unique<logger::StderrSink>(logger_name));
+        return Logger(
+            std::make_unique<logger::StderrSink>(logger_name, skip_prefix));
     }
 
     try {
@@ -102,14 +103,16 @@ inline Logger create_logger(std::string logger_name) {
             values = kv->second;
         }
 
-        sink = values.size() == 2
-                   ? sink_from_str(logger_name, values[0], values[1])
-                   : sink_from_str(logger_name, values[0]);
+        sink =
+            values.size() == 2
+                ? sink_from_str(logger_name, values[0], values[1], skip_prefix)
+                : sink_from_str(logger_name, values[0], "", skip_prefix);
     } catch (const std::invalid_argument &e) {
         std::cerr
             << "Error when creating a logger instance from environment variable"
             << e.what();
-        return Logger(std::make_unique<logger::StderrSink>(logger_name));
+        return Logger(
+            std::make_unique<logger::StderrSink>(logger_name, skip_prefix));
     }
     sink->setFlushLevel(flush_level);
 

source/common/logger/ur_logger_details.hpp

@@ -48,6 +48,10 @@ class Logger {
         log(logger::Level::WARN, format, std::forward<Args>(args)...);
     }
 
+    template <typename... Args> void warn(const char *format, Args &&...args) {
+        warning(format, std::forward<Args>(args)...);
+    }
+
     template <typename... Args> void error(const char *format, Args &&...args) {
         log(logger::Level::ERR, format, std::forward<Args>(args)...);
     }

source/common/logger/ur_sinks.hpp

@@ -23,8 +23,10 @@ class Sink {
   public:
     template <typename... Args>
     void log(logger::Level level, const char *fmt, Args &&...args) {
-        *ostream << "<" << logger_name << ">";
-        *ostream << "[" << level_to_str(level) << "]: ";
+        if (!skip_prefix) {
+            *ostream << "<" << logger_name << ">";
+            *ostream << "[" << level_to_str(level) << "]: ";
+        }
         format(fmt, std::forward<Args &&>(args)...);
         *ostream << "\n";
         if (level >= flush_level) {
@@ -40,12 +42,14 @@ class Sink {
     std::ostream *ostream;
     logger::Level flush_level;
 
-    Sink(std::string logger_name) : logger_name(logger_name) {
+    Sink(std::string logger_name, bool skip_prefix = false)
+        : logger_name(logger_name), skip_prefix(skip_prefix) {
         flush_level = logger::Level::ERR;
     }
 
   private:
     std::string logger_name;
+    bool skip_prefix;
 
     void format(const char *fmt) {
         while (*fmt != '\0') {
@@ -104,12 +108,14 @@ class Sink {
 
 class StdoutSink : public Sink {
   public:
-    StdoutSink(std::string logger_name) : Sink(logger_name) {
+    StdoutSink(std::string logger_name, bool skip_prefix = false)
+        : Sink(logger_name, skip_prefix) {
         this->ostream = &std::cout;
     }
 
-    StdoutSink(std::string logger_name, Level flush_lvl)
-        : StdoutSink(logger_name) {
+    StdoutSink(std::string logger_name, Level flush_lvl,
+               bool skip_prefix = false)
+        : StdoutSink(logger_name, skip_prefix) {
         this->flush_level = flush_lvl;
     }
 
@@ -118,12 +124,13 @@ class StdoutSink : public Sink {
 
 class StderrSink : public Sink {
   public:
-    StderrSink(std::string logger_name) : Sink(logger_name) {
+    StderrSink(std::string logger_name, bool skip_prefix = false)
+        : Sink(logger_name, skip_prefix) {
         this->ostream = &std::cerr;
     }
 
-    StderrSink(std::string logger_name, Level flush_lvl)
-        : StderrSink(logger_name) {
+    StderrSink(std::string logger_name, Level flush_lvl, bool skip_prefix)
+        : StderrSink(logger_name, skip_prefix) {
         this->flush_level = flush_lvl;
     }
 
@@ -132,8 +139,9 @@ class StderrSink : public Sink {
 
 class FileSink : public Sink {
   public:
-    FileSink(std::string logger_name, filesystem::path file_path)
-        : Sink(logger_name) {
+    FileSink(std::string logger_name, filesystem::path file_path,
+             bool skip_prefix = false)
+        : Sink(logger_name, skip_prefix) {
         ofstream = std::ofstream(file_path, std::ofstream::out);
         if (!ofstream.good()) {
             throw std::invalid_argument(
@@ -145,8 +153,8 @@ class FileSink : public Sink {
     }
 
     FileSink(std::string logger_name, filesystem::path file_path,
-             Level flush_lvl)
-        : FileSink(logger_name, file_path) {
+             Level flush_lvl, bool skip_prefix = false)
+        : FileSink(logger_name, file_path, skip_prefix) {
         this->flush_level = flush_lvl;
     }
 
@@ -156,14 +164,15 @@ class FileSink : public Sink {
 
 inline std::unique_ptr<Sink> sink_from_str(std::string logger_name,
                                            std::string name,
-                                           std::string file_path = "") {
+                                           std::string file_path = "",
+                                           bool skip_prefix = false) {
     if (name == "stdout") {
-        return std::make_unique<logger::StdoutSink>(logger_name);
+        return std::make_unique<logger::StdoutSink>(logger_name, skip_prefix);
     } else if (name == "stderr") {
-        return std::make_unique<logger::StderrSink>(logger_name);
+        return std::make_unique<logger::StderrSink>(logger_name, skip_prefix);
     } else if (name == "file" && !file_path.empty()) {
-        return std::make_unique<logger::FileSink>(logger_name,
-                                                  file_path.c_str());
+        return std::make_unique<logger::FileSink>(
+            logger_name, file_path.c_str(), skip_prefix);
     }
 
     throw std::invalid_argument(

source/common/ur_util.hpp

@@ -176,7 +176,8 @@ using EnvVarMap = std::map<std::string, std::vector<std::string>>;
 ///         Otherwise, optional is set to std::nullopt when the environment variable
 ///         is not set or is empty.
 /// @throws std::invalid_argument() when the parsed environment variable has wrong format
-inline std::optional<EnvVarMap> getenv_to_map(const char *env_var_name) {
+inline std::optional<EnvVarMap> getenv_to_map(const char *env_var_name,
+                                              bool reject_empty = true) {
     char main_delim = ';';
     char key_value_delim = ':';
     char values_delim = ',';
@@ -194,13 +195,13 @@ inline std::optional<EnvVarMap> getenv_to_map(const char *env_var_name) {
         std::string values;
         std::stringstream kv_ss(key_value);
 
-        if (key_value.find(':') == std::string::npos) {
+        if (reject_empty && key_value.find(':') == std::string::npos) {
             throw_wrong_format_map(env_var_name);
         }
 
         std::getline(kv_ss, key, key_value_delim);
         std::getline(kv_ss, values);
-        if (key.empty() || values.empty() ||
+        if (key.empty() || (reject_empty && values.empty()) ||
             values.find(':') != std::string::npos ||
             map.find(key) != map.end()) {
             throw_wrong_format_map(env_var_name);
@@ -215,9 +216,6 @@ inline std::optional<EnvVarMap> getenv_to_map(const char *env_var_name) {
             }
             values_vec.push_back(value);
         }
-        if (values_vec.empty()) {
-            throw_wrong_format_map(env_var_name);
-        }
         map[key] = values_vec;
     }
     return map;

test/CMakeLists.txt

@@ -18,3 +18,6 @@ add_subdirectory(conformance)
 add_subdirectory(unified_memory_allocation)
 add_subdirectory(layers)
 add_subdirectory(unit)
+if(UR_BUILD_TOOLS)
+  add_subdirectory(tools)
+endif()

test/layers/tracing/hello_world.out.match

@@ -7,7 +7,7 @@ function_with_args_begin(3) - urPlatformGet(unimplemented);
 function_with_args_end(3) - urPlatformGet(...) -> ur_result_t(0);
 function_with_args_begin(4) - urPlatformGetApiVersion(unimplemented);
 function_with_args_end(4) - urPlatformGetApiVersion(...) -> ur_result_t(0);
-API version: 0.6
+API version: {{0\.[0-9]+}}
 function_with_args_begin(5) - urDeviceGet(unimplemented);
 function_with_args_end(5) - urDeviceGet(...) -> ur_result_t(0);
 function_with_args_begin(6) - urDeviceGet(unimplemented);

test/tools/CMakeLists.txt

@@ -0,0 +1,6 @@
+# Copyright (C) 2023 Intel Corporation
+# SPDX-License-Identifier: MIT
+
+if(UR_ENABLE_TRACING)
+    add_subdirectory(urtrace)
+endif()

test/tools/urtrace/CMakeLists.txt

@@ -0,0 +1,23 @@
+# Copyright (C) 2023 Intel Corporation
+# SPDX-License-Identifier: MIT
+
+set(TEST_NAME trace-hello-world)
+
+function(add_trace_test name CLI_ARGS)
+    set(TEST_NAME trace_test_${name})
+    add_test(NAME ${TEST_NAME}
+        COMMAND ${CMAKE_COMMAND}
+        -D TEST_FILE=${Python3_EXECUTABLE}
+        -D TEST_ARGS="${CMAKE_RUNTIME_OUTPUT_DIRECTORY}/urtrace --stdout ${CLI_ARGS} $<TARGET_FILE:hello_world>"
+        -D MATCH_FILE=${CMAKE_CURRENT_SOURCE_DIR}/${name}.match
+        -P ${PROJECT_SOURCE_DIR}/cmake/match.cmake
+        DEPENDS ur_trace_cli hello_world
+    )
+    set_tests_properties(${TEST_NAME} PROPERTIES LABELS "urtrace")
+endfunction()
+
+add_trace_test(null_hello "--libpath $<TARGET_FILE_DIR:ur_adapter_null> --null")
+add_trace_test(null_hello_no_args "--libpath $<TARGET_FILE_DIR:ur_adapter_null> --null --no-args")
+add_trace_test(null_hello_filter_device "--libpath $<TARGET_FILE_DIR:ur_adapter_null> --null --filter \".*Device.*\"")
+add_trace_test(null_hello_profiling "--libpath $<TARGET_FILE_DIR:ur_adapter_null> --null --profiling --time-unit ns")
+add_trace_test(null_hello_begin "--libpath $<TARGET_FILE_DIR:ur_adapter_null> --null --print-begin")

test/tools/urtrace/null_hello.match

@@ -0,0 +1,12 @@
+urInit(.device_flags = 0) -> UR_RESULT_SUCCESS;
+Platform initialized.
+urPlatformGet(.NumEntries = 1, .phPlatforms = [], .pNumPlatforms = {{.*}} (1)) -> UR_RESULT_SUCCESS;
+urPlatformGet(.NumEntries = 1, .phPlatforms = [{{.*}}], .pNumPlatforms = nullptr) -> UR_RESULT_SUCCESS;
+urPlatformGetApiVersion(.hDriver = {{.*}}, .pVersion = {{.*}} ({{.*}})) -> UR_RESULT_SUCCESS;
+API version: {{.*}}
+urDeviceGet(.hPlatform = {{.*}}, .DeviceType = UR_DEVICE_TYPE_GPU, .NumEntries = 0, .phDevices = [], .pNumDevices = {{.*}} (1)) -> UR_RESULT_SUCCESS;
+urDeviceGet(.hPlatform = {{.*}}, .DeviceType = UR_DEVICE_TYPE_GPU, .NumEntries = 1, .phDevices = [{{.*}}], .pNumDevices = nullptr) -> UR_RESULT_SUCCESS;
+urDeviceGetInfo(.hDevice = {{.*}}, .propName = UR_DEVICE_INFO_TYPE, .propSize = {{.*}}, .pPropValue = {{.*}}, .pPropSizeRet = nullptr) -> UR_RESULT_SUCCESS;
+urDeviceGetInfo(.hDevice = {{.*}}, .propName = UR_DEVICE_INFO_NAME, .propSize = {{.*}}, .pPropValue = {{.*}}, .pPropSizeRet = nullptr) -> UR_RESULT_SUCCESS;
+Found a Null Device gpu.
+urTearDown(.pParams = nullptr) -> UR_RESULT_SUCCESS;