log bo creation and destruction, improve logging

Change-Id: Ic4d66e316ed08d056053a7a9f60611f4b5a762e6
Signed-off-by: Sebastian Luzynski <sebastian.jozef.luzynski@intel.com>
This commit is contained in:
Sebastian Luzynski
2020-08-13 10:10:48 +02:00
committed by sys_ocldev
parent 2e5c5b5f29
commit 26e700f649
7 changed files with 81 additions and 28 deletions

View File

@@ -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<uint32_t[]> buff(new uint32_t[1024]);
std::unique_ptr<BufferObject> bo(new TestedBufferObject(this->mock.get()));
ASSERT_NE(nullptr, bo.get());
bo->setAddress(reinterpret_cast<uint64_t>(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) {

View File

@@ -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);
}

View File

@@ -69,6 +69,7 @@ PrintProgramBinaryProcessingTime = 0
PrintRelocations = 0
PrintTimestampPacketContents = 0
WddmResidencyLogger = 0
PrintBOCreateDestroyResult = 0
PrintDriverDiagnostics = -1
PrintDeviceAndEngineIdOnSubmission = 0
EnableDirectSubmission = -1

View File

@@ -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")

View File

@@ -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) {

View File

@@ -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();

View File

@@ -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);