From 5a817d7444d50a0440382c3eaf32467f9d87b00c Mon Sep 17 00:00:00 2001 From: askmiao Date: Tue, 18 Aug 2020 19:56:24 +0800 Subject: [PATCH] add log and modify log level for gpu profiler --- .../profiler/device/gpu/gpu_profiling.cc | 51 ++++++++++--------- .../runtime/device/gpu/gpu_kernel_runtime.cc | 4 +- 2 files changed, 28 insertions(+), 27 deletions(-) diff --git a/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.cc b/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.cc index 3a5efa9822..0c0a7b54e7 100644 --- a/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.cc +++ b/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.cc @@ -108,7 +108,7 @@ void CUPTICallBackFunc(void *user_data, CUpti_CallbackDomain domain, CUpti_Callb PROFILER_ERROR_IF_NULLPTR(cb_data); if (cb_data->context == nullptr) { - MS_LOG(DEBUG) << "callback data context is null , correlation Id:" << cb_data->correlationId + MS_LOG(DEBUG) << "Callback data context is null , correlation Id:" << cb_data->correlationId << " callback id:" << cb_id; return; } @@ -320,12 +320,12 @@ void GPUProfiler::OpsParser() { } } - MS_LOG(INFO) << "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,|" - ",mem_bytes,registers_per_thread,static_shared_memory,dynamic_shared_memory" - ",block_x,block_y,block_z,grid_x,grid_y,grid_z" - << std::endl; + 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,|" + ",mem_bytes,registers_per_thread,static_shared_memory,dynamic_shared_memory" + ",block_x,block_y,block_z,grid_x,grid_y,grid_z" + << std::endl; std::vector> order_vec(op_info_map_.begin(), op_info_map_.end()); @@ -335,20 +335,20 @@ void GPUProfiler::OpsParser() { std::sort(order_vec.begin(), order_vec.end(), cmp_func); for (auto iter = order_vec.begin(); iter != order_vec.end(); iter++) { - MS_LOG(INFO) << "GPU_profiler" - << "," << iter->first << "," << iter->second.op_count << "," << iter->second.op_kernel_count << "," - << iter->second.op_kernel_api_count << "," - << "|," << iter->second.cupti_activity_time << "," << iter->second.cupti_api_call_time << "," - << round(iter->second.op_host_cost_time) << "," - << "|," << round(iter->second.cupti_activity_time / iter->second.op_count) << "," - << round(iter->second.cupti_api_call_time / iter->second.op_count) << "," - << round(iter->second.op_host_cost_time / iter->second.op_count) << "," - << "|," << iter->second.memcpy_info.bytes << "," << iter->second.kernel_info.registers_per_thread - << "," << iter->second.kernel_info.static_shared_memory << "," - << iter->second.kernel_info.dynamic_shared_memory << "," << iter->second.kernel_info.block_x << "," - << iter->second.kernel_info.block_y << "," << iter->second.kernel_info.block_z << "," - << iter->second.kernel_info.grid_x << "," << iter->second.kernel_info.grid_y << "," - << iter->second.kernel_info.grid_z << std::endl; + MS_LOG(DEBUG) << "GPU_profiler" + << "," << iter->first << "," << iter->second.op_count << "," << iter->second.op_kernel_count << "," + << iter->second.op_kernel_api_count << "," + << "|," << iter->second.cupti_activity_time << "," << iter->second.cupti_api_call_time << "," + << iter->second.op_host_cost_time << "," + << "|," << round(iter->second.cupti_activity_time / iter->second.op_count) << "," + << round(iter->second.cupti_api_call_time / iter->second.op_count) << "," + << round(iter->second.op_host_cost_time / iter->second.op_count) << "," + << "|," << iter->second.memcpy_info.bytes << "," << iter->second.kernel_info.registers_per_thread + << "," << iter->second.kernel_info.static_shared_memory << "," + << iter->second.kernel_info.dynamic_shared_memory << "," << iter->second.kernel_info.block_x << "," + << iter->second.kernel_info.block_y << "," << iter->second.kernel_info.block_z << "," + << iter->second.kernel_info.grid_x << "," << iter->second.kernel_info.grid_y << "," + << iter->second.kernel_info.grid_z << std::endl; } } @@ -454,6 +454,7 @@ void GPUProfiler::OpDataProducerEnd() { op_host_time_stop_ = GetHostTimeStamp(); op_time_elapsed = (op_host_time_stop_ - op_host_time_start_) / kTimeUnit; } + MS_LOG(DEBUG) << "Host Time Elapsed(us)," << op_name_ << "," << op_time_elapsed; SetRunTimeData(op_name_, op_time_elapsed); } @@ -478,7 +479,7 @@ void GPUProfiler::Stop() { void GPUProfiler::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 save profile data."; } else { DataSaver dataSaver; dataSaver.ParseOpInfo(op_info_map_); @@ -638,7 +639,7 @@ void GPUProfiler::HandleActivityRecord(CUpti_Activity *record) { break; } default: - MS_LOG(WARNING) << "unknown activity type!"; + MS_LOG(WARNING) << "Unknown activity type!"; return; } @@ -651,7 +652,7 @@ void CUPTIAPI GPUProfiler::AllocBuffer(uint8_t **buffer, size_t *size, size_t *m MS_LOG(ERROR) << "Out of memory, activity buffer alloc failed."; return; } - + MS_LOG(DEBUG) << "Alloc activity buffer, buffer size: " << BUF_SIZE; *size = BUF_SIZE; *maxNumRecords = 0; } @@ -659,12 +660,14 @@ void CUPTIAPI GPUProfiler::AllocBuffer(uint8_t **buffer, size_t *size, size_t *m void CUPTIAPI GPUProfiler::ProcessBuffer(CUcontext ctx, uint32_t streamId, uint8_t *buffer, size_t size, size_t validSize) { if (!enable_flag_) { + MS_LOG(DEBUG) << "Profiler is not enable, skip to process activity record."; free(buffer); return; } CUptiResult status; CUpti_Activity *record = NULL; + MS_LOG(DEBUG) << "Process activity buffer, valid size:" << validSize << ",Stream ID:" << streamId; if (validSize > 0) { do { status = CuptiActivityGetNextRecord(buffer, validSize, &record); diff --git a/mindspore/ccsrc/runtime/device/gpu/gpu_kernel_runtime.cc b/mindspore/ccsrc/runtime/device/gpu/gpu_kernel_runtime.cc index cff59023e1..eca69aa8dc 100644 --- a/mindspore/ccsrc/runtime/device/gpu/gpu_kernel_runtime.cc +++ b/mindspore/ccsrc/runtime/device/gpu/gpu_kernel_runtime.cc @@ -672,9 +672,7 @@ bool GPUKernelRuntime::LaunchKernelDynamic(const session::KernelGraph *graph, De int exec_order = 1; auto profiler_inst = profiler::gpu::GPUProfiler::GetInstance(); - if (profiler_inst == nullptr) { - MS_LOG(ERROR) << "gpu profiler instance is nullptr"; - } + MS_EXCEPTION_IF_NULL(profiler_inst); for (const auto &kernel : kernels) { auto kernel_mod = AnfAlgo::GetKernelMod(kernel);