diff --git a/mindspore/ccsrc/profiler/device/gpu/gpu_data_saver.cc b/mindspore/ccsrc/profiler/device/gpu/gpu_data_saver.cc index 5c64620a8b7..4cce9f86fdb 100644 --- a/mindspore/ccsrc/profiler/device/gpu/gpu_data_saver.cc +++ b/mindspore/ccsrc/profiler/device/gpu/gpu_data_saver.cc @@ -19,6 +19,7 @@ #include "sys/stat.h" #include "utils/log_adapter.h" #include "utils/ms_utils.h" +#include "runtime/framework/actor/actor_common.h" namespace mindspore { namespace profiler { @@ -120,8 +121,11 @@ void GpuDataSaver::WriteFile(std::string out_path_dir, const BaseTime &start_tim WriteOpType(out_path_dir); WriteActivity(out_path_dir); WriteOpTimestamp(out_path_dir); - WriteStepTrace(out_path_dir); WriteStartTime(out_path_dir, start_time); + if (IsMindRTUsed()) + WriteStepTraceAsyncLaunchKernel(out_path_dir); + else + WriteStepTrace(out_path_dir); } void GpuDataSaver::WriteActivity(const std::string &saver_base_dir) { @@ -162,6 +166,82 @@ void GpuDataSaver::WriteActivity(const std::string &saver_base_dir) { } } +void GpuDataSaver::WriteStepTraceAsyncLaunchKernel(const std::string &saver_base_dir) { + std::string file_path = saver_base_dir + "/step_trace_profiling_" + device_id_ + ".txt"; + std::ofstream ofs(file_path); + // check if the file is writable + if (!ofs.is_open()) { + MS_LOG(WARNING) << "Open file '" << file_path << "' failed!"; + return; + } + + // write step trace time info into file + uint32_t step = 0; + uint64_t duration; + for (auto step_start_end : all_step_start_end_info_) { + auto iter_start_op_name = step_start_end.iter_start_op_name; + auto fp_op_name = step_start_end.fp_start_op_name; + auto iter_end_op_name = step_start_end.iter_end_op_name; + auto iter_start_op_timestamp = op_timestamps_map_.find(iter_start_op_name); + auto fp_op_timestamp = op_timestamps_map_.find(fp_op_name); + auto bp_end_op_timestamp = op_timestamps_map_.find(step_trace_op_name_.trace_bp_end); + auto iter_end_op_timestamp = op_timestamps_map_.find(iter_end_op_name); + + if (iter_end_op_name == "Default/InitDataSetQueue-op0") continue; + + if (iter_start_op_timestamp == op_timestamps_map_.end() || fp_op_timestamp == op_timestamps_map_.end() || + iter_end_op_timestamp == op_timestamps_map_.end() || bp_end_op_timestamp == op_timestamps_map_.end()) { + MS_LOG(ERROR) << "[profiling step trace] failed, do not find " << fp_op_name << " or " << iter_end_op_name << "or" + << step_trace_op_name_.trace_bp_end; + return; + } + if (iter_start_op_timestamp->second.size() <= step || fp_op_timestamp->second.size() <= step || + iter_end_op_timestamp->second.size() <= step || bp_end_op_timestamp->second.size() <= step) { + MS_LOG(ERROR) << "[profiling step trace] the number of fp/bp/iter_end timestamp not enough"; + return; + } + + try { + // write fp,bp and iter_end timestamp. + duration = iter_end_op_timestamp->second[step].duration * kTimeUnit; + uint64_t iter_end_timestamp = iter_end_op_timestamp->second[step].start_timestamp + duration; + ofs << iter_start_op_name << "," << iter_start_op_timestamp->second[step].start_timestamp << " " << fp_op_name + << "," << fp_op_timestamp->second[step].start_timestamp << " " << step_trace_op_name_.trace_bp_end << "," + << bp_end_op_timestamp->second[step].start_timestamp << " " << iter_end_op_name << "," << iter_end_timestamp; + + // write communication op info + for (auto op_name : step_trace_op_name_.trace_custom_node) { + // convert the time unit from 1ns to 10ns (keep the same with ascend) + auto iter_op_timestamp = op_timestamps_map_.find(op_name); + if (iter_op_timestamp == op_timestamps_map_.end()) { + MS_LOG(ERROR) << "[profiling step trace] failed, do not find " << fp_op_name << " or " << iter_end_op_name + << "or" << step_trace_op_name_.trace_bp_end; + return; + } + + if (iter_op_timestamp->second.size() <= step) { + MS_LOG(ERROR) << "[profiling step trace] the number of communication op timestamp not enough"; + return; + } + + duration = iter_op_timestamp->second[step].duration * kTimeUnit; + uint64_t end_timestamp = (duration + iter_op_timestamp->second[step].start_timestamp); + uint64_t start_timestamp = iter_op_timestamp->second[step].start_timestamp; + ofs << " " << op_name << "," << start_timestamp << "," << end_timestamp; + } + ofs << std::endl; + } catch (const std::exception &e) { + MS_LOG(ERROR) << "Write " << file_path << "failed:" << e.what(); + ofs.close(); + } + step++; + } + + ofs.close(); + ChangeFileMode(file_path); + MS_LOG(INFO) << "Write step trace infos into file: " << file_path; +} + void GpuDataSaver::WriteStepTrace(const std::string &saver_base_dir) { std::string file_path = saver_base_dir + "/step_trace_profiling_" + device_id_ + ".txt"; std::ofstream ofs(file_path); @@ -174,12 +254,12 @@ void GpuDataSaver::WriteStepTrace(const std::string &saver_base_dir) { // write step trace time info into file const uint32_t factor = 10; std::vector op_name_arr; - op_name_arr.push_back(step_trace_op_name.trace_fp_start); - op_name_arr.push_back(step_trace_op_name.trace_bp_end); - op_name_arr.push_back(step_trace_op_name.trace_iter_end); - if (!step_trace_op_name.trace_custom_node.empty()) { - auto start = step_trace_op_name.trace_custom_node.begin(); - auto end = step_trace_op_name.trace_custom_node.end(); + op_name_arr.push_back(step_trace_op_name_from_graph_.trace_fp_start); + op_name_arr.push_back(step_trace_op_name_from_graph_.trace_bp_end); + op_name_arr.push_back(step_trace_op_name_from_graph_.trace_iter_end); + if (!step_trace_op_name_from_graph_.trace_custom_node.empty()) { + auto start = step_trace_op_name_from_graph_.trace_custom_node.begin(); + auto end = step_trace_op_name_from_graph_.trace_custom_node.end(); std::copy(start, end, std::back_inserter(op_name_arr)); } for (auto op_name : op_name_arr) { @@ -227,8 +307,6 @@ void GpuDataSaver::WriteStartTime(const std::string &saver_base_dir, const BaseT ChangeFileMode(file_path); MS_LOG(INFO) << "Write profiler start time infos into file: " << file_path; } - -void GpuDataSaver::SetStepTraceOpName(ProfilingTraceInfo trace_op_name) { step_trace_op_name = trace_op_name; } } // namespace gpu } // namespace profiler } // namespace mindspore diff --git a/mindspore/ccsrc/profiler/device/gpu/gpu_data_saver.h b/mindspore/ccsrc/profiler/device/gpu/gpu_data_saver.h index 129b6e127b9..94b39b64011 100644 --- a/mindspore/ccsrc/profiler/device/gpu/gpu_data_saver.h +++ b/mindspore/ccsrc/profiler/device/gpu/gpu_data_saver.h @@ -63,7 +63,12 @@ using AllActivityInfos = std::unordered_map; // class GpuDataSaver : public DataSaver { public: - GpuDataSaver() = default; + GpuDataSaver() = delete; + + GpuDataSaver(ProfilingTraceInfo step_trace_op_name, const std::vector &all_step_start_end_info) + : step_trace_op_name_(step_trace_op_name), all_step_start_end_info_(all_step_start_end_info) { + step_trace_op_name_from_graph_ = step_trace_op_name; + } ~GpuDataSaver() = default; @@ -71,8 +76,6 @@ class GpuDataSaver : public DataSaver { GpuDataSaver &operator=(const GpuDataSaver &) = delete; - void SetStepTraceOpName(ProfilingTraceInfo trace_op_name); - void ParseEvent(const std::vector &events); void WriteFile(std::string out_path, const BaseTime &start_time); @@ -86,10 +89,14 @@ class GpuDataSaver : public DataSaver { void WriteStepTrace(const std::string &saver_base_dir); + void WriteStepTraceAsyncLaunchKernel(const std::string &saver_base_dir); + void WriteStartTime(const std::string &saver_base_dir, const BaseTime &start_time); AllActivityInfos activity_infos_; - ProfilingTraceInfo step_trace_op_name; + ProfilingTraceInfo step_trace_op_name_from_graph_; + ProfilingTraceInfo step_trace_op_name_; + const std::vector &all_step_start_end_info_; }; } // namespace gpu } // namespace profiler diff --git a/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.cc b/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.cc index b762de0764b..4850c5b4ddf 100644 --- a/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.cc +++ b/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.cc @@ -25,6 +25,7 @@ #include "pybind_api/api_register.h" #include "utils/log_adapter.h" #include "utils/utils.h" +#include "runtime/framework/actor/actor_common.h" namespace mindspore { namespace profiler { @@ -432,6 +433,8 @@ void GPUProfiler::OpDataProducerBegin(const std::string op_name, void *stream) { op_cupti_time_start_ = GetCUPTITimeStamp(); } SetRunTimeData(op_name, stream); + + if (IsMindRTUsed()) RecordOneStepStartEndInfo(op_name); } void GPUProfiler::OpDataProducerEnd() { @@ -487,8 +490,7 @@ void GPUProfiler::SaveProfileData() { if (profile_data_path_.empty()) { MS_LOG(WARNING) << "Profile data path is empty, skip save profile data."; } else { - GpuDataSaver dataSaver; - dataSaver.SetStepTraceOpName(step_trace_op_name); + GpuDataSaver dataSaver(step_trace_op_name, all_step_start_end_info_); dataSaver.ParseOpInfo(op_info_map_); dataSaver.ParseEvent(events_); dataSaver.WriteFile(profile_data_path_, base_time_); @@ -496,6 +498,30 @@ void GPUProfiler::SaveProfileData() { } } +void GPUProfiler::RecordOneStepStartEndInfo() { + std::lock_guard locker(record_mutex_); + step_start_end_info_.iter_end_timestamp = GetCUPTITimeStamp(); + all_step_start_end_info_.push_back(step_start_end_info_); + step_start_end_info_.iter_start_op_name = ""; + step_start_end_info_.fp_start_op_name = ""; +} + +void GPUProfiler::RecordOneStepStartEndInfo(const std::string op_name) { + std::lock_guard locker(record_mutex_); + if (step_start_end_info_.iter_start_op_name.empty()) { + step_start_end_info_.iter_start_op_name = op_name; + step_start_end_info_.fp_start_op_name = op_name; + } + + std::string fp_start_op_name = step_start_end_info_.fp_start_op_name; + + auto op_type_begin_iter = fp_start_op_name.rfind('/') + 1; + auto op_type_end_iter = fp_start_op_name.rfind('-'); + auto op_type = fp_start_op_name.substr(op_type_begin_iter, op_type_end_iter - op_type_begin_iter); + if (op_type == "InitDataSetQueue" || op_type == "GetNext") step_start_end_info_.fp_start_op_name = op_name; + step_start_end_info_.iter_end_op_name = op_name; +} + void GPUProfiler::ClearInst() { op_info_map_.clear(); op_name_map_.clear(); diff --git a/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.h b/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.h index ed817ea2f10..2ae1140f331 100644 --- a/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.h +++ b/mindspore/ccsrc/profiler/device/gpu/gpu_profiling.h @@ -132,6 +132,7 @@ class GPUProfiler : public Profiler { void ProcessEvents(); void RegisterProfilingOp(std::shared_ptr node); void SetStepTraceOpName(ProfilingTraceInfo trace_op_name); + void RecordOneStepStartEndInfo(); std::string ProfileDataPath() const { return profile_data_path_; } private: @@ -142,6 +143,7 @@ class GPUProfiler : public Profiler { void AddEvent(Event &&event); void SetRunTimeData(const std::string &op_name, void *stream); void FixOpNameByCorrelationId(Event *event); + void RecordOneStepStartEndInfo(std::string op_name); static std::shared_ptr profiler_inst_; bool enable_flag_ = false; @@ -174,6 +176,7 @@ class GPUProfiler : public Profiler { std::string profile_data_path_; std::map> profiling_op_; ProfilingTraceInfo step_trace_op_name; + std::mutex record_mutex_; }; } // namespace gpu } // namespace profiler diff --git a/mindspore/ccsrc/profiler/device/profiling.h b/mindspore/ccsrc/profiler/device/profiling.h index 0e5a48e79a8..643ecf93966 100644 --- a/mindspore/ccsrc/profiler/device/profiling.h +++ b/mindspore/ccsrc/profiler/device/profiling.h @@ -33,6 +33,14 @@ struct StartDuration { float duration = 0l; }; +struct OneStepStartEndInfo { + std::string iter_start_op_name; + std::string fp_start_op_name; + std::string iter_end_op_name; + uint64_t fp_start_timestamp = 0l; + uint64_t iter_end_timestamp = 0l; +}; + struct OpInfo { std::string op_name; float cupti_api_call_time = 0l; @@ -67,6 +75,8 @@ class Profiler { bool enable_flag_ = false; std::string profile_data_path_; std::unordered_map op_info_map_; + OneStepStartEndInfo step_start_end_info_; + std::vector all_step_start_end_info_; }; } // namespace profiler } // namespace mindspore diff --git a/mindspore/ccsrc/runtime/framework/actor/recorder_actor.cc b/mindspore/ccsrc/runtime/framework/actor/recorder_actor.cc index 5b946b3afe2..fb54e94ad35 100644 --- a/mindspore/ccsrc/runtime/framework/actor/recorder_actor.cc +++ b/mindspore/ccsrc/runtime/framework/actor/recorder_actor.cc @@ -65,6 +65,12 @@ void RecorderActor::RecordInfo(const std::string op_name, const KernelLaunchInfo void RecorderActor::RecordOnStepEnd(OpContext *op_context) { MS_EXCEPTION_IF_NULL(op_context); // todo clear +#if ENABLE_GPU + // Record fp_start and iter_end op name and timestamp at the step end. (GPU) + auto profiler_inst = profiler::gpu::GPUProfiler::GetInstance(); + MS_EXCEPTION_IF_NULL(profiler_inst); + if (profiler_inst->GetEnableFlag()) profiler_inst->RecordOneStepStartEndInfo(); +#endif } } // namespace runtime diff --git a/mindspore/ccsrc/runtime/framework/actor/recorder_actor.h b/mindspore/ccsrc/runtime/framework/actor/recorder_actor.h index 9a0fd24e199..6fef41849fb 100644 --- a/mindspore/ccsrc/runtime/framework/actor/recorder_actor.h +++ b/mindspore/ccsrc/runtime/framework/actor/recorder_actor.h @@ -22,6 +22,9 @@ #include "runtime/framework/actor/actor_common.h" #include "runtime/framework/device_tensor_store.h" #include "runtime/hardware/device_context.h" +#if ENABLE_GPU +#include "profiler/device/gpu/gpu_profiling.h" +#endif namespace mindspore { namespace runtime { @@ -39,6 +42,7 @@ class RecorderActor : public ActorBase { OpContext *op_context); // Clear memory recorder at the step end. + // Record fp_start and iter_end op name and timestamp at the step end. (GPU) void RecordOnStepEnd(OpContext *op_context); }; } // namespace runtime diff --git a/mindspore/ccsrc/runtime/hardware/gpu/gpu_device_context.cc b/mindspore/ccsrc/runtime/hardware/gpu/gpu_device_context.cc index f2c35d16878..45be9ddfecd 100644 --- a/mindspore/ccsrc/runtime/hardware/gpu/gpu_device_context.cc +++ b/mindspore/ccsrc/runtime/hardware/gpu/gpu_device_context.cc @@ -372,6 +372,7 @@ bool GPUDeviceContext::LaunchKernelWithProfiling(const CNodePtr &kernel, const s const std::vector &workspace, const std::vector &outputs) const { MS_EXCEPTION_IF_NULL(kernel); + auto kernel_graph = std::dynamic_pointer_cast(kernel->func_graph()); MS_EXCEPTION_IF_NULL(kernel_graph); diff --git a/mindspore/profiler/parser/integrator.py b/mindspore/profiler/parser/integrator.py index 7fa35146453..ebbb67f488c 100644 --- a/mindspore/profiler/parser/integrator.py +++ b/mindspore/profiler/parser/integrator.py @@ -733,6 +733,7 @@ class GpuTimelineGenerator(BaseTimelineGenerator): _output_op_execute_time_file_path = "gpu_op_execute_timestamp_{}.txt" _output_activity_execute_time_file_path = "activity_execute_timestamp_{}.txt" _output_gpu_activity_info_file_path = "gpu_activity_data_{}.csv" + _step_trace_original_filename = 'step_trace_profiling_{}.txt' _activity_keys_list = [] def __init__(self, profiling_dir, device_id): @@ -811,7 +812,12 @@ class GpuTimelineGenerator(BaseTimelineGenerator): # Generate step time. factor_start_time_uint_to_duration = 1e-3 self._set_step_start_and_end_op_name(timeline_list) - step_time_list = self._get_step_time_list(timeline_list, factor_start_time_uint_to_duration) + # Fit gpu kernel async launch solution. + if self.is_gpu_kernel_async_launch(): + step_time_list = self._get_step_time_list_from_step_trace() + else: + step_time_list = self._get_step_time_list(timeline_list, factor_start_time_uint_to_duration) + # Add Scope Name. default_scope_name_time_list = self._get_scope_name_time_list(timeline_list, "Default", factor_start_time_uint_to_duration) @@ -934,6 +940,54 @@ class GpuTimelineGenerator(BaseTimelineGenerator): return True return False + def _get_step_time_list_from_step_trace(self): + """Produce the time of each step based on step_trace_profiling file.""" + # Record the time of each step. + step_time_list = [] + step_start_op_name = [] + step_end_op_name = [] + step_num = 1 + tid = "Steps" + step_trace_profiling_path = self._get_and_validate_path( + self._step_trace_original_filename + ) + + try: + with open(step_trace_profiling_path, 'r') as f_obj: + for line in f_obj: + line = line.strip().split() + step_start_op_name.append(line[0].split(',')[0]) + step_end_op_name.append(line[3].split(',')[0]) + cur_step_start_time = float(line[0].split(',')[1]) + cur_step_end_time = float(line[3].split(',')[1]) + # convert duration time unit from ns to us. + cur_step_duration_time = (cur_step_end_time - cur_step_start_time) / 1e3 + step_time_item = [str(step_num), tid, cur_step_start_time, cur_step_duration_time] + step_time_list.append(step_time_item) + step_num += 1 + except (IOError, OSError) as err: + logger.error(f'Error occurred when read {step_trace_profiling_path}: {err}') + raise ProfilerIOException + + return step_time_list + + def is_gpu_kernel_async_launch(self): + """Recognize the solution that launch the gpu kernel async.""" + step_trace_profiling_path = self._get_and_validate_path( + self._step_trace_original_filename + ) + try: + with open(step_trace_profiling_path, 'r') as f_obj: + line = next(f_obj) + first_string = line.strip().split()[0] + # the data format of launch the gpu kernel async is "Default/op1,160123 op-name" + # otherwise, the data format is "Default/op1 160123,12 " + return bool(len(first_string.split(',')) == 2) + except (IOError, OSError) as err: + logger.error(f'Error occurred when read {step_trace_profiling_path}: {err}') + raise ProfilerIOException + + class AscendTimelineGenerator(BaseTimelineGenerator): """Generate ascend Timeline data from file.""" _display_filename = 'ascend_timeline_display_{}.json' diff --git a/mindspore/profiler/parser/step_trace_parser.py b/mindspore/profiler/parser/step_trace_parser.py index c50c6d98890..f1755ba3dd7 100644 --- a/mindspore/profiler/parser/step_trace_parser.py +++ b/mindspore/profiler/parser/step_trace_parser.py @@ -20,6 +20,7 @@ import stat import struct from collections import namedtuple from decimal import Decimal +from abc import abstractmethod from mindspore.profiler.common.exceptions.exceptions import ProfilerPathErrorException, \ JobIdMismatchException, ProfilerIOException, ProfilerRawFileException @@ -43,9 +44,11 @@ class BaseStepTraceParser: job_id (int): The job id used to define the start of new step. Default: 0. skip_first_step (bool): Whether skip the first step or not. is_training_mode (bool): Whether in training mode or not. + is_gpu_kernel_async_launch (bool): Whether is gpu kernel async launch or not. """ - def __init__(self, input_dir, output_file_path, job_id=0, skip_first_step=False, is_training_mode=True): + def __init__(self, input_dir, output_file_path, job_id=0, skip_first_step=False, + is_training_mode=True, is_gpu_kernel_async_launch=False): self._input_dir = input_dir self._output_path = output_file_path self._job_id = job_id @@ -56,6 +59,7 @@ class BaseStepTraceParser: self._tag_map = {} self._is_training_mode = is_training_mode self._step_end_tag_id = 255 + self._is_gpu_kernel_async_launch = is_gpu_kernel_async_launch @property def output_file(self): @@ -78,7 +82,10 @@ class BaseStepTraceParser: """Parse step trace files and save the result.""" try: source_files = self._get_step_trace_files() - self._parse(source_files) + if self._is_gpu_kernel_async_launch: + self._parse_async_launch(source_files) + else: + self._parse(source_files) self._save() except IOError as err: log.warning(err) @@ -175,6 +182,7 @@ class BaseStepTraceParser: log.info("Find %d step trace files.", len(file_paths)) return file_paths + @abstractmethod def _parse(self, source_files): """Parse source step trace files.""" @@ -368,34 +376,48 @@ class GpuStepTraceParser(BaseStepTraceParser): dict, parsed point info. """ fp_start, bp_end = 0, 1 + all_step_points = [] + all_step_fp = [] + all_step_bp = [] try: - with open(source_file, 'r') as f: - lines = f.readlines() - fp_start_name = lines[fp_start].split()[0] - bp_end_name = lines[bp_end].split()[0] + with open(source_file, 'r') as f_obj: + if self._is_gpu_kernel_async_launch: + for line in f_obj: + line = line.strip().split() + all_step_fp.append(line[1].split(',')[0]) + all_step_bp.append(line[2].split(',')[0]) + else: + lines = f_obj.readlines() + all_step_fp.append(lines[fp_start].split()[0]) + all_step_bp.append(lines[bp_end].split()[0]) except (IOError, OSError) as err: log.warning(f'Failed to read {source_file}', err) raise ProfilerIOException - if self._is_training_mode: - points = { - 'fp_start': fp_start_name, - 'bp_end': bp_end_name - } - else: - points = { - 'fp_start': fp_start_name, - } - if os.path.exists(output_path): - return points + for fp_name, bp_name in zip(all_step_fp, all_step_bp): + if self._is_training_mode: + points = { + 'fp_start': fp_name, + 'bp_end': bp_name + } + else: + points = { + 'fp_start': fp_name, + } + all_step_points.append(points) + try: with open(output_path, 'w') as json_file: - json.dump(points, json_file) + if self._is_gpu_kernel_async_launch: + json.dump(all_step_points, json_file) + else: + json.dump(all_step_points[0], json_file) os.chmod(output_path, stat.S_IREAD | stat.S_IWRITE) except (IOError, OSError) as err: log.warning('Failed to save point info. %s', err) raise ProfilerIOException - return points + + return all_step_points[0] def _get_step_trace_files(self): """Get step trace files.""" @@ -454,6 +476,43 @@ class GpuStepTraceParser(BaseStepTraceParser): self._record_average_info() log.info("Finish to parse step trace file.") + def _parse_async_launch(self, source_file): + """Parse source step trace files generated from async launch kernel.""" + log.info("Start to parse step trace file.") + source_file = validate_and_normalize_path(source_file) + + try: + with open(source_file, 'r') as f_obj: + for line in f_obj: + line = line.strip().split() + start_time = int(line[0].split(',')[1][:-1]) + fp_time = int(line[1].split(',')[1][:-1]) + bp_time = int(line[2].split(',')[1][:-1]) + end_time = int(line[3].split(',')[1][:-1]) + reduce_info = {} + reduce_time_info = [] + for reduce_item in line[4:]: + # add communication op start and end time, time unit from ns to 10ns. + reduce_time_info.append(reduce_item.split(',')[1][:-1]) + reduce_time_info.append(reduce_item.split(',')[2][:-1]) + step_trace = { + 'start': start_time, + 'fp': fp_time, + 'bp': bp_time, + 'end': end_time + } + if reduce_time_info: + reduce_info['ops'] = reduce_time_info + step_trace['reduce'] = reduce_info + self._record_trace_event(step_trace) + + except (IOError, OSError) as err: + log.warning(f'Failed to read {source_file}', err) + raise ProfilerIOException + + self._record_average_info() + log.info("Finish to parse step trace file.") + def _get_single_reduce_event_info(self, field_name, start_point, end_point): """ Get single reduce info. diff --git a/mindspore/profiler/profiling.py b/mindspore/profiler/profiling.py index b9ef793ae00..cf18a18cb6f 100644 --- a/mindspore/profiler/profiling.py +++ b/mindspore/profiler/profiling.py @@ -351,7 +351,10 @@ class Profiler: # analyse step trace info try: - self._analyse_step_trace(is_training_mode_flag=timeline_generator.check_op_name('Gradients')) + self._analyse_step_trace( + is_training_mode_flag=timeline_generator.check_op_name('Gradients'), + is_gpu_kernel_async_launch_flag=timeline_generator.is_gpu_kernel_async_launch() + ) except ProfilerException as err: logger.warning(err.message) @@ -363,7 +366,8 @@ class Profiler: 'otherwise, this warning can be ignored.' ) - def _analyse_step_trace(self, source_path=None, framework_parser=None, is_training_mode_flag=True): + def _analyse_step_trace(self, source_path=None, framework_parser=None, is_training_mode_flag=True, + is_gpu_kernel_async_launch_flag=False): """ Analyse step trace data and save the result. @@ -380,7 +384,7 @@ class Profiler: ) point_info_file_path = os.path.join( self._output_path, - 'step_trace_point_info.json' + f'step_trace_point_info_{self._dev_id}.json' ) step_trace_intermediate_file_path = validate_and_normalize_path(step_trace_intermediate_file_path) point_info_file_path = validate_and_normalize_path(point_info_file_path) @@ -392,7 +396,8 @@ class Profiler: ) parser = GpuStepTraceParser(input_dir=input_file_path, output_file_path=step_trace_intermediate_file_path, - is_training_mode=is_training_mode_flag) + is_training_mode=is_training_mode_flag, + is_gpu_kernel_async_launch=is_gpu_kernel_async_launch_flag) parser.parse_and_save() point_info = parser.record_point_info(input_file_path, point_info_file_path) else: