profiler_statistic.py 63.5 KB
Newer Older
C
chenjian 已提交
1
# Copyright (c) 2022 PaddlePaddle Authors. All Rights Reserved.
C
chenjian 已提交
2
#
C
chenjian 已提交
3 4 5
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
C
chenjian 已提交
6
#
C
chenjian 已提交
7
#     http://www.apache.org/licenses/LICENSE-2.0
C
chenjian 已提交
8
#
C
chenjian 已提交
9 10 11 12 13 14 15
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
import collections
from enum import Enum
16
import re
C
chenjian 已提交
17 18 19

from paddle.fluid.core import TracerEventType

C
chenjian 已提交
20 21 22 23 24 25 26 27 28 29 30 31
from .statistic_helper import *

_AllTracerEventType = [
    TracerEventType.Operator, TracerEventType.Dataloader,
    TracerEventType.ProfileStep, TracerEventType.CudaRuntime,
    TracerEventType.Kernel, TracerEventType.Memcpy, TracerEventType.Memset,
    TracerEventType.UserDefined, TracerEventType.OperatorInner,
    TracerEventType.Forward, TracerEventType.Backward,
    TracerEventType.Optimization, TracerEventType.Communication,
    TracerEventType.PythonOp, TracerEventType.PythonUserDefined
]

32
_CommunicationOpName = ['allreduce', 'broadcast', 'rpc']
C
chenjian 已提交
33

C
chenjian 已提交
34 35 36

class SortedKeys(Enum):
    r"""
C
chenjian 已提交
37
    SortedKeys is used to specify how to sort items when printing :ref:`summary <api_paddle_profiler_profiler_summary>` table.
C
chenjian 已提交
38

C
chenjian 已提交
39
    The meaning of each SortedKeys is as following
C
chenjian 已提交
40

C
chenjian 已提交
41
    - **SortedKeys.CPUTotal** :  Sorted by CPU total time.
C
chenjian 已提交
42

C
chenjian 已提交
43
    - **SortedKeys.CPUAvg**  : Sorted by CPU average time.
C
chenjian 已提交
44

C
chenjian 已提交
45
    - **SortedKeys.CPUMax**  : Sorted by CPU max time.
C
chenjian 已提交
46

C
chenjian 已提交
47
    - **SortedKeys.CPUMin**  : Sorted by CPU min time.
C
chenjian 已提交
48

C
chenjian 已提交
49
    - **SortedKeys.GPUTotal**  : Sorted by GPU total time.
C
chenjian 已提交
50

C
chenjian 已提交
51
    - **SortedKeys.GPUAvg**  : Sorted by GPU average time.
C
chenjian 已提交
52

C
chenjian 已提交
53 54 55
    - **SortedKeys.GPUMax**  : Sorted by GPU max time.

    - **SortedKeys.GPUMin**  : Sorted by GPU min time.
C
chenjian 已提交
56 57 58 59 60 61 62 63 64
    """
    CPUTotal = 0
    CPUAvg = 1
    CPUMax = 2
    CPUMin = 3
    GPUTotal = 4
    GPUAvg = 5
    GPUMax = 6
    GPUMin = 7
C
chenjian 已提交
65 66 67 68 69 70 71 72 73 74 75 76 77


class HostStatisticNode:
    r'''
    Wrap original node for calculating statistic metrics.
    '''

    def __init__(self, hostnode):
        self.hostnode = hostnode
        self.children_node = []
        self.runtime_node = []
        self.cpu_time = 0
        self.self_cpu_time = 0
78
        self.gpu_time = 0  # kernel time
C
chenjian 已提交
79
        self.self_gpu_time = 0
80 81
        self.general_gpu_time = 0  # besides kernel, include time of gpu events like memcpy and memset
        self.self_general_gpu_time = 0
82
        self.is_terminal_operator_node = True
C
chenjian 已提交
83 84 85 86

    def cal_statistic(self):
        for child in self.children_node:
            child.cal_statistic()
87 88
            if child.is_terminal_operator_node == False:
                self.is_terminal_operator_node = False
C
chenjian 已提交
89 90 91 92
        for rt in self.runtime_node:
            rt.cal_statistic()
        self.cpu_time = self.hostnode.end_ns - self.hostnode.start_ns
        for child in self.children_node:
93 94
            if child.type == TracerEventType.Operator:
                self.is_terminal_operator_node = False
C
chenjian 已提交
95
            self.gpu_time += child.gpu_time
96
            self.general_gpu_time += child.general_gpu_time
C
chenjian 已提交
97 98 99 100 101
            self.self_cpu_time -= (child.end_ns - child.start_ns)
        for rt in self.runtime_node:
            self.self_cpu_time -= (rt.end_ns - rt.start_ns)
            self.gpu_time += rt.gpu_time
            self.self_gpu_time += rt.gpu_time
102 103
            self.general_gpu_time += rt.general_gpu_time
            self.self_general_gpu_time += rt.general_gpu_time
C
chenjian 已提交
104
        for device in self.hostnode.device_node:
105 106 107 108 109
            if device.type == TracerEventType.Kernel:
                self.gpu_time += (device.end_ns - device.start_ns)
                self.self_gpu_time += (device.end_ns - device.start_ns)
            self.general_gpu_time += (device.end_ns - device.start_ns)
            self.self_general_gpu_time += (device.end_ns - device.start_ns)
C
chenjian 已提交
110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136

    @property
    def end_ns(self):
        return self.hostnode.end_ns

    @property
    def start_ns(self):
        return self.hostnode.start_ns

    def __getattr__(self, name):
        return getattr(self.hostnode, name)


def traverse_tree(nodetrees):
    results = collections.defaultdict(list)
    for thread_id, rootnode in nodetrees.items():
        stack = []
        stack.append(rootnode)
        threadlist = results[thread_id]
        while stack:
            current_node = stack.pop()
            threadlist.append(current_node)
            for childnode in current_node.children_node:
                stack.append(childnode)
    return results


C
chenjian 已提交
137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153
def get_device_nodes(hostnode):
    '''
    Get all device nodes called in the time range of hostnode.
    '''
    stack = []
    device_nodes = []
    stack.append(hostnode)
    while stack:
        current_node = stack.pop()
        for childnode in current_node.children_node:
            stack.append(childnode)
        for runtimenode in current_node.runtime_node:
            for devicenode in runtimenode.device_node:
                device_nodes.append(devicenode)
    return device_nodes


C
chenjian 已提交
154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261
def wrap_tree(nodetrees):
    '''
    Using HostStatisticNode to wrap original profiler result tree, and calculate node statistic metrics.
    '''
    node_statistic_tree = {}
    results = collections.defaultdict(list)
    newresults = collections.defaultdict(list)
    for thread_id, rootnode in nodetrees.items():
        stack = []
        stack.append(rootnode)
        root_statistic_node = HostStatisticNode(rootnode)
        newstack = []
        newstack.append(root_statistic_node)
        node_statistic_tree[thread_id] = root_statistic_node
        threadlist = results[thread_id]
        newthreadlist = newresults[thread_id]
        while stack:
            current_node = stack.pop()
            threadlist.append(current_node)
            current_statistic_node = newstack.pop()
            newthreadlist.append(current_statistic_node)
            for childnode in current_node.children_node:
                stack.append(childnode)
                child_statistic_node = HostStatisticNode(childnode)
                current_statistic_node.children_node.append(
                    child_statistic_node)
                newstack.append(child_statistic_node)
            for runtimenode in current_node.runtime_node:
                runtime_statistic_node = HostStatisticNode(runtimenode)
                current_statistic_node.runtime_node.append(
                    runtime_statistic_node)
    # recursive calculate node statistic values
    for thread_id, root_statistic_node in node_statistic_tree.items():
        root_statistic_node.cal_statistic()

    return node_statistic_tree, newresults


class TimeRangeSummary:
    r"""
    Analyse time ranges for each TracerEventType, and summarize the time.
    """

    def __init__(self):
        self.CPUTimeRange = collections.defaultdict(list)
        self.GPUTimeRange = collections.defaultdict(
            lambda: collections.defaultdict(list)
        )  # GPU events should be divided into different devices
        self.CPUTimeRangeSum = collections.defaultdict(int)
        self.GPUTimeRangeSum = collections.defaultdict(
            lambda: collections.defaultdict(int))
        self.call_times = collections.defaultdict(int)

    def parse(self, nodetrees):
        r"""
        Analysis node trees in profiler result, and get time range for different tracer event type.
        """
        thread2hostnodes = traverse_tree(nodetrees)
        for threadid, hostnodes in thread2hostnodes.items():
            CPUTimeRange = collections.defaultdict(list)
            GPUTimeRange = collections.defaultdict(
                lambda: collections.defaultdict(lambda: collections.defaultdict(list))
            )  # device_id/type/stream_id
            for hostnode in hostnodes[1:]:  #skip root node
                CPUTimeRange[hostnode.type].append(
                    (hostnode.start_ns, hostnode.end_ns))
                self.call_times[hostnode.type] += 1
                for runtimenode in hostnode.runtime_node:
                    CPUTimeRange[runtimenode.type].append(
                        (runtimenode.start_ns, runtimenode.end_ns))
                    self.call_times[runtimenode.type] += 1
                    for devicenode in runtimenode.device_node:
                        GPUTimeRange[devicenode.device_id][devicenode.type][
                            devicenode.stream_id].append(
                                (devicenode.start_ns, devicenode.end_ns))
                        self.call_times[devicenode.type] += 1

            for event_type, time_ranges in CPUTimeRange.items():
                time_ranges = merge_self_ranges(time_ranges, is_sorted=False)
                self.CPUTimeRange[event_type] = merge_ranges(
                    self.CPUTimeRange[event_type], time_ranges, is_sorted=True)
            for device_id, device_time_ranges in GPUTimeRange.items():
                for event_type, event_time_ranges in device_time_ranges.items():
                    for stream_id, time_ranges in event_time_ranges.items():
                        time_ranges = merge_self_ranges(
                            time_ranges, is_sorted=False)
                        self.GPUTimeRange[device_id][event_type] = merge_ranges(
                            self.GPUTimeRange[device_id][event_type],
                            time_ranges,
                            is_sorted=True)

        for event_type, time_ranges in self.CPUTimeRange.items():
            self.CPUTimeRangeSum[event_type] = sum_ranges(time_ranges)
        for device_id, device_time_ranges in self.GPUTimeRange.items():
            for event_type, time_ranges in device_time_ranges.items():
                self.GPUTimeRangeSum[device_id][event_type] = sum_ranges(
                    time_ranges)

    def get_gpu_devices(self):
        return self.GPUTimeRange.keys()

    def get_gpu_range_sum(self, device_id, event_type):
        return self.GPUTimeRangeSum[device_id][event_type]

    def get_cpu_range_sum(self, event_type):
        return self.CPUTimeRangeSum[event_type]


C
chenjian 已提交
262 263 264 265 266 267 268 269 270 271 272 273
class DistributedSummary:
    r"""
    Analysis communication and computation time range, and their overlap.
    The computation time is all kernel except kernels for communication like nccl.
    """

    def __init__(self):
        self.cpu_communication_range = []
        self.gpu_communication_range = []
        self.communication_range = []
        self.computation_range = []
        self.overlap_range = []
274 275
        self.cpu_calls = 0
        self.gpu_calls = 0
C
chenjian 已提交
276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317

    def parse(self, nodetrees):
        '''
        Collect all communication and computation time ranges.
        '''
        thread2hostnodes = traverse_tree(nodetrees)
        for threadid, hostnodes in thread2hostnodes.items():
            for hostnode in hostnodes[1:]:  #skip root node
                # case 1: TracerEventType is Communication
                if hostnode.type == TracerEventType.Communication:
                    self.cpu_communication_range.append(
                        (hostnode.start_ns, hostnode.end_ns))
                    device_nodes = get_device_nodes(hostnode)
                    for device_node in device_nodes:
                        if device_node.type == TracerEventType.Kernel:
                            self.gpu_communication_range.append(
                                (device_node.start_ns, device_node.end_ns))

                #case 2: TracerEventType is Operator but is communication op
                elif hostnode.type == TracerEventType.Operator and any([
                        name in hostnode.name.lower()
                        for name in _CommunicationOpName
                ]):
                    self.cpu_communication_range.append(
                        (hostnode.start_ns, hostnode.end_ns))
                    device_nodes = get_device_nodes(hostnode)
                    for device_node in device_nodes:
                        if device_node.type == TracerEventType.Kernel:
                            self.gpu_communication_range.append(
                                (device_node.start_ns, device_node.end_ns))

                #case 3: Others, filter kernels named with nccl
                else:
                    for runtimenode in hostnode.runtime_node:
                        for devicenode in runtimenode.device_node:
                            if devicenode.type == TracerEventType.Kernel:
                                if 'nccl' in devicenode.name.lower():
                                    self.gpu_communication_range.append((
                                        devicenode.start_ns, devicenode.end_ns))
                                else:
                                    self.computation_range.append((
                                        devicenode.start_ns, devicenode.end_ns))
318 319
        self.cpu_calls = len(set(self.cpu_communication_range))
        self.gpu_calls = len(set(self.gpu_communication_range))
C
chenjian 已提交
320 321 322 323 324 325 326 327 328 329 330 331 332 333
        self.cpu_communication_range = merge_self_ranges(
            self.cpu_communication_range, is_sorted=False)
        self.gpu_communication_range = merge_self_ranges(
            self.gpu_communication_range, is_sorted=False)
        self.communication_range = merge_ranges(
            self.cpu_communication_range,
            self.gpu_communication_range,
            is_sorted=True)
        self.computation_range = merge_self_ranges(
            self.computation_range, is_sorted=False)
        self.overlap_range = intersection_ranges(
            self.communication_range, self.computation_range, is_sorted=True)


C
chenjian 已提交
334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373
class EventSummary:
    r"""
    Analyse operator event in profiling data, correlate with its device event.
    """

    class DeviceItem:
        def __init__(self, name):
            self.name = name
            self.call = 0
            self.gpu_time = 0
            self.max_gpu_time = 0
            self.min_gpu_time = float('inf')

        @property
        def avg_gpu_time(self):
            return self.gpu_time / self.call

        def add_gpu_time(self, time):
            if time > self.max_gpu_time:
                self.max_gpu_time = time
            if time < self.min_gpu_time:
                self.min_gpu_time = time
            self.gpu_time += time

        def add_item(self, node):
            self.call += 1
            self.add_gpu_time(node.end_ns - node.start_ns)

    class OperatorItem:
        def __init__(self, name):
            self.name = name
            self.call = 0
            self.cpu_time = 0
            self.gpu_time = 0
            self.max_cpu_time = 0
            self.min_cpu_time = float('inf')
            self.max_gpu_time = 0
            self.min_gpu_time = float('inf')
            self.devices = {}
            self.operator_inners = {}
374 375 376
            self.general_gpu_time = 0
            self.min_general_gpu_time = float('inf')
            self.max_general_gpu_time = 0
C
chenjian 已提交
377 378 379 380 381 382 383 384 385

        @property
        def avg_cpu_time(self):
            return self.cpu_time / self.call

        @property
        def avg_gpu_time(self):
            return self.gpu_time / self.call

386 387 388 389
        @property
        def avg_general_gpu_time(self):
            return self.general_gpu_time / self.call

C
chenjian 已提交
390 391 392 393 394 395 396 397 398 399 400 401 402 403
        def add_cpu_time(self, time):
            if time > self.max_cpu_time:
                self.max_cpu_time = time
            if time < self.min_cpu_time:
                self.min_cpu_time = time
            self.cpu_time += time

        def add_gpu_time(self, time):
            if time > self.max_gpu_time:
                self.max_gpu_time = time
            if time < self.min_gpu_time:
                self.min_gpu_time = time
            self.gpu_time += time

404 405 406 407 408 409 410
        def add_general_gpu_time(self, time):
            if time > self.max_general_gpu_time:
                self.max_general_gpu_time = time
            if time < self.min_general_gpu_time:
                self.min_general_gpu_time = time
            self.general_gpu_time += time

C
chenjian 已提交
411 412 413 414 415 416 417
        def add_call(self):
            self.call += 1

        def add_item(self, node):
            self.add_call()
            self.add_cpu_time(node.cpu_time)
            self.add_gpu_time(node.gpu_time)
418
            self.add_general_gpu_time(node.general_gpu_time)
C
chenjian 已提交
419 420 421 422 423 424 425 426
            for child in node.children_node:
                if child.name not in self.operator_inners:
                    self.operator_inners[
                        child.name] = EventSummary.OperatorItem(child.name)
                self.operator_inners[child.name].add_item(child)

            for runtimenode in node.runtime_node:
                for devicenode in runtimenode.device_node:
427 428 429 430
                    name = devicenode.name
                    if name not in self.devices:
                        self.devices[name] = EventSummary.DeviceItem(name)
                    self.devices[name].add_item(devicenode)
C
chenjian 已提交
431 432 433 434 435 436 437 438 439 440 441

    class GeneralItem:
        def __init__(self, name):
            self.name = name
            self.call = 0
            self.cpu_time = 0
            self.max_cpu_time = 0
            self.min_cpu_time = float('inf')
            self.gpu_time = 0
            self.max_gpu_time = 0
            self.min_gpu_time = float('inf')
442 443 444
            self.general_gpu_time = 0
            self.min_general_gpu_time = float('inf')
            self.max_general_gpu_time = 0
C
chenjian 已提交
445 446 447 448 449 450 451 452 453

        @property
        def avg_cpu_time(self):
            return self.cpu_time / self.call

        @property
        def avg_gpu_time(self):
            return self.gpu_time / self.call

454 455 456 457
        @property
        def avg_general_gpu_time(self):
            return self.general_gpu_time / self.call

C
chenjian 已提交
458 459 460 461 462 463 464 465 466 467 468 469 470 471
        def add_cpu_time(self, time):
            if time > self.max_cpu_time:
                self.max_cpu_time = time
            if time < self.min_cpu_time:
                self.min_cpu_time = time
            self.cpu_time += time

        def add_gpu_time(self, time):
            if time > self.max_gpu_time:
                self.max_gpu_time = time
            if time < self.min_gpu_time:
                self.min_gpu_time = time
            self.gpu_time += time

472 473 474 475 476 477 478
        def add_general_gpu_time(self, time):
            if time > self.max_general_gpu_time:
                self.max_general_gpu_time = time
            if time < self.min_general_gpu_time:
                self.min_general_gpu_time = time
            self.general_gpu_time += time

C
chenjian 已提交
479 480 481 482 483 484 485
        def add_call(self):
            self.call += 1

        def add_item(self, node):
            self.add_call()
            self.add_cpu_time(node.cpu_time)
            self.add_gpu_time(node.gpu_time)
486
            self.add_general_gpu_time(node.general_gpu_time)
C
chenjian 已提交
487 488 489 490 491 492 493 494 495 496

    def __init__(self):
        self.items = {}  # for operator summary
        self.thread_items = collections.defaultdict(
            dict)  # for operator summary
        self.userdefined_items = {}  # for userdefined summary
        self.userdefined_thread_items = collections.defaultdict(
            dict)  # for userdefined summary
        self.model_perspective_items = {}  # for model summary
        self.memory_manipulation_items = {}  # for memory manipulation summary
497
        self.kernel_items = {}  # for kernel summary
C
chenjian 已提交
498 499 500 501 502 503 504 505 506 507 508 509 510 511 512 513 514 515 516

    def parse(self, nodetrees):
        r"""
        Analysis operator event in the nodetress.
        """
        node_statistic_trees, thread2host_statistic_nodes = wrap_tree(nodetrees)
        for threadid, host_statistic_nodes in thread2host_statistic_nodes.items(
        ):
            for host_statistic_node in host_statistic_nodes[
                    1:]:  #skip root node
                if host_statistic_node.type == TracerEventType.Operator:
                    self.add_operator_item(host_statistic_node)
                if host_statistic_node.type == TracerEventType.UserDefined\
                    or host_statistic_node.type == TracerEventType.PythonUserDefined:
                    if 'memcpy' in host_statistic_node.name.lower() or 'memorycopy' in host_statistic_node.name.lower()\
                        or 'memset' in host_statistic_node.name.lower():
                        self.add_memory_manipulation_item(host_statistic_node)
                    else:
                        self.add_userdefined_item(host_statistic_node)
517
            self.add_kernel_item(host_statistic_nodes[0])
C
chenjian 已提交
518 519 520 521 522 523 524 525 526 527 528 529

        for threadid, root_statistic_node in node_statistic_trees.items():
            deque = collections.deque()
            deque.append(root_statistic_node)
            while deque:
                current_node = deque.popleft()
                for child in current_node.children_node:
                    if child.type == TracerEventType.Forward or child.type == TracerEventType.Dataloader\
                        or child.type == TracerEventType.Backward or child.type == TracerEventType.Optimization:
                        self.add_model_perspective_item(
                            child)  #find first model perspective node
                    else:
530 531
                        if child.type == TracerEventType.ProfileStep:
                            self.add_model_perspective_item(child)
C
chenjian 已提交
532 533 534
                        deque.append(child)

    def add_operator_item(self, operator_node):
535
        if operator_node.is_terminal_operator_node == False:
C
chenjian 已提交
536
            return
C
chenjian 已提交
537 538 539 540 541 542 543 544 545 546 547 548 549 550 551 552 553 554 555 556 557 558 559 560 561 562 563 564 565 566 567 568 569 570 571 572 573 574 575 576 577 578 579 580 581 582
        if operator_node.name not in self.items:
            self.items[operator_node.name] = EventSummary.OperatorItem(
                operator_node.name)

        self.items[operator_node.name].add_item(operator_node)

        if operator_node.name not in self.thread_items[operator_node.thread_id]:
            self.thread_items[operator_node.thread_id][
                operator_node.name] = EventSummary.OperatorItem(
                    operator_node.name)
        self.thread_items[operator_node.thread_id][operator_node.name].add_item(
            operator_node)

    def add_userdefined_item(self, userdefined_node):
        if userdefined_node.name not in self.userdefined_items:
            self.userdefined_items[
                userdefined_node.name] = EventSummary.GeneralItem(
                    userdefined_node.name)

        self.userdefined_items[userdefined_node.name].add_item(userdefined_node)

        if userdefined_node.name not in self.userdefined_thread_items[
                userdefined_node.thread_id]:
            self.userdefined_thread_items[userdefined_node.thread_id][
                userdefined_node.name] = EventSummary.GeneralItem(
                    userdefined_node.name)
        self.userdefined_thread_items[userdefined_node.thread_id][
            userdefined_node.name].add_item(userdefined_node)

    def add_memory_manipulation_item(self, memory_manipulation_node):
        if memory_manipulation_node.name not in self.memory_manipulation_items:
            self.memory_manipulation_items[
                memory_manipulation_node.name] = EventSummary.GeneralItem(
                    memory_manipulation_node.name)
        self.memory_manipulation_items[memory_manipulation_node.name].add_item(
            memory_manipulation_node)

    def add_model_perspective_item(self, model_perspective_node):
        if model_perspective_node.type == TracerEventType.Forward:
            name = 'Forward'
        elif model_perspective_node.type == TracerEventType.Backward:
            name = 'Backward'
        elif model_perspective_node.type == TracerEventType.Optimization:
            name = 'Optimization'
        elif model_perspective_node.type == TracerEventType.Dataloader:
            name = 'Dataloader'
583 584
        elif model_perspective_node.type == TracerEventType.ProfileStep:
            name = 'ProfileStep'
C
chenjian 已提交
585 586 587 588 589 590
        else:
            return
        if name not in self.model_perspective_items:
            self.model_perspective_items[name] = EventSummary.GeneralItem(name)
        self.model_perspective_items[name].add_item(model_perspective_node)

591 592 593 594 595 596 597 598 599
    def add_kernel_item(self, root_node):
        device_nodes = get_device_nodes(root_node)
        for device_node in device_nodes:
            if device_node.type == TracerEventType.Kernel:
                name = device_node.name
                if name not in self.kernel_items:
                    self.kernel_items[name] = EventSummary.DeviceItem(name)
                self.kernel_items[name].add_item(device_node)

C
chenjian 已提交
600 601 602 603 604 605 606 607 608 609 610

class StatisticData:
    r"""
    Hold all analysed results.
    """

    def __init__(self, node_trees, extra_info):
        self.node_trees = node_trees
        self.extra_info = extra_info
        self.time_range_summary = TimeRangeSummary()
        self.event_summary = EventSummary()
C
chenjian 已提交
611
        self.distributed_summary = DistributedSummary()
C
chenjian 已提交
612 613
        self.time_range_summary.parse(node_trees)
        self.event_summary.parse(node_trees)
C
chenjian 已提交
614
        self.distributed_summary.parse(node_trees)
C
chenjian 已提交
615 616 617 618 619 620 621 622 623 624 625 626 627 628 629 630 631 632 633 634 635 636 637 638 639 640 641 642 643 644 645 646 647 648 649 650 651 652 653 654 655 656 657 658 659 660 661 662 663 664 665 666 667 668 669 670 671 672 673 674 675 676 677 678 679 680 681 682 683 684 685 686 687 688 689 690 691 692 693 694 695 696 697 698 699 700 701 702 703 704 705 706 707 708 709 710 711


def _build_table(statistic_data,
                 sorted_by=SortedKeys.CPUTotal,
                 op_detail=True,
                 thread_sep=False,
                 time_unit='ms',
                 row_limit=100,
                 max_src_column_width=75):
    """Prints a summary of events."""
    # format table row
    SPACING_SIZE = 2
    row_format_list = [""]
    header_sep_list = [""]
    line_length_list = [-SPACING_SIZE]

    def add_column(padding, text_dir='<'):
        row_format_list[0] += '{: ' + text_dir + str(padding) + '}' + (
            ' ' * SPACING_SIZE)
        header_sep_list[0] += '-' * padding + (' ' * SPACING_SIZE)
        line_length_list[0] += padding + SPACING_SIZE

    def add_title(padding, text):
        left_length = padding - len(text)
        half = left_length // 2
        return '-' * half + text + '-' * (left_length - half)

    result = []

    def append(s):
        result.append(s)
        result.append('\n')

    def format_time(time, unit='ms', indent=0):
        r"""
        Transform time in ns to time in unit.
        """
        if time == float('inf'):
            return '-'
        else:
            result = float(time)
            if unit == 's':
                result /= 1e9
            elif unit == 'ms':
                result /= 1e6
            elif unit == 'us':
                result /= 1e3
            return '{}{:.2f}'.format(' ' * indent, result)

    def format_ratio(ratio, indent=0):
        r"""
        Transform ratio within [0, 1] to percentage presentation.
        """
        return '{}{:.2f}'.format(' ' * indent, ratio * 100)

    total_time = statistic_data.time_range_summary.get_cpu_range_sum(
        TracerEventType.ProfileStep)
    ###### Print Device Summary ######
    headers = ['Device', 'Utilization (%)']
    name_column_width = 30
    DEFAULT_COLUMN_WIDTH = 20
    add_column(name_column_width)
    for _ in headers[1:]:
        add_column(DEFAULT_COLUMN_WIDTH)

    row_format = row_format_list[0]
    header_sep = header_sep_list[0]
    line_length = line_length_list[0]

    # construct table string

    append(add_title(line_length, "Device Summary"))
    append(header_sep)
    append(row_format.format(*headers))
    append(header_sep)
    row_values = [
        'CPU(Process)', format_ratio(
            float(statistic_data.extra_info['Process Cpu Utilization']))
    ]
    append(row_format.format(*row_values))
    row_values = [
        'CPU(System)', format_ratio(
            float(statistic_data.extra_info['System Cpu Utilization']))
    ]
    append(row_format.format(*row_values))
    for gpu_name in statistic_data.time_range_summary.get_gpu_devices():
        gpu_time = float(
            statistic_data.time_range_summary.get_gpu_range_sum(
                gpu_name, TracerEventType.Kernel))
        utilization = gpu_time / total_time
        row_values = ['GPU{}'.format(gpu_name), format_ratio(utilization)]
        append(row_format.format(*row_values))

    append(header_sep)
    append(
        "Note:\nCPU(Process) Utilization = Current process CPU time over all cpu cores / elapsed time, so max utilization can be reached 100% * number of cpu cores.\n"
        "CPU(System) Utilization = All processes CPU time over all cpu cores(busy time) / (busy time + idle time).\n"
C
chenjian 已提交
712
        "GPU Utilization = Current process GPU time / elapsed time.")
C
chenjian 已提交
713 714 715 716 717 718 719 720
    append('-' * line_length)
    append('')
    append('')

    if total_time == 0:
        return ''.join(result)

    ###### Print Overview Summary ######
721
    headers = ['Event Type', 'Calls', 'CPU Time', 'Ratio (%)']
C
chenjian 已提交
722 723 724 725 726 727 728 729 730 731 732 733 734 735 736 737 738 739 740 741
    row_format_list = [""]
    header_sep_list = [""]
    line_length_list = [-SPACING_SIZE]

    DEFAULT_COLUMN_WIDTH = 25
    for _ in headers:
        add_column(DEFAULT_COLUMN_WIDTH)

    row_format = row_format_list[0]
    header_sep = header_sep_list[0]
    line_length = line_length_list[0]

    # construct table string
    append(add_title(line_length, "Overview Summary"))
    append('Time unit: {}'.format(time_unit))
    append(header_sep)
    append(row_format.format(*headers))
    append(header_sep)
    cpu_type_time = collections.defaultdict(int)
    gpu_type_time = collections.defaultdict(int)
742 743 744 745 746
    cpu_call_times = collections.defaultdict(int)
    gpu_call_times = collections.defaultdict(int)
    cpu_call_times.update(statistic_data.time_range_summary.call_times)
    gpu_call_times.update(statistic_data.time_range_summary.call_times)

C
chenjian 已提交
747 748
    for event_type, value in statistic_data.time_range_summary.CPUTimeRangeSum.items(
    ):
C
chenjian 已提交
749 750 751 752 753
        if event_type != TracerEventType.Communication:
            cpu_type_time[event_type] = value
    if statistic_data.distributed_summary.cpu_communication_range:
        cpu_type_time[TracerEventType.Communication] = sum_ranges(
            statistic_data.distributed_summary.cpu_communication_range)
754 755 756 757 758 759 760 761 762 763 764 765 766
        cpu_call_times[
            TracerEventType.
            Communication] = statistic_data.distributed_summary.cpu_calls

    for event_type in [
            TracerEventType.Dataloader, TracerEventType.Forward,
            TracerEventType.Backward, TracerEventType.Optimization
    ]:
        event_type_name = str(event_type).split('.')[1]
        if event_type in cpu_call_times and event_type_name in statistic_data.event_summary.model_perspective_items:
            cpu_call_times[
                event_type] = statistic_data.event_summary.model_perspective_items[
                    event_type_name].call
767 768 769
            cpu_type_time[
                event_type] = statistic_data.event_summary.model_perspective_items[
                    event_type_name].cpu_time
C
chenjian 已提交
770 771 772 773 774 775 776 777 778

    gpu_time_range = collections.defaultdict(list)
    for device_id, device_time_ranges in statistic_data.time_range_summary.GPUTimeRange.items(
    ):
        for event_type, time_range in device_time_ranges.items():
            gpu_time_range[event_type] = merge_ranges(
                gpu_time_range[event_type], time_range, is_sorted=True)
    for event_type, time_range in gpu_time_range.items():
        gpu_type_time[event_type] = sum_ranges(time_range)
C
chenjian 已提交
779 780 781
    if statistic_data.distributed_summary.gpu_communication_range:
        gpu_type_time[TracerEventType.Communication] = sum_ranges(
            statistic_data.distributed_summary.gpu_communication_range)
782 783 784
        gpu_call_times[
            TracerEventType.
            Communication] = statistic_data.distributed_summary.gpu_calls
C
chenjian 已提交
785 786 787

    sorted_items = sorted(
        cpu_type_time.items(), key=lambda x: x[1], reverse=True)
788 789 790 791 792 793 794 795
    event_type, time = sorted_items[0]
    row_values = [
        '{}'.format(str(event_type).split('.')[1]), cpu_call_times[event_type],
        format_time(
            time, unit=time_unit), format_ratio(float(time) / total_time)
    ]
    append(row_format.format(*row_values))
    for event_type, time in sorted_items[1:]:
C
chenjian 已提交
796
        row_values = [
797 798
            '  {}'.format(str(event_type).split('.')[1]),
            cpu_call_times[event_type], format_time(
C
chenjian 已提交
799 800 801 802
                time, unit=time_unit), format_ratio(float(time) / total_time)
        ]
        append(row_format.format(*row_values))
    append(header_sep)
803
    headers = ['', 'Calls', 'GPU Time', 'Ratio (%)']
C
chenjian 已提交
804 805 806 807
    append(row_format.format(*headers))
    append(header_sep)
    for event_type, time in gpu_type_time.items():
        row_values = [
808 809
            '  {}'.format(str(event_type).split('.')[1]),
            gpu_call_times[event_type], format_time(
C
chenjian 已提交
810 811 812 813 814 815 816 817 818 819 820 821 822 823 824 825 826 827 828 829 830
                time, unit=time_unit), format_ratio(float(time) / total_time)
        ]
        append(row_format.format(*row_values))

    append(header_sep)
    append(
        "Note:\nIn this table, We sum up all collected events in terms of event type.\n"
        "The time of events collected on host are presented as CPU Time, and as GPU Time if on device.\n"
        "Events with different types may overlap or inclusion, e.g. Operator includes OperatorInner, so the sum of ratios is not 100%.\n"
        "The time of events in the same type with overlap will not calculate twice, and all time is summed after merged.\n"
        "Example:\n"
        "Thread 1:\n"
        "  Operator: |___________|     |__________|\n"
        "Thread 2:\n"
        "  Operator:   |____________|     |___|\n"
        "After merged:\n"
        "  Result:   |______________|  |__________|\n")
    append('-' * line_length)
    append('')
    append('')

C
chenjian 已提交
831 832
    ###### Print Model Summary Report ######
    model_perspective_items = statistic_data.event_summary.model_perspective_items
833
    if len(model_perspective_items) > 1:
C
chenjian 已提交
834 835
        all_row_values = []
        accmulation_time = 0
836
        gpu_accmulation_time = 0
837 838
        gpu_total_time = statistic_data.event_summary.model_perspective_items[
            'ProfileStep'].general_gpu_time
839 840 841 842
        for name in [
                'ProfileStep', 'Dataloader', 'Forward', 'Backward',
                'Optimization'
        ]:
C
chenjian 已提交
843 844
            if name in model_perspective_items:
                item = model_perspective_items[name]
845 846 847 848
                if gpu_total_time == 0:
                    gpu_ratio = 0
                else:
                    gpu_ratio = float(item.general_gpu_time) / gpu_total_time
849 850
                name = '{}'.format(
                    name) if 'ProfileStep' in name else '  {}'.format(name)
C
chenjian 已提交
851
                row_values = [
852
                    '{}'.format(name), item.call,
C
chenjian 已提交
853 854 855 856 857 858 859 860 861 862 863 864 865 866 867 868 869 870 871
                    '{} / {} / {} / {} / {}'.format(
                        format_time(
                            item.cpu_time, unit=time_unit),
                        format_time(
                            item.avg_cpu_time, unit=time_unit),
                        format_time(
                            item.max_cpu_time, unit=time_unit),
                        format_time(
                            item.min_cpu_time, unit=time_unit),
                        format_ratio(float(item.cpu_time) / total_time)),
                    '{} / {} / {} / {} / {}'.format(
                        format_time(
                            item.gpu_time, unit=time_unit),
                        format_time(
                            item.avg_gpu_time, unit=time_unit),
                        format_time(
                            item.max_gpu_time, unit=time_unit),
                        format_time(
                            item.min_gpu_time, unit=time_unit),
872
                        format_ratio(gpu_ratio))
C
chenjian 已提交
873
                ]
C
chenjian 已提交
874
                all_row_values.append(row_values)
875 876
                if 'ProfileStep' not in name:
                    accmulation_time += item.cpu_time
877
                    gpu_accmulation_time += item.general_gpu_time
C
chenjian 已提交
878 879

        other_time = total_time - accmulation_time
880
        other_gpu_time = gpu_total_time - gpu_accmulation_time
881 882 883 884
        if gpu_total_time == 0:
            gpu_ratio = 0
        else:
            gpu_ratio = float(other_gpu_time) / gpu_total_time
C
chenjian 已提交
885 886 887 888 889
        row_values = [
            '  Others', '-', '{} / - / - / - / {}'.format(
                format_time(
                    other_time, unit=time_unit),
                format_ratio(float(other_time) / total_time)),
890 891 892
            '{} / - / - / - / {}'.format(
                format_time(
                    other_gpu_time, unit=time_unit),
893
                format_ratio(gpu_ratio))
C
chenjian 已提交
894
        ]
C
chenjian 已提交
895 896 897 898 899 900 901 902 903 904 905 906 907 908 909 910 911 912 913 914 915 916 917 918 919 920 921 922 923 924 925 926 927 928 929
        all_row_values.append(row_values)
        # Calculate the column width
        calltime_width = 6
        cpu_data_description_width = 40
        gpu_data_description_width = 40
        for row_values in all_row_values:
            if isinstance(row_values[1],
                          int) and len(str(row_values[1])) > calltime_width:
                calltime_width = len(str(row_values[1]))
            if len(row_values[2]) > cpu_data_description_width:
                cpu_data_description_width = len(row_values[2])
            if len(row_values[3]) > gpu_data_description_width:
                gpu_data_description_width = len(row_values[3])
        headers = [
            'Name', 'Calls', 'CPU Total / Avg / Max / Min / Ratio(%)',
            'GPU Total / Avg / Max / Min / Ratio(%)'
        ]
        row_format_list = [""]
        header_sep_list = [""]
        line_length_list = [-SPACING_SIZE]
        name_column_width = 15
        add_column(name_column_width)
        add_column(calltime_width)
        add_column(cpu_data_description_width)
        add_column(gpu_data_description_width)

        row_format = row_format_list[0]
        header_sep = header_sep_list[0]
        line_length = line_length_list[0]

        # construct table string
        append(add_title(line_length, "Model Summary"))
        append('Time unit: {}'.format(time_unit))
        append(header_sep)
        append(row_format.format(*headers))
C
chenjian 已提交
930
        append(header_sep)
C
chenjian 已提交
931 932 933 934 935 936 937 938
        for row_values in all_row_values:
            append(row_format.format(*row_values))
        append(header_sep)
        append(
            "Note:\nIn this table, GPU time is the sum of all device(GPU) events called in the phase.\n"
            "Unlike overview summary, if two device(GPU) events execute on different streams with overlap time, we sum them directly here.\n"
        )
        append('-' * line_length)
C
chenjian 已提交
939 940 941 942
        append('')
        append('')

    ###### Print Distribution Summary Report ######
C
chenjian 已提交
943
    if statistic_data.distributed_summary.communication_range:
C
chenjian 已提交
944 945 946 947 948 949 950 951 952
        headers = [
            'Name',
            'Total Time',
            'Ratio (%)',
        ]
        row_format_list = [""]
        header_sep_list = [""]
        line_length_list = [-SPACING_SIZE]

C
chenjian 已提交
953
        DEFAULT_COLUMN_WIDTH = 25
C
chenjian 已提交
954 955 956 957 958 959 960 961 962 963 964 965 966
        for _ in headers:
            add_column(DEFAULT_COLUMN_WIDTH)

        row_format = row_format_list[0]
        header_sep = header_sep_list[0]
        line_length = line_length_list[0]

        # construct table string
        append(add_title(line_length, "Distribution Summary"))
        append('Time unit: {}'.format(time_unit))
        append(header_sep)
        append(row_format.format(*headers))
        append(header_sep)
C
chenjian 已提交
967 968 969 970 971 972
        communication_time = sum_ranges(
            statistic_data.distributed_summary.communication_range)
        computation_time = sum_ranges(
            statistic_data.distributed_summary.computation_range)
        overlap_time = sum_ranges(
            statistic_data.distributed_summary.overlap_range)
C
chenjian 已提交
973
        row_values = [
974 975 976 977 978 979 980
            'ProfileStep', format_time(
                total_time, unit=time_unit),
            format_ratio(float(total_time) / total_time)
        ]
        append(row_format.format(*row_values))
        row_values = [
            '  Communication', format_time(
C
chenjian 已提交
981 982 983 984 985 986
                communication_time, unit=time_unit),
            format_ratio(float(communication_time) / total_time)
        ]
        append(row_format.format(*row_values))

        row_values = [
987
            '  Computation', format_time(
C
chenjian 已提交
988 989 990 991 992 993
                computation_time, unit=time_unit),
            format_ratio(float(computation_time) / total_time)
        ]
        append(row_format.format(*row_values))

        row_values = [
994
            '  Overlap', format_time(
C
chenjian 已提交
995 996 997 998 999 1000
                overlap_time, unit=time_unit),
            format_ratio(float(overlap_time) / total_time)
        ]
        append(row_format.format(*row_values))
        append(header_sep)
        append(
C
chenjian 已提交
1001 1002 1003
            "Note:\nCommunication time: Communication Event time, Communication Op time and its kernel time on gpu.\n"
            "Computation time: Kernel time, except kernels belong to communication(nccl kernels).\n"
            "Overlap time: Communication time intersects with computation time.\n"
C
chenjian 已提交
1004 1005 1006 1007 1008 1009 1010 1011 1012 1013 1014 1015
            "Example:\n"
            "Communication:\n"
            "  CPU:              |_________________|\n"
            "  GPU:                                  |______________|\n"
            "  Total:            |_________________| |______________|\n"
            "Computation time(Kernel):\n"
            "  GPU:         |________________|\n"
            "Overlap time:       |___________|\n")
        append('-' * line_length)
        append('')
        append('')

C
chenjian 已提交
1016 1017
    ###### Print Operator Summary Report ######
    if statistic_data.event_summary.items:
C
chenjian 已提交
1018 1019
        all_row_values = []
        name_column_width = 52
C
chenjian 已提交
1020 1021 1022 1023 1024 1025 1026
        if thread_sep == True:
            thread_items = statistic_data.event_summary.thread_items
        else:
            thread_items = {
                'All threads merged': statistic_data.event_summary.items
            }
        for thread_id, items in thread_items.items():
C
chenjian 已提交
1027
            all_row_values.append("Thread: {}".format(thread_id))
C
chenjian 已提交
1028 1029 1030 1031 1032 1033 1034 1035 1036 1037 1038 1039 1040 1041 1042 1043 1044 1045
            if sorted_by == SortedKeys.CPUTotal:
                sorted_items = sorted(
                    items.items(), key=lambda x: x[1].cpu_time, reverse=True)
            elif sorted_by == SortedKeys.CPUAvg:
                sorted_items = sorted(
                    items.items(),
                    key=lambda x: x[1].avg_cpu_time,
                    reverse=True)
            elif sorted_by == SortedKeys.CPUMax:
                sorted_items = sorted(
                    items.items(),
                    key=lambda x: x[1].max_cpu_time,
                    reverse=True)
            elif sorted_by == SortedKeys.CPUMin:
                sorted_items = sorted(
                    items.items(), key=lambda x: x[1].min_cpu_time)
            elif sorted_by == SortedKeys.GPUTotal:
                sorted_items = sorted(
1046 1047 1048
                    items.items(),
                    key=lambda x: x[1].general_gpu_time,
                    reverse=True)
C
chenjian 已提交
1049 1050 1051
            elif sorted_by == SortedKeys.GPUAvg:
                sorted_items = sorted(
                    items.items(),
1052
                    key=lambda x: x[1].avg_general_gpu_time,
C
chenjian 已提交
1053 1054 1055 1056
                    reverse=True)
            elif sorted_by == SortedKeys.GPUMax:
                sorted_items = sorted(
                    items.items(),
1057
                    key=lambda x: x[1].max_general_gpu_time,
C
chenjian 已提交
1058 1059 1060
                    reverse=True)
            elif sorted_by == SortedKeys.GPUMin:
                sorted_items = sorted(
1061
                    items.items(), key=lambda x: x[1].min_general_gpu_time)
1062 1063 1064 1065 1066 1067
            total_op_cpu_time = 0
            total_op_gpu_time = 0

            for name, item in sorted_items:
                total_op_cpu_time += item.cpu_time
                total_op_gpu_time += item.general_gpu_time
C
chenjian 已提交
1068 1069

            for name, item in sorted_items:
1070 1071 1072 1073 1074 1075 1076 1077
                if total_op_cpu_time == 0:
                    cpu_ratio = 0
                else:
                    cpu_ratio = float(item.cpu_time) / total_op_cpu_time
                if total_op_gpu_time == 0:
                    gpu_ratio = 0
                else:
                    gpu_ratio = float(item.general_gpu_time) / total_op_gpu_time
C
chenjian 已提交
1078 1079 1080 1081 1082 1083 1084 1085 1086 1087
                row_values = [
                    name, item.call, '{} / {} / {} / {} / {}'.format(
                        format_time(
                            item.cpu_time, unit=time_unit),
                        format_time(
                            item.avg_cpu_time, unit=time_unit),
                        format_time(
                            item.max_cpu_time, unit=time_unit),
                        format_time(
                            item.min_cpu_time, unit=time_unit),
1088
                        format_ratio(cpu_ratio)),
C
chenjian 已提交
1089 1090
                    '{} / {} / {} / {} / {}'.format(
                        format_time(
1091
                            item.general_gpu_time, unit=time_unit),
C
chenjian 已提交
1092
                        format_time(
1093
                            item.avg_general_gpu_time, unit=time_unit),
C
chenjian 已提交
1094
                        format_time(
1095
                            item.max_general_gpu_time, unit=time_unit),
C
chenjian 已提交
1096
                        format_time(
1097
                            item.min_general_gpu_time, unit=time_unit),
1098
                        format_ratio(gpu_ratio))
C
chenjian 已提交
1099
                ]
C
chenjian 已提交
1100
                all_row_values.append(row_values)
C
chenjian 已提交
1101 1102 1103
                if op_detail:
                    for innerop_name, innerop_node in item.operator_inners.items(
                    ):
1104 1105 1106 1107 1108 1109 1110 1111 1112 1113
                        if item.cpu_time == 0:
                            cpu_ratio = 0
                        else:
                            cpu_ratio = float(
                                innerop_node.cpu_time) / item.cpu_time
                        if item.general_gpu_time == 0:
                            gpu_ratio = 0
                        else:
                            gpu_ratio = float(innerop_node.general_gpu_time
                                              ) / item.general_gpu_time
C
chenjian 已提交
1114 1115 1116
                        if len(innerop_name) + 2 > name_column_width:
                            innerop_name = innerop_name[:name_column_width - 5]
                            innerop_name += "..."
C
chenjian 已提交
1117 1118 1119 1120 1121 1122 1123 1124 1125 1126 1127
                        row_values = [
                            '  {}'.format(innerop_name), innerop_node.call,
                            '{} / {} / {} / {} / {}'.format(
                                format_time(
                                    innerop_node.cpu_time, unit=time_unit),
                                format_time(
                                    innerop_node.avg_cpu_time, unit=time_unit),
                                format_time(
                                    innerop_node.max_cpu_time, unit=time_unit),
                                format_time(
                                    innerop_node.min_cpu_time, unit=time_unit),
1128
                                format_ratio(cpu_ratio)),
C
chenjian 已提交
1129 1130
                            '{} / {} / {} / {} / {}'.format(
                                format_time(
1131 1132
                                    innerop_node.general_gpu_time,
                                    unit=time_unit),
C
chenjian 已提交
1133
                                format_time(
1134 1135
                                    innerop_node.avg_general_gpu_time,
                                    unit=time_unit),
C
chenjian 已提交
1136
                                format_time(
1137 1138
                                    innerop_node.max_general_gpu_time,
                                    unit=time_unit),
C
chenjian 已提交
1139
                                format_time(
1140 1141
                                    innerop_node.min_general_gpu_time,
                                    unit=time_unit),
1142
                                format_ratio(gpu_ratio))
C
chenjian 已提交
1143
                        ]
C
chenjian 已提交
1144
                        all_row_values.append(row_values)
1145
                        for device_node_name, device_node in innerop_node.devices.items(
C
chenjian 已提交
1146
                        ):
1147 1148 1149 1150 1151 1152
                            if innerop_node.general_gpu_time == 0:
                                gpu_ratio = 0
                            else:
                                gpu_ratio = float(
                                    device_node.
                                    gpu_time) / innerop_node.general_gpu_time
C
chenjian 已提交
1153 1154 1155 1156 1157 1158 1159
                            if len(device_node_name) + 4 > name_column_width:
                                device_node_name = device_node_name[:
                                                                    name_column_width
                                                                    - 7]
                                device_node_name += "..."
                            row_values = [
                                '    {}'.format(device_node_name),
1160
                                device_node.call, '- / - / - / - / -',
C
chenjian 已提交
1161 1162
                                '{} / {} / {} / {} / {}'.format(
                                    format_time(
1163
                                        device_node.gpu_time, unit=time_unit),
C
chenjian 已提交
1164
                                    format_time(
1165
                                        device_node.avg_gpu_time,
C
chenjian 已提交
1166 1167
                                        unit=time_unit),
                                    format_time(
1168
                                        device_node.max_gpu_time,
C
chenjian 已提交
1169 1170
                                        unit=time_unit),
                                    format_time(
1171
                                        device_node.min_gpu_time,
C
chenjian 已提交
1172
                                        unit=time_unit),
1173
                                    format_ratio(gpu_ratio))
C
chenjian 已提交
1174
                            ]
C
chenjian 已提交
1175
                            all_row_values.append(row_values)
C
chenjian 已提交
1176
                    for device_node_name, device_node in item.devices.items():
1177 1178 1179 1180 1181
                        if item.general_gpu_time == 0:
                            gpu_ratio = 0
                        else:
                            gpu_ratio = float(
                                device_node.gpu_time) / item.general_gpu_time
C
chenjian 已提交
1182 1183 1184 1185 1186 1187
                        if len(device_node_name) + 2 > name_column_width:
                            device_node_name = device_node_name[:
                                                                name_column_width
                                                                - 5]
                            device_node_name += "..."
                        row_values = [
1188
                            '  {}'.format(device_node_name), device_node.call,
C
chenjian 已提交
1189 1190 1191
                            '- / - / - / - / -',
                            '{} / {} / {} / {} / {}'.format(
                                format_time(
1192
                                    device_node.gpu_time, unit=time_unit),
C
chenjian 已提交
1193
                                format_time(
1194
                                    device_node.avg_gpu_time, unit=time_unit),
C
chenjian 已提交
1195
                                format_time(
1196
                                    device_node.max_gpu_time, unit=time_unit),
C
chenjian 已提交
1197
                                format_time(
1198
                                    device_node.min_gpu_time, unit=time_unit),
1199
                                format_ratio(gpu_ratio))
C
chenjian 已提交
1200
                        ]
C
chenjian 已提交
1201 1202 1203 1204 1205 1206 1207 1208 1209 1210 1211 1212 1213 1214 1215
                        all_row_values.append(row_values)
        # Calculate the column width
        calltime_width = 6
        cpu_data_description_width = 40
        gpu_data_description_width = 40
        for row_values in all_row_values:
            if isinstance(row_values, str):
                continue
            if isinstance(row_values[1],
                          int) and len(str(row_values[1])) > calltime_width:
                calltime_width = len(str(row_values[1]))
            if len(row_values[2]) > cpu_data_description_width:
                cpu_data_description_width = len(row_values[2])
            if len(row_values[3]) > gpu_data_description_width:
                gpu_data_description_width = len(row_values[3])
C
chenjian 已提交
1216 1217 1218 1219 1220 1221 1222 1223
        headers = [
            'Name', 'Calls', 'CPU Total / Avg / Max / Min / Ratio(%)',
            'GPU Total / Avg / Max / Min / Ratio(%)'
        ]
        row_format_list = [""]
        header_sep_list = [""]
        line_length_list = [-SPACING_SIZE]
        add_column(name_column_width)
C
chenjian 已提交
1224 1225 1226
        add_column(calltime_width)
        add_column(cpu_data_description_width)
        add_column(gpu_data_description_width)
C
chenjian 已提交
1227 1228 1229 1230 1231 1232

        row_format = row_format_list[0]
        header_sep = header_sep_list[0]
        line_length = line_length_list[0]

        # construct table string
C
chenjian 已提交
1233
        append(add_title(line_length, "Operator Summary"))
C
chenjian 已提交
1234 1235 1236 1237
        append('Time unit: {}'.format(time_unit))
        append(header_sep)
        append(row_format.format(*headers))
        append(header_sep)
C
chenjian 已提交
1238 1239 1240 1241 1242 1243 1244 1245 1246
        for row_values in all_row_values:
            if isinstance(row_values, str):
                append(add_title(line_length, row_values))
            else:
                append(row_format.format(*row_values))
        append(header_sep)
        append('')
        append('')

1247 1248 1249 1250 1251 1252 1253 1254 1255 1256 1257 1258 1259 1260 1261 1262 1263 1264 1265 1266 1267 1268 1269 1270 1271 1272 1273 1274 1275 1276 1277 1278 1279 1280 1281 1282 1283 1284 1285 1286 1287 1288 1289 1290 1291 1292 1293 1294 1295 1296 1297 1298 1299 1300 1301 1302 1303 1304 1305 1306 1307 1308 1309 1310 1311 1312 1313 1314 1315 1316 1317 1318 1319 1320
    ###### Print Kernel Summary Report ######
    if statistic_data.event_summary.kernel_items:
        all_row_values = []
        kernel_items = statistic_data.event_summary.kernel_items
        if sorted_by == SortedKeys.GPUAvg:
            sorted_items = sorted(
                kernel_items.items(),
                key=lambda x: x[1].avg_gpu_time,
                reverse=True)
        elif sorted_by == SortedKeys.GPUMax:
            sorted_items = sorted(
                kernel_items.items(),
                key=lambda x: x[1].max_gpu_time,
                reverse=True)
        elif sorted_by == SortedKeys.GPUMin:
            sorted_items = sorted(
                kernel_items.items(), key=lambda x: x[1].min_gpu_time)
        else:
            sorted_items = sorted(
                kernel_items.items(), key=lambda x: x[1].gpu_time, reverse=True)

        total_kernel_gpu_time = 0
        for name, item in sorted_items:
            total_kernel_gpu_time += item.gpu_time
        for name, item in sorted_items:
            if total_kernel_gpu_time == 0:
                gpu_ratio = 0
            else:
                gpu_ratio = float(item.gpu_time) / total_kernel_gpu_time
            row_values = [
                name,
                item.call,
                '{} / {} / {} / {} / {}'.format(
                    format_time(
                        item.gpu_time, unit=time_unit),
                    format_time(
                        item.avg_gpu_time, unit=time_unit),
                    format_time(
                        item.max_gpu_time, unit=time_unit),
                    format_time(
                        item.min_gpu_time, unit=time_unit),
                    format_ratio(gpu_ratio)),
            ]
            all_row_values.append(row_values)

        headers = ['Name', 'Calls', 'GPU Total / Avg / Max / Min / Ratio(%)']
        # Calculate the column width
        name_column_width = 90
        calltime_width = 6
        gpu_data_description_width = 40
        for row_values in all_row_values:
            if isinstance(row_values[1],
                          int) and len(str(row_values[1])) > calltime_width:
                calltime_width = len(str(row_values[1]))
            if len(row_values[2]) > gpu_data_description_width:
                gpu_data_description_width = len(row_values[2])

        row_format_list = [""]
        header_sep_list = [""]
        line_length_list = [-SPACING_SIZE]
        add_column(name_column_width)
        add_column(calltime_width)
        add_column(gpu_data_description_width)

        row_format = row_format_list[0]
        header_sep = header_sep_list[0]
        line_length = line_length_list[0]

        # construct table string
        append(add_title(line_length, "Kernel Summary"))
        append('Time unit: {}'.format(time_unit))
        append(header_sep)
        append(row_format.format(*headers))
        append(header_sep)
1321
        kernel_name_pattern = re.compile('(.+?)(<.*>)(\(.*\))')
1322
        for row_values in all_row_values:
1323 1324 1325
            match = kernel_name_pattern.match(row_values[0])
            if match:
                name = match.group(1) + match.group(2)
1326 1327 1328 1329 1330 1331 1332 1333 1334 1335 1336
            else:
                name = row_values[0]
            if len(name) > name_column_width:
                row_values[0] = name[:name_column_width - 3] + '...'
            else:
                row_values[0] = name
            append(row_format.format(*row_values))
        append(header_sep)
        append('')
        append('')

C
chenjian 已提交
1337 1338 1339
    ###### Print Memory Manipulation Summary Report ######
    if statistic_data.event_summary.memory_manipulation_items:
        all_row_values = []
C
chenjian 已提交
1340
        memory_manipulation_items = statistic_data.event_summary.memory_manipulation_items
1341 1342
        gpu_total_time = statistic_data.event_summary.model_perspective_items[
            'ProfileStep'].general_gpu_time
C
chenjian 已提交
1343
        for name, item in memory_manipulation_items.items():
1344 1345 1346 1347
            if gpu_total_time == 0:
                gpu_ratio = 0
            else:
                gpu_ratio = float(item.general_gpu_time) / gpu_total_time
C
chenjian 已提交
1348 1349 1350 1351 1352 1353 1354 1355 1356 1357 1358 1359 1360 1361 1362
            row_values = [
                name,
                item.call,
                '{} / {} / {} / {} / {}'.format(
                    format_time(
                        item.cpu_time, unit=time_unit),
                    format_time(
                        item.avg_cpu_time, unit=time_unit),
                    format_time(
                        item.max_cpu_time, unit=time_unit),
                    format_time(
                        item.min_cpu_time, unit=time_unit),
                    format_ratio(float(item.cpu_time) / total_time)),
                '{} / {} / {} / {} / {}'.format(
                    format_time(
1363
                        item.general_gpu_time, unit=time_unit),
C
chenjian 已提交
1364
                    format_time(
1365
                        item.avg_general_gpu_time, unit=time_unit),
C
chenjian 已提交
1366
                    format_time(
1367
                        item.max_general_gpu_time, unit=time_unit),
C
chenjian 已提交
1368
                    format_time(
1369
                        item.min_general_gpu_time, unit=time_unit),
1370
                    format_ratio(gpu_ratio)),
C
chenjian 已提交
1371
            ]
C
chenjian 已提交
1372 1373
            all_row_values.append(row_values)

C
chenjian 已提交
1374 1375 1376 1377
        headers = [
            'Name', 'Calls', 'CPU Total / Avg / Max / Min / Ratio(%)',
            'GPU Total / Avg / Max / Min / Ratio(%)'
        ]
C
chenjian 已提交
1378 1379 1380 1381 1382 1383 1384 1385 1386 1387 1388 1389 1390 1391 1392 1393
        # Calculate the column width
        name_column_width = 0
        calltime_width = 6
        cpu_data_description_width = 40
        gpu_data_description_width = 40
        for row_values in all_row_values:
            if len(row_values[0]) > name_column_width:
                name_column_width = len(row_values[0])
            if isinstance(row_values[1],
                          int) and len(str(row_values[1])) > calltime_width:
                calltime_width = len(str(row_values[1]))
            if len(row_values[2]) > cpu_data_description_width:
                cpu_data_description_width = len(row_values[2])
            if len(row_values[3]) > gpu_data_description_width:
                gpu_data_description_width = len(row_values[3])

C
chenjian 已提交
1394 1395 1396 1397
        row_format_list = [""]
        header_sep_list = [""]
        line_length_list = [-SPACING_SIZE]
        add_column(name_column_width)
C
chenjian 已提交
1398 1399 1400
        add_column(calltime_width)
        add_column(cpu_data_description_width)
        add_column(gpu_data_description_width)
C
chenjian 已提交
1401 1402 1403 1404 1405 1406

        row_format = row_format_list[0]
        header_sep = header_sep_list[0]
        line_length = line_length_list[0]

        # construct table string
C
chenjian 已提交
1407
        append(add_title(line_length, "Memory Manipulation Summary"))
C
chenjian 已提交
1408 1409 1410 1411
        append('Time unit: {}'.format(time_unit))
        append(header_sep)
        append(row_format.format(*headers))
        append(header_sep)
C
chenjian 已提交
1412 1413 1414 1415 1416 1417 1418 1419
        for row_values in all_row_values:
            append(row_format.format(*row_values))
        append(header_sep)
        append('')
        append('')
    ###### Print UserDefined Summary Report ######
    if statistic_data.event_summary.userdefined_items:
        all_row_values = []
1420 1421
        gpu_total_time = statistic_data.event_summary.model_perspective_items[
            'ProfileStep'].general_gpu_time
C
chenjian 已提交
1422 1423 1424 1425 1426 1427 1428 1429
        if thread_sep == True:
            userdefined_thread_items = statistic_data.event_summary.userdefined_thread_items
        else:
            userdefined_thread_items = {
                'All threads merged':
                statistic_data.event_summary.userdefined_items
            }
        for thread_id, items in userdefined_thread_items.items():
C
chenjian 已提交
1430
            all_row_values.append("Thread: {}".format(thread_id))
C
chenjian 已提交
1431 1432 1433 1434 1435 1436 1437 1438 1439 1440 1441 1442 1443 1444 1445 1446 1447 1448
            if sorted_by == SortedKeys.CPUTotal:
                sorted_items = sorted(
                    items.items(), key=lambda x: x[1].cpu_time, reverse=True)
            elif sorted_by == SortedKeys.CPUAvg:
                sorted_items = sorted(
                    items.items(),
                    key=lambda x: x[1].avg_cpu_time,
                    reverse=True)
            elif sorted_by == SortedKeys.CPUMax:
                sorted_items = sorted(
                    items.items(),
                    key=lambda x: x[1].max_cpu_time,
                    reverse=True)
            elif sorted_by == SortedKeys.CPUMin:
                sorted_items = sorted(
                    items.items(), key=lambda x: x[1].min_cpu_time)
            elif sorted_by == SortedKeys.GPUTotal:
                sorted_items = sorted(
1449 1450 1451
                    items.items(),
                    key=lambda x: x[1].general_gpu_time,
                    reverse=True)
C
chenjian 已提交
1452 1453 1454
            elif sorted_by == SortedKeys.GPUAvg:
                sorted_items = sorted(
                    items.items(),
1455
                    key=lambda x: x[1].avg_general_gpu_time,
C
chenjian 已提交
1456 1457 1458 1459
                    reverse=True)
            elif sorted_by == SortedKeys.GPUMax:
                sorted_items = sorted(
                    items.items(),
1460
                    key=lambda x: x[1].max_general_gpu_time,
C
chenjian 已提交
1461 1462 1463
                    reverse=True)
            elif sorted_by == SortedKeys.GPUMin:
                sorted_items = sorted(
1464
                    items.items(), key=lambda x: x[1].min_general_gpu_time)
C
chenjian 已提交
1465 1466

            for name, item in sorted_items:
1467 1468 1469 1470
                if gpu_total_time == 0:
                    gpu_ratio = 0
                else:
                    gpu_ratio = float(item.general_gpu_time) / gpu_total_time
C
chenjian 已提交
1471 1472 1473 1474 1475 1476 1477 1478 1479 1480 1481 1482 1483 1484 1485
                row_values = [
                    name,
                    item.call,
                    '{} / {} / {} / {} / {}'.format(
                        format_time(
                            item.cpu_time, unit=time_unit),
                        format_time(
                            item.avg_cpu_time, unit=time_unit),
                        format_time(
                            item.max_cpu_time, unit=time_unit),
                        format_time(
                            item.min_cpu_time, unit=time_unit),
                        format_ratio(float(item.cpu_time) / total_time)),
                    '{} / {} / {} / {} / {}'.format(
                        format_time(
1486
                            item.general_gpu_time, unit=time_unit),
C
chenjian 已提交
1487
                        format_time(
1488
                            item.avg_general_gpu_time, unit=time_unit),
C
chenjian 已提交
1489
                        format_time(
1490
                            item.max_general_gpu_time, unit=time_unit),
C
chenjian 已提交
1491
                        format_time(
1492
                            item.min_general_gpu_time, unit=time_unit),
1493
                        format_ratio(gpu_ratio)),
C
chenjian 已提交
1494
                ]
C
chenjian 已提交
1495 1496 1497 1498 1499 1500 1501 1502 1503 1504 1505 1506 1507 1508 1509 1510 1511 1512 1513 1514 1515 1516 1517 1518 1519 1520 1521 1522 1523 1524 1525 1526 1527 1528 1529 1530 1531 1532 1533 1534 1535 1536 1537 1538 1539 1540 1541
                all_row_values.append(row_values)

        # Calculate the column width
        name_column_width = 0
        calltime_width = 6
        cpu_data_description_width = 40
        gpu_data_description_width = 40
        for row_values in all_row_values:
            if isinstance(row_values, str):
                continue
            if len(row_values[0]) > name_column_width:
                name_column_width = len(row_values[0])
            if isinstance(row_values[1],
                          int) and len(str(row_values[1])) > calltime_width:
                calltime_width = len(str(row_values[1]))
            if len(row_values[2]) > cpu_data_description_width:
                cpu_data_description_width = len(row_values[2])
            if len(row_values[3]) > gpu_data_description_width:
                gpu_data_description_width = len(row_values[3])

        headers = [
            'Name', 'Calls', 'CPU Total / Avg / Max / Min / Ratio(%)',
            'GPU Total / Avg / Max / Min / Ratio(%)'
        ]
        row_format_list = [""]
        header_sep_list = [""]
        line_length_list = [-SPACING_SIZE]

        add_column(name_column_width)
        add_column(calltime_width)
        add_column(cpu_data_description_width)
        add_column(gpu_data_description_width)

        row_format = row_format_list[0]
        header_sep = header_sep_list[0]
        line_length = line_length_list[0]

        # construct table string
        append(add_title(line_length, "UserDefined Summary"))
        append('Time unit: {}'.format(time_unit))
        append(header_sep)
        append(row_format.format(*headers))
        append(header_sep)
        for row_values in all_row_values:
            if isinstance(row_values, str):
                append(add_title(line_length, row_values))
            else:
C
chenjian 已提交
1542
                append(row_format.format(*row_values))
C
chenjian 已提交
1543 1544 1545
        append('')
        append('')

C
chenjian 已提交
1546
    return ''.join(result)