mirror of
https://github.com/saymrwulf/onnxruntime.git
synced 2026-07-30 20:18:08 +00:00
Add more statistics in transformer profiler (#9578)
* add statistics of cuda kernel * grouping by provider + operator * add --input to import profiling result
This commit is contained in:
Tianlei Wu
GitHub
parent
85874bb315
commit
a01a3f2552
1 changed files with 188 additions and 58 deletions
|
|
@ -8,6 +8,8 @@ from onnx import TensorProto
|
|||
This profiler tool could run a transformer model and print out the kernel time spent on each Node of the model.
|
||||
Example of profiling of longformer model:
|
||||
python profiler.py --model longformer-base-4096_fp32.onnx --batch_size 1 --sequence_length 4096 --global_length 8 --samples 1000 --thread_num 8 --dummy_inputs longformer --use_gpu
|
||||
Example of importing profile result file from onnxruntime_perf_test:
|
||||
python profiler.py --input profile_2021-10-25_12-02-41.json
|
||||
"""
|
||||
|
||||
NODES_TYPE_CONTAINING_SUBGRAPH = ['Scan', 'Loop', 'If']
|
||||
|
|
@ -15,7 +17,12 @@ NODES_TYPE_CONTAINING_SUBGRAPH = ['Scan', 'Loop', 'If']
|
|||
|
||||
def parse_arguments(argv=None):
|
||||
parser = argparse.ArgumentParser()
|
||||
parser.add_argument('-m', '--model', required=True, type=str, help="onnx model path")
|
||||
|
||||
parser.add_argument('-i', '--input', required=False,
|
||||
type=str,
|
||||
help="Set the input file for reading the profile results")
|
||||
|
||||
parser.add_argument('-m', '--model', required=False, type=str, help="onnx model path to run profiling. Required when --input is not specified.")
|
||||
|
||||
parser.add_argument('-b', '--batch_size', required=False, type=int, default=1, help="batch size of input")
|
||||
|
||||
|
|
@ -128,7 +135,88 @@ def load_profile_json(profile_file):
|
|||
return sess_time
|
||||
|
||||
|
||||
def parse_profile_results(sess_time, kernel_time_only=False, threshold=0):
|
||||
def parse_kernel_results(sess_time, threshold=0):
|
||||
"""Parse profile data and output nodes in two sections - nodes in the original order, and top expensive nodes.
|
||||
|
||||
Args:
|
||||
sess_time (List[Dict]): profile data
|
||||
kernel_time_only (bool, optional): Only include items for kernel time. Defaults to False.
|
||||
threshold (int, optional): Minimum ratio of duration among all. Defaults to 0.
|
||||
|
||||
Returns:
|
||||
List[str]: lines of string for output.
|
||||
"""
|
||||
kernel_name_to_op_name = {}
|
||||
kernel_time = {}
|
||||
kernel_freq = {}
|
||||
total = 0
|
||||
session_init = False
|
||||
for item in sess_time:
|
||||
# Skip all MemcpyHostToDevice before session_initialization
|
||||
if item["cat"] == "Session" and item["name"] == "session_initialization":
|
||||
session_init = True
|
||||
if not session_init:
|
||||
continue
|
||||
|
||||
if item["cat"] == "Kernel" and "dur" in item and "args" in item and "op_name" in item["args"]:
|
||||
kernel_name = item["name"]
|
||||
|
||||
op_name = item["args"]["op_name"]
|
||||
if op_name in NODES_TYPE_CONTAINING_SUBGRAPH:
|
||||
continue
|
||||
|
||||
# Handle MemcpyHostToDevice and MemcpyDeviceToHost here
|
||||
if not op_name:
|
||||
op_name = f"({kernel_name})"
|
||||
|
||||
if kernel_name in kernel_time:
|
||||
kernel_time[kernel_name] += item["dur"]
|
||||
kernel_freq[kernel_name] += 1
|
||||
else:
|
||||
kernel_time[kernel_name] = item["dur"]
|
||||
kernel_freq[kernel_name] = 1
|
||||
kernel_name_to_op_name[kernel_name] = op_name
|
||||
|
||||
total += item["dur"]
|
||||
|
||||
if not kernel_time:
|
||||
return ["No kernel record found!"]
|
||||
|
||||
# Output items with run time ratio > thresholds, and sorted by duration in the descending order.
|
||||
lines = []
|
||||
lines.append(f"\nTop expensive kernels with Time% >= {threshold*100:.2f}:")
|
||||
lines.append("-" * 64)
|
||||
lines.append("Total(μs)\tTime%\tCalls\tAvg(μs)\tKernel")
|
||||
for kernel_name, duration in sorted(kernel_time.items(), key=lambda x: x[1], reverse=True):
|
||||
ratio = duration / total
|
||||
if ratio < threshold:
|
||||
continue
|
||||
|
||||
calls = kernel_freq[kernel_name]
|
||||
avg_time = duration / float(calls)
|
||||
lines.append(f"{duration:10d}\t{ratio * 100.0:5.2f}\t{calls:5d}\t{avg_time:8.1f}\t{kernel_name}")
|
||||
|
||||
|
||||
# Group by operator
|
||||
op_time = {}
|
||||
for kernel_name, op_name in kernel_name_to_op_name.items():
|
||||
duration = kernel_time[kernel_name]
|
||||
if op_name in op_time:
|
||||
op_time[op_name] += duration
|
||||
else:
|
||||
op_time[op_name] = duration
|
||||
|
||||
lines.append(f"\nGroup kernel time by operator:")
|
||||
lines.append("-" * 64)
|
||||
lines.append("Total(μs)\tTime%\tOperator")
|
||||
for op_name, duration in sorted(op_time.items(), key=lambda x: x[1], reverse=True):
|
||||
ratio = duration / total
|
||||
lines.append(f"{duration:10d}\t{ratio * 100.0:5.2f}\t{op_name}")
|
||||
|
||||
return lines
|
||||
|
||||
|
||||
def parse_node_results(sess_time, kernel_time_only=False, threshold=0):
|
||||
"""Parse profile data and output nodes in two sections - nodes in the original order, and top expensive nodes.
|
||||
|
||||
Args:
|
||||
|
|
@ -180,8 +268,8 @@ def parse_profile_results(sess_time, kernel_time_only=False, threshold=0):
|
|||
|
||||
# Output items in the original order.
|
||||
lines = [
|
||||
"Results:", "-" * 64,
|
||||
"Duration(μs)\tPercentage\tBefore(Exclusive)\tAfter(Inclusive)\tCalls\tProvider\tNode_Name"
|
||||
"\nNodes in the original order:", "-" * 64,
|
||||
"Total(μs)\tTime%\tAcc %\tAvg(μs)\tCalls\tProvider\tNode"
|
||||
]
|
||||
before_percentage = 0.0
|
||||
for node_name in node_name_list:
|
||||
|
|
@ -190,15 +278,16 @@ def parse_profile_results(sess_time, kernel_time_only=False, threshold=0):
|
|||
avg_time = duration / float(calls)
|
||||
percentage = (duration / total) * 100.0
|
||||
provider = node_provider[node_name] if node_name in node_provider else ""
|
||||
lines.append(
|
||||
f"{avg_time:.1f}\t{percentage:5.2f}\t{before_percentage:5.1f}\t{100.0 - before_percentage:5.1f}\t{calls}\t{provider}\t{node_name}"
|
||||
)
|
||||
before_percentage += percentage
|
||||
lines.append(
|
||||
f"{duration:10d}\t{percentage:5.2f}\t{before_percentage:5.2f}\t{avg_time:8.1f}\t{calls:5d}\t{provider:8s}\t{node_name}"
|
||||
)
|
||||
|
||||
|
||||
# Output items with run time ratio > thresholds, and sorted by duration in the descending order.
|
||||
lines.append(f"\nTop expensive nodes with threshold={threshold:.2f}:")
|
||||
lines.append(f"\nTop expensive nodes with Time% >= {threshold*100:.2f}:")
|
||||
lines.append("-" * 64)
|
||||
lines.append("Duration(μs)\tPercentage\tProvider\tName")
|
||||
lines.append("Total(μs)\tTime%\tAvg(μs)\tCalls\tProvider\tNode")
|
||||
for node_name, duration in sorted(node_time.items(), key=lambda x: x[1], reverse=True):
|
||||
ratio = duration / total
|
||||
if ratio < threshold:
|
||||
|
|
@ -206,13 +295,14 @@ def parse_profile_results(sess_time, kernel_time_only=False, threshold=0):
|
|||
|
||||
calls = node_freq[node_name]
|
||||
avg_time = duration / float(calls)
|
||||
percentage = (duration / total) * 100.0
|
||||
provider = node_provider[node_name] if node_name in node_provider else ""
|
||||
lines.append(f"{avg_time:.1f}\t{ratio * 100.0:5.2f}\t{provider}\t{node_name}")
|
||||
lines.append(f"{duration:10d}\t{percentage:5.2f}\t{avg_time:8.1f}\t{calls:5d}\t{provider:8s}\t{node_name}")
|
||||
|
||||
return lines
|
||||
|
||||
|
||||
def group_profile_results(sess_time, kernel_time_only, use_gpu):
|
||||
def group_node_results(sess_time, kernel_time_only, use_gpu):
|
||||
"""Group results by operator name.
|
||||
|
||||
Args:
|
||||
|
|
@ -223,56 +313,87 @@ def group_profile_results(sess_time, kernel_time_only, use_gpu):
|
|||
Returns:
|
||||
List[str]: lines of string for output.
|
||||
"""
|
||||
op_time = {}
|
||||
op_records = {}
|
||||
op_cpu_time = {}
|
||||
op_cpu_records = {}
|
||||
total = 0
|
||||
op_kernel_time = {}
|
||||
op_kernel_records = {}
|
||||
total_kernel_time = 0
|
||||
|
||||
provider_op_kernel_time = {}
|
||||
provider_op_kernel_records = {}
|
||||
provider_kernel_time = {}
|
||||
|
||||
op_fence_time = {}
|
||||
total_fence_time = 0
|
||||
|
||||
provider_counter = {}
|
||||
for item in sess_time:
|
||||
if item["cat"] == "Node" and "dur" in item and "args" in item and "op_name" in item["args"]:
|
||||
if kernel_time_only and "provider" not in item["args"]:
|
||||
continue
|
||||
|
||||
op_name = item["args"]["op_name"]
|
||||
|
||||
# TODO: shall we have a separated group for nodes with subgraph?
|
||||
if op_name in NODES_TYPE_CONTAINING_SUBGRAPH:
|
||||
continue
|
||||
|
||||
if op_name in op_time:
|
||||
op_time[op_name] += item["dur"]
|
||||
op_records[op_name] += 1
|
||||
if "provider" not in item["args"]:
|
||||
if "fence" in item["name"]:
|
||||
if op_name in op_fence_time:
|
||||
op_fence_time[op_name] += item["dur"]
|
||||
else:
|
||||
op_fence_time[op_name] = item["dur"]
|
||||
total_fence_time += item["dur"]
|
||||
continue
|
||||
|
||||
provider = item["args"]["provider"] if "provider" in item["args"] else ""
|
||||
if provider in provider_counter:
|
||||
provider_counter[provider] += 1
|
||||
else:
|
||||
op_time[op_name] = item["dur"]
|
||||
op_records[op_name] = 1
|
||||
provider_counter[provider] = 1
|
||||
|
||||
total += item["dur"]
|
||||
key = f"{provider}:{op_name}"
|
||||
if key in provider_op_kernel_time:
|
||||
provider_op_kernel_time[key] += item["dur"]
|
||||
provider_op_kernel_records[key] += 1
|
||||
else:
|
||||
provider_op_kernel_time[key] = item["dur"]
|
||||
provider_op_kernel_records[key] = 1
|
||||
|
||||
is_cpu = "provider" in item["args"] and item["args"]["provider"] == "CPUExecutionProvider"
|
||||
if is_cpu:
|
||||
if op_name in op_cpu_time:
|
||||
op_cpu_time[op_name] += item["dur"]
|
||||
op_cpu_records[op_name] += 1
|
||||
else:
|
||||
op_cpu_time[op_name] = item["dur"]
|
||||
op_cpu_records[op_name] = 1
|
||||
if provider in provider_kernel_time:
|
||||
provider_kernel_time[provider] += item["dur"]
|
||||
else:
|
||||
provider_kernel_time[provider] = item["dur"]
|
||||
|
||||
if use_gpu:
|
||||
lines = ["Average(μs)\tTotal(μs)\tTotal_Percentage\tCalls\tCpu_Duration\tCpu_Calls\tName"]
|
||||
else:
|
||||
lines = ["Average(μs)\tTotal(μs)\tTotal_Percentage\tCalls\tName"]
|
||||
if op_name in op_kernel_time:
|
||||
op_kernel_time[op_name] += item["dur"]
|
||||
op_kernel_records[op_name] += 1
|
||||
else:
|
||||
op_kernel_time[op_name] = item["dur"]
|
||||
op_kernel_records[op_name] = 1
|
||||
|
||||
for op_name, duration in sorted(op_time.items(), key=lambda x: x[1], reverse=True):
|
||||
ratio = duration / total
|
||||
calls = op_records[op_name]
|
||||
cpu_time = op_cpu_time[op_name] if op_name in op_cpu_time else 0
|
||||
cpu_calls = op_cpu_records[op_name] if op_name in op_cpu_records else 0
|
||||
avg_time = duration / float(calls)
|
||||
total_kernel_time += item["dur"]
|
||||
|
||||
if use_gpu:
|
||||
lines.append(
|
||||
f"{avg_time:.1f}\t{duration}\t{ratio * 100.0:5.2f}\t{calls}\t{cpu_time}\t{cpu_calls}\t{op_name}")
|
||||
else:
|
||||
lines.append(f"{avg_time:.1f}\t{duration}\t{ratio * 100.0:5.2f}\t{calls}\t{op_name}")
|
||||
lines = ["", "Grouped by operator"]
|
||||
lines.append("-" * 64)
|
||||
lines.append("Total(μs)\tTime%\tKernel(μs)\tKernel%\tCalls\tAvgKernel(μs)\tFence(μs)\tOperator")
|
||||
for op_name, kernel_time in sorted(op_kernel_time.items(), key=lambda x: x[1], reverse=True):
|
||||
fence_time = op_fence_time[op_name] if op_name in op_fence_time else 0
|
||||
kernel_time_ratio = kernel_time / total_kernel_time
|
||||
total_time = kernel_time + fence_time
|
||||
time_ratio = total_time / (total_kernel_time + total_fence_time)
|
||||
kernel_calls = op_kernel_records[op_name]
|
||||
avg_kernel_time = kernel_time / kernel_calls
|
||||
lines.append(f"{total_time:10d}\t{time_ratio * 100.0:5.2f}\t{kernel_time:11d}\t{kernel_time_ratio * 100.0:5.2f}\t{kernel_calls:5d}\t{avg_kernel_time:14.1f}\t{fence_time:10d}\t{op_name}")
|
||||
|
||||
lines += ["", "Grouped by provider + operator"]
|
||||
lines.append("-" * 64)
|
||||
lines.append("Kernel(μs)\tProvider%\tCalls\tAvgKernel(μs)\tProvider\tOperator")
|
||||
for key, kernel_time in sorted(provider_op_kernel_time.items(), key=lambda x: x[1], reverse=True):
|
||||
parts = key.split(':')
|
||||
provider = parts[0]
|
||||
op_name = parts[1]
|
||||
short_ep = provider.replace("ExecutionProvider", "")
|
||||
calls = provider_op_kernel_records[key]
|
||||
avg_kernel_time = kernel_time / calls
|
||||
provider_time_ratio = kernel_time / provider_kernel_time[provider]
|
||||
lines.append(f"{kernel_time:10d}\t{provider_time_ratio * 100.0:9.2f}\t{calls:5d}\t{avg_kernel_time:14.1f}\t{short_ep:8s}\t{op_name}")
|
||||
|
||||
return lines
|
||||
|
||||
|
|
@ -448,6 +569,16 @@ def create_longformer_inputs(onnx_model, batch_size, sequence_length, global_len
|
|||
all_inputs = [dummy_inputs for _ in range(samples)]
|
||||
return all_inputs
|
||||
|
||||
def process_results(profile_file, args):
|
||||
profile_records = load_profile_json(profile_file)
|
||||
|
||||
lines = parse_kernel_results(profile_records, args.threshold)
|
||||
|
||||
lines += parse_node_results(profile_records, args.kernel_time_only, args.threshold)
|
||||
|
||||
lines += group_node_results(profile_records, args.kernel_time_only, args.use_gpu)
|
||||
|
||||
return lines
|
||||
|
||||
def run(args):
|
||||
num_threads = args.thread_num if args.thread_num > 0 else psutil.cpu_count(logical=False)
|
||||
|
|
@ -475,15 +606,7 @@ def run(args):
|
|||
|
||||
profile_file = run_profile(args.model, args.use_gpu, args.basic_optimization, args.thread_num, all_inputs, args.use_dml)
|
||||
|
||||
profile_records = load_profile_json(profile_file)
|
||||
|
||||
lines = parse_profile_results(profile_records, args.kernel_time_only, args.threshold)
|
||||
|
||||
lines.append("\nGrouped by operator type:")
|
||||
lines.append("-" * 64)
|
||||
lines += group_profile_results(profile_records, args.kernel_time_only, args.use_gpu)
|
||||
|
||||
return lines
|
||||
return profile_file
|
||||
|
||||
|
||||
if __name__ == '__main__':
|
||||
|
|
@ -493,6 +616,13 @@ if __name__ == '__main__':
|
|||
from benchmark_helper import setup_logger
|
||||
setup_logger(arguments.verbose)
|
||||
|
||||
results = run(arguments)
|
||||
if not arguments.input:
|
||||
assert arguments.model, "requires either --model to run profiling or --input to read profiling results"
|
||||
profile_file = run(arguments)
|
||||
else:
|
||||
profile_file = arguments.input
|
||||
|
||||
results = process_results(profile_file, arguments)
|
||||
|
||||
for line in results:
|
||||
print(line)
|
||||
|
|
|
|||
Loading…
Reference in a new issue