From cb6e63ed05476d7b9d301b362a959f349894beb3 Mon Sep 17 00:00:00 2001 From: Brandon Yates Date: Mon, 20 May 2024 17:33:59 +0000 Subject: [PATCH] feature: Add elapsed time to debugger logs Related-to: NEO-11469 Signed-off-by: Brandon Yates --- .../debug/linux/prelim/test_debug_api_linux.cpp | 5 +++-- .../debug_settings/debug_settings_manager.cpp | 9 ++++++++- .../debug_settings/debug_settings_manager.h | 17 +++++++++++++++-- .../debug_settings_manager_tests.cpp | 9 +++++++++ 4 files changed, 35 insertions(+), 5 deletions(-) diff --git a/level_zero/tools/test/unit_tests/sources/debug/linux/prelim/test_debug_api_linux.cpp b/level_zero/tools/test/unit_tests/sources/debug/linux/prelim/test_debug_api_linux.cpp index 9317eb1b9f..13ca9c0040 100644 --- a/level_zero/tools/test/unit_tests/sources/debug/linux/prelim/test_debug_api_linux.cpp +++ b/level_zero/tools/test/unit_tests/sources/debug/linux/prelim/test_debug_api_linux.cpp @@ -1035,7 +1035,7 @@ TEST_F(DebugApiLinuxTest, GivenDebuggerLogsWhenOpenDebuggerSucceedsThenCorrectMe EXPECT_EQ(ZE_RESULT_SUCCESS, result); auto errorMessage = ::testing::internal::GetCapturedStdout(); - EXPECT_EQ(std::string("\nINFO: PRELIM_DRM_IOCTL_I915_DEBUGGER_OPEN: open.pid: 4660, open.events: 0, debugFd: 10\n"), errorMessage); + EXPECT_TRUE(hasSubstr(errorMessage, std::string("INFO: PRELIM_DRM_IOCTL_I915_DEBUGGER_OPEN: open.pid: 4660, open.events: 0, debugFd: 10\n"))); } TEST_F(DebugApiLinuxTest, GivenDebugSessionWhenClosingConnectionThenSysCallCloseOnFdIsCalled) { @@ -5276,7 +5276,8 @@ TEST_F(DebugApiLinuxTest, GivenDebuggerInfoLogsWhenHandlingContextParamEventWith session->clientHandleToConnection[contextParamEvent.client_handle]->contextsCreated.find(77)); auto errorMessage = ::testing::internal::GetCapturedStdout(); - EXPECT_TRUE(hasSubstr(errorMessage, std::string("client_handle = 1 ctx_handle = 20\n\nINFO: I915_CONTEXT_PARAM UNHANDLED = 1\n"))); + EXPECT_TRUE(hasSubstr(errorMessage, std::string("client_handle = 1 ctx_handle = 20\n"))); + EXPECT_TRUE(hasSubstr(errorMessage, std::string("INFO: I915_CONTEXT_PARAM UNHANDLED = 1\n"))); } TEST_F(DebugApiLinuxTest, WhenCallingThreadControlForInterruptThenProperIoctlsIsCalled) { diff --git a/shared/source/debug_settings/debug_settings_manager.cpp b/shared/source/debug_settings/debug_settings_manager.cpp index 626f387d38..aba0636fc7 100644 --- a/shared/source/debug_settings/debug_settings_manager.cpp +++ b/shared/source/debug_settings/debug_settings_manager.cpp @@ -1,5 +1,5 @@ /* - * Copyright (C) 2018-2023 Intel Corporation + * Copyright (C) 2018-2024 Intel Corporation * * SPDX-License-Identifier: MIT * @@ -164,6 +164,13 @@ void logDebugString(std::string_view debugString) { NEO::fileLoggerInstance().logDebugString(true, debugString); } +std::string DurationLog::getTimeString() { + static const std::chrono::time_point processStartTime = std::chrono::steady_clock::now(); + auto elapsedTime = std::chrono::steady_clock::now().time_since_epoch() - processStartTime.time_since_epoch(); + auto elapsedTimeUs = std::chrono::duration_cast(elapsedTime); + return std::to_string(elapsedTimeUs.count()); +} + template class DebugSettingsManager; template class DebugSettingsManager; template class DebugSettingsManager; diff --git a/shared/source/debug_settings/debug_settings_manager.h b/shared/source/debug_settings/debug_settings_manager.h index 5c57607bf1..b988d2af4d 100644 --- a/shared/source/debug_settings/debug_settings_manager.h +++ b/shared/source/debug_settings/debug_settings_manager.h @@ -1,5 +1,5 @@ /* - * Copyright (C) 2018-2023 Intel Corporation + * Copyright (C) 2018-2024 Intel Corporation * * SPDX-License-Identifier: MIT * @@ -9,8 +9,11 @@ #include "shared/source/helpers/string.h" #include "shared/source/utilities/io_functions.h" +#include #include +#include #include +#include #include enum class DebugFunctionalityLevel { @@ -172,6 +175,13 @@ class DebugSettingsManager { extern DebugSettingsManager debugManager; +class DurationLog { + DurationLog() = delete; + + public: + static std::string getTimeString(); +}; + #define PRINT_DEBUGGER_LOG_TO_FILE(...) \ NEO::debugManager.logLazyEvaluateArgs([&] { \ char temp[4000]; \ @@ -189,7 +199,10 @@ extern DebugSettingsManager debugManager; #define PRINT_DEBUGGER_INFO_LOG(STR, ...) \ if (NEO::debugManager.flags.DebuggerLogBitmask.get() & NEO::DebugVariables::DEBUGGER_LOG_BITMASK::LOG_INFO) { \ - PRINT_DEBUGGER_LOG(stdout, "\nINFO: " STR, __VA_ARGS__) \ + \ + auto time = NEO::DurationLog::getTimeString(); \ + time = "\n" + time + " INFO: " + STR; \ + PRINT_DEBUGGER_LOG(stdout, time.c_str(), __VA_ARGS__) \ } #define PRINT_DEBUGGER_THREAD_LOG(STR, ...) \ diff --git a/shared/test/unit_test/debug_settings/debug_settings_manager_tests.cpp b/shared/test/unit_test/debug_settings/debug_settings_manager_tests.cpp index 6a37934b8c..6787600ea1 100644 --- a/shared/test/unit_test/debug_settings/debug_settings_manager_tests.cpp +++ b/shared/test/unit_test/debug_settings/debug_settings_manager_tests.cpp @@ -12,6 +12,7 @@ #include "shared/source/utilities/logger.h" #include "shared/test/common/debug_settings/debug_settings_manager_fixture.h" #include "shared/test/common/helpers/debug_manager_state_restore.h" +#include "shared/test/common/helpers/gtest_helpers.h" #include "shared/test/common/helpers/variable_backup.h" #include "shared/test/common/mocks/mock_io_functions.h" #include "shared/test/common/test_macros/test.h" @@ -20,6 +21,7 @@ #include #include #include +#include #include #include @@ -440,3 +442,10 @@ TEST(DebugLog, WhenLogDebugStringCalledThenNothingIsPrintedToStdout) { auto output = ::testing::internal::GetCapturedStdout(); EXPECT_EQ(0u, output.size()); } + +TEST(DurationLogTest, givenDurationGetTimeStringThenTimeStringIsCorrect) { + auto timeString = DurationLog::getTimeString(); + for (auto c : timeString) { + EXPECT_TRUE(std::isdigit(c)); + } +}