refactor: Add timestamp to all debugger log

Signed-off-by: Jitendra Sharma <[email protected]>

Author: jitendrasharma1989

level_zero/tools/source/debug/debug_session_imp.cpp

@@ -830,6 +830,7 @@ bool DebugSessionImp::isAIPequalToThreadStartIP(uint32_t *cr0, uint32_t *dbg0) {
 void DebugSessionImp::fillResumeAndStoppedThreadsFromNewlyStopped(std::vector<EuThread::ThreadId> &resumeThreads, std::vector<EuThread::ThreadId> &stoppedThreadsToReport, std::vector<EuThread::ThreadId> &interruptedThreads) {
 
     if (newlyStoppedThreads.empty()) {
+        PRINT_DEBUGGER_INFO_LOG("%s", "No newly stopped threads found. Returning");
         return;
     }
     const auto regSize = std::max(getRegisterSize(ZET_DEBUG_REGSET_TYPE_CR_INTEL_GPU), 64u);
@@ -1716,14 +1717,14 @@ ze_result_t DebugSessionImp::readFifo(uint64_t vmHandle, std::vector<EuThread::T
             for (uint32_t i = 0; i < readSize; i++) {
                 const uint64_t gpuVa = currentFifoOffset + (i * sizeof(SIP::fifo_node));
                 PRINT_DEBUGGER_FIFO_LOG("Validate entry at index %u in SW Fifo:: vmHandle: %" SCNx64
-                                        " gpuVa: %" SCNx64
-                                        " valid: %" SCNx8
-                                        " thread_id: %" SCNx8
-                                        " eu_id: %" SCNx8
-                                        " subslice_id: %" SCNx8
-                                        " slice_id: %" SCNx8
+                                        " gpuVa = %" SCNx64
+                                        " valid = %" SCNx8
+                                        " slice = %" SCNx8
+                                        " subslice = %" SCNx8
+                                        " eu = %" SCNx8
+                                        " thread = %" SCNx8
                                         "\n",
-                                        (i + fifoTailIndex), vmHandle, gpuVa, nodes[i].valid, nodes[i].thread_id, nodes[i].eu_id, nodes[i].subslice_id, nodes[i].slice_id);
+                                        (i + fifoTailIndex), vmHandle, gpuVa, nodes[i].valid, nodes[i].slice_id, nodes[i].subslice_id, nodes[i].eu_id, nodes[i].thread_id);
                 retVal = isValidNode(vmHandle, gpuVa, nodes[i]);
                 if (retVal != ZE_RESULT_SUCCESS) {
                     return retVal;

level_zero/tools/test/unit_tests/sources/debug/eu_thread_tests.cpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (C) 2021-2023 Intel Corporation
+ * Copyright (C) 2021-2024 Intel Corporation
  *
  * SPDX-License-Identifier: MIT
  *
@@ -158,7 +158,10 @@ TEST(EuThread, GivenEnabledErrorLogsWhenThreadStateStoppedAndVerifyingStopWithEv
     EXPECT_TRUE(euThread.isRunning());
 
     auto message = ::testing::internal::GetCapturedStderr();
-    EXPECT_STREQ("\nERROR: Thread: device index = 0 slice = 0 subslice = 0 eu = 0 thread = 0 state STOPPED when thread is running. Switching to RUNNING", message.c_str());
+    // Trim message and remove timestamp + first space
+    size_t pos = message.find(']');
+    message.erase(0, pos + 2);
+    EXPECT_STREQ("ERROR: Thread: device index = 0 slice = 0 subslice = 0 eu = 0 thread = 0 state STOPPED when thread is running. Switching to RUNNING", message.c_str());
 }
 
 TEST(EuThread, GivenThreadStateRunningWhenVerifyingStopWithOddCounterForSecondStopThenTrueIsReturnedAndStateStopped) {
@@ -210,7 +213,10 @@ TEST(EuThread, GivenEnabledErrorLogsWhenThreadStateStoppedAndVerifyingStopWithOd
     EXPECT_TRUE(euThread.isStopped());
 
     auto message = ::testing::internal::GetCapturedStderr();
-    EXPECT_STREQ("\nERROR: Thread: device index = 0 slice = 0 subslice = 0 eu = 0 thread = 0 state out of sync.", message.c_str());
+    // Trim message and remove timestamp + first space
+    size_t pos = message.find(']');
+    message.erase(0, pos + 2);
+    EXPECT_STREQ("ERROR: Thread: device index = 0 slice = 0 subslice = 0 eu = 0 thread = 0 state out of sync.", message.c_str());
 }
 
 TEST(EuThread, GivenEnabledErrorLogsWhenThreadStateRunningAndVerifyingStopWithOddCounterEqualToPreviousThenErrorMessageIsPrinted) {
@@ -230,7 +236,10 @@ TEST(EuThread, GivenEnabledErrorLogsWhenThreadStateRunningAndVerifyingStopWithOd
     EXPECT_TRUE(euThread.isStopped());
 
     auto message = ::testing::internal::GetCapturedStderr();
-    EXPECT_STREQ("\nERROR: Thread: device index = 0 slice = 0 subslice = 0 eu = 0 thread = 0 state RUNNING when thread is stopped. Switching to STOPPED", message.c_str());
+    // Trim message and remove timestamp + first space
+    size_t pos = message.find(']');
+    message.erase(0, pos + 2);
+    EXPECT_STREQ("ERROR: Thread: device index = 0 slice = 0 subslice = 0 eu = 0 thread = 0 state RUNNING when thread is stopped. Switching to STOPPED", message.c_str());
 }
 
 TEST(EuThread, GivenThreadStateStoppedWhenVerifyingStopWithEvenCounterBiggerByMoreThanTwoThenFalseIsReturnedAndStateRunning) {

level_zero/tools/test/unit_tests/sources/debug/linux/prelim/test_debug_api_linux.cpp

@@ -1003,7 +1003,10 @@ TEST_F(DebugApiLinuxTest, GivenDebuggerLogsWhenOpenDebuggerFailsThenCorrectMessa
     EXPECT_EQ(ZE_RESULT_ERROR_UNKNOWN, result);
 
     auto errorMessage = ::testing::internal::GetCapturedStderr();
-    EXPECT_EQ(std::string("\nERROR: PRELIM_DRM_IOCTL_I915_DEBUGGER_OPEN failed: open.pid: 4660, open.events: 0, retCode: -1, errno: 22\n"), errorMessage);
+    // Trim errorMessage and remove timestamp + first space
+    size_t pos = errorMessage.find(']');
+    errorMessage.erase(0, pos + 2);
+    EXPECT_EQ(std::string("ERROR: PRELIM_DRM_IOCTL_I915_DEBUGGER_OPEN failed: open.pid: 4660, open.events: 0, retCode: -1, errno: 22\n"), errorMessage);
 }
 
 TEST_F(DebugApiLinuxTest, WhenOpenDebuggerFailsThenCorrectErrorIsReturned) {
@@ -1147,7 +1150,10 @@ TEST_F(DebugApiLinuxTest, GivenPrintDebugMessagesWhenDebugSessionClosesConnectio
     NEO::SysCalls::closeFuncRetVal = 0;
 
     auto errorMessage = ::testing::internal::GetCapturedStderr();
-    EXPECT_EQ(std::string("\nERROR: Debug connection close() on fd: 10 failed: retCode: -1\n"), errorMessage);
+    // Trim errorMessage and remove timestamp + first space
+    size_t pos = errorMessage.find(']');
+    errorMessage.erase(0, pos + 2);
+    EXPECT_EQ(std::string("ERROR: Debug connection close() on fd: 10 failed: retCode: -1\n"), errorMessage);
 }
 
 TEST_F(DebugApiLinuxTest, GivenDebugSessionWhenCallingIoctlThenIoctlHandlerIsInvokedWithDebugFd) {
@@ -5076,7 +5082,10 @@ TEST_F(DebugApiLinuxTest, GivenDebuggerLogsAndFailingReadUuidEventIoctlWhenHandl
     EXPECT_EQ(0u, session->getClassHandleToIndex().size());
 
     auto errorMessage = ::testing::internal::GetCapturedStderr();
-    EXPECT_EQ(std::string("\nERROR: PRELIM_I915_DEBUG_IOCTL_READ_UUID ret = -1 errno = 0\n"), errorMessage);
+    // Trim errorMessage and remove timestamp + first space
+    size_t pos = errorMessage.find(']');
+    errorMessage.erase(0, pos + 2);
+    EXPECT_EQ(std::string("ERROR: PRELIM_I915_DEBUG_IOCTL_READ_UUID ret = -1 errno = 0\n"), errorMessage);
 }
 
 TEST_F(DebugApiLinuxTest, GivenEventsAvailableWhenReadingEventThenEventsAreReturned) {
@@ -5316,7 +5325,10 @@ TEST_F(DebugApiLinuxTest, GivenDebuggerErrorLogsWhenContextParamWithInvalidConte
               session->clientHandleToConnection[contextParamEvent.client_handle]->contextsCreated.find(77));
 
     auto errorMessage = ::testing::internal::GetCapturedStderr();
-    EXPECT_EQ(std::string("\nERROR: CONTEXT handle does not exist\n"), errorMessage);
+    // Trim errorMessage and remove timestamp + first space
+    size_t pos = errorMessage.find(']');
+    errorMessage.erase(0, pos + 2);
+    EXPECT_EQ(std::string("ERROR: CONTEXT handle does not exist\n"), errorMessage);
 }
 
 TEST_F(DebugApiLinuxTest, GivenDebuggerInfoLogsWhenHandlingContextParamEventWithUnknownParamThenInfoIsPrinted) {

shared/source/debug_settings/debug_settings_manager.cpp

@@ -16,7 +16,10 @@
 #include "shared/source/utilities/io_functions.h"
 #include "shared/source/utilities/logger.h"
 
+#include <chrono>
+#include <cinttypes>
 #include <fstream>
+#include <iomanip>
 #include <iostream>
 #include <sstream>
 #include <type_traits>
@@ -165,10 +168,14 @@ void logDebugString(std::string_view debugString) {
 }
 
 std::string DurationLog::getTimeString() {
-    static const std::chrono::time_point<std::chrono::steady_clock> 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<std::chrono::microseconds>(elapsedTime);
-    return std::to_string(elapsedTimeUs.count());
+    auto now = std::chrono::steady_clock::now();
+    auto microseconds = std::chrono::duration_cast<std::chrono::microseconds>(now.time_since_epoch());
+    auto seconds = microseconds.count() / 1000000;
+    auto remainingMicroSeconds = microseconds.count() % 1000000;
+    char buffer[32];
+    std::snprintf(buffer, sizeof(buffer), "[%5" PRId64 ".%06" PRId64 "]",
+                  static_cast<int64_t>(seconds), static_cast<int64_t>(remainingMicroSeconds));
+    return std::string(buffer);
 }
 
 template class DebugSettingsManager<DebugFunctionalityLevel::none>;

shared/source/debug_settings/debug_settings_manager.h

@@ -208,22 +208,34 @@ class DurationLog {
 
 #define PRINT_DEBUGGER_THREAD_LOG(STR, ...)                                                                          \
     if (NEO::debugManager.flags.DebuggerLogBitmask.get() & NEO::DebugVariables::DEBUGGER_LOG_BITMASK::LOG_THREADS) { \
-        PRINT_DEBUGGER_LOG(stdout, "\nTHREAD INFO: " STR, __VA_ARGS__)                                               \
+                                                                                                                     \
+        auto time = NEO::DurationLog::getTimeString();                                                               \
+        time = "\n" + time + " THREAD INFO: " + STR;                                                                 \
+        PRINT_DEBUGGER_LOG(stdout, time.c_str(), __VA_ARGS__)                                                        \
     }
 
 #define PRINT_DEBUGGER_ERROR_LOG(STR, ...)                                                                         \
     if (NEO::debugManager.flags.DebuggerLogBitmask.get() & NEO::DebugVariables::DEBUGGER_LOG_BITMASK::LOG_ERROR) { \
-        PRINT_DEBUGGER_LOG(stderr, "\nERROR: " STR, __VA_ARGS__)                                                   \
+                                                                                                                   \
+        auto time = NEO::DurationLog::getTimeString();                                                             \
+        time = "\n" + time + " ERROR: " + STR;                                                                     \
+        PRINT_DEBUGGER_LOG(stderr, time.c_str(), __VA_ARGS__)                                                      \
     }
 
 #define PRINT_DEBUGGER_MEM_ACCESS_LOG(STR, ...)                                                                  \
     if (NEO::debugManager.flags.DebuggerLogBitmask.get() & NEO::DebugVariables::DEBUGGER_LOG_BITMASK::LOG_MEM) { \
-        PRINT_DEBUGGER_LOG(stdout, "\nINFO: " STR, __VA_ARGS__)                                                  \
+                                                                                                                 \
+        auto time = NEO::DurationLog::getTimeString();                                                           \
+        time = "\n" + time + " MEM_ACCESS: " + STR;                                                              \
+        PRINT_DEBUGGER_LOG(stdout, time.c_str(), __VA_ARGS__)                                                    \
     }
 
 #define PRINT_DEBUGGER_FIFO_LOG(STR, ...)                                                                         \
     if (NEO::debugManager.flags.DebuggerLogBitmask.get() & NEO::DebugVariables::DEBUGGER_LOG_BITMASK::LOG_FIFO) { \
-        PRINT_DEBUGGER_LOG(stdout, "\nFIFO ACCESS: " STR, __VA_ARGS__)                                            \
+                                                                                                                  \
+        auto time = NEO::DurationLog::getTimeString();                                                            \
+        time = "\n" + time + " FIFO ACCESS: " + STR;                                                              \
+        PRINT_DEBUGGER_LOG(stdout, time.c_str(), __VA_ARGS__)                                                     \
     }
 
 template <DebugFunctionalityLevel debugLevel>

shared/test/unit_test/debug_settings/debug_settings_manager_tests.cpp

@@ -446,6 +446,6 @@ TEST(DebugLog, WhenLogDebugStringCalledThenNothingIsPrintedToStdout) {
 TEST(DurationLogTest, givenDurationGetTimeStringThenTimeStringIsCorrect) {
     auto timeString = DurationLog::getTimeString();
     for (auto c : timeString) {
-        EXPECT_TRUE(std::isdigit(c));
+        EXPECT_TRUE(std::isdigit(c) || c == '[' || c == ']' || c == '.');
     }
 }