Fit Gpu LoopCount for profiler module

This commit is contained in:
gzhcv 2021-06-08 11:17:37 +08:00
parent e7ea93dacd
commit 001985ca25
11 changed files with 292 additions and 39 deletions

View File

@ -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<std::string> 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

View File

@ -63,7 +63,12 @@ using AllActivityInfos = std::unordered_map<uint32_t, DeviceActivityInfos>; //
class GpuDataSaver : public DataSaver {
public:
GpuDataSaver() = default;
GpuDataSaver() = delete;
GpuDataSaver(ProfilingTraceInfo step_trace_op_name, const std::vector<OneStepStartEndInfo> &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<Event> &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<OneStepStartEndInfo> &all_step_start_end_info_;
};
} // namespace gpu
} // namespace profiler

View File

@ -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<std::mutex> 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<std::mutex> 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();

View File

@ -132,6 +132,7 @@ class GPUProfiler : public Profiler {
void ProcessEvents();
void RegisterProfilingOp(std::shared_ptr<ProfilingOp> 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<GPUProfiler> profiler_inst_;
bool enable_flag_ = false;
@ -174,6 +176,7 @@ class GPUProfiler : public Profiler {
std::string profile_data_path_;
std::map<std::string, std::shared_ptr<ProfilingOp>> profiling_op_;
ProfilingTraceInfo step_trace_op_name;
std::mutex record_mutex_;
};
} // namespace gpu
} // namespace profiler

View File

@ -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<std::string, OpInfo> op_info_map_;
OneStepStartEndInfo step_start_end_info_;
std::vector<OneStepStartEndInfo> all_step_start_end_info_;
};
} // namespace profiler
} // namespace mindspore

View File

@ -65,6 +65,12 @@ void RecorderActor::RecordInfo(const std::string op_name, const KernelLaunchInfo
void RecorderActor::RecordOnStepEnd(OpContext<DeviceTensor> *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

View File

@ -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<DeviceTensor> *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<DeviceTensor> *op_context);
};
} // namespace runtime

View File

@ -359,6 +359,7 @@ bool GPUDeviceContext::LaunchKernelWithProfiling(const CNodePtr &kernel, const s
const std::vector<AddressPtr> &workspace,
const std::vector<AddressPtr> &outputs) const {
MS_EXCEPTION_IF_NULL(kernel);
auto kernel_graph = std::dynamic_pointer_cast<KernelGraph>(kernel->func_graph());
MS_EXCEPTION_IF_NULL(kernel_graph);

View File

@ -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'

View File

@ -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.

View File

@ -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: