From 26e700f649cf0615f7065309526cf830770570df Mon Sep 17 00:00:00 2001 From: Sebastian Luzynski Date: Thu, 13 Aug 2020 10:10:48 +0200 Subject: [PATCH] log bo creation and destruction, improve logging Change-Id: Ic4d66e316ed08d056053a7a9f60611f4b5a762e6 Signed-off-by: Sebastian Luzynski --- .../linux/drm_buffer_object_tests.cpp | 33 ++++++++++-- .../linux/drm_memory_manager_tests.cpp | 19 +++++++ .../test/unit_test/test_files/igdrcl.config | 1 + .../debug_settings/debug_variables_base.inl | 1 + .../os_interface/linux/drm_buffer_object.cpp | 51 ++++++++++--------- .../os_interface/linux/drm_buffer_object.h | 2 +- .../os_interface/linux/drm_memory_manager.cpp | 2 + 7 files changed, 81 insertions(+), 28 deletions(-) diff --git a/opencl/test/unit_test/os_interface/linux/drm_buffer_object_tests.cpp b/opencl/test/unit_test/os_interface/linux/drm_buffer_object_tests.cpp index 17dbd77ba1..1192a95289 100644 --- a/opencl/test/unit_test/os_interface/linux/drm_buffer_object_tests.cpp +++ b/opencl/test/unit_test/os_interface/linux/drm_buffer_object_tests.cpp @@ -149,20 +149,47 @@ TEST_F(DrmBufferObjectTest, onPinIoctlFailed) { EXPECT_EQ(EINVAL, ret); } -TEST_F(DrmBufferObjectTest, whenPrintExecutionBufferIsSetToTrueThenMessageFoundInStdStream) { +TEST_F(DrmBufferObjectTest, givenResidentBOWhenPrintExecutionBufferIsSetToTrueThenDebugInformationAboutBOIsPrinted) { mock->ioctl_expected.total = 1; DebugManagerStateRestore restore; DebugManager.flags.PrintExecutionBuffer.set(true); - drm_i915_gem_exec_object2 execObjectsStorage = {}; + + std::unique_ptr buff(new uint32_t[1024]); + std::unique_ptr bo(new TestedBufferObject(this->mock.get())); + ASSERT_NE(nullptr, bo.get()); + bo->setAddress(reinterpret_cast(buff.get())); + BufferObject *boArray[1] = {bo.get()}; testing::internal::CaptureStdout(); - auto ret = bo->exec(0, 0, 0, false, osContext.get(), 0, 1, nullptr, 0u, &execObjectsStorage); + + auto ret = bo->pin(boArray, 1, osContext.get(), 0, 1); EXPECT_EQ(0, ret); std::string output = testing::internal::GetCapturedStdout(); auto idx = output.find("drm_i915_gem_execbuffer2 {"); size_t expectedValue = 0; EXPECT_EQ(expectedValue, idx); + + idx = output.find("Buffer Object = { handle: "); + EXPECT_NE(std::string::npos, idx); + + idx = output.find("Command Buffer Object = { handle: "); + EXPECT_NE(std::string::npos, idx); +} + +TEST_F(DrmBufferObjectTest, whenPrintBOCreateDestroyResultFlagIsSetAndCloseIsCalledOnBOThenDebugInfromationIsPrinted) { + mock->ioctl_expected.total = 1; + DebugManagerStateRestore stateRestore; + DebugManager.flags.PrintBOCreateDestroyResult.set(true); + + testing::internal::CaptureStdout(); + bool result = bo->close(); + EXPECT_EQ(true, result); + + std::string output = testing::internal::GetCapturedStdout(); + size_t idx = output.find("Calling gem close on BO handle"); + size_t expectedValue = 0; + EXPECT_EQ(expectedValue, idx); } TEST(DrmBufferObjectSimpleTest, givenInvalidBoWhenPinIsCalledThenErrorIsReturned) { diff --git a/opencl/test/unit_test/os_interface/linux/drm_memory_manager_tests.cpp b/opencl/test/unit_test/os_interface/linux/drm_memory_manager_tests.cpp index d22a36e632..b6009ff986 100644 --- a/opencl/test/unit_test/os_interface/linux/drm_memory_manager_tests.cpp +++ b/opencl/test/unit_test/os_interface/linux/drm_memory_manager_tests.cpp @@ -462,6 +462,25 @@ TEST_F(DrmMemoryManagerTest, unreference) { memoryManager->unreference(bo, false); } +TEST_F(DrmMemoryManagerTest, whenPrintBOCreateDestroyResultIsSetAndAllocUserptrIsCalledThenBufferObjectIsCreatedAndDebugInformationIsPrinted) { + DebugManagerStateRestore stateRestore; + DebugManager.flags.PrintBOCreateDestroyResult.set(true); + + mock->ioctl_expected.gemUserptr = 1; + mock->ioctl_expected.gemClose = 1; + + testing::internal::CaptureStdout(); + BufferObject *bo = memoryManager->allocUserptr(0, (size_t)1024, 0ul, rootDeviceIndex); + ASSERT_NE(nullptr, bo); + + std::string output = testing::internal::GetCapturedStdout(); + size_t idx = output.find("Created new BO with GEM_USERPTR, BO handle - "); + size_t expectedValue = 0; + EXPECT_EQ(expectedValue, idx); + + memoryManager->unreference(bo, false); +} + TEST_F(DrmMemoryManagerTest, UnreferenceNullPtr) { memoryManager->unreference(nullptr, false); } diff --git a/opencl/test/unit_test/test_files/igdrcl.config b/opencl/test/unit_test/test_files/igdrcl.config index 62b5987899..69a3f81116 100644 --- a/opencl/test/unit_test/test_files/igdrcl.config +++ b/opencl/test/unit_test/test_files/igdrcl.config @@ -69,6 +69,7 @@ PrintProgramBinaryProcessingTime = 0 PrintRelocations = 0 PrintTimestampPacketContents = 0 WddmResidencyLogger = 0 +PrintBOCreateDestroyResult = 0 PrintDriverDiagnostics = -1 PrintDeviceAndEngineIdOnSubmission = 0 EnableDirectSubmission = -1 diff --git a/shared/source/debug_settings/debug_variables_base.inl b/shared/source/debug_settings/debug_variables_base.inl index 82ca9c5393..34fcbc3d96 100644 --- a/shared/source/debug_settings/debug_variables_base.inl +++ b/shared/source/debug_settings/debug_variables_base.inl @@ -100,6 +100,7 @@ DECLARE_DEBUG_VARIABLE(bool, PrintProgramBinaryProcessingTime, false, "prints ex DECLARE_DEBUG_VARIABLE(bool, PrintRelocations, false, "prints relocations debug information") DECLARE_DEBUG_VARIABLE(bool, PrintTimestampPacketContents, false, "prints all timestamps values during profiling data calculation") DECLARE_DEBUG_VARIABLE(bool, WddmResidencyLogger, false, "gather Wddm residency statistics to file") +DECLARE_DEBUG_VARIABLE(bool, PrintBOCreateDestroyResult, false, "tracks the result of creation and destruction of BOs") /*DIRECT SUBMISSION FLAGS*/ DECLARE_DEBUG_VARIABLE(int32_t, EnableDirectSubmission, -1, "-1: default (disabled), 0: disable, 1:enable. Enables direct submission of command buffers bypassing KMD") diff --git a/shared/source/os_interface/linux/drm_buffer_object.cpp b/shared/source/os_interface/linux/drm_buffer_object.cpp index 894ba73e86..8b8c07f3bf 100644 --- a/shared/source/os_interface/linux/drm_buffer_object.cpp +++ b/shared/source/os_interface/linux/drm_buffer_object.cpp @@ -55,6 +55,8 @@ bool BufferObject::close() { drm_gem_close close = {}; close.handle = this->handle; + printDebugString(DebugManager.flags.PrintBOCreateDestroyResult.get(), stdout, "Calling gem close on BO handle %d\n", this->handle); + int ret = this->drm->ioctl(DRM_IOCTL_GEM_CLOSE, &close); if (ret != 0) { int err = errno; @@ -130,7 +132,7 @@ int BufferObject::exec(uint32_t used, size_t startOffset, unsigned int flags, bo execbuf.rsvd1 = drmContextId; if (DebugManager.flags.PrintExecutionBuffer.get()) { - printExecutionBuffer(execbuf, residencyCount, execObjectsStorage); + printExecutionBuffer(execbuf, residencyCount, execObjectsStorage, residency); } int ret = this->drm->ioctl(DRM_IOCTL_I915_GEM_EXECBUFFER2, &execbuf); @@ -165,31 +167,32 @@ void BufferObject::unbind(OsContext *osContext, uint32_t vmHandleId) { } } -void BufferObject::printExecutionBuffer(drm_i915_gem_execbuffer2 &execbuf, const size_t &residencyCount, drm_i915_gem_exec_object2 *execObjectsStorage) { - std::string logger = "drm_i915_gem_execbuffer2 {\n"; - logger += " buffers_ptr: " + std::to_string(execbuf.buffers_ptr) + ",\n"; - logger += " buffer_count: " + std::to_string(execbuf.buffer_count) + ",\n"; - logger += " batch_start_offset: " + std::to_string(execbuf.batch_start_offset) + ",\n"; - logger += " batch_len: " + std::to_string(execbuf.batch_len) + ",\n"; - logger += " flags: " + std::to_string(execbuf.flags) + ",\n"; - logger += " rsvd1: " + std::to_string(execbuf.rsvd1) + ",\n"; - logger += "}\n"; +void BufferObject::printExecutionBuffer(drm_i915_gem_execbuffer2 &execbuf, const size_t &residencyCount, drm_i915_gem_exec_object2 *execObjectsStorage, BufferObject *const residency[]) { + std::stringstream logger; + logger << "drm_i915_gem_execbuffer2 { " + << "buffer_ptr: " + std::to_string(execbuf.buffers_ptr) + << ", buffer_count: " + std::to_string(execbuf.buffer_count) + << ", batch_start_offset: " + std::to_string(execbuf.batch_start_offset) + << ", batch_len: " + std::to_string(execbuf.batch_len) + << ", flags: " + std::to_string(execbuf.flags) + << ", rsvd1: " + std::to_string(execbuf.rsvd1) + << " }\n"; - for (size_t i = 0; i < residencyCount + 1; i++) { - std::string temp = "drm_i915_gem_exec_object2 {\n"; - temp += " handle: " + std::to_string(execObjectsStorage[i].handle) + ",\n"; - temp += " relocation_count: " + std::to_string(execObjectsStorage[i].relocation_count) + ",\n"; - temp += " relocs_ptr: " + std::to_string(execObjectsStorage[i].relocs_ptr) + ",\n"; - temp += " alignment: " + std::to_string(execObjectsStorage[i].alignment) + ",\n"; - temp += " offset: " + std::to_string(execObjectsStorage[i].offset) + ",\n"; - temp += " flags: " + std::to_string(execObjectsStorage[i].flags) + ",\n"; - temp += " rsvd1: " + std::to_string(execObjectsStorage[i].rsvd1) + ",\n"; - temp += " rsvd2: " + std::to_string(execObjectsStorage[i].rsvd2) + ",\n"; - temp += " pad_to_size: " + std::to_string(execObjectsStorage[i].pad_to_size) + ",\n"; - temp += "}\n"; - logger += temp; + size_t i; + for (i = 0; i < residencyCount; i++) { + logger << "Buffer Object = { handle: " << execObjectsStorage[i].handle + << ", address range: 0x" << (void *)execObjectsStorage[i].offset + << " - 0x" << (void *)ptrOffset(execObjectsStorage[i].offset, residency[i]->peekSize()) + << ", flags: " << execObjectsStorage[i].flags + << ", size: " << residency[i]->peekSize() << " }\n"; } - std::cout << logger << std::endl; + logger << "Command Buffer Object = { handle: " << execObjectsStorage[i].handle + << ", address range: 0x" << (void *)execObjectsStorage[i].offset + << " - 0x" << (void *)ptrOffset(execObjectsStorage[i].offset, this->peekSize()) + << ", flags: " << execObjectsStorage[i].flags + << ", size: " << this->peekSize() << " }\n"; + + std::cout << logger.str() << std::endl; } int BufferObject::pin(BufferObject *const boToPin[], size_t numberOfBos, OsContext *osContext, uint32_t vmHandleId, uint32_t drmContextId) { diff --git a/shared/source/os_interface/linux/drm_buffer_object.h b/shared/source/os_interface/linux/drm_buffer_object.h index 86c1cf7764..e6664cd050 100644 --- a/shared/source/os_interface/linux/drm_buffer_object.h +++ b/shared/source/os_interface/linux/drm_buffer_object.h @@ -48,7 +48,7 @@ class BufferObject { void bind(OsContext *osContext, uint32_t vmHandleId); void unbind(OsContext *osContext, uint32_t vmHandleId); - void printExecutionBuffer(drm_i915_gem_execbuffer2 &execbuf, const size_t &residencyCount, drm_i915_gem_exec_object2 *execObjectsStorage); + void printExecutionBuffer(drm_i915_gem_execbuffer2 &execbuf, const size_t &residencyCount, drm_i915_gem_exec_object2 *execObjectsStorage, BufferObject *const residency[]); int wait(int64_t timeoutNs); bool close(); diff --git a/shared/source/os_interface/linux/drm_memory_manager.cpp b/shared/source/os_interface/linux/drm_memory_manager.cpp index 824c339453..98edd573ba 100644 --- a/shared/source/os_interface/linux/drm_memory_manager.cpp +++ b/shared/source/os_interface/linux/drm_memory_manager.cpp @@ -175,6 +175,8 @@ NEO::BufferObject *DrmMemoryManager::allocUserptr(uintptr_t address, size_t size return nullptr; } + printDebugString(DebugManager.flags.PrintBOCreateDestroyResult.get(), stdout, "Created new BO with GEM_USERPTR, BO handle - %d\n", userptr.handle); + auto res = new (std::nothrow) BufferObject(&getDrm(rootDeviceIndex), userptr.handle, size, maxOsContextCount); if (!res) { DEBUG_BREAK_IF(true);