From 2720f2316c3fe8d421a0798874aa62d28e5ff59b Mon Sep 17 00:00:00 2001 From: Slawomir Milczarek Date: Sat, 21 Jun 2025 18:05:09 +0000 Subject: [PATCH] feature: Add capability to print debug messages with pid and timestamp Controlled with the knob DebugMessagesBitmask (1 - pid, 2 - timestamp) Related-To: NEO-12952 Signed-off-by: Slawomir Milczarek --- .../debug_settings/debug_settings_manager.h | 43 +++++++++++++------ .../debug_settings/debug_variables_base.inl | 1 + shared/source/helpers/timestamp.h | 6 ++- .../os_interface/linux/drm_command_stream.inl | 2 +- shared/source/os_interface/linux/drm_neo.cpp | 10 ++--- .../os_interface/linux/xe/ioctl_helper_xe.h | 1 - shared/test/common/test_files/igdrcl.config | 1 + .../utilities/debug_settings_reader_tests.cpp | 27 ++++++++++++ 8 files changed, 70 insertions(+), 21 deletions(-) diff --git a/shared/source/debug_settings/debug_settings_manager.h b/shared/source/debug_settings/debug_settings_manager.h index 2145bb6fc1..e4f7c9e96e 100644 --- a/shared/source/debug_settings/debug_settings_manager.h +++ b/shared/source/debug_settings/debug_settings_manager.h @@ -9,6 +9,7 @@ #include "shared/source/helpers/non_copyable_or_moveable.h" #include "shared/source/helpers/options.h" #include "shared/source/helpers/string.h" +#include "shared/source/helpers/timestamp.h" #include "shared/source/utilities/io_functions.h" #include @@ -16,6 +17,13 @@ #include #include +#if defined(_WIN32) +#include +#pragma warning(disable : 4996) +#else +#include +#endif + enum class DebugFunctionalityLevel { none, // Debug functionality disabled full, // Debug functionality fully enabled @@ -30,11 +38,11 @@ constexpr DebugFunctionalityLevel globalDebugFunctionalityLevel = DebugFunctiona constexpr DebugFunctionalityLevel globalDebugFunctionalityLevel = DebugFunctionalityLevel::none; #endif -#define PRINT_DEBUG_STRING(flag, ...) \ - if (flag) \ - NEO::printDebugString(flag, __VA_ARGS__); +#define PRINT_DEBUG_STRING(flag, stream, ...) \ + if (flag) \ + NEO::printDebugString(flag, stream, __VA_ARGS__); -#define EMIT_WARNING(flag, ...) PRINT_DEBUG_STRING(flag, __VA_ARGS__) +#define EMIT_WARNING(flag, stream, ...) PRINT_DEBUG_STRING(flag, stream, __VA_ARGS__) namespace NEO { template @@ -46,14 +54,6 @@ void flushDebugStream(StreamT stream, Args &&...args) { IoFunctions::fflushPtr(stream); } -template -void printDebugString(bool showDebugLogs, Args... args) { - if (showDebugLogs) { - IoFunctions::fprintf(args...); - flushDebugStream(args...); - } -} - void logDebugString(std::string_view debugString); #if defined(__clang__) @@ -222,6 +222,25 @@ static_assert(NEO::NonCopyableAndNonMovable debugManager; +struct DebugMessagesBitmask { + constexpr static int32_t withPid = 1 << 0; + constexpr static int32_t withTimestamp = 1 << 1; +}; + +template +void printDebugString(bool showDebugLogs, FILE *stream, Args... args) { + if (showDebugLogs) { + if (NEO::debugManager.flags.DebugMessagesBitmask.get() & DebugMessagesBitmask::withPid) { + IoFunctions::fprintf(stream, "[PID: %d] ", getpid()); + } + if (NEO::debugManager.flags.DebugMessagesBitmask.get() & DebugMessagesBitmask::withTimestamp) { + IoFunctions::fprintf(stream, "%s", TimestampHelper::getTimestamp().c_str()); + } + IoFunctions::fprintf(stream, args...); + flushDebugStream(stream, args...); + } +} + class DurationLog { DurationLog() = delete; diff --git a/shared/source/debug_settings/debug_variables_base.inl b/shared/source/debug_settings/debug_variables_base.inl index 6c3551c9d7..2c4e9dfd7c 100644 --- a/shared/source/debug_settings/debug_variables_base.inl +++ b/shared/source/debug_settings/debug_variables_base.inl @@ -327,6 +327,7 @@ DECLARE_DEBUG_VARIABLE(bool, PrintExecutionBuffer, false, "print execution buffe DECLARE_DEBUG_VARIABLE(bool, PrintBOsForSubmit, false, "print all BOs passed to submission") DECLARE_DEBUG_SCOPED_V(bool, PrintDebugSettings, false, S_RT | S_OCLOC, "Dump all debug variables settings to text file. Print to stdout if value is different than default.") DECLARE_DEBUG_VARIABLE(bool, PrintDebugMessages, false, "when enabled, some debug messages will be propagated to console") +DECLARE_DEBUG_VARIABLE(int32_t, DebugMessagesBitmask, 0, "Bitmask: 1 - print debug messages with PID, 2 - with Timestamp, 3 - both") DECLARE_DEBUG_VARIABLE(bool, PrintXeLogs, false, "when enabled, xe logs will be propagated to console") DECLARE_DEBUG_VARIABLE(bool, DumpZEBin, false, "Enables dumping zebin (elf) to a binary file (.elf extension)") DECLARE_DEBUG_VARIABLE(bool, DumpKernels, false, "Enables dumping kernels' program source code to text files and program from binary to bin file") diff --git a/shared/source/helpers/timestamp.h b/shared/source/helpers/timestamp.h index 6a9c2fce44..6bdb5b7e00 100644 --- a/shared/source/helpers/timestamp.h +++ b/shared/source/helpers/timestamp.h @@ -1,5 +1,5 @@ /* - * Copyright (C) 2024 Intel Corporation + * Copyright (C) 2024-2025 Intel Corporation * * SPDX-License-Identifier: MIT * @@ -22,7 +22,9 @@ static inline std::string getTimestamp() { std::stringstream ss; - ss << "[" << std::put_time(&timeInfo, "%Y-%m-%d %H:%M:%S") << "] "; + char buffer[32]; + std::strftime(buffer, sizeof(buffer), "[%Y-%m-%d %H:%M:%S] ", &timeInfo); + ss << buffer; return ss.str(); } diff --git a/shared/source/os_interface/linux/drm_command_stream.inl b/shared/source/os_interface/linux/drm_command_stream.inl index 43c5b5b435..c1b502182b 100644 --- a/shared/source/os_interface/linux/drm_command_stream.inl +++ b/shared/source/os_interface/linux/drm_command_stream.inl @@ -198,7 +198,7 @@ SubmissionStatus DrmCommandStreamReceiver::printBOsForSubmit(Residenc } } } - printf("Buffer object for submit\n"); + PRINT_DEBUG_STRING(true, stdout, "Buffer object for submit\n"); for (const auto &bo : bosForSubmit) { printf("BO-%d, range: %" SCNx64 " - %" SCNx64 ", size: %" SCNdPTR "\n", bo->peekHandle(), bo->peekAddress(), ptrOffset(bo->peekAddress(), bo->peekSize()), bo->peekSize()); } diff --git a/shared/source/os_interface/linux/drm_neo.cpp b/shared/source/os_interface/linux/drm_neo.cpp index 2477061c33..e5637d7c68 100644 --- a/shared/source/os_interface/linux/drm_neo.cpp +++ b/shared/source/os_interface/linux/drm_neo.cpp @@ -102,7 +102,7 @@ int Drm::ioctl(DrmIoctl request, void *arg) { auto printIoctl = debugManager.flags.PrintIoctlEntries.get(); if (printIoctl) { - printf("IOCTL %s called\n", ioctlHelper->getIoctlString(request).c_str()); + PRINT_DEBUG_STRING(true, stdout, "IOCTL %s called\n", ioctlHelper->getIoctlString(request).c_str()); } if (measureTime) { @@ -137,11 +137,11 @@ int Drm::ioctl(DrmIoctl request, void *arg) { if (printIoctl) { if (ret == 0) { - printf("IOCTL %s returns %d\n", - ioctlHelper->getIoctlString(request).c_str(), ret); + PRINT_DEBUG_STRING(true, stdout, "IOCTL %s returns %d\n", + ioctlHelper->getIoctlString(request).c_str(), ret); } else { - printf("IOCTL %s returns %d, errno %d(%s)\n", - ioctlHelper->getIoctlString(request).c_str(), ret, returnedErrno, strerror(returnedErrno)); + PRINT_DEBUG_STRING(true, stdout, "IOCTL %s returns %d, errno %d(%s)\n", + ioctlHelper->getIoctlString(request).c_str(), ret, returnedErrno, strerror(returnedErrno)); } } diff --git a/shared/source/os_interface/linux/xe/ioctl_helper_xe.h b/shared/source/os_interface/linux/xe/ioctl_helper_xe.h index f995eebe85..cea4c76e29 100644 --- a/shared/source/os_interface/linux/xe/ioctl_helper_xe.h +++ b/shared/source/os_interface/linux/xe/ioctl_helper_xe.h @@ -229,7 +229,6 @@ class IoctlHelperXe : public IoctlHelper { template void IoctlHelperXe::xeLog(XeLogArgs &&...args) const { if (debugManager.flags.PrintXeLogs.get()) { - PRINT_DEBUG_STRING(debugManager.flags.PrintXeLogs.get(), stderr, TimestampHelper::getTimestamp().c_str()); PRINT_DEBUG_STRING(debugManager.flags.PrintXeLogs.get(), stderr, args...); } } diff --git a/shared/test/common/test_files/igdrcl.config b/shared/test/common/test_files/igdrcl.config index 5bcb332f68..8041af38b6 100644 --- a/shared/test/common/test_files/igdrcl.config +++ b/shared/test/common/test_files/igdrcl.config @@ -83,6 +83,7 @@ WddmPagingFenceCpuWaitDelayTime = 0 PrintL0SetKernelArg = 0 UsePipeControlMultiKernelEventSync = -1 PrintDebugMessages = 0 +DebugMessagesBitmask = 0 DumpZEBin = 0 DumpKernels = 0 DumpKernelArgs = 0 diff --git a/shared/test/unit_test/utilities/debug_settings_reader_tests.cpp b/shared/test/unit_test/utilities/debug_settings_reader_tests.cpp index 0f8a2a3e89..3bfd50ed3e 100644 --- a/shared/test/unit_test/utilities/debug_settings_reader_tests.cpp +++ b/shared/test/unit_test/utilities/debug_settings_reader_tests.cpp @@ -6,6 +6,8 @@ */ #include "shared/source/helpers/api_specific_config.h" +#include "shared/test/common/helpers/debug_manager_state_restore.h" +#include "shared/test/common/helpers/gtest_helpers.h" #include "shared/test/common/helpers/stream_capture.h" #include "shared/test/common/mocks/mock_settings_reader.h" #include "shared/test/common/test_macros/test.h" @@ -101,4 +103,29 @@ TEST(SettingsReader, GivenFalseWhenPrintingDebugStringThenNoOutput) { std::string output = capture.getCapturedStdout(); EXPECT_STREQ(output.c_str(), ""); } + +TEST(SettingsReader, GivenDebugMessagesBitmaskWithPidWhenPrintingDebugStringThenPrintsPidToOutput) { + DebugManagerStateRestore restorer; + NEO::debugManager.flags.DebugMessagesBitmask.set(DebugMessagesBitmask::withPid); + + int i = 4; + StreamCapture capture; + capture.captureStdout(); + PRINT_DEBUG_STRING(true, stdout, "debug string %d", i); + std::string output = capture.getCapturedStdout(); + EXPECT_TRUE(hasSubstr(output, "[PID: ")); +} + +TEST(SettingsReader, GivenDebugMessagesBitmaskWithTimestampWhenPrintingDebugStringThenPrintsTimestampToOutput) { + DebugManagerStateRestore restorer; + NEO::debugManager.flags.DebugMessagesBitmask.set(DebugMessagesBitmask::withTimestamp); + + int i = 4; + StreamCapture capture; + capture.captureStdout(); + PRINT_DEBUG_STRING(true, stdout, "debug string %d", i); + std::string output = capture.getCapturedStdout(); + std::string dateRegex = R"(\[20\d{2}-\d{2}-\d{2})"; + EXPECT_TRUE(containsRegex(output, dateRegex)); +} } // namespace SettingsReaderTests \ No newline at end of file