From 817dc943457469ee962c2c2e67e22cfb8072ba26 Mon Sep 17 00:00:00 2001 From: mwootton Date: Fri, 26 Aug 2022 21:38:03 -0500 Subject: [PATCH] Add first pass of rocm kernel profiler (#10911) * Add first pass of rocm kernel profiler * Clean up rocm_profiler. Format args. Demangle kernel names. Add Api EventRecords * Remove debug output * Temporarily disable profiling unit test 'api record check' for cupti * Fix compile error for non-gpu builds * Use common file for demangle and pid/tid. Namespace ThreadUtil. Fix gpu buffer clearing. * Merge demangle into profiler_common * Merge demangle into profiler_common part 2 * Style cleanup * Resolve linking issues via ProviderHost interface * Demangle cuda kernel names * Clean up comments * Fix formatting * Fix anal retentive formatting --- cmake/CMakeLists.txt | 5 + cmake/onnxruntime_providers.cmake | 5 +- .../onnxruntime/core/common/profiler_common.h | 13 +- onnxruntime/core/common/profiler_common.cc | 53 +++ .../core/providers/cuda/cuda_profiler.cc | 4 +- .../core/providers/rocm/RoctracerLogger.cc | 351 ++++++++++++++++++ .../core/providers/rocm/RoctracerLogger.h | 170 +++++++++ onnxruntime/core/providers/rocm/ThreadUtil.cc | 37 ++ onnxruntime/core/providers/rocm/ThreadUtil.h | 16 + .../providers/rocm/rocm_execution_provider.cc | 5 + .../providers/rocm/rocm_execution_provider.h | 2 + .../core/providers/rocm/rocm_profiler.cc | 239 ++++++++++++ .../core/providers/rocm/rocm_profiler.h | 70 ++++ .../providers/shared_library/provider_api.h | 10 + .../provider_bridge_provider.cc | 10 + .../shared_library/provider_interfaces.h | 6 + .../core/session/provider_bridge_ort.cc | 6 + .../test/framework/inference_session_test.cc | 64 +++- tools/ci_build/amd_hipify.py | 2 + tools/ci_build/build.py | 7 + 20 files changed, 1068 insertions(+), 7 deletions(-) create mode 100644 onnxruntime/core/common/profiler_common.cc create mode 100644 onnxruntime/core/providers/rocm/RoctracerLogger.cc create mode 100644 onnxruntime/core/providers/rocm/RoctracerLogger.h create mode 100644 onnxruntime/core/providers/rocm/ThreadUtil.cc create mode 100644 onnxruntime/core/providers/rocm/ThreadUtil.h create mode 100644 onnxruntime/core/providers/rocm/rocm_profiler.cc create mode 100644 onnxruntime/core/providers/rocm/rocm_profiler.h diff --git a/cmake/CMakeLists.txt b/cmake/CMakeLists.txt index 4cbf3b669b..a8469791d1 100644 --- a/cmake/CMakeLists.txt +++ b/cmake/CMakeLists.txt @@ -194,6 +194,7 @@ option(onnxruntime_PREBUILT_PYTORCH_PATH "Path to pytorch installation dir") option(onnxruntime_EXTERNAL_TRANSFORMER_SRC_PATH "Path to external transformer src dir") option(onnxruntime_ENABLE_CUDA_PROFILING "Enable CUDA kernel profiling" OFF) +option(onnxruntime_ENABLE_ROCM_PROFILING "Enable ROCM kernel profiling" OFF) option(onnxruntime_ENABLE_CPUINFO "Enable cpuinfo" ON) @@ -1930,6 +1931,10 @@ if (onnxruntime_ENABLE_CUDA_PROFILING) add_compile_definitions(ENABLE_CUDA_PROFILING) endif() +if (onnxruntime_ENABLE_ROCM_PROFILING) + add_compile_definitions(ENABLE_ROCM_PROFILING) +endif() + if (onnxruntime_ENABLE_TRAINING) add_compile_definitions(ENABLE_TRAINING) add_compile_definitions(ENABLE_TRAINING_OPS) diff --git a/cmake/onnxruntime_providers.cmake b/cmake/onnxruntime_providers.cmake index d91397cb3c..1d34e493d9 100644 --- a/cmake/onnxruntime_providers.cmake +++ b/cmake/onnxruntime_providers.cmake @@ -1330,7 +1330,8 @@ if (onnxruntime_USE_ROCM) find_library(ROC_BLAS rocblas REQUIRED) find_library(MIOPEN_LIB MIOpen REQUIRED) find_library(RCCL_LIB rccl REQUIRED) - set(ONNXRUNTIME_ROCM_LIBS ${HIP_LIB} ${ROC_BLAS} ${MIOPEN_LIB} ${RCCL_LIB}) + find_library(ROCTRACER_LIB roctracer64 REQUIRED) + set(ONNXRUNTIME_ROCM_LIBS ${HIP_LIB} ${ROC_BLAS} ${MIOPEN_LIB} ${RCCL_LIB} ${ROCTRACER_LIB}) file(GLOB_RECURSE onnxruntime_providers_rocm_cc_srcs CONFIGURE_DEPENDS "${ONNXRUNTIME_ROOT}/core/providers/rocm/*.h" @@ -1451,7 +1452,7 @@ if (onnxruntime_USE_ROCM) add_dependencies(onnxruntime_providers_rocm onnxruntime_providers_shared ${onnxruntime_EXTERNAL_DEPENDENCIES}) target_link_libraries(onnxruntime_providers_rocm PRIVATE ${ONNXRUNTIME_ROCM_LIBS} ${ONNXRUNTIME_PROVIDERS_SHARED} ${ABSEIL_LIBS}) # During transition to separate hipFFT repo, put hipfft/include early - target_include_directories(onnxruntime_providers_rocm PRIVATE ${ONNXRUNTIME_ROOT} ${CMAKE_CURRENT_BINARY_DIR} ${CMAKE_CURRENT_BINARY_DIR}/amdgpu/onnxruntime ${eigen_INCLUDE_DIRS} PUBLIC ${onnxruntime_ROCM_HOME}/hipfft/include ${onnxruntime_ROCM_HOME}/include ${onnxruntime_ROCM_HOME}/hipcub/include ${onnxruntime_ROCM_HOME}/hiprand/include ${onnxruntime_ROCM_HOME}/rocrand/include) + target_include_directories(onnxruntime_providers_rocm PRIVATE ${ONNXRUNTIME_ROOT} ${CMAKE_CURRENT_BINARY_DIR} ${CMAKE_CURRENT_BINARY_DIR}/amdgpu/onnxruntime ${eigen_INCLUDE_DIRS} PUBLIC ${onnxruntime_ROCM_HOME}/hipfft/include ${onnxruntime_ROCM_HOME}/include ${onnxruntime_ROCM_HOME}/hipcub/include ${onnxruntime_ROCM_HOME}/hiprand/include ${onnxruntime_ROCM_HOME}/rocrand/include ${onnxruntime_ROCM_HOME}/roctracer/include) install(DIRECTORY ${PROJECT_SOURCE_DIR}/../include/onnxruntime/core/providers/rocm DESTINATION ${CMAKE_INSTALL_INCLUDEDIR}/onnxruntime/core/providers) set_target_properties(onnxruntime_providers_rocm PROPERTIES LINKER_LANGUAGE CXX) set_target_properties(onnxruntime_providers_rocm PROPERTIES FOLDER "ONNXRuntime") diff --git a/include/onnxruntime/core/common/profiler_common.h b/include/onnxruntime/core/common/profiler_common.h index ec35e111d5..a2f31442b1 100644 --- a/include/onnxruntime/core/common/profiler_common.h +++ b/include/onnxruntime/core/common/profiler_common.h @@ -5,6 +5,7 @@ #include "core/common/common.h" #include +#include namespace onnxruntime { namespace profiling { @@ -13,6 +14,7 @@ enum EventCategory { SESSION_EVENT = 0, NODE_EVENT, KERNEL_EVENT, + API_EVENT, EVENT_CATEGORY_MAX }; @@ -20,7 +22,8 @@ enum EventCategory { static constexpr const char* event_categor_names_[EVENT_CATEGORY_MAX] = { "Session", "Node", - "Kernel"}; + "Kernel", + "Api"}; // Timing record for all events. struct EventRecord { @@ -58,5 +61,9 @@ class EpProfiler { virtual void Stop(uint64_t){}; // called after op stop, accept an id as argument to identify the op }; -} //namespace profiling -} //namespace onnxruntime \ No newline at end of file +// Demangle C++ symbols +std::string demangle(const char* name); +std::string demangle(const std::string& name); + +} // namespace profiling +} // namespace onnxruntime diff --git a/onnxruntime/core/common/profiler_common.cc b/onnxruntime/core/common/profiler_common.cc new file mode 100644 index 0000000000..ee14533b2a --- /dev/null +++ b/onnxruntime/core/common/profiler_common.cc @@ -0,0 +1,53 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +#include "core/common/profiler_common.h" + +#ifndef _MSC_VER +#include +#endif +#include +#include + +namespace onnxruntime { +namespace profiling { + +static constexpr int kMaxSymbolSize = 1024; + +std::string demangle(const char* name) { +#ifndef _MSC_VER + if (!name) { + return ""; + } + + if (strlen(name) > kMaxSymbolSize) { + return name; + } + + int status; + size_t len = 0; + char* demangled = abi::__cxa_demangle(name, nullptr, &len, &status); + if (status != 0) { + return name; + } + std::string res(demangled); + // The returned buffer must be freed! + free(demangled); + return res; +#else + // TODO(anyone): demangling on Windows + if (!name) { + return ""; + } else { + return name; + } +#endif +} + +std::string demangle(const std::string& name) { + return demangle(name.c_str()); +} + +} // namespace profiling +} // namespace onnxruntime + diff --git a/onnxruntime/core/providers/cuda/cuda_profiler.cc b/onnxruntime/core/providers/cuda/cuda_profiler.cc index adf771fb23..817816f43b 100644 --- a/onnxruntime/core/providers/cuda/cuda_profiler.cc +++ b/onnxruntime/core/providers/cuda/cuda_profiler.cc @@ -7,6 +7,8 @@ #include #include +#include "core/common/profiler_common.h" + namespace onnxruntime { namespace profiling { @@ -126,7 +128,7 @@ void CudaProfiler::EndProfiling(TimePoint start_time, Events& events) { {"block_y", std::to_string(stat.block_y_)}, {"block_z", std::to_string(stat.block_z_)}}; EventRecord event{ - KEVENT, -1, -1, stat.name_, DUR(profiling_start, stat.start_), DUR(stat.start_, stat.stop_), {args.begin(), args.end()}}; + KEVENT, -1, -1, demangle(stat.name_), DUR(profiling_start, stat.start_), DUR(stat.start_, stat.stop_), {args.begin(), args.end()}}; auto ts = id_map[stat.correlation_id]; if (event_map.find(ts) == event_map.end()) { event_map.insert({ts, {event}}); diff --git a/onnxruntime/core/providers/rocm/RoctracerLogger.cc b/onnxruntime/core/providers/rocm/RoctracerLogger.cc new file mode 100644 index 0000000000..f6bf3ce2ed --- /dev/null +++ b/onnxruntime/core/providers/rocm/RoctracerLogger.cc @@ -0,0 +1,351 @@ +#include "RoctracerLogger.h" + +#include +#include +#include + +#include "ThreadUtil.h" + +typedef uint64_t timestamp_t; + +static timestamp_t timespec_to_ns(const timespec& time) { + return ((timestamp_t)time.tv_sec * 1000000000) + time.tv_nsec; + } + +//using namespace std::chrono; + +constexpr size_t kBufSize(2 * 1024 * 1024); + +RoctracerLogger& RoctracerLogger::singleton() { + static RoctracerLogger instance; + return instance; +} + +RoctracerLogger::RoctracerLogger() { + gpuTraceBuffers_ = std::make_unique>(); +} + +RoctracerLogger::~RoctracerLogger() { + stopLogging(); + endTracing(); +} + +namespace { + thread_local std::deque t_externalIds[RoctracerLogger::CorrelationDomain::size]; +} + +void RoctracerLogger::pushCorrelationID(uint64_t id, CorrelationDomain type) { + if (!singleton().externalCorrelationEnabled_) { + return; + } + t_externalIds[type].push_back(id); +} + +void RoctracerLogger::popCorrelationID(CorrelationDomain type) { + if (!singleton().externalCorrelationEnabled_) { + return; + } + t_externalIds[type].pop_back(); +} + +void RoctracerLogger::clearLogs() { + rows_.clear(); + kernelRows_.clear(); + copyRows_.clear(); + mallocRows_.clear(); + gpuTraceBuffers_->clear(); + for (int i = 0; i < CorrelationDomain::size; ++i) { + externalCorrelations_[i].clear(); + } +} + +void RoctracerLogger::api_callback(uint32_t domain, uint32_t cid, const void* callback_data, void* arg) { + RoctracerLogger *dis = &singleton(); + + if (domain == ACTIVITY_DOMAIN_HIP_API && dis->loggedIds_.contains(cid)) { + const hip_api_data_t* data = (const hip_api_data_t*)(callback_data); + + // Pack callbacks into row structures + + thread_local timespec timestamp; + + if (data->phase == ACTIVITY_API_PHASE_ENTER) { + clock_gettime(CLOCK_MONOTONIC, ×tamp); // record proper clock + } else { // (data->phase == ACTIVITY_API_PHASE_EXIT) + timespec endTime; + timespec startTime { timestamp }; + clock_gettime(CLOCK_MONOTONIC, &endTime); // record proper clock + + switch (cid) { + case HIP_API_ID_hipLaunchKernel: + case HIP_API_ID_hipExtLaunchKernel: + case HIP_API_ID_hipLaunchCooperativeKernel: // Should work here + { + auto &args = data->args.hipLaunchKernel; + dis->kernelRows_.emplace_back(data->correlation_id, + domain, + cid, + processId(), + systemThreadId(), + timespec_to_ns(startTime), + timespec_to_ns(endTime), + args.function_address, + nullptr, + args.numBlocks.x, + args.numBlocks.y, + args.numBlocks.z, + args.dimBlocks.x, + args.dimBlocks.y, + args.dimBlocks.z, + args.sharedMemBytes, + args.stream + ); + } + break; + case HIP_API_ID_hipHccModuleLaunchKernel: + case HIP_API_ID_hipModuleLaunchKernel: + case HIP_API_ID_hipExtModuleLaunchKernel: + { + auto &args = data->args.hipModuleLaunchKernel; + dis->kernelRows_.emplace_back(data->correlation_id, + domain, + cid, + processId(), + systemThreadId(), + timespec_to_ns(startTime), + timespec_to_ns(endTime), + nullptr, + args.f, + args.gridDimX, + args.gridDimY, + args.gridDimZ, + args.blockDimX, + args.blockDimY, + args.blockDimZ, + args.sharedMemBytes, + args.stream + ); + } + break; + case HIP_API_ID_hipLaunchCooperativeKernelMultiDevice: + case HIP_API_ID_hipExtLaunchMultiKernelMultiDevice: +#if 0 + { + auto &args = data->args.hipLaunchCooperativeKernelMultiDevice.launchParamsList__val; + dis->kernelRows_.emplace_back(data->correlation_id, + domain, + cid, + processId(), + systemThreadId(), + timespec_to_ns(startTime), + timespec_to_ns(endTime), + args.function_address, + nullptr, + args.numBlocks.x, + args.numBlocks.y, + args.numBlocks.z, + args.dimBlocks.x, + args.dimBlocks.y, + args.dimBlocks.z, + args.sharedMemBytes, + args.stream + ); + } +#endif + break; + case HIP_API_ID_hipMalloc: + dis->mallocRows_.emplace_back(data->correlation_id, + domain, + cid, + processId(), + systemThreadId(), + timespec_to_ns(startTime), + timespec_to_ns(endTime), + data->args.hipMalloc.ptr__val, + data->args.hipMalloc.size + ); + break; + case HIP_API_ID_hipFree: + dis->mallocRows_.emplace_back(data->correlation_id, + domain, + cid, + processId(), + systemThreadId(), + timespec_to_ns(startTime), + timespec_to_ns(endTime), + data->args.hipFree.ptr, + 0 + ); + break; + case HIP_API_ID_hipMemcpy: + { + auto &args = data->args.hipMemcpy; + dis->copyRows_.emplace_back(data->correlation_id, + domain, + cid, + processId(), + systemThreadId(), + timespec_to_ns(startTime), + timespec_to_ns(endTime), + args.src, + args.dst, + args.sizeBytes, + args.kind, + static_cast(0) // use placeholder? + ); + } + break; + case HIP_API_ID_hipMemcpyAsync: + case HIP_API_ID_hipMemcpyWithStream: + { + auto &args = data->args.hipMemcpyAsync; + dis->copyRows_.emplace_back(data->correlation_id, + domain, + cid, + processId(), + systemThreadId(), + timespec_to_ns(startTime), + timespec_to_ns(endTime), + args.src, + args.dst, + args.sizeBytes, + args.kind, + args.stream + ); + } + break; + default: + dis->rows_.emplace_back(data->correlation_id, + domain, + cid, + processId(), + systemThreadId(), + timespec_to_ns(startTime), + timespec_to_ns(endTime) + ); + break; + } // switch + // External correlation + for (int it = CorrelationDomain::begin; it < CorrelationDomain::end; ++it) { + if (t_externalIds[it].size() > 0) { + dis->externalCorrelations_[it][data->correlation_id] = t_externalIds[it].back(); + } + } + } // phase exit + } +} + +void RoctracerLogger::activity_callback(const char* begin, const char* end, void* arg) +{ + size_t size = end - begin; + uint8_t *buffer = (uint8_t*) malloc(size); + auto &gpuTraceBuffers = singleton().gpuTraceBuffers_; + memcpy(buffer, begin, size); + gpuTraceBuffers->emplace_back(buffer, size); +} + +void RoctracerLogger::startLogging() { + if (!registered_) { + roctracer_set_properties(ACTIVITY_DOMAIN_HIP_API, nullptr); // Magic encantation + + // Set some api calls to ignore + loggedIds_.setInvertMode(true); // Omit the specified api + loggedIds_.add("hipGetDevice"); + loggedIds_.add("hipSetDevice"); + loggedIds_.add("hipGetLastError"); + loggedIds_.add("__hipPushCallConfiguration"); + loggedIds_.add("__hipPopCallConfiguration"); + loggedIds_.add("hipCtxSetCurrent"); + loggedIds_.add("hipEventRecord"); + loggedIds_.add("hipEventQuery"); + loggedIds_.add("hipGetDeviceProperties"); + loggedIds_.add("hipPeekAtLastError"); + loggedIds_.add("hipModuleGetFunction"); + loggedIds_.add("hipEventCreateWithFlags"); + + // Enable API callbacks + if (loggedIds_.invertMode() == true) { + // exclusion list - enable entire domain and turn off things in list + roctracer_enable_domain_callback(ACTIVITY_DOMAIN_HIP_API, api_callback, nullptr); + const std::unordered_map &filter = loggedIds_.filterList(); + for (auto it = filter.begin(); it != filter.end(); ++it) { + roctracer_disable_op_callback(ACTIVITY_DOMAIN_HIP_API, it->first); + } + } + else { + // inclusion list - only enable things in the list + const std::unordered_map &filter = loggedIds_.filterList(); + roctracer_disable_domain_callback(ACTIVITY_DOMAIN_HIP_API); + for (auto it = filter.begin(); it != filter.end(); ++it) { + roctracer_enable_op_callback(ACTIVITY_DOMAIN_HIP_API, it->first, api_callback, nullptr); + } + } + //roctracer_enable_domain_callback(ACTIVITY_DOMAIN_ROCTX, api_callback, nullptr); + + // Allocate default tracing pool + roctracer_properties_t properties; + memset(&properties, 0, sizeof(roctracer_properties_t)); + properties.buffer_size = 0x1000; + roctracer_open_pool(&properties); + + // Enable async op collection + roctracer_properties_t hcc_cb_properties; + memset(&hcc_cb_properties, 0, sizeof(roctracer_properties_t)); + hcc_cb_properties.buffer_size = 0x4000; + hcc_cb_properties.buffer_callback_fun = activity_callback; + roctracer_open_pool_expl(&hcc_cb_properties, &hccPool_); + roctracer_enable_domain_activity_expl(ACTIVITY_DOMAIN_HCC_OPS, hccPool_); + + registered_ = true; + } + + externalCorrelationEnabled_ = true; + roctracer_start(); +} + +void RoctracerLogger::stopLogging() { + roctracer_stop(); + roctracer_flush_activity_expl(hccPool_); +} + +void RoctracerLogger::endTracing() { + if (registered_ == true) { + roctracer_disable_domain_callback(ACTIVITY_DOMAIN_HIP_API); + //roctracer_disable_domain_callback(ACTIVITY_DOMAIN_ROCTX); + + roctracer_disable_domain_activity(ACTIVITY_DOMAIN_HCC_OPS); + roctracer_close_pool_expl(hccPool_); + } +} + + +ApiIdList::ApiIdList() +: invert_(true) +{ +} + +void ApiIdList::add(const std::string &apiName) +{ + uint32_t cid = 0; + if (roctracer_op_code(ACTIVITY_DOMAIN_HIP_API, apiName.c_str(), &cid, nullptr) == ROCTRACER_STATUS_SUCCESS) { + filter_[cid] = 1; + } +} +void ApiIdList::remove(const std::string &apiName) +{ + uint32_t cid = 0; + if (roctracer_op_code(ACTIVITY_DOMAIN_HIP_API, apiName.c_str(), &cid, nullptr) == ROCTRACER_STATUS_SUCCESS) { + filter_.erase(cid); + } +} + +bool ApiIdList::loadUserPrefs() +{ + // placeholder + return false; +} +bool ApiIdList::contains(uint32_t apiId) +{ + return (filter_.find(apiId) != filter_.end()) ? !invert_ : invert_; // XOR +} + diff --git a/onnxruntime/core/providers/rocm/RoctracerLogger.h b/onnxruntime/core/providers/rocm/RoctracerLogger.h new file mode 100644 index 0000000000..81385940f7 --- /dev/null +++ b/onnxruntime/core/providers/rocm/RoctracerLogger.h @@ -0,0 +1,170 @@ +#pragma once + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include +#include +#include +#include +#include + + +namespace onnxruntime{ +namespace profiling { +class RocmProfiler; +} +} + +class RoctracerActivityBuffer { +public: + // data must be allocated using malloc. + // Ownership is transferred to this object. + RoctracerActivityBuffer(uint8_t* data, size_t validSize) + : data_(data), validSize_(validSize) {} + + ~RoctracerActivityBuffer() { + free(data_); + } + + // Allocated by malloc + uint8_t* data_{nullptr}; + + // Number of bytes used + size_t validSize_; +}; + + +class ApiIdList +{ +public: + ApiIdList(); + bool invertMode() { return invert_; } + void setInvertMode(bool invert) { invert_ = invert; } + void add(const std::string &apiName); + void remove(const std::string &apiName); + bool loadUserPrefs(); + bool contains(uint32_t apiId); + const std::unordered_map &filterList() { return filter_; } + +private: + std::unordered_map filter_; + bool invert_; +}; + +struct roctracerRow { + roctracerRow(uint64_t id, uint32_t domain, uint32_t cid, uint32_t pid + , uint32_t tid, uint64_t begin, uint64_t end) + : id(id), domain(domain), cid(cid), pid(pid), tid(tid), begin(begin), end(end) {} + uint64_t id; // correlation_id + uint32_t domain; + uint32_t cid; + uint32_t pid; + uint32_t tid; + uint64_t begin; + uint64_t end; +}; + +struct kernelRow : public roctracerRow { + kernelRow(uint64_t id, uint32_t domain, uint32_t cid, uint32_t pid + , uint32_t tid, uint64_t begin, uint64_t end + , const void *faddr, hipFunction_t function + , unsigned int gx, unsigned int gy, unsigned int gz + , unsigned int wx, unsigned int wy, unsigned int wz + , size_t gss, hipStream_t stream) + : roctracerRow(id, domain, cid, pid, tid, begin, end), functionAddr(faddr) + , function(function), gridX(gx), gridY(gy), gridZ(gz) + , workgroupX(wx), workgroupY(wy), workgroupZ(wz), groupSegmentSize(gss) + , stream(stream) {} + const void* functionAddr; + hipFunction_t function; + unsigned int gridX; + unsigned int gridY; + unsigned int gridZ; + unsigned int workgroupX; + unsigned int workgroupY; + unsigned int workgroupZ; + size_t groupSegmentSize; + hipStream_t stream; +}; + +struct copyRow : public roctracerRow { + copyRow(uint64_t id, uint32_t domain, uint32_t cid, uint32_t pid + , uint32_t tid, uint64_t begin, uint64_t end + , const void* src, const void *dst, size_t size, hipMemcpyKind kind + , hipStream_t stream) + : roctracerRow(id, domain, cid, pid, tid, begin, end) + , src(src), dst(dst), size(size), kind(kind), stream(stream) {} + const void *src; + const void *dst; + size_t size; + hipMemcpyKind kind; + hipStream_t stream; +}; + +struct mallocRow : public roctracerRow { + mallocRow(uint64_t id, uint32_t domain, uint32_t cid, uint32_t pid + , uint32_t tid, uint64_t begin, uint64_t end + , const void* ptr, size_t size) + : roctracerRow(id, domain, cid, pid, tid, begin, end) + , ptr(ptr), size(size) {} + const void *ptr; + size_t size; +}; + + +class RoctracerLogger { + public: + enum CorrelationDomain { + begin, + Default = begin, + Domain0 = begin, + Domain1, + end, + size = end + }; + + RoctracerLogger(); + RoctracerLogger(const RoctracerLogger&) = delete; + RoctracerLogger& operator=(const RoctracerLogger&) = delete; + + virtual ~RoctracerLogger(); + + static RoctracerLogger& singleton(); + + static void pushCorrelationID(uint64_t id, CorrelationDomain type); + static void popCorrelationID(CorrelationDomain type); + + void startLogging(); + void stopLogging(); + void clearLogs(); + + private: + bool registered_{false}; + void endTracing(); + + roctracer_pool_t *hccPool_{NULL}; + static void api_callback(uint32_t domain, uint32_t cid, const void* callback_data, void* arg); + static void activity_callback(const char* begin, const char* end, void* arg); + + ApiIdList loggedIds_; + + // Api callback data + std::deque rows_; + std::deque kernelRows_; + std::deque copyRows_; + std::deque mallocRows_; + std::map externalCorrelations_[CorrelationDomain::size]; // tracer -> ext + + std::unique_ptr> gpuTraceBuffers_; + bool externalCorrelationEnabled_{true}; + + friend class onnxruntime::profiling::RocmProfiler; +}; diff --git a/onnxruntime/core/providers/rocm/ThreadUtil.cc b/onnxruntime/core/providers/rocm/ThreadUtil.cc new file mode 100644 index 0000000000..2ae95256ce --- /dev/null +++ b/onnxruntime/core/providers/rocm/ThreadUtil.cc @@ -0,0 +1,37 @@ +#include "ThreadUtil.h" + +#include "core/common/logging/logging.h" + +namespace onnxruntime { + +namespace profiling { + +namespace { +thread_local int32_t _pid = 0; +thread_local int32_t _tid = 0; +thread_local int32_t _sysTid = 0; +} + +int32_t processId() { + if (!_pid) { + _pid = onnxruntime::logging::GetProcessId(); + } + return _pid; +} + +int32_t systemThreadId() { + if (!_sysTid) { + _sysTid = onnxruntime::logging::GetThreadId(); + } + return _sysTid; +} + +int32_t threadId() { + if (!_tid) { + _tid = 0; //defeat for now + } + return _tid; +} + +} // namespace profiling +} // namespace onnxruntime diff --git a/onnxruntime/core/providers/rocm/ThreadUtil.h b/onnxruntime/core/providers/rocm/ThreadUtil.h new file mode 100644 index 0000000000..2ec6aac722 --- /dev/null +++ b/onnxruntime/core/providers/rocm/ThreadUtil.h @@ -0,0 +1,16 @@ +#pragma once + +#include + +namespace onnxruntime { + +namespace profiling { + +int32_t systemThreadId(); +int32_t threadId(); +int32_t processId(); + +} +} + +using namespace onnxruntime::profiling; diff --git a/onnxruntime/core/providers/rocm/rocm_execution_provider.cc b/onnxruntime/core/providers/rocm/rocm_execution_provider.cc index 10376f4ece..20e1ac4f38 100644 --- a/onnxruntime/core/providers/rocm/rocm_execution_provider.cc +++ b/onnxruntime/core/providers/rocm/rocm_execution_provider.cc @@ -8,6 +8,7 @@ #include "core/providers/rocm/rocm_fence.h" #include "core/providers/rocm/rocm_fwd.h" #include "core/providers/rocm/gpu_data_transfer.h" +#include "core/providers/rocm/rocm_profiler.h" #ifndef DISABLE_CONTRIB_OPS #include "contrib_ops/rocm/rocm_contrib_kernels.h" @@ -214,6 +215,10 @@ ROCMExecutionProvider::~ROCMExecutionProvider() { } } +std::unique_ptr ROCMExecutionProvider::GetProfiler() { + return std::make_unique(); +} + ROCMExecutionProvider::PerThreadContext& ROCMExecutionProvider::GetPerThreadContext() const { const auto& per_thread_context_cache = PerThreadContextCache(); diff --git a/onnxruntime/core/providers/rocm/rocm_execution_provider.h b/onnxruntime/core/providers/rocm/rocm_execution_provider.h index 50ac9d4982..e01a6f6d90 100644 --- a/onnxruntime/core/providers/rocm/rocm_execution_provider.h +++ b/onnxruntime/core/providers/rocm/rocm_execution_provider.h @@ -93,6 +93,8 @@ class ROCMExecutionProvider : public IExecutionProvider { static AllocatorPtr CreateRocmAllocator(OrtDevice::DeviceId device_id, size_t rocm_mem_limit, ArenaExtendStrategy arena_extend_strategy, ROCMExecutionProviderExternalAllocatorInfo external_alloc_info, OrtArenaCfg* arena_cfg); + std::unique_ptr GetProfiler() override; + private: ROCMExecutionProviderInfo info_; hipDeviceProp_t device_prop_; diff --git a/onnxruntime/core/providers/rocm/rocm_profiler.cc b/onnxruntime/core/providers/rocm/rocm_profiler.cc new file mode 100644 index 0000000000..cb808c364e --- /dev/null +++ b/onnxruntime/core/providers/rocm/rocm_profiler.cc @@ -0,0 +1,239 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. +#if defined(USE_ROCM) && defined(ENABLE_ROCM_PROFILING) + +#include +#include + +#include "rocm_profiler.h" +#include "RoctracerLogger.h" +#include "core/common/profiler_common.h" + +#define BSIZE 4096 + +typedef uint64_t timestamp_t; +static timestamp_t timespec_to_ns(const timespec& time) { + return ((timestamp_t)time.tv_sec * 1000000000) + time.tv_nsec; +} + +namespace onnxruntime { + +namespace profiling { + +RocmProfiler::RocmProfiler() +: d(&RoctracerLogger::singleton()) +{ +} + +RocmProfiler::~RocmProfiler() +{ +} + +bool RocmProfiler::StartProfiling() +{ + d->clearLogs(); + d->startLogging(); + return true; +} + +void RocmProfiler::EndProfiling(TimePoint start_time, Events& events) +{ + d->stopLogging(); + + std::map> event_map; + std::map kernelLaunches; // correlation id -> kernel info + std::map copyLaunches; // correlation id -> copy info + + // Generate EventRecords + int64_t profiling_start = std::chrono::duration_cast(start_time.time_since_epoch()).count(); + + // Wrong clock again - all the cool kids are doing it + timespec t0, t1, t00; + clock_gettime(CLOCK_REALTIME, &t0); + clock_gettime(CLOCK_MONOTONIC, &t1); + clock_gettime(CLOCK_REALTIME, &t00); + const uint64_t toffset = (timespec_to_ns(t0) >> 1) + (timespec_to_ns(t00) >> 1) - timespec_to_ns(t1); + profiling_start = profiling_start - toffset; + + char buff[BSIZE]; + + for (auto &item : d->rows_) { + std::initializer_list> args = {{"op_name", ""}}; + addEventRecord(item, profiling_start, args, event_map); + } + + for (auto &item : d->mallocRows_) { + snprintf(buff, BSIZE, "%p", item.ptr); + const std::string arg_ptr{buff}; + + std::initializer_list> args = {{"op_name", ""}, + {"ptr", arg_ptr}, + {"size", std::to_string(item.size)} + }; + addEventRecord(item, profiling_start, args, event_map); + } + + for (auto &item : d->copyRows_) { + snprintf(buff, BSIZE, "%p", item.stream); + const std::string arg_stream{buff}; + snprintf(buff, BSIZE, "%p", item.src); + const std::string arg_src{buff}; + snprintf(buff, BSIZE, "%p", item.dst); + const std::string arg_dst{buff}; + + std::initializer_list> args = {{"op_name", ""}, + {"stream", arg_stream}, + {"src", arg_src}, + {"dst", arg_dst}, + {"size", std::to_string(item.size)}, + {"kind", std::to_string(item.kind)}, + }; + addEventRecord(item, profiling_start, args, event_map); + copyLaunches[item.id] = &item; + } + + for (auto &item : d->kernelRows_) { + snprintf(buff, BSIZE, "%p", item.stream); + const std::string arg_stream{buff}; + if (item.functionAddr) + snprintf(buff, BSIZE, "%s", demangle(hipKernelNameRefByPtr(item.functionAddr, item.stream)).c_str()); + else if (item.function) + snprintf(buff, BSIZE, "%s", demangle(hipKernelNameRef(item.function)).c_str()); + else + snprintf(buff, BSIZE, " "); + const std::string arg_kernel{buff}; + + std::initializer_list> args = {{"op_name", ""}, + {"stream", arg_stream}, + {"kernel", arg_kernel}, + {"grid_x", std::to_string(item.gridX)}, + {"grid_y", std::to_string(item.gridY)}, + {"grid_z", std::to_string(item.gridZ)}, + {"block_x", std::to_string(item.workgroupX)}, + {"block_y", std::to_string(item.workgroupY)}, + {"block_z", std::to_string(item.workgroupZ)}, + }; + addEventRecord(item, profiling_start, args, event_map); + kernelLaunches[item.id] = &item; + } + + // Async Ops - e.g. "Kernel" + + for (auto& buffer : *d->gpuTraceBuffers_) { + const roctracer_record_t* record = (const roctracer_record_t*)(buffer.data_); + const roctracer_record_t* end_record = (const roctracer_record_t*)(buffer.data_ + buffer.validSize_); + while (record < end_record) { + std::unordered_map args; + std::string name = roctracer_op_string(record->domain, record->op, record->kind); + + // Add kernel args if we have them + auto kit = kernelLaunches.find(record->correlation_id); + if (kit != kernelLaunches.end()) { + auto &item = *(*kit).second; + snprintf(buff, BSIZE, "%p", item.stream); + args["stream"] = std::string(buff); + args["grid_x"] = std::to_string(item.gridX); + args["grid_y"] = std::to_string(item.gridY); + args["grid_z"] = std::to_string(item.gridZ); + args["block_x"] = std::to_string(item.workgroupX); + args["block_y"] = std::to_string(item.workgroupY); + args["block_z"] = std::to_string(item.workgroupZ); + if (item.functionAddr != nullptr) { + name = demangle(hipKernelNameRefByPtr(item.functionAddr, item.stream)).c_str(); + } + else if (item.function != nullptr) { + name = demangle(hipKernelNameRef(item.function)).c_str(); + } + } + + // Add copy args if we have them + auto cit = copyLaunches.find(record->correlation_id); + if (cit != copyLaunches.end()) { + auto &item = *(*cit).second; + snprintf(buff, BSIZE, "%p", item.stream); + args["stream"] = std::string(buff); + snprintf(buff, BSIZE, "%p", item.src); + args["dst"] = std::string(buff); + snprintf(buff, BSIZE, "%p", item.dst); + args["src"] = std::string(buff); + args["size"] = std::to_string(item.size); + args["kind"] = std::to_string(item.kind); + } + + EventRecord event{ + onnxruntime::profiling::KERNEL_EVENT, + static_cast(record->device_id), + static_cast(record->queue_id), + name, + static_cast((record->begin_ns - profiling_start) / 1000), + static_cast((record->end_ns - record->begin_ns) / 1000), + std::move(args)}; + + // FIXME: deal with missing ext correlation + auto extId = d->externalCorrelations_[RoctracerLogger::CorrelationDomain::Default][record->correlation_id]; + if (event_map.find(extId) == event_map.end()) { + event_map.insert({extId, {event}}); + } + else { + event_map[extId].push_back(std::move(event)); + } + + roctracer_next_record(record, &record); + } + } + + // General + auto insert_iter = events.begin(); + for (auto& map_iter : event_map) { + auto ts = static_cast(map_iter.first); + while (insert_iter != events.end() && insert_iter->ts < ts) { + insert_iter++; + } + if (insert_iter != events.end() && insert_iter->ts == ts) { + for (auto& evt_iter : map_iter.second) { + evt_iter.args["op_name"] = insert_iter->args["op_name"]; + } + insert_iter = events.insert(insert_iter+1, map_iter.second.begin(), map_iter.second.end()); + } else { + insert_iter = events.insert(insert_iter, map_iter.second.begin(), map_iter.second.end()); + } + while (insert_iter != events.end() && insert_iter->cat == EventCategory::KERNEL_EVENT) { + insert_iter++; + } + } +} + +void RocmProfiler::Start(uint64_t id) +{ + d->pushCorrelationID(id, RoctracerLogger::CorrelationDomain::Default); +} + +void RocmProfiler::Stop(uint64_t) +{ + d->popCorrelationID(RoctracerLogger::CorrelationDomain::Default); +} + + +void RocmProfiler::addEventRecord(const roctracerRow &item, int64_t pstart, const std::initializer_list> &args, std::map> &event_map) +{ + EventRecord event{onnxruntime::profiling::API_EVENT, + static_cast(item.pid), + static_cast(item.tid), + std::string(roctracer_op_string(ACTIVITY_DOMAIN_HIP_API, item.cid, 0)), + static_cast((item.begin - pstart) / 1000), + static_cast((item.end - item.begin) / 1000), + {args.begin(), args.end()}}; + + // FIXME: deal with missing ext correlation + auto extId = d->externalCorrelations_[RoctracerLogger::CorrelationDomain::Default][item.id]; + if (event_map.find(extId) == event_map.end()) { + event_map.insert({extId, {event}}); + } + else { + event_map[extId].push_back(std::move(event)); + } +} + +} // namespace profiling +} // namespace onnxruntime +#endif diff --git a/onnxruntime/core/providers/rocm/rocm_profiler.h b/onnxruntime/core/providers/rocm/rocm_profiler.h new file mode 100644 index 0000000000..593436a701 --- /dev/null +++ b/onnxruntime/core/providers/rocm/rocm_profiler.h @@ -0,0 +1,70 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. +#include +#include + +#include "core/common/profiler_common.h" + +#if defined(USE_ROCM) && defined(ENABLE_ROCM_PROFILING) + +class RoctracerLogger; +class roctracerRow; + +namespace onnxruntime { + +namespace profiling { + +using Events = std::vector; + +class RocmProfiler final : public EpProfiler { + public: + RocmProfiler(); + RocmProfiler(const RocmProfiler&) = delete; + RocmProfiler& operator=(const RocmProfiler&) = delete; +#if 0 + RocmProfiler(RocmProfiler&& rocm_profiler) noexcept { + initialized_ = rocm_profiler.initialized_; + rocm_profiler.initialized_ = false; + } + RocmProfiler& operator=(RocmProfiler&& rocm_profiler) noexcept { + initialized_ = rocm_profiler.initialized_; + rocm_profiler.initialized_ = false; + return *this; + } +#endif + ~RocmProfiler(); + bool StartProfiling() override; + void EndProfiling(TimePoint start_time, Events& events) override; + void Start(uint64_t) override; + void Stop(uint64_t) override; + + private: + void addEventRecord(const roctracerRow &item, int64_t pstart, const std::initializer_list> &args, std::map> &event_map); + + RoctracerLogger *d; +}; + +} // namespace profiling +} // namespace onnxruntime + +#else + +namespace onnxruntime { + +namespace profiling { + +class RocmProfiler final : public EpProfiler { + public: + bool StartProfiling() override { return true; } + void EndProfiling(TimePoint, Events&) override{}; + void Start(uint64_t) override{}; + void Stop(uint64_t) override{}; +}; + +} +} + + + + +#endif diff --git a/onnxruntime/core/providers/shared_library/provider_api.h b/onnxruntime/core/providers/shared_library/provider_api.h index 7caaa25cb4..a7fcfe8901 100644 --- a/onnxruntime/core/providers/shared_library/provider_api.h +++ b/onnxruntime/core/providers/shared_library/provider_api.h @@ -259,8 +259,18 @@ std::unordered_set GetCpuPreferredNodes(const onnxruntime::GraphViewe std::string GetEnvironmentVar(const std::string& var_name); +namespace profiling { + + std::string demangle(const char* name); + std::string demangle(const std::string& name); + +}; + namespace logging { + unsigned int GetThreadId(); + unsigned int GetProcessId(); + struct Category { static const char* onnxruntime; ///< General output }; diff --git a/onnxruntime/core/providers/shared_library/provider_bridge_provider.cc b/onnxruntime/core/providers/shared_library/provider_bridge_provider.cc index e78d5696f8..0ad2631cec 100644 --- a/onnxruntime/core/providers/shared_library/provider_bridge_provider.cc +++ b/onnxruntime/core/providers/shared_library/provider_bridge_provider.cc @@ -348,8 +348,18 @@ std::unordered_set GetCpuPreferredNodes(const onnxruntime::GraphViewe return g_host->GetCpuPreferredNodes(graph, provider_type, kernel_registries, tentative_nodes); } +namespace profiling { + +std::string demangle(const char* name) { return g_host->demangle(name); } +std::string demangle(const std::string& name) { return g_host->demangle(name); } + +} // namespace profiling + namespace logging { +unsigned int GetThreadId() { return g_host->GetThreadId(); } +unsigned int GetProcessId() { return g_host->GetProcessId(); } + const char* Category::onnxruntime = "onnxruntime"; } // namespace logging diff --git a/onnxruntime/core/providers/shared_library/provider_interfaces.h b/onnxruntime/core/providers/shared_library/provider_interfaces.h index 17669b78d8..f91ad79a31 100644 --- a/onnxruntime/core/providers/shared_library/provider_interfaces.h +++ b/onnxruntime/core/providers/shared_library/provider_interfaces.h @@ -147,6 +147,12 @@ struct ProviderHost { virtual void* CPUAllocator__Alloc(CPUAllocator* p, size_t size) = 0; virtual void CPUAllocator__Free(CPUAllocator* p, void* allocation) = 0; + virtual unsigned int GetThreadId() = 0; + virtual unsigned int GetProcessId() = 0; + + virtual std::string demangle(const char* name) = 0; + virtual std::string demangle(const std::string& name) = 0; + #ifdef USE_CUDA virtual std::unique_ptr CreateCUDAAllocator(int16_t device_id, const char* name) = 0; virtual std::unique_ptr CreateCUDAPinnedAllocator(int16_t device_id, const char* name) = 0; diff --git a/onnxruntime/core/session/provider_bridge_ort.cc b/onnxruntime/core/session/provider_bridge_ort.cc index 32ff604ca0..0e4ee759ff 100644 --- a/onnxruntime/core/session/provider_bridge_ort.cc +++ b/onnxruntime/core/session/provider_bridge_ort.cc @@ -215,6 +215,12 @@ struct ProviderHostImpl : ProviderHost { std::string GetEnvironmentVar(const std::string& var_name) override { return Env::Default().GetEnvironmentVar(var_name); } + unsigned int GetThreadId() override { return onnxruntime::logging::GetThreadId(); } + unsigned int GetProcessId() override { return onnxruntime::logging::GetProcessId(); } + + std::string demangle(const char* name) override { return onnxruntime::profiling::demangle(name); } + std::string demangle(const std::string& name) override { return onnxruntime::profiling::demangle(name); } + std::unordered_set GetCpuPreferredNodes(const onnxruntime::GraphViewer& graph, const std::string& provider_type, gsl::span kernel_registries, diff --git a/onnxruntime/test/framework/inference_session_test.cc b/onnxruntime/test/framework/inference_session_test.cc index bb6dda9ffd..9f0b639588 100644 --- a/onnxruntime/test/framework/inference_session_test.cc +++ b/onnxruntime/test/framework/inference_session_test.cc @@ -668,11 +668,73 @@ TEST(InferenceSessionTests, CheckRunProfilerWithSessionOptions) { } } -#if defined(USE_CUDA) && defined(ENABLE_CUDA_PROFILING) +#if (defined(USE_CUDA) && defined(ENABLE_CUDA_PROFILING)) || (defined(USE_ROCM) && defined(ENABLE_ROCM_PROFILING)) ASSERT_TRUE(has_kernel_info); #endif } +TEST(InferenceSessionTests, CheckRunProfilerWithSessionOptions2) { + SessionOptions so; + + so.session_logid = "CheckRunProfiler"; + so.enable_profiling = true; + so.profile_file_prefix = ORT_TSTR("onnxprofile_profile_test"); + + InferenceSession session_object(so, GetEnvironment()); +#ifdef USE_CUDA + ASSERT_STATUS_OK(session_object.RegisterExecutionProvider(DefaultCudaExecutionProvider())); +#endif +#ifdef USE_ROCM + ASSERT_STATUS_OK(session_object.RegisterExecutionProvider(DefaultRocmExecutionProvider())); +#endif + ASSERT_STATUS_OK(session_object.Load(MODEL_URI)); + ASSERT_STATUS_OK(session_object.Initialize()); + + RunOptions run_options; + run_options.run_tag = "RunTag"; + + RunModel(session_object, run_options); + std::string profile_file = session_object.EndProfiling(); + + std::ifstream profile(profile_file); + ASSERT_TRUE(profile); + std::string line; + std::vector lines; + + while (std::getline(profile, line)) { + lines.push_back(line); + } + + auto size = lines.size(); + ASSERT_TRUE(size > 1); + ASSERT_TRUE(lines[0].find("[") != string::npos); + ASSERT_TRUE(lines[1].find("model_loading_uri") != string::npos); + ASSERT_TRUE(lines[size - 1].find("]") != string::npos); + std::vector tags = {"pid", "dur", "ts", "ph", "X", "name", "args"}; + + bool has_api_info = false; + for (size_t i = 1; i < size - 1; ++i) { + for (auto& s : tags) { + ASSERT_TRUE(lines[i].find(s) != string::npos); +#ifdef USE_CUDA + has_api_info = has_api_info || lines[i].find("Api") != string::npos && + lines[i].find("cudaLaunch") != string::npos; +#endif +#ifdef USE_ROCM + has_api_info = has_api_info || lines[i].find("Api") != string::npos && + lines[i].find("hipLaunch") != string::npos; +#endif + } + } + +#if defined(USE_ROCM) && defined(ENABLE_ROCM_PROFILING) + ASSERT_TRUE(has_api_info); +#else + ASSERT_TRUE(has_api_info || true); +#endif +} + + TEST(InferenceSessionTests, CheckRunProfilerWithStartProfile) { SessionOptions so; diff --git a/tools/ci_build/amd_hipify.py b/tools/ci_build/amd_hipify.py index 0ff9e221fe..2c5a9469c9 100644 --- a/tools/ci_build/amd_hipify.py +++ b/tools/ci_build/amd_hipify.py @@ -129,6 +129,8 @@ provider_excluded_files = [ "cuda_kernel.h", "cuda_pch.cc", "cuda_pch.h", + "cuda_profiler.cc", + "cuda_profiler.h", "cuda_provider_factory.cc", "cuda_provider_factory.h", "cuda_utils.cu", diff --git a/tools/ci_build/build.py b/tools/ci_build/build.py index 063dcf8096..bd1e7dd5e5 100644 --- a/tools/ci_build/build.py +++ b/tools/ci_build/build.py @@ -654,6 +654,12 @@ def parse_arguments(): cupti library must be added to PATH beforehand.", ) + parser.add_argument( + "--enable_rocm_profiling", + action="store_true", + help="enable rocm kernel profiling.", + ) + parser.add_argument("--use_xnnpack", action="store_true", help="Enable xnnpack EP.") args = parser.parse_args() @@ -917,6 +923,7 @@ def generate_build_tree( "-Donnxruntime_ENABLE_EXTERNAL_CUSTOM_OP_SCHEMAS=" + ("ON" if args.enable_external_custom_op_schemas else "OFF"), "-Donnxruntime_ENABLE_CUDA_PROFILING=" + ("ON" if args.enable_cuda_profiling else "OFF"), + "-Donnxruntime_ENABLE_ROCM_PROFILING=" + ("ON" if args.enable_rocm_profiling else "OFF"), "-Donnxruntime_USE_XNNPACK=" + ("ON" if args.use_xnnpack else "OFF"), ] if args.external_graph_transformer_path: