Improve ioctl statistics

Related-To: NEO-5845

Signed-off-by: Zbigniew Zdanowicz <zbigniew.zdanowicz@intel.com>
This commit is contained in:
Zbigniew Zdanowicz 2021-08-19 15:26:34 +00:00 committed by Compute-Runtime-Automation
parent c6ee7065db
commit 6d510240e6
3 changed files with 101 additions and 43 deletions

View File

@ -30,6 +30,7 @@
#include "os_inc.h"
#include <string>
#include <string_view>
namespace Os {
extern const char *dxcoreDllName;
@ -199,6 +200,9 @@ TEST_F(DrmSimpleTests, givenPrintIoctlTimesWhenCallIoctlThenStatisticsAreGathere
};
::testing::internal::CaptureStdout();
constexpr long long initialMin = std::numeric_limits<long long>::max();
constexpr long long initialMax = 0;
auto executionEnvironment = std::make_unique<ExecutionEnvironment>();
executionEnvironment->prepareRootDeviceEnvironments(1);
auto drm = static_cast<DrmMock *>(DrmWrap::createDrm(*executionEnvironment->rootDeviceEnvironments[0]).release());
@ -212,70 +216,109 @@ TEST_F(DrmSimpleTests, givenPrintIoctlTimesWhenCallIoctlThenStatisticsAreGathere
uint32_t contextId = 1u;
drm->getEuTotal(euTotal);
EXPECT_EQ(drm->ioctlStatistics.size(), 1u);
EXPECT_EQ(1u, drm->ioctlStatistics.size());
drm->getEuTotal(euTotal);
EXPECT_EQ(drm->ioctlStatistics.size(), 1u);
EXPECT_EQ(1u, drm->ioctlStatistics.size());
drm->setLowPriorityContextParam(contextId);
EXPECT_EQ(drm->ioctlStatistics.size(), 2u);
EXPECT_EQ(2u, drm->ioctlStatistics.size());
auto euTotalData = drm->ioctlStatistics.find(DRM_IOCTL_I915_GETPARAM);
ASSERT_TRUE(euTotalData != drm->ioctlStatistics.end());
EXPECT_EQ(euTotalData->first, static_cast<unsigned long>(DRM_IOCTL_I915_GETPARAM));
EXPECT_EQ(euTotalData->second.second, 2u);
EXPECT_NE(euTotalData->second.first, 0);
auto firstTime = euTotalData->second.first;
EXPECT_EQ(static_cast<unsigned long>(DRM_IOCTL_I915_GETPARAM), euTotalData->first);
EXPECT_EQ(2u, euTotalData->second.count);
EXPECT_NE(0, euTotalData->second.totalTime);
EXPECT_NE(initialMin, euTotalData->second.minTime);
EXPECT_NE(initialMax, euTotalData->second.minTime);
EXPECT_NE(initialMin, euTotalData->second.maxTime);
EXPECT_NE(initialMax, euTotalData->second.maxTime);
auto firstTime = euTotalData->second.totalTime;
auto lowPriorityData = drm->ioctlStatistics.find(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM);
ASSERT_TRUE(lowPriorityData != drm->ioctlStatistics.end());
EXPECT_EQ(lowPriorityData->first, static_cast<unsigned long>(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM));
EXPECT_EQ(lowPriorityData->second.second, 1u);
EXPECT_NE(lowPriorityData->second.first, 0);
EXPECT_EQ(static_cast<unsigned long>(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM), lowPriorityData->first);
EXPECT_EQ(1u, lowPriorityData->second.count);
EXPECT_NE(0, lowPriorityData->second.totalTime);
EXPECT_NE(initialMin, lowPriorityData->second.minTime);
EXPECT_NE(initialMax, lowPriorityData->second.minTime);
EXPECT_NE(initialMin, lowPriorityData->second.maxTime);
EXPECT_NE(initialMax, lowPriorityData->second.maxTime);
drm->getEuTotal(euTotal);
EXPECT_EQ(drm->ioctlStatistics.size(), 2u);
euTotalData = drm->ioctlStatistics.find(DRM_IOCTL_I915_GETPARAM);
ASSERT_TRUE(euTotalData != drm->ioctlStatistics.end());
EXPECT_EQ(euTotalData->first, static_cast<unsigned long>(DRM_IOCTL_I915_GETPARAM));
EXPECT_EQ(euTotalData->second.second, 3u);
EXPECT_NE(euTotalData->second.first, 0);
EXPECT_EQ(static_cast<unsigned long>(DRM_IOCTL_I915_GETPARAM), euTotalData->first);
EXPECT_EQ(3u, euTotalData->second.count);
EXPECT_NE(0u, euTotalData->second.totalTime);
auto secondTime = euTotalData->second.first;
auto secondTime = euTotalData->second.totalTime;
EXPECT_GT(secondTime, firstTime);
lowPriorityData = drm->ioctlStatistics.find(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM);
ASSERT_TRUE(lowPriorityData != drm->ioctlStatistics.end());
EXPECT_EQ(lowPriorityData->first, static_cast<unsigned long>(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM));
EXPECT_EQ(lowPriorityData->second.second, 1u);
EXPECT_NE(lowPriorityData->second.first, 0);
EXPECT_EQ(static_cast<unsigned long>(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM), lowPriorityData->first);
EXPECT_EQ(1u, lowPriorityData->second.count);
EXPECT_NE(0, lowPriorityData->second.totalTime);
drm->destroyDrmContext(contextId);
EXPECT_EQ(drm->ioctlStatistics.size(), 3u);
EXPECT_EQ(3u, drm->ioctlStatistics.size());
euTotalData = drm->ioctlStatistics.find(DRM_IOCTL_I915_GETPARAM);
ASSERT_TRUE(euTotalData != drm->ioctlStatistics.end());
EXPECT_EQ(euTotalData->first, static_cast<unsigned long>(DRM_IOCTL_I915_GETPARAM));
EXPECT_EQ(euTotalData->second.second, 3u);
EXPECT_NE(euTotalData->second.first, 0);
EXPECT_EQ(static_cast<unsigned long>(DRM_IOCTL_I915_GETPARAM), euTotalData->first);
EXPECT_EQ(3u, euTotalData->second.count);
EXPECT_NE(0, euTotalData->second.totalTime);
lowPriorityData = drm->ioctlStatistics.find(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM);
ASSERT_TRUE(lowPriorityData != drm->ioctlStatistics.end());
EXPECT_EQ(lowPriorityData->first, static_cast<unsigned long>(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM));
EXPECT_EQ(lowPriorityData->second.second, 1u);
EXPECT_NE(lowPriorityData->second.first, 0);
EXPECT_EQ(static_cast<unsigned long>(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM), lowPriorityData->first);
EXPECT_EQ(1u, lowPriorityData->second.count);
EXPECT_NE(0, lowPriorityData->second.totalTime);
auto destroyData = drm->ioctlStatistics.find(DRM_IOCTL_I915_GEM_CONTEXT_DESTROY);
ASSERT_TRUE(destroyData != drm->ioctlStatistics.end());
EXPECT_EQ(destroyData->first, static_cast<unsigned long>(DRM_IOCTL_I915_GEM_CONTEXT_DESTROY));
EXPECT_EQ(destroyData->second.second, 1u);
EXPECT_NE(destroyData->second.first, 0);
EXPECT_EQ(static_cast<unsigned long>(DRM_IOCTL_I915_GEM_CONTEXT_DESTROY), destroyData->first);
EXPECT_EQ(1u, destroyData->second.count);
EXPECT_NE(0, destroyData->second.totalTime);
delete drm;
std::string output = ::testing::internal::GetCapturedStdout();
EXPECT_STRNE(output.c_str(), "");
EXPECT_STRNE("", output.c_str());
std::string_view requestString("Request");
std::string_view totalTimeString("Total time(ns)");
std::string_view countString("Count");
std::string_view avgTimeString("Avg time per ioctl");
std::string_view minString("Min");
std::string_view maxString("Max");
std::size_t position = output.find(requestString);
EXPECT_NE(std::string::npos, position);
position += requestString.size();
position = output.find(totalTimeString, position);
EXPECT_NE(std::string::npos, position);
position += totalTimeString.size();
position = output.find(countString, position);
EXPECT_NE(std::string::npos, position);
position += countString.size();
position = output.find(avgTimeString, position);
EXPECT_NE(std::string::npos, position);
position += avgTimeString.size();
position = output.find(minString, position);
EXPECT_NE(std::string::npos, position);
position += minString.size();
position = output.find(maxString, position);
EXPECT_NE(std::string::npos, position);
position += maxString.size();
}
TEST_F(DrmSimpleTests, GivenSelectedNonExistingDeviceWhenOpenDirFailsThenRetryOpeningRenderDevicesAndNoDevicesAreCreated) {

View File

@ -202,39 +202,41 @@ int Drm::ioctl(unsigned long request, void *arg) {
std::chrono::steady_clock::time_point start;
std::chrono::steady_clock::time_point end;
if (measureTime) {
start = std::chrono::steady_clock::now();
}
auto printIoctl = DebugManager.flags.PrintIoctlEntries.get();
if (printIoctl) {
printf("IOCTL %s called\n", IoctlHelper::getIoctlString(request).c_str());
}
if (measureTime) {
start = std::chrono::steady_clock::now();
}
ret = SysCalls::ioctl(getFileDescriptor(), request, arg);
returnedErrno = errno;
if (printIoctl) {
printf("IOCTL %s returns %d, errno %d(%s)\n", IoctlHelper::getIoctlString(request).c_str(), ret, returnedErrno, strerror(returnedErrno));
}
if (measureTime) {
end = std::chrono::steady_clock::now();
auto elapsedTime = std::chrono::duration_cast<std::chrono::nanoseconds>(end - start).count();
long long elapsedTime = std::chrono::duration_cast<std::chrono::nanoseconds>(end - start).count();
std::pair<long long, uint64_t> ioctlData{};
IoctlStatisticsEntry ioctlData{};
auto ioctlDataIt = this->ioctlStatistics.find(request);
if (ioctlDataIt != this->ioctlStatistics.end()) {
ioctlData = ioctlDataIt->second;
}
ioctlData.first += elapsedTime;
ioctlData.second++;
ioctlData.totalTime += elapsedTime;
ioctlData.count++;
ioctlData.minTime = std::min(ioctlData.minTime, elapsedTime);
ioctlData.maxTime = std::max(ioctlData.maxTime, elapsedTime);
this->ioctlStatistics[request] = ioctlData;
}
if (printIoctl) {
printf("IOCTL %s returns %d, errno %d(%s)\n", IoctlHelper::getIoctlString(request).c_str(), ret, returnedErrno, strerror(returnedErrno));
}
} while (ret == -1 && (returnedErrno == EINTR || returnedErrno == EAGAIN || returnedErrno == EBUSY));
SYSTEM_LEAVE(request);
return ret;
@ -599,9 +601,15 @@ void Drm::printIoctlStatistics() {
}
printf("\n--- Ioctls statistics ---\n");
printf("%40s %15s %10s %20s", "Request", "Total time(ns)", "Count", "Avg time per ioctl\n");
printf("%41s %15s %10s %20s %20s %20s", "Request", "Total time(ns)", "Count", "Avg time per ioctl", "Min", "Max\n");
for (const auto &ioctlData : this->ioctlStatistics) {
printf("%40s %15llu %10lu %20f\n", IoctlHelper::getIoctlString(ioctlData.first).c_str(), ioctlData.second.first, static_cast<unsigned long>(ioctlData.second.second), ioctlData.second.first / static_cast<double>(ioctlData.second.second));
printf("%41s %15llu %10lu %20f %20lld %20lld\n",
IoctlHelper::getIoctlString(ioctlData.first).c_str(),
ioctlData.second.totalTime,
static_cast<unsigned long>(ioctlData.second.count),
ioctlData.second.totalTime / static_cast<double>(ioctlData.second.count),
ioctlData.second.minTime,
ioctlData.second.maxTime);
}
printf("\n");
}

View File

@ -26,6 +26,7 @@
#include <array>
#include <cerrno>
#include <fcntl.h>
#include <limits>
#include <memory>
#include <mutex>
#include <string>
@ -275,7 +276,13 @@ class Drm : public DriverModel {
ADAPTER_BDF adapterBDF{};
TopologyMap topologyMap;
std::unordered_map<unsigned long, std::pair<long long, uint64_t>> ioctlStatistics;
struct IoctlStatisticsEntry {
long long totalTime = 0;
uint64_t count = 0;
long long minTime = std::numeric_limits<long long>::max();
long long maxTime = 0;
};
std::unordered_map<unsigned long, IoctlStatisticsEntry> ioctlStatistics;
std::mutex bindFenceMutex;
std::array<uint64_t, EngineLimits::maxHandleCount> pagingFence;