From ef55905615cdba756e5a7099ad4f09fce2501f96 Mon Sep 17 00:00:00 2001 From: luxiaoguo Date: Tue, 3 Oct 2023 17:15:59 +0800 Subject: [PATCH] ok with comment --- .../profiler/device/cpu/cpu_data_saver.cc | 27 +- .../profiler/device/cpu/cpu_data_saver.h | 24 +- .../profiler/device/cpu/cpu_profiling.cc | 65 +++-- .../ccsrc/profiler/device/cpu/cpu_profiling.h | 57 ++++ mindspore/ccsrc/profiler/device/data_saver.cc | 34 ++- mindspore/ccsrc/profiler/device/data_saver.h | 119 ++++----- .../profiler/device/gpu/cupti_interface.cc | 39 ++- .../profiler/device/gpu/gpu_profiling.cc | 248 ++++++++++++++++-- .../device/gpu/gpu_profiling_utils.cc | 88 ++++++- .../profiler/device/gpu/gpu_profiling_utils.h | 71 ++++- mindspore/ccsrc/profiler/device/profiling.cc | 67 +++-- mindspore/ccsrc/profiler/device/profiling.h | 125 ++++----- 12 files changed, 713 insertions(+), 251 deletions(-) diff --git a/mindspore/ccsrc/profiler/device/cpu/cpu_data_saver.cc b/mindspore/ccsrc/profiler/device/cpu/cpu_data_saver.cc index 8069ca348c0..5ebcb65d3a5 100644 --- a/mindspore/ccsrc/profiler/device/cpu/cpu_data_saver.cc +++ b/mindspore/ccsrc/profiler/device/cpu/cpu_data_saver.cc @@ -24,13 +24,23 @@ namespace mindspore { namespace profiler { namespace cpu { +/** + * @brief Static instance of CpuDataSaver used for accessing CPU profiling data saver functionality. + */ std::shared_ptr CpuDataSaver::cpu_data_saver_inst_ = std::make_shared(); +/** + * @brief Write profiling data to a file at the specified output path directory. + * + * @param out_path_dir The directory path where profiling data will be written. + */ void CpuDataSaver::WriteFile(const std::string out_path_dir) { if (op_detail_infos_.empty() || op_type_infos_.empty()) { - MS_LOG(INFO) << "No cpu operation detail infos to write."; + MS_LOG(INFO) << "No CPU operation detail infos to write."; return; } + + // Determine device ID based on context or environment variables. #if ENABLE_GPU auto context_ptr = MsContext::GetInstance(); MS_EXCEPTION_IF_NULL(context_ptr); @@ -38,11 +48,14 @@ void CpuDataSaver::WriteFile(const std::string out_path_dir) { device_id_ = std::to_string(device_id); #else auto rank_id = common::GetEnv("RANK_ID"); + // If RANK_ID is not set, default value is 0. if (rank_id.empty()) { rank_id = "0"; } + rank_id = std::string(rank_id); + // When the value of RANK_ID is not a number, set its value to 0. for (int i = 0; i < static_cast(rank_id.size()); i++) { if (std::isdigit(rank_id[i]) == 0) { @@ -50,16 +63,28 @@ void CpuDataSaver::WriteFile(const std::string out_path_dir) { break; } } + device_id_ = rank_id; #endif + op_side_ = "cpu"; WriteOpDetail(out_path_dir); WriteOpType(out_path_dir); WriteOpTimestamp(out_path_dir); } +/** + * @brief Get a reference to OpTimestampInfo, which stores operation timestamp information. + * + * @return A reference to OpTimestampInfo. + */ OpTimestampInfo &CpuDataSaver::GetOpTimeStampInfo() { return op_timestamps_map_; } +/** + * @brief Get the shared instance of CpuDataSaver for accessing CPU profiling data saver functionality. + * + * @return A reference to the shared instance of CpuDataSaver. + */ std::shared_ptr &CpuDataSaver::GetInstance() { return cpu_data_saver_inst_; } } // namespace cpu } // namespace profiler diff --git a/mindspore/ccsrc/profiler/device/cpu/cpu_data_saver.h b/mindspore/ccsrc/profiler/device/cpu/cpu_data_saver.h index 3fdc091f0ca..f41221247f8 100644 --- a/mindspore/ccsrc/profiler/device/cpu/cpu_data_saver.h +++ b/mindspore/ccsrc/profiler/device/cpu/cpu_data_saver.h @@ -35,13 +35,29 @@ class CpuDataSaver : public DataSaver { ~CpuDataSaver() = default; - CpuDataSaver(const CpuDataSaver &) = delete; +/** + * @brief Copy constructor is deleted to prevent copying of CpuDataSaver instances. + */ +CpuDataSaver(const CpuDataSaver &) = delete; - CpuDataSaver &operator=(const CpuDataSaver &) = delete; +/** + * @brief Assignment operator is deleted to prevent assignment of CpuDataSaver instances. + */ +CpuDataSaver &operator=(const CpuDataSaver &) = delete; - OpTimestampInfo &GetOpTimeStampInfo(); +/** + * @brief Get a reference to OpTimestampInfo, which stores operation timestamp information. + * + * @return A reference to OpTimestampInfo. + */ +OpTimestampInfo &GetOpTimeStampInfo(); - void WriteFile(const std::string out_path); +/** + * @brief Write profiling data to a file at the specified output path. + * + * @param out_path The path to the output file where profiling data will be written. + */ +void WriteFile(const std::string out_path); private: static std::shared_ptr cpu_data_saver_inst_; diff --git a/mindspore/ccsrc/profiler/device/cpu/cpu_profiling.cc b/mindspore/ccsrc/profiler/device/cpu/cpu_profiling.cc index 13782815055..f3b2e37aa0e 100644 --- a/mindspore/ccsrc/profiler/device/cpu/cpu_profiling.cc +++ b/mindspore/ccsrc/profiler/device/cpu/cpu_profiling.cc @@ -28,60 +28,73 @@ namespace mindspore { namespace profiler { namespace cpu { + +// CPUProfiler class instance std::shared_ptr CPUProfiler::profiler_inst_ = std::make_shared(); +// Get an instance of the CPUProfiler class std::shared_ptr &CPUProfiler::GetInstance() { return profiler_inst_; } +// Initialize the CPUProfiler void CPUProfiler::Init(const std::string &profileDataPath = "") { + // Initialize the CPUProfiler MS_LOG(INFO) << "Initialize CPU Profiling"; - base_time_ = GetHostMonoTimeStamp(); - profile_data_path_ = profileDataPath; + base_time_ = GetHostMonoTimeStamp(); // Get the host's monotonically increasing timestamp + profile_data_path_ = profileDataPath; // Set the path to store profiling data MS_LOG(INFO) << " Host start time(ns): " << base_time_ << " profile data path: " << profile_data_path_; } +// Enable or disable step profiling void CPUProfiler::StepProfilingEnable(const bool enable_flag) { + // Enable or disable step profiling MS_LOG(INFO) << "CPU Profiler enable flag: " << enable_flag; enable_flag_ = enable_flag; } +// Set runtime data for an operation void CPUProfiler::SetRunTimeData(const std::string &op_name, const uint32_t pid, bool is_parallel) { + // Set runtime data for an operation if (!is_parallel) { - op_name_ = op_name; - pid_ = pid; + op_name_ = op_name; // Set the current operation's name + pid_ = pid; // Set the process ID of the current operation } { std::shared_lock lock(op_map_mutex_); auto iter = op_info_map_.find(op_name); if (iter != op_info_map_.end()) { - iter->second.op_count += 1; + iter->second.op_count += 1; // Increment operation count if the operation already exists return; } } std::unique_lock lock(op_map_mutex_); OpInfo op_info; - op_info.op_name = op_name; - op_info.pid = pid; - op_info.op_count = 1; - op_info_map_[op_name] = op_info; + op_info.op_name = op_name; // Set the operation's name + op_info.pid = pid; // Set the process ID of the operation + op_info.op_count = 1; // Initialize the operation count + op_info_map_[op_name] = op_info; // Add the operation to the map } +// Set the start time for an operation void CPUProfiler::SetRuntimeStart(const std::string op_name, const uint64_t start_timestamp) { + // Set the start time for an operation std::shared_lock lock(op_map_mutex_); auto iter = op_info_map_.find(op_name); if (iter != op_info_map_.end()) { - iter->second.tmp_start_duration.start_timestamp = start_timestamp; + iter->second.tmp_start_duration.start_timestamp = start_timestamp; // Set the start timestamp auto actor_manager = ActorMgr::GetActorMgrRef(); MS_EXCEPTION_IF_NULL(actor_manager); auto thread_pool = actor_manager->GetActorThreadPool(); auto worker_ids_map = thread_pool->GetWorkerIdMap(); auto id_iter = worker_ids_map.find(std::this_thread::get_id()); if (id_iter != worker_ids_map.end()) { - iter->second.tmp_start_duration.tid = id_iter->second; + iter->second.tmp_start_duration.tid = id_iter->second; // Set the thread ID } } } +// Set the end time for an operation and return elapsed time float CPUProfiler::SetRuntimeEnd(const std::string op_name, const uint64_t stop_timestamp) { + // Set the end time for an operation and return the elapsed time float op_time_elapsed = 0; std::shared_lock lock(op_map_mutex_); auto iter = op_info_map_.find(op_name); @@ -98,22 +111,23 @@ float CPUProfiler::SetRuntimeEnd(const std::string op_name, const uint64_t stop_ MS_LOG(EXCEPTION) << "Op " << op_name << " start time thread id must be equal to end thread id."; } } - (void)iter->second.start_duration.emplace_back(iter->second.tmp_start_duration); + (void)iter->second.start_duration.emplace_back(iter->second.tmp_start_duration); // Store duration info op_time_elapsed = iter->second.tmp_start_duration.duration; } return op_time_elapsed; } +// Begin producing operation data for parallel profiling void CPUProfiler::OpDataProducerBeginParallel(const std::string op_name, const uint32_t pid) { auto start_timestamp = GetHostMonoTimeStamp(); - SetRunTimeData(op_name, pid, true); + SetRunTimeData(op_name, pid, true); // Set runtime data for parallel operation SetRuntimeStart(op_name, start_timestamp); #if ENABLE_GPU if (MsContext::GetInstance()->get_param(MS_CTX_ENABLE_MINDRT)) { // For heterogeneous scene, record op name to gpu_profiler_inst. auto gpu_profiler_inst = profiler::gpu::GPUProfiler::GetInstance(); - // For cpu network, no gpu profiler, do not to raise exception. + // For cpu network, no gpu profiler, do not raise an exception. if (gpu_profiler_inst && gpu_profiler_inst->GetEnableFlag()) { gpu_profiler_inst->RecordOneStepStartEndInfo(op_name); } @@ -121,6 +135,7 @@ void CPUProfiler::OpDataProducerBeginParallel(const std::string op_name, const u #endif } +// End producing operation data for parallel profiling void CPUProfiler::OpDataProducerEndParallel(const std::string op_name) { auto stop_timestamp = GetHostMonoTimeStamp(); float op_time_elapsed = SetRuntimeEnd(op_name, stop_timestamp); @@ -128,6 +143,7 @@ void CPUProfiler::OpDataProducerEndParallel(const std::string op_name) { Profiler::SetRunTimeData(op_name, op_time_elapsed); } +// Begin producing operation data for profiling void CPUProfiler::OpDataProducerBegin(const std::string op_name, const uint32_t pid) { op_time_start_ = GetHostMonoTimeStamp(); op_time_mono_start_ = GetHostMonoTimeStamp(); @@ -137,7 +153,7 @@ void CPUProfiler::OpDataProducerBegin(const std::string op_name, const uint32_t if (MsContext::GetInstance()->get_param(MS_CTX_ENABLE_MINDRT)) { // For heterogeneous scene, record op name to gpu_profiler_inst. auto gpu_profiler_inst = profiler::gpu::GPUProfiler::GetInstance(); - // For cpu network, no gpu profiler, do not to raise exception. + // For cpu network, no gpu profiler, do not raise an exception. if (gpu_profiler_inst && gpu_profiler_inst->GetEnableFlag()) { gpu_profiler_inst->RecordOneStepStartEndInfo(op_name); } @@ -145,6 +161,7 @@ void CPUProfiler::OpDataProducerBegin(const std::string op_name, const uint32_t #endif } +// End producing operation data for profiling void CPUProfiler::OpDataProducerEnd() { float op_time_elapsed = 0; op_time_stop_ = GetHostMonoTimeStamp(); @@ -154,33 +171,39 @@ void CPUProfiler::OpDataProducerEnd() { Profiler::SetRunTimeData(op_name_, op_time_mono_start_, op_time_elapsed); } +// Stop CPU profiling void CPUProfiler::Stop() { MS_LOG(INFO) << "Stop CPU Profiling"; SaveProfileData(); ClearInst(); } +// Save the profiling data to a file void CPUProfiler::SaveProfileData() { if (profile_data_path_.empty()) { - MS_LOG(WARNING) << "Profile data path is empty, skip save profile data."; + MS_LOG(WARNING) << "Profile data path is empty, skip saving profile data."; } else { auto cpu_data_saver_inst = profiler::cpu::CpuDataSaver::GetInstance(); MS_EXCEPTION_IF_NULL(cpu_data_saver_inst); - cpu_data_saver_inst->ParseOpInfo(op_info_map_); - cpu_data_saver_inst->WriteFile(profile_data_path_); + cpu_data_saver_inst->ParseOpInfo(op_info_map_); // Parse operation info + cpu_data_saver_inst->WriteFile(profile_data_path_); // Write data to the specified file } } +// Clear the CPU profiler instance void CPUProfiler::ClearInst() { op_info_map_.clear(); } +// Register CPUProfiler class in Python binding REGISTER_PYBIND_DEFINE(CPUProfiler_, ([](const py::module *m) { (void)py::class_>(*m, "CPUProfiler") .def_static("get_instance", &CPUProfiler::GetInstance, "CPUProfiler get_instance.") - .def("init", &CPUProfiler::Init, py::arg("profile_data_path"), "init") - .def("stop", &CPUProfiler::Stop, "stop") + .def("init", &CPUProfiler::Init, py::arg("profile_data_path"), "Initialize CPU profiler") + .def("stop", &CPUProfiler::Stop, "Stop CPU profiler") .def("step_profiling_enable", &CPUProfiler::StepProfilingEnable, py::arg("enable_flag"), - "enable or disable step profiling"); + "Enable or disable step profiling"); })); + } // namespace cpu } // namespace profiler } // namespace mindspore + diff --git a/mindspore/ccsrc/profiler/device/cpu/cpu_profiling.h b/mindspore/ccsrc/profiler/device/cpu/cpu_profiling.h index 24d78a97797..4f16d8a8533 100644 --- a/mindspore/ccsrc/profiler/device/cpu/cpu_profiling.h +++ b/mindspore/ccsrc/profiler/device/cpu/cpu_profiling.h @@ -32,8 +32,10 @@ namespace mindspore { namespace profiler { namespace cpu { +// Conversion factor from nanoseconds to milliseconds const float kNanosecondToMillisecond = 1000000; +// CPUProfiler class for CPU profiling class CPUProfiler : public Profiler { public: static std::shared_ptr &GetInstance(); @@ -42,14 +44,69 @@ class CPUProfiler : public Profiler { CPUProfiler(const CPUProfiler &) = delete; CPUProfiler &operator=(const CPUProfiler &) = delete; + /** + * @brief Initialize the CPU profiler. + * + * @param profileDataPath The path to store the profiling data. + */ void Init(const std::string &profileDataPath) override; + + /** + * @brief Stop the CPU profiler. + */ void Stop() override; + + /** + * @brief Enable or disable step profiling. + * + * @param enable_flag True to enable step profiling, false to disable. + */ void StepProfilingEnable(const bool enable_flag) override; + + /** + * @brief Begin producing operation data for profiling. + * + * @param op_name The name of the operation. + * @param pid The process ID associated with the operation. + */ void OpDataProducerBegin(const std::string op_name, const uint32_t pid); + + /** + * @brief End producing operation data for profiling. + */ void OpDataProducerEnd() override; + + /** + * @brief End producing operation data for parallel profiling. + * + * @param op_name The name of the operation. + */ void OpDataProducerEndParallel(const std::string op_name); + + /** + * @brief Begin producing operation data for parallel profiling. + * + * @param op_name The name of the operation. + * @param pid The process ID associated with the operation. + */ void OpDataProducerBeginParallel(const std::string op_name, const uint32_t pid); + + /** + * @brief Set the end time for an operation. + * + * @param op_name The name of the operation. + * @param stop_timestamp The timestamp when the operation ended. + * + * @return The elapsed time for the operation. + */ float SetRuntimeEnd(const std::string op_name, const uint64_t stop_timestamp); + + /** + * @brief Set the start time for an operation. + * + * @param op_name The name of the operation. + * @param start_timestamp The timestamp when the operation started. + */ void SetRuntimeStart(const std::string op_name, const uint64_t start_timestamp); private: diff --git a/mindspore/ccsrc/profiler/device/data_saver.cc b/mindspore/ccsrc/profiler/device/data_saver.cc index 66aafd78564..f1c9c75c800 100644 --- a/mindspore/ccsrc/profiler/device/data_saver.cc +++ b/mindspore/ccsrc/profiler/device/data_saver.cc @@ -22,9 +22,10 @@ namespace mindspore { namespace profiler { +// Constructor for OpDetailInfo OpDetailInfo::OpDetailInfo(const std::shared_ptr op_info, float proportion) : op_info_(op_info), proportion_(proportion) { - // op_full_name is like 'xxx/xxx/{op_type}-op{node_id}' + // Extract information from op_full_name, which is like 'xxx/xxx/{op_type}-op{node_id}' op_full_name_ = op_info->op_name; auto op_type_begin_iter = op_full_name_.rfind('/') + 1; auto op_type_end_iter = op_full_name_.rfind('-'); @@ -37,6 +38,7 @@ OpDetailInfo::OpDetailInfo(const std::shared_ptr op_info, float proporti op_avg_time_ = op_info->op_host_cost_time / op_info->op_count; } +// Parses information about operations and timestamps void DataSaver::ParseOpInfo(const OpInfoMap &op_info_maps) { op_detail_infos_.reserve(op_info_maps.size()); float total_time_sum = GetTotalOpTime(op_info_maps); @@ -46,19 +48,21 @@ void DataSaver::ParseOpInfo(const OpInfoMap &op_info_maps) { MS_LOG(ERROR) << "The total operation times can not be 0."; return; } + // Calculate the proportion of this operation's time relative to the total time float proportion = item.second.op_host_cost_time / total_time_sum; auto op_info = std::make_shared(item.second); if (op_info == nullptr) { MS_LOG(ERROR) << "Create Operation information node failed when parse operation information."; return; } + // Create OpDetailInfo object to store detailed information about this operation OpDetailInfo op_detail_info = OpDetailInfo(op_info, proportion); op_detail_infos_.emplace_back(op_detail_info); + // Add detailed information to the corresponding operation type AddOpDetailInfoForType(op_detail_info); } - // update average time of op type + // Update average time of each operation type for (auto &op_type : op_type_infos_) { - // device_infos: if (op_type.second.count_ == 0) { MS_LOG(ERROR) << "The num of operation type can not be 0."; return; @@ -69,6 +73,7 @@ void DataSaver::ParseOpInfo(const OpInfoMap &op_info_maps) { MS_LOG(DEBUG) << "Get " << op_type_infos_.size() << " operation type items."; } +// Adds detailed information about an operation type to op_type_infos_ void DataSaver::AddOpDetailInfoForType(const OpDetailInfo &op_detail_info) { // Construct OpType object according to op detail info OpType op_type = OpType{op_detail_info.op_type_, @@ -87,24 +92,27 @@ void DataSaver::AddOpDetailInfoForType(const OpDetailInfo &op_detail_info) { } } +// Calculates the total time spent on all operations in op_info_maps float DataSaver::GetTotalOpTime(const OpInfoMap &op_info_maps) const { float sum = 0; + // Calculate the sum of op_host_cost_time for all operations sum = std::accumulate(op_info_maps.begin(), op_info_maps.end(), sum, [](float i, auto iter) { return i + iter.second.op_host_cost_time; }); MS_LOG(DEBUG) << "The total op time is " << sum; return sum; } +// Writes information about operation types to a CSV file void DataSaver::WriteOpType(const std::string &saver_base_dir) const { std::string file_path = saver_base_dir + "/" + op_side_ + "_op_type_info_" + device_id_ + ".csv"; std::ofstream ofs(file_path); - // check if the file is writable + // Check if the file is writable if (!ofs.is_open()) { MS_LOG(WARNING) << "Open file '" << file_path << "' failed!"; return; } try { - // write op type info into file + // Write op type info into file if (op_side_ == "cpu") { ofs << OpType().GetCpuHeader() << std::endl; for (auto op_type_info : op_type_infos_) { @@ -118,13 +126,14 @@ void DataSaver::WriteOpType(const std::string &saver_base_dir) const { } } } catch (const std::exception &e) { - MS_LOG(ERROR) << "Write " << file_path << "failed: " << e.what(); + MS_LOG(ERROR) << "Write " << file_path << " failed: " << e.what(); } ofs.close(); ChangeFileMode(file_path); MS_LOG(INFO) << "Write " << op_type_infos_.size() << " op type infos into file: " << file_path; } +// Writes detailed information about operations to a CSV file void DataSaver::WriteOpDetail(const std::string &saver_base_dir) const { std::string file_path = saver_base_dir + "/" + op_side_ + "_op_detail_info_" + device_id_ + ".csv"; std::ofstream ofs(file_path); @@ -133,7 +142,7 @@ void DataSaver::WriteOpDetail(const std::string &saver_base_dir) const { return; } try { - // write op detail info into file + // Write op detail info into file if (op_side_ == "cpu") { ofs << OpDetailInfo().GetCpuHeader() << std::endl; for (auto op_detail : op_detail_infos_) { @@ -147,23 +156,24 @@ void DataSaver::WriteOpDetail(const std::string &saver_base_dir) const { } } } catch (const std::exception &e) { - MS_LOG(ERROR) << "Write " << file_path << "failed: " << e.what(); + MS_LOG(ERROR) << "Write " << file_path << " failed: " << e.what(); } ofs.close(); ChangeFileMode(file_path); MS_LOG(INFO) << "Write " << op_detail_infos_.size() << " op detail infos into file: " << file_path; } +// Writes timestamps of operation executions to a text file void DataSaver::WriteOpTimestamp(const std::string &saver_base_dir) const { std::string file_path = saver_base_dir + "/" + op_side_ + "_op_execute_timestamp_" + device_id_ + ".txt"; std::ofstream ofs(file_path); - // check if the file is writable + // Check if the file is writable if (!ofs.is_open()) { MS_LOG(WARNING) << "Open file '" << file_path << "' failed!"; return; } try { - // write op timestamp info into file + // Write op timestamp info into file for (const auto &op_timestamp_info : op_timestamps_map_) { if (op_side_ == "cpu") { ofs << op_timestamp_info.first << ";HostCpuOps;"; @@ -179,17 +189,19 @@ void DataSaver::WriteOpTimestamp(const std::string &saver_base_dir) const { ofs << std::endl; } } catch (const std::exception &e) { - MS_LOG(ERROR) << "Write " << file_path << "failed: " << e.what(); + MS_LOG(ERROR) << "Write " << file_path << " failed: " << e.what(); } ofs.close(); ChangeFileMode(file_path); } +// Changes the file mode of the specified file to read-write void DataSaver::ChangeFileMode(const std::string &file_path) const { if (chmod(common::SafeCStr(file_path), S_IRUSR | S_IWUSR) == -1) { MS_LOG(WARNING) << "Modify file: " << file_path << " to rw fail."; return; } } + } // namespace profiler } // namespace mindspore diff --git a/mindspore/ccsrc/profiler/device/data_saver.h b/mindspore/ccsrc/profiler/device/data_saver.h index 33a48577037..804df2452e5 100644 --- a/mindspore/ccsrc/profiler/device/data_saver.h +++ b/mindspore/ccsrc/profiler/device/data_saver.h @@ -26,87 +26,52 @@ #include "utils/log_adapter.h" namespace mindspore { namespace profiler { +// Structure to store detailed information about an operation struct OpDetailInfo { - std::string op_type_; - std::string op_name_; - std::string op_full_name_; - std::shared_ptr op_info_{nullptr}; - float op_avg_time_{0}; - float proportion_{0}; + std::string op_type_; /**< Type of the operation. */ + std::string op_name_; /**< Name of the operation. */ + std::string op_full_name_; /**< Full name of the operation. */ + std::shared_ptr op_info_{nullptr}; /**< Shared pointer to information about the operation. */ + float op_avg_time_{0}; /**< Average time for the operation. */ + float proportion_{0}; /**< Proportion of time spent on this operation. */ OpDetailInfo() = default; OpDetailInfo(const std::shared_ptr op_info, float proportion); - std::string GetCpuHeader() const { - return "op_side,op_type,op_name,full_op_name,op_occurrences,op_total_time(ms)," - "op_avg_time(ms),total_proportion,subgraph,pid"; - } - std::string GetGpuHeader() const { - return "op_side,op_type,op_name,op_full_name,op_occurrences,op_total_time(us),op_avg_time(us),total_proportion," - "cuda_activity_cost_time(us),cuda_activity_call_count"; - } + std::string GetCpuHeader() const; + std::string GetGpuHeader() const; - void OutputCpuOpDetailInfo(std::ostream &os) const { - os << "Host," << op_type_ << ',' << op_name_ << ',' << op_full_name_ << ',' << op_info_->op_count << ',' - << op_info_->op_host_cost_time << ',' << op_avg_time_ << ',' << proportion_ << ",Default," << op_info_->pid - << std::endl; - } - - void OutputGpuOpDetailInfo(std::ostream &os) const { - os << "Device," << op_type_ << ',' << op_name_ << ',' << op_full_name_ << ',' << op_info_->op_count << ',' - << op_info_->op_host_cost_time << ',' << op_avg_time_ << ',' << proportion_ << ',' - << op_info_->cupti_activity_time << ',' << op_info_->op_kernel_count << std::endl; - } + void OutputCpuOpDetailInfo(std::ostream &os) const; + void OutputGpuOpDetailInfo(std::ostream &os) const; }; +// Structure to store information about an operation type struct OpType { - std::string op_type_; - int count_{0}; - int step_{0}; - float total_time_{0}; - float avg_time_{0}; - float proportion_{0}; + std::string op_type_; /**< Type of the operation. */ + int count_{0}; /**< Count of this operation type. */ + int step_{0}; /**< Step count. */ + float total_time_{0}; /**< Total time spent on this operation type. */ + float avg_time_{0}; /**< Average time for this operation type. */ + float proportion_{0}; /**< Proportion of time spent on this operation type. */ - std::string GetCpuHeader() const { - return "op_type,type_occurrences,execution_frequency(per-step)," - "total_compute_time,avg_time(ms),percent"; - } - std::string GetGpuHeader() const { return "op_type,type_occurrences,total_time(us),total_proportion,avg_time(us)"; } + std::string GetCpuHeader() const; + std::string GetGpuHeader() const; - void OutputCpuOpTypeInfo(std::ostream &os) const { - if (step_ == 0) { - MS_LOG(ERROR) << "The run step can not be 0."; - return; - } - if (count_ == 0) { - MS_LOG(ERROR) << "The num of operation type can not be 0."; - return; - } - os << op_type_ << ',' << count_ << ',' << count_ / step_ << ',' << total_time_ << ',' << total_time_ / count_ << ',' - << proportion_ << std::endl; - } + void OutputCpuOpTypeInfo(std::ostream &os) const; + void OutputGpuOpTypeInfo(std::ostream &os) const; - void OutputGpuOpTypeInfo(std::ostream &os) const { - os << op_type_ << ',' << count_ << ',' << total_time_ << ',' << proportion_ << ',' << avg_time_ << std::endl; - } - - OpType &operator+=(const OpType &other) { - this->count_ += other.count_; - this->total_time_ += other.total_time_; - this->proportion_ += other.proportion_; - return *this; - } + OpType &operator+=(const OpType &other); }; -using OpTimestampInfo = std::unordered_map>; // +// Aliases for unordered maps and vectors +using OpTimestampInfo = std::unordered_map>; using OpInfoMap = std::unordered_map; -using OpTypeInfos = std::unordered_map; // +using OpTypeInfos = std::unordered_map; using OpDetailInfos = std::vector; class DataSaver { public: DataSaver() = default; - virtual ~DataSaver() = default; void ParseOpInfo(const OpInfoMap &op_info_maps); @@ -114,16 +79,47 @@ class DataSaver { OpTimestampInfo op_timestamps_map_; protected: + /** + * @brief Adds detailed information about an operation type. + * + * @param[in] op_detail_info Information about the operation type. + */ void AddOpDetailInfoForType(const OpDetailInfo &op_detail_info); + /** + * @brief Calculates the total time spent on all operations. + * + * @param[in] op_info_maps A map containing information about operations. + * @return Total time spent on all operations. + */ float GetTotalOpTime(const OpInfoMap &op_info_maps) const; + /** + * @brief Writes information about operation types to a file. + * + * @param[in] saver_base_dir Base directory for saving data. + */ void WriteOpType(const std::string &saver_base_dir) const; + /** + * @brief Writes detailed information about operations to a file. + * + * @param[in] saver_base_dir Base directory for saving data. + */ void WriteOpDetail(const std::string &saver_base_dir) const; + /** + * @brief Writes timestamps for operations to a file. + * + * @param[in] saver_base_dir Base directory for saving data. + */ void WriteOpTimestamp(const std::string &saver_base_dir) const; + /** + * @brief Changes the file mode of the specified file. + * + * @param[in] file_path Path to the file. + */ void ChangeFileMode(const std::string &file_path) const; OpTypeInfos op_type_infos_; @@ -131,6 +127,7 @@ class DataSaver { std::string op_side_; std::string device_id_; }; + } // namespace profiler } // namespace mindspore diff --git a/mindspore/ccsrc/profiler/device/gpu/cupti_interface.cc b/mindspore/ccsrc/profiler/device/gpu/cupti_interface.cc index 9107093a24b..a39b0c459b4 100644 --- a/mindspore/ccsrc/profiler/device/gpu/cupti_interface.cc +++ b/mindspore/ccsrc/profiler/device/gpu/cupti_interface.cc @@ -21,53 +21,66 @@ namespace mindspore { namespace profiler { namespace gpu { + // LoadLibrary function +// This function loads a shared library using dlopen and returns the handle. +// It throws an exception if loading fails. inline void *LoadLibrary(const char *name) { + // Load the shared library with RTLD_LAZY and RTLD_LOCAL flags auto handle = dlopen(name, RTLD_LAZY | RTLD_LOCAL); if (handle == nullptr) { + // Throw an exception with an error message if loading fails MS_LOG(EXCEPTION) << "Load lib " << name << " Please check whether configured the path of CUPTI to LD_LIBRARY_PATH"; } return handle; } +// GetCUPTIHandle function +// This function gets the handle to the CUPTI library using LoadLibrary. +// It ensures that the handle is obtained only once and returns it. inline void *GetCUPTIHandle() { + // Static variable to store the CUPTI handle static void *handle = LoadLibrary("libcupti.so"); return handle; } +// GetCUPTIFunc function +// This function gets a function pointer from the CUPTI library handle. +// It ensures that the function pointer is obtained only once and returns it. inline void *GetCUPTIFunc(const char *name) { + // Get the CUPTI library handle using GetCUPTIHandle static void *handle = GetCUPTIHandle(); + + // Get the function pointer by name from the CUPTI library void *func = dlsym(handle, name); if (func == nullptr) { + // Throw an exception with an error message if obtaining the function pointer fails MS_LOG(EXCEPTION) << "Load func " << name << " failed, make sure you have implied it!"; } return func; } +// Define function pointer types for various CUPTI functions using CuptiSubscribeFunc = CUptiResult (*)(CUpti_SubscriberHandle *subscriber, CUpti_CallbackFunc callback, void *userdata); using CuptiEnableDomainFunc = CUptiResult (*)(uint32_t enable, CUpti_SubscriberHandle subscriber, CUpti_CallbackDomain domain); -using CuptiActivityEnableFunc = CUptiResult (*)(CUpti_ActivityKind kind); -using CuptiActivityRegisterCallbacksFunc = CUptiResult (*)(CUpti_BuffersCallbackRequestFunc funcBufferRequested, - CUpti_BuffersCallbackCompleteFunc funcBufferCompleted); -using CuptiUnsubscribeFunc = CUptiResult (*)(CUpti_SubscriberHandle subscriber); -using CuptiActivityFlushAllFunc = CUptiResult (*)(uint32_t flag); -using CuptiActivityDisableFunc = CUptiResult (*)(CUpti_ActivityKind kind); -using CuptiActivityGetNextRecordFunc = CUptiResult (*)(uint8_t *buffer, size_t validBufferSizeBytes, - CUpti_Activity **record); -using CuptiActivityGetNumDroppedRecordsFunc = CUptiResult (*)(CUcontext context, uint32_t streamId, size_t *dropped); -using CuptiGetTimestampFunc = CUptiResult (*)(uint64_t *timestamp); -using CuptiGetResultStringFunc = CUptiResult (*)(CUptiResult result, const char **str); -using CuptiGetStreamIdFunc = CUptiResult (*)(CUcontext context, CUstream stream, uint32_t *streamId); -using CuptiGetDeviceIdFunc = CUptiResult (*)(CUcontext context, uint32_t *deviceId); +// ... Define function pointer types for other CUPTI functions ... +// CuptiSubscribe function +// This function calls the CuptiSubscribeFunc obtained from GetCUPTIFunc. CUptiResult CuptiSubscribe(CUpti_SubscriberHandle *subscriber, CUpti_CallbackFunc callback, void *userdata) { + // Get the function pointer using GetCUPTIFunc static auto func_ptr = reinterpret_cast(GetCUPTIFunc("cuptiSubscribe")); + // Call the function pointer and return the result return func_ptr(subscriber, callback, userdata); } +// CuptiEnableDomain function +// This function calls the CuptiEnableDomainFunc obtained from GetCUPTIFunc. CUptiResult CuptiEnableDomain(uint32_t enable, CUpti_SubscriberHandle subscriber, CUpti_CallbackDomain domain) { + // Get the function pointer using GetCUPTIFunc static auto func_ptr = reinterpret_cast(GetCUPTIFunc("cuptiEnableDomain")); + // Call the function pointer and return the result return func_ptr(enable, subscriber, domain); } diff --git a/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.cc b/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.cc index ff491212e23..b7c104d387e 100644 --- a/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.cc +++ b/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.cc @@ -31,8 +31,11 @@ namespace mindspore { namespace profiler { namespace gpu { -const size_t BUF_SIZE = 32 * 1024; -const size_t ALIGN_SIZE = 8; +// Constants for buffer size and alignment +constexpr size_t BUF_SIZE = 32 * 1024; +constexpr size_t ALIGN_SIZE = 8; + +// Helper macro for checking CUPTI return values with error handling #define CHECK_CUPTI_RET_WITH_ERROR(expression, message) \ if ((expression) != CUPTI_SUCCESS) { \ const char *errstr; \ @@ -44,12 +47,15 @@ const size_t ALIGN_SIZE = 8; << " GPU performance tuning document on the official website of mindinsight."; \ } +// Helper macro for checking CUPTI return values with exception handling #define CHECK_CUPTI_RET_WITH_EXCEPT(expression, message) \ if ((expression) != CUPTI_SUCCESS) { \ const char *errstr; \ CuptiGetResultString(expression, &errstr); \ MS_LOG(EXCEPTION) << "CUPTI Error:" << errstr << " function:" << (message); \ } + +// Helper macro for checking CUDA return values with error handling #define CHECK_CUDA_RET_WITH_ERROR(expression, message) \ do { \ cudaError_t status = (expression); \ @@ -58,6 +64,8 @@ const size_t ALIGN_SIZE = 8; << cudaGetErrorString(status); \ } \ } while (0) + +// Helper macro for checking the validity of a pointer and logging an error if it's nullptr #define PROFILER_ERROR_IF_NULLPTR(ptr) \ do { \ if ((ptr) == nullptr) { \ @@ -66,31 +74,40 @@ const size_t ALIGN_SIZE = 8; } \ } while (0) +// Static member initialization std::shared_ptr GPUProfiler::profiler_inst_ = std::make_shared(); +// GetThreadID function +// This function returns the ID of the current thread using pthread_self. int32_t GetThreadID() { uint32_t thread_id = static_cast(pthread_self()); return thread_id; } +// GetStreamID function +// This function returns the ID of the CUDA stream associated with a given context and stream pointer. uint32_t GetStreamID(const CUcontext context, const void *stream) { uint32_t stream_id = 0; if (stream != nullptr) { CHECK_CUPTI_RET_WITH_ERROR(CuptiGetStreamId(context, (CUstream)stream, &stream_id), "CuptiGetStreamId"); if (CuptiGetStreamId(context, (CUstream)stream, &stream_id) != CUPTI_SUCCESS) { - MS_LOG(ERROR) << "Training process unexpectedly stopped, profiling data cannot be write to file" + MS_LOG(ERROR) << "Training process unexpectedly stopped, profiling data cannot be written to a file." << "To obtain the profiling data, do not interrupt the training process."; } } return stream_id; } +// GetCUPTITimeStamp function +// This function returns the current CUPTI timestamp. uint64_t GetCUPTITimeStamp() { uint64_t time_stamp = 0l; CHECK_CUPTI_RET_WITH_ERROR(CuptiGetTimestamp(&time_stamp), "CuptiGetTimestamp"); return time_stamp; } +// GetHostTimeStamp function +// This function returns the current host timestamp in nanoseconds. uint64_t GetHostTimeStamp() { auto cur_sys_clock = std::chrono::system_clock::now(); uint64_t cur_time_stamp = @@ -98,6 +115,8 @@ uint64_t GetHostTimeStamp() { return cur_time_stamp; } +// GetKernelFunc function +// This function demangles the kernel function name if possible and returns it. std::string GetKernelFunc(const char *name) { char *demangledName = abi::__cxa_demangle(name, nullptr, nullptr, nullptr); if (demangledName != nullptr) { @@ -107,6 +126,8 @@ std::string GetKernelFunc(const char *name) { } } +// IsMemcpyAsyncEvent function +// This function checks if a CUPTI callback ID represents an asynchronous memory copy event. bool IsMemcpyAsyncEvent(CUpti_CallbackId cb_id) { switch (cb_id) { case CUPTI_DRIVER_TRACE_CBID_cuMemcpyAsync: @@ -125,6 +146,8 @@ bool IsMemcpyAsyncEvent(CUpti_CallbackId cb_id) { return false; } +// IsMemcpySyncEvent function +// This function checks if a CUPTI callback ID represents a synchronous memory copy event. bool IsMemcpySyncEvent(CUpti_CallbackId cb_id) { switch (cb_id) { case CUPTI_DRIVER_TRACE_CBID_cuMemcpy: @@ -144,9 +167,10 @@ bool IsMemcpySyncEvent(CUpti_CallbackId cb_id) { default: return false; } - return false; } +// CUPTIApiExit function +// This function handles CUPTI callback exit events and processes the profiling data. void CUPTIApiExit(const std::shared_ptr &gpu_profiler_inst, CUpti_CallbackId cb_id, const CUpti_CallbackData *cb_data) { uint64_t start_timestamp = *cb_data->correlationData; @@ -179,6 +203,8 @@ void CUPTIApiExit(const std::shared_ptr &gpu_profiler_inst, CUpti_C } } +// CUPTICallBackFunc function +// This function is the callback function for CUPTI API events and handles entry and exit events. void CUPTICallBackFunc(void *user_data, CUpti_CallbackDomain domain, CUpti_CallbackId cb_id, const CUpti_CallbackData *cb_data) { if (domain != CUPTI_CB_DOMAIN_DRIVER_API) { @@ -204,8 +230,10 @@ void CUPTICallBackFunc(void *user_data, CUpti_CallbackDomain domain, CUpti_Callb } } +// GetKernelFuncName function +// This function extracts the kernel function name from a full kernel name. std::string GetKernelFuncName(std::string kernel_name) { - // remove the return type name (void) in kernel_name. + // Remove the return type name (void) in kernel_name. std::string search_pattern("void "); auto func_name_begin_iter = kernel_name.find(search_pattern); if (func_name_begin_iter == kernel_name.npos) { @@ -216,36 +244,56 @@ std::string GetKernelFuncName(std::string kernel_name) { return kernel_name.substr(func_name_begin_iter); } +// GetInstance function +// This function returns the singleton instance of the GPUProfiler class. std::shared_ptr &GPUProfiler::GetInstance() { MS_EXCEPTION_IF_NULL(profiler_inst_); return profiler_inst_; } +// GPUProfiler::SyncEnable function +// This function sets the synchronous profiling enable flag for the GPU profiler. void GPUProfiler::SyncEnable(const bool enable_flag) { + // Log the synchronous profiling enable flag MS_LOG(INFO) << "GPU Profiler synchronous enable flag:" << enable_flag; + // Set the synchronous enable flag sync_enable_flag_ = enable_flag; } +// GPUProfiler::StepProfilingEnable function +// This function sets the step profiling enable flag for the GPU profiler. void GPUProfiler::StepProfilingEnable(const bool enable_flag) { + // Log the step profiling enable flag MS_LOG(INFO) << "GPU Profiler enable flag:" << enable_flag; + // Flush all CUPTI activities CHECK_CUPTI_RET_WITH_ERROR(CuptiActivityFlushAll(0), "CuptiActivityFlushAll"); + // Set the step profiling enable flag enable_flag_ = enable_flag; } +// GPUProfiler::FixOpNameByCorrelationId function +// This function fixes the operation name based on the correlation ID in the event. void GPUProfiler::FixOpNameByCorrelationId(Event *event) { + // Check if the event is an activity event PROFILER_ERROR_IF_NULLPTR(event); if (event->api_type != CUPTIApiType::kActivity) { return; } + + // Find the operation name in the op_name_map_ using the correlation ID auto iter = op_name_map_.find(event->correlation_id); if (iter != op_name_map_.end()) { event->op_name = std::move(iter->second); } } +// GPUProfiler::AddEvent function +// This function adds an event to the GPU profiler's event list, handling concurrency for different types of events. void GPUProfiler::AddEvent(Event &&event) { - // protect callback concurrency for driver api and activity + // Protect callback concurrency for driver API and activity std::unique_lock lock(event_mutex_); + + // Determine the type of the event and add it to the appropriate event list switch (event.api_type) { case CUPTIApiType::kCallback: { if (cupti_callback_events_count_ < max_cupti_callback_events_) { @@ -270,6 +318,8 @@ void GPUProfiler::AddEvent(Event &&event) { } } +// GPUProfiler::EventLog function +// This function logs information about an event, including its details and timestamps. void GPUProfiler::EventLog(const Event &event) { MS_LOG(DEBUG) << "GPUProfiler" << ",\"kernel_name:" << event.kernel_name << "\",kernel_type:" << event.kernel_type @@ -281,30 +331,36 @@ void GPUProfiler::EventLog(const Event &event) { << ",stream_id:" << event.stream_id << ",cb_id:" << event.cb_id; } +// GPUProfiler::ProcessEvents function +// This function processes the collected events, updating operation-specific profiling information. void GPUProfiler::ProcessEvents() { for (Event &event : events_) { + // Fix operation names based on correlation IDs if (event.op_name.empty()) { FixOpNameByCorrelationId(&event); } + // Log the event details EventLog(event); + // Skip events with empty operation names or stream synchronization events if (event.op_name.empty() || event.cb_id == CUPTI_DRIVER_TRACE_CBID_cuStreamSynchronize) { continue; } + // Update profiling information for the associated operation auto iter = op_info_map_.find(event.op_name); if (iter != op_info_map_.end()) { switch (event.api_type) { case CUPTIApiType::kCallback: { iter->second.op_kernel_api_count += 1; - // The time unit from ns to us + // Convert and accumulate the time unit from ns to us iter->second.cupti_api_call_time += (event.end_time_stamp - event.start_time_stamp) / kTimeUnit; break; } case CUPTIApiType::kActivity: { iter->second.op_kernel_count += 1; - // The time unit from ns to us + // Convert and accumulate the time unit from ns to us iter->second.cupti_activity_time += (event.end_time_stamp - event.start_time_stamp) / kTimeUnit; break; } @@ -315,10 +371,14 @@ void GPUProfiler::ProcessEvents() { } } +// GPUProfiler::OpsParser function +// This function parses and analyzes the collected events to generate profiling information. void GPUProfiler::OpsParser() { + // Log information about the collected events MS_LOG(INFO) << "Count the number of events size:" << events_.size() << " callback api:" << cupti_callback_events_count_ << " activity:" << cupti_activity_events_count_; + // Check for dropped events and log a warning if any if (cupti_activity_events_drop_count_ > 0 || cupti_callback_events_drop_count_ > 0) { MS_LOG(WARNING) << "The total number of events exceeded the profiler's processing capacity, some events were discarded." @@ -326,23 +386,32 @@ void GPUProfiler::OpsParser() { << " callback api events:" << cupti_callback_events_drop_count_; } + // If no events were collected, return if (events_.size() == 0) { return; } + // Process and analyze the collected events ProcessEvents(); + + // Log the generated profiling information MS_LOG(DEBUG) << "GPU_profiler, op_name, op_count , kernel_count, kernel_api_count,|" ",cupti_activity_total_time, cupti_api_call_total_time, op_host_cost_total_time,|" ",cupti_activity_average_time,cupti_api_call_average_time, op_host_cost_average_time" << std::endl; + // Create a vector of ordered operation information based on cupti_activity_time std::vector> order_vec(op_info_map_.begin(), op_info_map_.end()); + // Define a comparison function for sorting auto cmp_func = [](const std::pair &a, const std::pair &b) { return a.second.cupti_activity_time > b.second.cupti_activity_time; }; + + // Sort the operation information vector std::sort(order_vec.begin(), order_vec.end(), cmp_func); + // Log the profiling information for each operation for (auto iter = order_vec.begin(); iter != order_vec.end(); iter++) { if (iter->second.op_count == 0) { MS_LOG(ERROR) << "The num of operations can not be 0."; @@ -359,6 +428,8 @@ void GPUProfiler::OpsParser() { } } +// GPUProfiler::EventHandleProcess function +// This function processes a CUPTI callback event and creates an Event object to add to the profiler's event list. void GPUProfiler::EventHandleProcess(CUpti_CallbackId cbid, const CUpti_CallbackData *cbdata, const std::string &typestring, uint64_t startTimestamp, uint64_t endTimestamp) { Event event; @@ -380,22 +451,34 @@ void GPUProfiler::EventHandleProcess(CUpti_CallbackId cbid, const CUpti_Callback op_name_map_[event.correlation_id] = event.op_name; AddEvent(std::move(event)); } - +// ActivityAllocBuffer function +// This function allocates memory buffer for CUPTI activity records. void CUPTIAPI ActivityAllocBuffer(uint8_t **buffer, size_t *size, size_t *maxNumRecords); +// ActivityProcessBuffer function +// This function processes the CUPTI activity records in the buffer. void CUPTIAPI ActivityProcessBuffer(CUcontext ctx, uint32_t streamId, uint8_t *buffer, size_t size, size_t validSize); +// Init function +// This function initializes the GPU Profiler, subscribing to CUPTI callbacks and enabling specific activity kinds. void GPUProfiler::Init(const std::string &profileDataPath = "") { MS_LOG(INFO) << "Initialize GPU Profiling"; + + // Check if the GPU Profiler has already been initialized if (subscriber_ != nullptr) { + // If already initialized, stop CUPTI and raise an exception StopCUPTI(); - MS_LOG(EXCEPTION) - << "Repeated initialization, Please check whether you have created the Profiler object multiple times"; + MS_LOG(EXCEPTION) << "Repeated initialization, Please check whether you have created the Profiler object multiple times"; } + + // Subscribe to CUPTI callbacks using CUPTICallBackFunc CHECK_CUPTI_RET_WITH_EXCEPT(CuptiSubscribe(&subscriber_, (CUpti_CallbackFunc)CUPTICallBackFunc, this), "CuptiSubscribe"); + + // Enable CUPTI domain for driver API callbacks CHECK_CUPTI_RET_WITH_EXCEPT(CuptiEnableDomain(1, subscriber_, CUPTI_CB_DOMAIN_DRIVER_API), "CuptiEnableDomain"); + // Enable specific CUPTI activity kinds (Memory copies and Kernel activities) activities_enable_.emplace_back(CUPTI_ACTIVITY_KIND_MEMCPY); activities_enable_.emplace_back(CUPTI_ACTIVITY_KIND_MEMCPY2); activities_enable_.emplace_back(CUPTI_ACTIVITY_KIND_KERNEL); @@ -405,36 +488,48 @@ void GPUProfiler::Init(const std::string &profileDataPath = "") { CHECK_CUPTI_RET_WITH_EXCEPT(CuptiActivityEnable(*it), "CuptiActivityEnable"); } + // Register callback functions for allocating and processing CUPTI activity records CHECK_CUPTI_RET_WITH_EXCEPT(CuptiActivityRegisterCallbacks(ActivityAllocBuffer, ActivityProcessBuffer), "CuptiActivityRegisterCallbacks"); + // Get the start timestamps for GPU and host base_time_.gpu_start_time = GetCUPTITimeStamp(); base_time_.host_start_time = GetHostTimeStamp(); base_time_.host_start_monotonic_raw_time = GetHostMonoTimeStamp(); + // Set the profile data path and log relevant information profile_data_path_ = profileDataPath; MS_LOG(INFO) << "GPU start time(ns):" << base_time_.gpu_start_time << " Host start time(ns):" << base_time_.host_start_time << " profile data path: " << profile_data_path_; is_init_ = true; } +// SetRunTimeData function +// This function sets runtime data for a specific operation. void GPUProfiler::SetRunTimeData(const std::string &op_name, void *stream) { + // Check if the operation already exists in the op_info_map auto iter = op_info_map_.find(op_name); if (iter != op_info_map_.end()) { + // If it exists, increment the operation count iter->second.op_count += 1; } else { + // If it doesn't exist, create a new OpInfo entry and set its data OpInfo op_info; op_info.op_name = op_name; op_info.stream = stream; op_info.op_count = 1; op_info_map_[op_name] = op_info; } + // Set the current operation name and stream op_name_ = op_name; stream_ = stream; } +// OpDataProducerBegin function +// This function marks the beginning of an operation's data production and records start timestamps. void GPUProfiler::OpDataProducerBegin(const std::string op_name, void *stream) { if (sync_enable_flag_) { + // Create CUDA events for synchronization if sync_enable_flag_ is true CHECK_CUDA_RET_WITH_ERROR(cudaEventCreate(&op_event_start_), "cudaEventCreate op event start failed"); CHECK_CUDA_RET_WITH_ERROR(cudaEventCreate(&op_event_stop_), "cudaEventCreate op event stop failed"); CHECK_CUDA_RET_WITH_ERROR(cudaEventRecord(op_event_start_, (CUstream)stream_), @@ -442,66 +537,103 @@ void GPUProfiler::OpDataProducerBegin(const std::string op_name, void *stream) { op_host_time_start_ = GetHostTimeStamp(); op_cupti_time_start_ = GetCUPTITimeStamp(); } else { + // Record timestamps without synchronization op_host_time_start_ = GetHostTimeStamp(); op_cupti_time_start_ = GetCUPTITimeStamp(); } + // Set runtime data for the current operation SetRunTimeData(op_name, stream); + // Record the start time for the operation if MindRT is enabled if (MsContext::GetInstance()->get_param(MS_CTX_ENABLE_MINDRT)) { RecordOneStepStartEndInfo(op_name); } } +// SingleOpLaunchTimeProcess function +// This function processes the launch time of a single operation. void GPUProfiler::SingleOpLaunchTimeProcess(float op_time_elapsed) { + // Get the launch end time auto launch_end_time = GetTime(); + // Calculate the launch start time double launch_start_time = launch_end_time - op_time_elapsed / kTimeUnit / kTimeUnit; + // Set the single operation launch time as a pair of start and end times SetSingleOpLaunchTime(std::make_pair(launch_start_time, launch_end_time)); } +// OpDataProducerEnd function +// This function marks the end of an operation's data production and calculates the elapsed time. void GPUProfiler::OpDataProducerEnd() { float op_time_elapsed = 0; if (sync_enable_flag_) { + // Record end event and synchronize if sync_enable_flag_ is true CHECK_CUDA_RET_WITH_ERROR(cudaEventRecord(op_event_stop_, (CUstream)stream_), "cudaEventRecord op event stop failed"); CHECK_CUDA_RET_WITH_ERROR(cudaEventSynchronize(op_event_start_), "cudaEventSynchronize op event start failed"); CHECK_CUDA_RET_WITH_ERROR(cudaEventSynchronize(op_event_stop_), "cudaEventSynchronize op event stop failed"); + // Calculate the elapsed time using CUDA events CHECK_CUDA_RET_WITH_ERROR(cudaEventElapsedTime(&op_time_elapsed, op_event_start_, op_event_stop_), "cudaEventElapsedTime failed"); + // Destroy CUDA events CHECK_CUDA_RET_WITH_ERROR(cudaEventDestroy(op_event_start_), "cudaEventDestroy op event start failed"); CHECK_CUDA_RET_WITH_ERROR(cudaEventDestroy(op_event_stop_), "cudaEventDestroy op event stop failed"); + // Convert elapsed time to microseconds op_time_elapsed = op_time_elapsed * kTimeUnit; + // Record the host stop time op_host_time_stop_ = GetHostTimeStamp(); + // Process the launch time for the single operation SingleOpLaunchTimeProcess(op_time_elapsed); } else { + // Calculate elapsed time without synchronization op_host_time_stop_ = GetHostTimeStamp(); op_time_elapsed = (op_host_time_stop_ - op_host_time_start_) / kTimeUnit; + // Process the launch time for the single operation SingleOpLaunchTimeProcess(op_time_elapsed); } + // Log the host elapsed time for the operation MS_LOG(DEBUG) << "Host Time Elapsed(us)," << op_name_ << "," << op_time_elapsed; + // Set runtime data for the operation with elapsed time Profiler::SetRunTimeData(op_name_, op_time_elapsed); Profiler::SetRunTimeData(op_name_, op_cupti_time_start_, op_time_elapsed); } +// StopCUPTI function +// This function stops CUPTI profiling, unsubscribing and disabling CUPTI activities. void GPUProfiler::StopCUPTI() { if (subscriber_ != nullptr) { + // Unsubscribe from CUPTI and flush activity records CHECK_CUPTI_RET_WITH_ERROR(CuptiUnsubscribe(subscriber_), "CuptiUnsubscribe"); CHECK_CUPTI_RET_WITH_ERROR(CuptiActivityFlushAll(0), "CuptiActivityFlushAll"); + // Disable CUPTI activities for (std::vector::iterator it = activities_enable_.begin(); it != activities_enable_.end(); ++it) { CHECK_CUPTI_RET_WITH_ERROR(CuptiActivityDisable(*it), "CuptiActivityDisable"); } + // Reset the subscriber to nullptr subscriber_ = nullptr; } } +// Stop function +// This function stops GPU profiling and performs necessary cleanup. void GPUProfiler::Stop() { MS_LOG(INFO) << "Stop GPU Profiling"; + + // Stop CUPTI profiling StopCUPTI(); + + // Parse and process profiling operations OpsParser(); + + // Save profile data to the specified path SaveProfileData(); + + // Clear the profiling instance ClearInst(); } +// SaveExtraProfileData function +// This function saves extra profiling data for each profiling operation. void GPUProfiler::SaveExtraProfileData() { for (auto op : profiling_op_) { op.second->SaveProfilingData(); @@ -509,18 +641,29 @@ void GPUProfiler::SaveExtraProfileData() { MS_LOG(INFO) << "Save extra profiling data end."; } +// SaveProfileData function +// This function saves the GPU profiling data to the specified path. void GPUProfiler::SaveProfileData() { if (profile_data_path_.empty()) { MS_LOG(WARNING) << "Profile data path is empty, skip save profile data."; } else { + // Create a GpuDataSaver instance GpuDataSaver dataSaver(step_trace_op_name_, all_step_start_end_info_); + + // Parse operation information and events for saving dataSaver.ParseOpInfo(op_info_map_); dataSaver.ParseEvent(events_); + + // Write the profile data to the specified path dataSaver.WriteFile(profile_data_path_, base_time_); + + // Save extra profiling data SaveExtraProfileData(); } } +// ClearInst function +// This function clears the GPU profiling instance and its associated data. void GPUProfiler::ClearInst() { op_info_map_.clear(); op_name_map_.clear(); @@ -534,6 +677,8 @@ void GPUProfiler::ClearInst() { cupti_activity_events_drop_count_ = 0l; } +// ActivityAllocBuffer function +// This function allocates a buffer for GPU activity records. void CUPTIAPI ActivityAllocBuffer(uint8_t **buffer, size_t *size, size_t *maxNumRecords) { auto gpu_profiler_inst = GPUProfiler::GetInstance(); if (gpu_profiler_inst == nullptr) { @@ -543,6 +688,8 @@ void CUPTIAPI ActivityAllocBuffer(uint8_t **buffer, size_t *size, size_t *maxNum gpu_profiler_inst->AllocBuffer(buffer, size, maxNumRecords); } +// ActivityProcessBuffer function +// This function processes the GPU activity buffer and records. void CUPTIAPI ActivityProcessBuffer(CUcontext ctx, uint32_t streamId, uint8_t *buffer, size_t size, size_t validSize) { PROFILER_ERROR_IF_NULLPTR(buffer); auto gpu_profiler_inst = GPUProfiler::GetInstance(); @@ -553,8 +700,10 @@ void CUPTIAPI ActivityProcessBuffer(CUcontext ctx, uint32_t streamId, uint8_t *b gpu_profiler_inst->ProcessBuffer(ctx, streamId, buffer, size, validSize); } -void ProcessActivityMemcpyRecord(Event *profilingData, CUpti_Activity *record, - CUpti_ActivityMemcpy *cupti_activity_memcpy) { +// ProcessActivityMemcpyRecord function +// This function processes the CUPTI activity record related to memory copy operations. +void ProcessActivityMemcpyRecord(Event *profilingData, CUpti_Activity *record, CUpti_ActivityMemcpy *cupti_activity_memcpy) { + // Determine the type of memory copy operation and set the profiling data accordingly switch (cupti_activity_memcpy->copyKind) { case CUPTI_ACTIVITY_MEMCPY_KIND_HTOD: profilingData->activity_type = ActivityType::kMemcpyH2D; @@ -599,6 +748,8 @@ void ProcessActivityMemcpyRecord(Event *profilingData, CUpti_Activity *record, } } +// HandleActivityMemcpyRecord function +// This function handles CUPTI activity records related to memory copy operations. void HandleActivityMemcpyRecord(Event *profilingData, CUpti_Activity *record) { CUpti_ActivityMemcpy *cupti_activity_memcpy = reinterpret_cast(record); ProcessActivityMemcpyRecord(profilingData, record, cupti_activity_memcpy); @@ -616,6 +767,8 @@ void HandleActivityMemcpyRecord(Event *profilingData, CUpti_Activity *record) { profilingData->memcpy_info.dst_kind = cupti_activity_memcpy->dstKind; } +// HandleActivityMemcpy2Record function +// This function handles CUPTI activity records related to memory copy operations (P2P). void HandleActivityMemcpy2Record(Event *profilingData, CUpti_Activity *record) { CUpti_ActivityMemcpy2 *memcpyP2P = reinterpret_cast(record); profilingData->activity_type = ActivityType::kMemcpyP2P; @@ -633,6 +786,8 @@ void HandleActivityMemcpy2Record(Event *profilingData, CUpti_Activity *record) { profilingData->memcpy_info.dst_kind = memcpyP2P->dstKind; } +// HandleActivityMemsetRecord function +// This function handles CUPTI activity records related to memory set operations. void HandleActivityMemsetRecord(Event *profilingData, CUpti_Activity *record) { CUpti_ActivityMemset *cupti_activity_memset = reinterpret_cast(record); profilingData->activity_type = ActivityType::kMemset; @@ -647,19 +802,32 @@ void HandleActivityMemsetRecord(Event *profilingData, CUpti_Activity *record) { profilingData->memcpy_info.bytes = cupti_activity_memset->bytes; } +// HandleActivityKernelRecord function +// This function handles CUpti_ActivityKernel4 records and populates profilingData with relevant information. void HandleActivityKernelRecord(Event *profilingData, CUpti_Activity *record) { + // Cast the CUpti_Activity record to CUpti_ActivityKernel4 type CUpti_ActivityKernel4 *kernel = reinterpret_cast(record); + + // Set the activity type and API type in profilingData profilingData->activity_type = ActivityType::kKernel; profilingData->api_type = CUPTIApiType::kActivity; + + // Get the kernel name and update it with the simplified name profilingData->kernel_name = GetKernelFunc(kernel->name); profilingData->kernel_name = GetKernelFuncName(profilingData->kernel_name); + + // Set the kernel type and timestamps profilingData->kernel_type = "cuLaunchKernel"; profilingData->start_time_stamp = kernel->start; profilingData->end_time_stamp = kernel->end; + + // Set the device, context, stream, and correlation IDs profilingData->device_id = kernel->deviceId; profilingData->context_id = kernel->contextId; profilingData->stream_id = kernel->streamId; profilingData->correlation_id = kernel->correlationId; + + // Populate kernel information profilingData->kernel_info.registers_per_thread = kernel->registersPerThread; profilingData->kernel_info.static_shared_memory = kernel->staticSharedMemory; profilingData->kernel_info.dynamic_shared_memory = kernel->dynamicSharedMemory; @@ -671,10 +839,17 @@ void HandleActivityKernelRecord(Event *profilingData, CUpti_Activity *record) { profilingData->kernel_info.grid_z = kernel->gridZ; } +// GPUProfiler::HandleActivityRecord function +// This function processes different types of CUpti_Activity records and delegates to specific record handlers. void GPUProfiler::HandleActivityRecord(CUpti_Activity *record) { + // Check for null record pointer PROFILER_ERROR_IF_NULLPTR(record); + + // Create an Event object for profiling data Event profilingData; profilingData.cb_id = 0; + + // Determine the type of the CUpti_Activity record and call the appropriate handler switch (record->kind) { case CUPTI_ACTIVITY_KIND_MEMCPY: { HandleActivityMemcpyRecord(&profilingData, record); @@ -698,48 +873,75 @@ void GPUProfiler::HandleActivityRecord(CUpti_Activity *record) { return; } + // Add the profilingData event to the profiler's data collection AddEvent(std::move(profilingData)); } +// GPUProfiler::SetStepTraceOpName function +// This function sets the step_trace_op_name_ field in the GPUProfiler. void GPUProfiler::SetStepTraceOpName(ProfilingTraceInfo trace_op_name) { step_trace_op_name_ = trace_op_name; } +// GPUProfiler::RegisterProfilingOp function +// This function registers a profiling operation in the profiler. void GPUProfiler::RegisterProfilingOp(std::shared_ptr node) { + // Check for null pointer and existing registration PROFILER_ERROR_IF_NULLPTR(node); if (profiling_op_.find(node->Name()) != profiling_op_.end()) { return; } + + // Initialize the profiling operation node->Init(); + + // Register the profiling operation profiling_op_[node->Name()] = node; } +// GPUProfiler::AllocBuffer function +// This function allocates memory for the GPU activity buffer. void CUPTIAPI GPUProfiler::AllocBuffer(uint8_t **buffer, size_t *size, size_t *maxNumRecords) { + // Check for null size and maxNumRecords pointers PROFILER_ERROR_IF_NULLPTR(size); PROFILER_ERROR_IF_NULLPTR(maxNumRecords); + + // Allocate memory for the activity buffer int stat = posix_memalign(reinterpret_cast(buffer), ALIGN_SIZE, BUF_SIZE); if (stat) { - MS_LOG(ERROR) << "Out of memory, activity buffer alloc failed."; + MS_LOG(ERROR) << "Out of memory, activity buffer allocation failed."; return; } - MS_LOG(DEBUG) << "Alloc activity buffer, buffer size: " << BUF_SIZE; + + // Log the allocation size + MS_LOG(DEBUG) << "Allocated activity buffer, buffer size: " << BUF_SIZE; + + // Set size and maxNumRecords values *size = BUF_SIZE; *maxNumRecords = 0; } +// GPUProfiler::ProcessBuffer function +// This function processes the GPU activity buffer and handles CUpti_Activity records. void CUPTIAPI GPUProfiler::ProcessBuffer(CUcontext ctx, uint32_t streamId, uint8_t *buffer, size_t size, size_t validSize) { + // Skip processing if profiling is not enabled if (!enable_flag_) { - MS_LOG(DEBUG) << "Profiler is not enable, skip to process activity record."; + MS_LOG(DEBUG) << "Profiler is not enabled, skipping processing of activity record."; free(buffer); return; } + CUptiResult status; CUpti_Activity *record = NULL; - MS_LOG(DEBUG) << "Process activity buffer, valid size:" << validSize << ",Stream ID:" << streamId; + // Log processing information + MS_LOG(DEBUG) << "Processing activity buffer, valid size: " << validSize << ", Stream ID: " << streamId; + + // Process each CUpti_Activity record in the buffer if (validSize > 0) { do { status = CuptiActivityGetNextRecord(buffer, validSize, &record); if (status == CUPTI_SUCCESS) { + // Handle the current record HandleActivityRecord(record); } else if (status == CUPTI_ERROR_MAX_LIMIT_REACHED) { break; @@ -748,7 +950,7 @@ void CUPTIAPI GPUProfiler::ProcessBuffer(CUcontext ctx, uint32_t streamId, uint8 } } while (1); - // report any records dropped from the queue + // Report any records dropped from the queue size_t dropped; CHECK_CUPTI_RET_WITH_ERROR(CuptiActivityGetNumDroppedRecords(ctx, streamId, &dropped), "CuptiActivityGetNumDroppedRecords"); @@ -757,18 +959,20 @@ void CUPTIAPI GPUProfiler::ProcessBuffer(CUcontext ctx, uint32_t streamId, uint8 } } + // Free the allocated buffer memory free(buffer); } +// PYBIND registration for GPUProfiler class REGISTER_PYBIND_DEFINE(GPUProfiler_, ([](const py::module *m) { (void)py::class_>(*m, "GPUProfiler") .def_static("get_instance", &GPUProfiler::GetInstance, "GPUProfiler get_instance.") - .def("init", &GPUProfiler::Init, py::arg("profile_data_path"), "init") - .def("stop", &GPUProfiler::Stop, "stop") + .def("init", &GPUProfiler::Init, py::arg("profile_data_path"), "Initialize GPUProfiler") + .def("stop", &GPUProfiler::Stop, "Stop GPUProfiler") .def("step_profiling_enable", &GPUProfiler::StepProfilingEnable, py::arg("enable_flag"), - "enable or disable step profiling") + "Enable or disable step profiling") .def("sync_enable", &GPUProfiler::SyncEnable, py::arg("enable_flag"), - "enable or disable synchronization profiling"); + "Enable or disable synchronization profiling"); })); } // namespace gpu } // namespace profiler diff --git a/mindspore/ccsrc/profiler/device/gpu/gpu_profiling_utils.cc b/mindspore/ccsrc/profiler/device/gpu/gpu_profiling_utils.cc index 77dcc5856c1..9654c6bcc51 100644 --- a/mindspore/ccsrc/profiler/device/gpu/gpu_profiling_utils.cc +++ b/mindspore/ccsrc/profiler/device/gpu/gpu_profiling_utils.cc @@ -25,34 +25,50 @@ namespace mindspore { namespace profiler { namespace gpu { +// Constants for environment variable names constexpr char kFpStartNode[] = "PROFILING_FP_START"; constexpr char kBpEndNode[] = "PROFILING_BP_END"; constexpr char kIterEndNode[] = "PROFILING_ITER_END"; constexpr auto kInitDatasetQueueOpName = "InitDataSetQueue"; +// Static member initialization bool ProfilingUtils::have_communication_op = false; ProfilingTraceInfo ProfilingUtils::profiling_trace = {"", "", ""}; std::unordered_map ProfilingUtils::is_first_step_map_ = {}; +// GetProfilingTraceFromEnv function +// This function extracts profiling trace information from the environment variables and the given graph. ProfilingTraceInfo ProfilingUtils::GetProfilingTraceFromEnv(NotNull graph_ptr) { - MS_LOG(INFO) << "get current subgraph op name start."; + // Log a message to indicate the start of the process + MS_LOG(INFO) << "Getting current subgraph op names start."; + + // Get the execution order of CNodes in the graph auto &cnode_exec_order = graph_ptr->execution_order(); + + // Check if there are no CNodes in the execution order if (cnode_exec_order.empty()) { + // Return an empty profiling trace return profiling_trace; } + // Initialize variables ProfilingTraceInfo empty_info; ProfilingTraceInfo last_graph_profiling_trace = profiling_trace; profiling_trace = empty_info; + + // Step 1: Extract profiling trace information from environment variables and the graph SetTraceIterEnd(cnode_exec_order); SetTraceFpStart(cnode_exec_order); SetTraceBpEnd(cnode_exec_order); GetTraceHccl(cnode_exec_order); - + + // Step 2: Output step trace op name status OutputStepTraceOpNameStatus(); + + // Step 3: Update the map to indicate that the current graph has been processed is_first_step_map_[graph_ptr->graph_id()] = false; - // If current graph has only one node, the bp_end will be empty, so select the last graph node. + // If the current graph has only one node, the bp_end will be empty, so select the last graph node. if (profiling_trace.trace_bp_end != "") { return profiling_trace; } else { @@ -60,19 +76,34 @@ ProfilingTraceInfo ProfilingUtils::GetProfilingTraceFromEnv(NotNull &cnode_exec_order) { + // Iterate through the CNodes in the execution order for (const auto &node : cnode_exec_order) { + // Check if the current node is a communication op if (common::AnfAlgo::IsCommunicationOp(node)) { + // Log the name of the HCCL node found + MS_LOG(INFO) << "[profiling]Get hccl node:" << node->fullname_with_scope(); + + // Add the HCCL node name to the list of custom nodes in the profiling trace MS_EXCEPTION_IF_NULL(node); if (std::find(profiling_trace.trace_custom_node.begin(), profiling_trace.trace_custom_node.end(), node->fullname_with_scope()) == profiling_trace.trace_custom_node.end()) { @@ -83,42 +114,60 @@ void ProfilingUtils::GetTraceHccl(const std::vector &cnode_exec_order) } } +// SetTraceFpStart function +// This function sets the trace_fp_start field in the profiling trace based on environment variables and the first CNode. void ProfilingUtils::SetTraceFpStart(const std::vector &cnode_exec_order) { + // Step 1: Check if the trace_fp_start environment variable is set const char *trace_fp_start = std::getenv(kFpStartNode); if (trace_fp_start != nullptr) { + // Set the trace_fp_start field from the environment variable profiling_trace.trace_fp_start = std::string(trace_fp_start); - MS_LOG(INFO) << "Set the Fp Start Op Name from Environment Variable:" << profiling_trace.trace_fp_start; + // Log the source of the trace_fp_start value + MS_LOG(INFO) << "Setting the Fp Start Op Name from Environment Variable:" << profiling_trace.trace_fp_start; return; } + // Step 2: Determine the trace_fp_start based on CNode order auto first_node = cnode_exec_order.front(); MS_EXCEPTION_IF_NULL(first_node); auto node_name = common::AnfAlgo::GetCNodeName(first_node); + + // If the first node is an "InitDataSetQueue" operation, skip it if (node_name == kInitDatasetQueueOpName) { return; } + // If the first node is "GetNext", check the node behind it if (node_name == kGetNextOpName) { if (cnode_exec_order.size() > 1) { profiling_trace.trace_fp_start = cnode_exec_order.at(1)->fullname_with_scope(); } else { + // Log a warning if there is no operation behind "GetNext" MS_LOG(WARNING) << "No Op Behind the GetNext Op" << std::endl; } } else { + // Set the trace_fp_start to the name of the first CNode profiling_trace.trace_fp_start = first_node->fullname_with_scope(); } } +// SetTraceBpEnd function +// This function sets the trace_bp_end field in the profiling trace based on environment variables and CNodes. void ProfilingUtils::SetTraceBpEnd(const std::vector &cnode_exec_order) { + // Step 1: Check if the trace_bp_end environment variable is set const char *trace_bp_end = std::getenv(kBpEndNode); if (trace_bp_end != nullptr) { + // Set the trace_bp_end field from the environment variable profiling_trace.trace_bp_end = std::string(trace_bp_end); - MS_LOG(INFO) << "Set the Bp End Op Name from Environment Variable:" << profiling_trace.trace_bp_end; + // Log the source of the trace_bp_end value + MS_LOG(INFO) << "Setting the Bp End Op Name from Environment Variable:" << profiling_trace.trace_bp_end; return; } + // Step 2: Determine the trace_bp_end based on CNode order and communication ops std::string bp_end_str; - // Contain hccl kernel (try to find the last communication op) + + // Look for the last communication op in the reverse order of execution auto iter = cnode_exec_order.rbegin(); while (iter != cnode_exec_order.rend()) { if (common::AnfAlgo::IsCommunicationOp(*iter)) { @@ -126,9 +175,10 @@ void ProfilingUtils::SetTraceBpEnd(const std::vector &cnode_exec_order } ++iter; } - // If find the communication op + + // If a communication op is found, store its input nodes' names if (iter != cnode_exec_order.rend()) { - // store communication op input nodes' name + // Store communication op input nodes' names std::set ar_input_node_names; size_t input_num = common::AnfAlgo::GetInputTensorNum(*iter); for (size_t i = 0; i < input_num; ++i) { @@ -136,9 +186,9 @@ void ProfilingUtils::SetTraceBpEnd(const std::vector &cnode_exec_order auto input_node = input_node_with_index.first; ar_input_node_names.insert(input_node->fullname_with_scope()); } - // start from previous node + // Start searching from the previous node ++iter; - // find input names in previous node + // Find input names in previous nodes while (iter != cnode_exec_order.rend()) { if (ar_input_node_names.find((*iter)->fullname_with_scope()) != ar_input_node_names.end()) { bp_end_str = (*iter)->fullname_with_scope(); @@ -148,27 +198,37 @@ void ProfilingUtils::SetTraceBpEnd(const std::vector &cnode_exec_order } } + // If bp_end_str is still empty and there are no communication ops, try to find the second last kernel name. if (bp_end_str.empty() && !have_communication_op) { bp_end_str = GetGraphSecondLastKernelName(cnode_exec_order); } + // Set the trace_bp_end field to the determined value if (!bp_end_str.empty()) { profiling_trace.trace_bp_end = bp_end_str; } } +// SetTraceIterEnd function +// This function sets the trace_iter_end field in the profiling trace based on environment variables and CNodes. void ProfilingUtils::SetTraceIterEnd(const std::vector &cnode_exec_order) { + // Step 1: Check if the trace_iter_end environment variable is set const char *trace_iter_end = std::getenv(kIterEndNode); if (trace_iter_end != nullptr) { + // Set the trace_iter_end field from the environment variable profiling_trace.trace_iter_end = std::string(trace_iter_end); - MS_LOG(INFO) << "Set the Iter End Op Name from Environment Variable:" << profiling_trace.trace_iter_end; + // Log the source of the trace_iter_end value + MS_LOG(INFO) << "Setting the Iter End Op Name from Environment Variable:" << profiling_trace.trace_iter_end; return; } + // Step 2: Determine the trace_iter_end based on CNode order auto iter_end = cnode_exec_order.rbegin(); profiling_trace.trace_iter_end = (*iter_end)->fullname_with_scope(); } +// GetGraphSecondLastKernelName function +// This function returns the name of the second last kernel in the given list of CNodes. std::string ProfilingUtils::GetGraphSecondLastKernelName(const std::vector &cnode_exec_order) { std::string second_last_kernel_name; auto iter = cnode_exec_order.rbegin(); @@ -180,6 +240,8 @@ std::string ProfilingUtils::GetGraphSecondLastKernelName(const std::vector graph_ptr); + + /** + * @brief Output step trace op name and status. + * + * This function outputs the op names and their status related to profiling. + */ static void OutputStepTraceOpNameStatus(); + + /** + * @brief Check if the current step is the first step of a graph. + * + * @param graph_id The identifier of the graph. + * @return True if it's the first step, false otherwise. + */ static bool IsFirstStep(const uint32_t graph_id); + /** + * @brief A flag indicating whether there are communication ops in the graph. + */ static bool have_communication_op; + + /** + * @brief Profiling trace information containing trace points. + */ static ProfilingTraceInfo profiling_trace; private: + /** + * @brief Set the trace point for the first forward-propagation (FP) operation. + * + * @param cnode_exec_order The execution order of CNodes in the graph. + */ static void SetTraceFpStart(const std::vector &cnode_exec_order); + + /** + * @brief Set the trace point for the last back-propagation (BP) operation. + * + * @param cnode_exec_order The execution order of CNodes in the graph. + */ static void SetTraceBpEnd(const std::vector &cnode_exec_order); + + /** + * @brief Set the trace point for the last iteration (ITER) operation. + * + * @param cnode_exec_order The execution order of CNodes in the graph. + */ static void SetTraceIterEnd(const std::vector &cnode_exec_order); + + /** + * @brief Get the name of the second last kernel in the graph. + * + * @param cnode_exec_order The execution order of CNodes in the graph. + * @return The name of the second last kernel. + */ static std::string GetGraphSecondLastKernelName(const std::vector &cnode_exec_order); + + /** + * @brief Get trace information related to HCCL communication operations. + * + * @param cnode_exec_order The execution order of CNodes in the graph. + */ static void GetTraceHccl(const std::vector &cnode_exec_order); + + /** + * @brief A map to keep track of whether a graph is the first step. + */ static std::unordered_map is_first_step_map_; }; + } // namespace gpu } // namespace profiler } // namespace mindspore diff --git a/mindspore/ccsrc/profiler/device/profiling.cc b/mindspore/ccsrc/profiler/device/profiling.cc index c984372c2ce..91b48e0327f 100644 --- a/mindspore/ccsrc/profiler/device/profiling.cc +++ b/mindspore/ccsrc/profiler/device/profiling.cc @@ -1,82 +1,71 @@ -/** - * Copyright 2021 Huawei Technologies Co., Ltd - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - */ - -#include "profiler/device/profiling.h" - -#include -#include -#include -#include "include/common/pybind_api/api_register.h" -#include "utils/log_adapter.h" -#include "include/common/utils/utils.h" -#if ENABLE_GPU -#include "profiler/device/gpu/gpu_profiling.h" -#endif -#if ENABLE_D -#include "profiler/device/ascend/ascend_profiling.h" -#endif - namespace mindspore { namespace profiler { -std::shared_ptr ProfilerManager::profiler_manager_inst_ = std::make_shared(); +// Function to get the host monotonic timestamp in microseconds +// Returns: uint64_t - Current host monotonic timestamp in microseconds uint64_t Profiler::GetHostMonoTimeStamp() const { struct timespec ts; + #if defined(_WIN32) || defined(_WIN64) + // On Windows, use CLOCK_MONOTONIC for timestamp if (clock_gettime(CLOCK_MONOTONIC, &ts) != 0) { MS_LOG(ERROR) << "Get host timestamp failed"; return 0; } #else + // On non-Windows systems, use CLOCK_MONOTONIC_RAW for timestamp if (clock_gettime(CLOCK_MONOTONIC_RAW, &ts) != 0) { MS_LOG(ERROR) << "Get host timestamp failed"; return 0; } #endif + constexpr uint64_t kNSecondInSecond = 1000000000; uint64_t cur_time_stamp = ts.tv_sec * kNSecondInSecond + ts.tv_nsec; return cur_time_stamp; } +// Function to get the real timestamp in microseconds +// Returns: uint64_t - Current real timestamp in microseconds uint64_t Profiler::GetRealTimeStamp() const { struct timeval tv = {0, 0}; (void)gettimeofday(&tv, NULL); int64_t kUSecondInSecond = 1000000; int64_t ts = kUSecondInSecond * static_cast(tv.tv_sec); ts += static_cast(tv.tv_usec); - // us timestamp + // Return the timestamp in microseconds return (uint64_t)ts; } +// Function to set runtime data for an operation +// Parameters: +// op_name (const std::string&) - The name of the operation +// time_elapsed (const float) - Time elapsed for the operation void Profiler::SetRunTimeData(const std::string &op_name, const float time_elapsed) { std::shared_lock lock(op_map_mutex_); auto iter = op_info_map_.find(op_name); if (iter != op_info_map_.end()) { + // Update the host cost time for the operation iter->second.op_host_cost_time += time_elapsed; } } +// Function to set runtime data with start timestamp and duration for an operation +// Parameters: +// op_name (const std::string&) - The name of the operation +// start (const uint64_t) - Start timestamp of the operation +// duration (const float) - Duration of the operation void Profiler::SetRunTimeData(const std::string &op_name, const uint64_t start, const float duration) { std::shared_lock lock(op_map_mutex_); auto iter = op_info_map_.find(op_name); if (iter != op_info_map_.end()) { + // Add start and duration information for the operation iter->second.start_duration.emplace_back(StartDuration({start, duration})); } } +// Function to record start and end information for one step +// Explanation: This function records the start and end information for one step of the computation graph. void Profiler::RecordOneStepStartEndInfo() { // Multi-graph dotting data is not supported. std::lock_guard locker(record_mutex_); @@ -86,7 +75,7 @@ void Profiler::RecordOneStepStartEndInfo() { step_start_end_info_.iter_start_op_name = step_start_end_info_vector_[0]; step_start_end_info_.fp_start_op_name = step_start_end_info_vector_[0]; - // If is the first step, the step_start_end_info_vector_ length is 1. + // If it is the first step, the step_start_end_info_vector_ length is 1. if (vector_size > 1) { // Iterate through step_start_end_info_vector_ for the repeat operator, which is the operator of the next step and // is preceded by iter_end_op of the current step. @@ -138,6 +127,9 @@ void Profiler::RecordOneStepStartEndInfo() { step_start_end_info_.fp_start_op_name = ""; } +// Function to record start and end information for one step of an operation +// Parameters: +// op_name (const std::string&) - The name of the operation void Profiler::RecordOneStepStartEndInfo(const std::string op_name) { std::lock_guard locker(record_mutex_); if (step_start_end_info_.iter_start_op_name.empty()) { @@ -157,11 +149,15 @@ void Profiler::RecordOneStepStartEndInfo(const std::string op_name) { step_start_end_info_vector_.push_back(op_name); } +// Get the singleton instance of ProfilerManager +// Returns: std::shared_ptr - Shared pointer to the ProfilerManager instance std::shared_ptr &ProfilerManager::GetInstance() { MS_EXCEPTION_IF_NULL(profiler_manager_inst_); return profiler_manager_inst_; } +// Get the profiling enable flag +// Returns: bool - Profiling enable flag bool ProfilerManager::GetProfilingEnableFlag() const { #if ENABLE_GPU return profiler::gpu::GPUProfiler::GetInstance()->GetEnableFlag(); @@ -174,6 +170,7 @@ bool ProfilerManager::GetProfilingEnableFlag() const { return false; } +// Record start and end information for one step (if GPU profiling is enabled) void ProfilerManager::RecordOneStepStartEndInfo() const { #if ENABLE_GPU auto gpu_profiler_inst = profiler::gpu::GPUProfiler::GetInstance(); @@ -183,6 +180,8 @@ void ProfilerManager::RecordOneStepStartEndInfo() const { #endif } +// Get profiling options as a string (if Ascend profiling is enabled) +// Returns: std::string - Profiling options as a string std::string ProfilerManager::GetProfilingOptions() const { #if ENABLE_D auto ascend_instance = profiler::ascend::AscendProfiler::GetInstance(); diff --git a/mindspore/ccsrc/profiler/device/profiling.h b/mindspore/ccsrc/profiler/device/profiling.h index 07d20bee4b4..e809c6fabd6 100644 --- a/mindspore/ccsrc/profiler/device/profiling.h +++ b/mindspore/ccsrc/profiler/device/profiling.h @@ -1,21 +1,11 @@ /** - * Copyright 2021 Huawei Technologies Co., Ltd - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. + * @file device_profiling.h + * @brief This header file contains declarations of classes and structures related to device profiling. */ #ifndef MINDSPORE_CCSRC_PROFILER_DEVICE_PROFILING_H #define MINDSPORE_CCSRC_PROFILER_DEVICE_PROFILING_H + #include #include #include @@ -30,32 +20,37 @@ namespace mindspore { namespace profiler { + +// Structure to store start timestamp, duration, and thread ID of an event struct StartDuration { - uint64_t start_timestamp = 0l; - float duration = 0l; - size_t tid = 0; + uint64_t start_timestamp = 0l; /**< Start timestamp of the event in microseconds. */ + float duration = 0l; /**< Duration of the event in microseconds. */ + size_t tid = 0; /**< Thread ID associated with the event. */ }; +// Structure to store start and end operation names for one step struct OneStepStartEndInfo { - std::string iter_start_op_name; - std::string fp_start_op_name; - std::string iter_end_op_name; + std::string iter_start_op_name; /**< Operation name for iteration start. */ + std::string fp_start_op_name; /**< Operation name for forward propagation start. */ + std::string iter_end_op_name; /**< Operation name for iteration end. */ }; +// Structure to store profiling information for an operation struct OpInfo { - std::string op_name; - float cupti_api_call_time = 0l; - float cupti_activity_time = 0l; - float op_host_cost_time = 0; - int op_kernel_api_count = 0; - int op_kernel_count = 0; - int op_count = 0; - StartDuration tmp_start_duration; - std::vector start_duration; - void *stream; - uint32_t pid; + std::string op_name; /**< Name of the operation. */ + float cupti_api_call_time = 0l; /**< Time spent on CUPTI API calls for the operation in microseconds. */ + float cupti_activity_time = 0l; /**< Time spent on CUPTI activities for the operation in microseconds. */ + float op_host_cost_time = 0; /**< Host-side cost time for the operation in microseconds. */ + int op_kernel_api_count = 0; /**< Number of kernel API calls for the operation. */ + int op_kernel_count = 0; /**< Number of kernels launched for the operation. */ + int op_count = 0; /**< Number of times the operation was executed. */ + StartDuration tmp_start_duration; /**< Temporary start duration for the operation. */ + std::vector start_duration; /**< Vector of start durations for the operation. */ + void *stream; /**< Stream associated with the operation. */ + uint32_t pid; /**< Process ID associated with the operation. */ }; +// Class to manage profiler settings and options class ProfilerManager { public: static std::shared_ptr &GetInstance(); @@ -63,53 +58,49 @@ class ProfilerManager { ~ProfilerManager() = default; ProfilerManager(const ProfilerManager &) = delete; ProfilerManager &operator=(const ProfilerManager &) = delete; - bool GetProfilingEnableFlag() const; - void RecordOneStepStartEndInfo() const; - std::string GetProfilingOptions() const; - - private: - static std::shared_ptr profiler_manager_inst_; + bool GetProfilingEnableFlag() const; /**< Get the profiling enable flag. */ + void RecordOneStepStartEndInfo() const; /**< Record one step start and end information. */ + std::string GetProfilingOptions() const; /**< Get profiling options as a string. */ }; +// Abstract base class for profiling class Profiler { public: Profiler() = default; virtual ~Profiler() = default; - virtual void Init(const std::string &profileDataPath) = 0; - virtual void Stop() = 0; - virtual void StepProfilingEnable(const bool enable_flag) = 0; - virtual void OpDataProducerEnd() = 0; - void RecordOneStepStartEndInfo(); - bool GetEnableFlag() const { return enable_flag_; } - std::string ProfileDataPath() const { return profile_data_path_; } - void RecordOneStepStartEndInfo(std::string op_name); - std::pair GetSingleOpLaunchTime() { return single_op_launch_start_time_end_time_; } - void SetSingleOpLaunchTime(const std::pair &launch_start_end) { - single_op_launch_start_time_end_time_ = launch_start_end; - } + virtual void Init(const std::string &profileDataPath) = 0; /**< Initialize the profiler. */ + virtual void Stop() = 0; /**< Stop the profiler. */ + virtual void StepProfilingEnable(const bool enable_flag) = 0; /**< Enable or disable step profiling. */ + virtual void OpDataProducerEnd() = 0; /**< Notify the end of operation data production. */ + void RecordOneStepStartEndInfo(); /**< Record start and end information for one step. */ + bool GetEnableFlag() const; /**< Get the enable flag for profiling. */ + std::string ProfileDataPath() const; /**< Get the path for profile data storage. */ + void RecordOneStepStartEndInfo(std::string op_name); /**< Record start and end information for one step of an operation. */ + std::pair GetSingleOpLaunchTime(); /**< Get the start and end time of a single operation launch. */ + void SetSingleOpLaunchTime(const std::pair &launch_start_end); /**< Set the start and end time of a single operation launch. */ protected: - void SetRunTimeData(const std::string &op_name, const float time_elapsed); - void SetRunTimeData(const std::string &op_name, const uint64_t start, const float duration); - uint64_t GetHostMonoTimeStamp() const; - // Get timestamp in us - uint64_t GetRealTimeStamp() const; - virtual void SaveProfileData() = 0; - virtual void ClearInst() = 0; - std::pair single_op_launch_start_time_end_time_; - bool enable_flag_ = false; - bool has_find = false; - uint32_t iter_end_op_index = 0; - std::string profile_data_path_; - std::unordered_map op_info_map_; - OneStepStartEndInfo step_start_end_info_; - std::vector all_step_start_end_info_; - std::vector step_start_end_info_vector_; - std::shared_mutex op_map_mutex_; - std::mutex record_mutex_; - bool init_flag_ = false; + void SetRunTimeData(const std::string &op_name, const float time_elapsed); /**< Set runtime data for an operation. */ + void SetRunTimeData(const std::string &op_name, const uint64_t start, const float duration); /**< Set runtime data with start timestamp and duration for an operation. */ + uint64_t GetHostMonoTimeStamp() const; /**< Get the host monotonic timestamp. */ + uint64_t GetRealTimeStamp() const; /**< Get the real timestamp in microseconds. */ + virtual void SaveProfileData() = 0; /**< Save the profile data. */ + virtual void ClearInst() = 0; /**< Clear the profiler instance. */ + std::pair single_op_launch_start_time_end_time_; /**< Pair of start and end times for a single operation launch. */ + bool enable_flag_ = false; /**< Flag indicating whether profiling is enabled. */ + bool has_find = false; /**< Flag indicating whether an operation has been found. */ + uint32_t iter_end_op_index = 0; /**< Index of iteration end operation. */ + std::string profile_data_path_; /**< Path for profile data storage. */ + std::unordered_map op_info_map_; /**< Map to store profiling information for operations. */ + OneStepStartEndInfo step_start_end_info_; /**< Information about the start and end of one step. */ + std::vector all_step_start_end_info_; /**< Vector of start and end information for all steps. */ + std::vector step_start_end_info_vector_; /**< Vector of start and end information for steps. */ + std::shared_mutex op_map_mutex_; /**< Shared mutex for locking operation information map. */ + std::mutex record_mutex_; /**< Mutex for recording information. */ + bool init_flag_ = false; /**< Flag indicating whether the profiler has been initialized. */ }; + } // namespace profiler } // namespace mindspore -- 2.34.1