From a01a3f2552a7a82b1264e0eb7c2ef38be065a1f5 Mon Sep 17 00:00:00 2001 From: Tianlei Wu Date: Thu, 28 Oct 2021 11:35:03 -0700 Subject: [PATCH] Add more statistics in transformer profiler (#9578) * add statistics of cuda kernel * grouping by provider + operator * add --input to import profiling result --- .../python/tools/transformers/profiler.py | 246 +++++++++++++----- 1 file changed, 188 insertions(+), 58 deletions(-) diff --git a/onnxruntime/python/tools/transformers/profiler.py b/onnxruntime/python/tools/transformers/profiler.py index 84fc150c6f..753b976758 100644 --- a/onnxruntime/python/tools/transformers/profiler.py +++ b/onnxruntime/python/tools/transformers/profiler.py @@ -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)