profiler_statistic.py 63.1 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
C
chenjian 已提交
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
]

C
chenjian 已提交
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
C
chenjian 已提交
78
        self.gpu_time = 0  # kernel time
C
chenjian 已提交
79
        self.self_gpu_time = 0
C
chenjian 已提交
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
C
chenjian 已提交
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
C
chenjian 已提交
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:
C
chenjian 已提交
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
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(
200 201
            lambda: collections.defaultdict(
                list))  # GPU events should be divided into different devices
C
chenjian 已提交
202 203 204 205 206 207 208 209 210 211 212 213 214
        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(
215 216
                lambda: collections.defaultdict(lambda: collections.defaultdict(
                    list)))  # device_id/type/stream_id
C
chenjian 已提交
217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237
            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():
238 239
                        time_ranges = merge_self_ranges(time_ranges,
                                                        is_sorted=False)
C
chenjian 已提交
240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261
                        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 = []
C
chenjian 已提交
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

    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():
313 314 315
                                    self.gpu_communication_range.append(
                                        (devicenode.start_ns,
                                         devicenode.end_ns))
C
chenjian 已提交
316
                                else:
317 318 319
                                    self.computation_range.append(
                                        (devicenode.start_ns,
                                         devicenode.end_ns))
C
chenjian 已提交
320 321
        self.cpu_calls = len(set(self.cpu_communication_range))
        self.gpu_calls = len(set(self.gpu_communication_range))
C
chenjian 已提交
322 323 324 325
        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)
326 327 328 329 330 331 332 333
        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


C
chenjian 已提交
336 337 338 339 340 341
class EventSummary:
    r"""
    Analyse operator event in profiling data, correlate with its device event.
    """

    class DeviceItem:
342

C
chenjian 已提交
343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365
        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:
366

C
chenjian 已提交
367 368 369 370 371 372 373 374 375 376 377
        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 = {}
C
chenjian 已提交
378 379 380
            self.general_gpu_time = 0
            self.min_general_gpu_time = float('inf')
            self.max_general_gpu_time = 0
C
chenjian 已提交
381 382 383 384 385 386 387 388 389

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

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

C
chenjian 已提交
390 391 392 393
        @property
        def avg_general_gpu_time(self):
            return self.general_gpu_time / self.call

C
chenjian 已提交
394 395 396 397 398 399 400 401 402 403 404 405 406 407
        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

C
chenjian 已提交
408 409 410 411 412 413 414
        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 已提交
415 416 417 418 419 420 421
        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)
C
chenjian 已提交
422
            self.add_general_gpu_time(node.general_gpu_time)
C
chenjian 已提交
423 424 425 426 427 428 429 430
            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:
431 432 433 434
                    name = devicenode.name
                    if name not in self.devices:
                        self.devices[name] = EventSummary.DeviceItem(name)
                    self.devices[name].add_item(devicenode)
C
chenjian 已提交
435 436

    class GeneralItem:
437

C
chenjian 已提交
438 439 440 441 442 443 444 445 446
        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')
C
chenjian 已提交
447 448 449
            self.general_gpu_time = 0
            self.min_general_gpu_time = float('inf')
            self.max_general_gpu_time = 0
C
chenjian 已提交
450 451 452 453 454 455 456 457 458

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

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

C
chenjian 已提交
459 460 461 462
        @property
        def avg_general_gpu_time(self):
            return self.general_gpu_time / self.call

C
chenjian 已提交
463 464 465 466 467 468 469 470 471 472 473 474 475 476
        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

C
chenjian 已提交
477 478 479 480 481 482 483
        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 已提交
484 485 486 487 488 489 490
        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)
C
chenjian 已提交
491
            self.add_general_gpu_time(node.general_gpu_time)
C
chenjian 已提交
492 493 494 495 496 497 498 499 500 501

    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
502
        self.kernel_items = {}  # for kernel summary
C
chenjian 已提交
503 504 505 506 507 508 509 510 511 512 513 514 515 516 517 518 519 520 521

    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)
522
            self.add_kernel_item(host_statistic_nodes[0])
C
chenjian 已提交
523 524 525 526 527 528 529 530 531 532 533 534

        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:
C
chenjian 已提交
535 536
                        if child.type == TracerEventType.ProfileStep:
                            self.add_model_perspective_item(child)
C
chenjian 已提交
537 538 539
                        deque.append(child)

    def add_operator_item(self, operator_node):
540
        if operator_node.is_terminal_operator_node == False:
C
chenjian 已提交
541
            return
C
chenjian 已提交
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 583 584 585 586 587
        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'
C
chenjian 已提交
588 589
        elif model_perspective_node.type == TracerEventType.ProfileStep:
            name = 'ProfileStep'
C
chenjian 已提交
590 591 592 593 594 595
        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)

596 597 598 599 600 601 602 603 604
    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 已提交
605 606 607 608 609 610 611 612 613 614 615

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 已提交
616
        self.distributed_summary = DistributedSummary()
C
chenjian 已提交
617 618
        self.time_range_summary.parse(node_trees)
        self.event_summary.parse(node_trees)
C
chenjian 已提交
619
        self.distributed_summary.parse(node_trees)
C
chenjian 已提交
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


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 = [
696 697 698
        'CPU(Process)',
        format_ratio(float(
            statistic_data.extra_info['Process Cpu Utilization']))
C
chenjian 已提交
699 700 701
    ]
    append(row_format.format(*row_values))
    row_values = [
702 703
        'CPU(System)',
        format_ratio(float(statistic_data.extra_info['System Cpu Utilization']))
C
chenjian 已提交
704 705 706 707 708 709 710 711 712 713 714 715 716 717
    ]
    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 已提交
718
        "GPU Utilization = Current process GPU time / elapsed time.")
C
chenjian 已提交
719 720 721 722 723 724 725 726
    append('-' * line_length)
    append('')
    append('')

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

    ###### Print Overview Summary ######
C
chenjian 已提交
727
    headers = ['Event Type', 'Calls', 'CPU Time', 'Ratio (%)']
C
chenjian 已提交
728 729 730 731 732 733 734 735 736 737 738 739 740 741 742 743 744 745 746 747
    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)
C
chenjian 已提交
748 749 750 751 752
    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 已提交
753 754
    for event_type, value in statistic_data.time_range_summary.CPUTimeRangeSum.items(
    ):
C
chenjian 已提交
755 756 757 758 759
        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)
C
chenjian 已提交
760 761 762
        cpu_call_times[
            TracerEventType.
            Communication] = statistic_data.distributed_summary.cpu_calls
C
chenjian 已提交
763

C
chenjian 已提交
764 765 766 767 768 769 770 771 772
    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
773 774 775
            cpu_type_time[
                event_type] = statistic_data.event_summary.model_perspective_items[
                    event_type_name].cpu_time
C
chenjian 已提交
776

C
chenjian 已提交
777 778 779 780 781 782 783 784
    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 已提交
785 786 787
    if statistic_data.distributed_summary.gpu_communication_range:
        gpu_type_time[TracerEventType.Communication] = sum_ranges(
            statistic_data.distributed_summary.gpu_communication_range)
C
chenjian 已提交
788 789 790
        gpu_call_times[
            TracerEventType.
            Communication] = statistic_data.distributed_summary.gpu_calls
C
chenjian 已提交
791

792 793 794
    sorted_items = sorted(cpu_type_time.items(),
                          key=lambda x: x[1],
                          reverse=True)
C
chenjian 已提交
795 796 797
    event_type, time = sorted_items[0]
    row_values = [
        '{}'.format(str(event_type).split('.')[1]), cpu_call_times[event_type],
798 799
        format_time(time, unit=time_unit),
        format_ratio(float(time) / total_time)
C
chenjian 已提交
800 801 802
    ]
    append(row_format.format(*row_values))
    for event_type, time in sorted_items[1:]:
C
chenjian 已提交
803
        row_values = [
C
chenjian 已提交
804
            '  {}'.format(str(event_type).split('.')[1]),
805 806 807
            cpu_call_times[event_type],
            format_time(time, unit=time_unit),
            format_ratio(float(time) / total_time)
C
chenjian 已提交
808 809 810
        ]
        append(row_format.format(*row_values))
    append(header_sep)
C
chenjian 已提交
811
    headers = ['', 'Calls', 'GPU Time', 'Ratio (%)']
C
chenjian 已提交
812 813 814 815
    append(row_format.format(*headers))
    append(header_sep)
    for event_type, time in gpu_type_time.items():
        row_values = [
C
chenjian 已提交
816
            '  {}'.format(str(event_type).split('.')[1]),
817 818 819
            gpu_call_times[event_type],
            format_time(time, unit=time_unit),
            format_ratio(float(time) / total_time)
C
chenjian 已提交
820 821 822 823 824 825 826 827 828 829 830 831 832 833 834 835 836 837 838 839
        ]
        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 已提交
840 841
    ###### Print Model Summary Report ######
    model_perspective_items = statistic_data.event_summary.model_perspective_items
C
chenjian 已提交
842
    if len(model_perspective_items) > 1:
C
chenjian 已提交
843 844
        all_row_values = []
        accmulation_time = 0
C
chenjian 已提交
845
        gpu_accmulation_time = 0
846 847
        gpu_total_time = statistic_data.event_summary.model_perspective_items[
            'ProfileStep'].general_gpu_time
C
chenjian 已提交
848 849 850 851
        for name in [
                'ProfileStep', 'Dataloader', 'Forward', 'Backward',
                'Optimization'
        ]:
C
chenjian 已提交
852 853
            if name in model_perspective_items:
                item = model_perspective_items[name]
854 855 856 857
                if gpu_total_time == 0:
                    gpu_ratio = 0
                else:
                    gpu_ratio = float(item.general_gpu_time) / gpu_total_time
C
chenjian 已提交
858 859
                name = '{}'.format(
                    name) if 'ProfileStep' in name else '  {}'.format(name)
C
chenjian 已提交
860
                row_values = [
C
chenjian 已提交
861
                    '{}'.format(name), item.call,
C
chenjian 已提交
862
                    '{} / {} / {} / {} / {}'.format(
863 864 865 866
                        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),
C
chenjian 已提交
867 868
                        format_ratio(float(item.cpu_time) / total_time)),
                    '{} / {} / {} / {} / {}'.format(
869 870 871 872
                        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),
873
                        format_ratio(gpu_ratio))
C
chenjian 已提交
874
                ]
C
chenjian 已提交
875
                all_row_values.append(row_values)
C
chenjian 已提交
876 877
                if 'ProfileStep' not in name:
                    accmulation_time += item.cpu_time
878
                    gpu_accmulation_time += item.general_gpu_time
C
chenjian 已提交
879 880

        other_time = total_time - accmulation_time
C
chenjian 已提交
881
        other_gpu_time = gpu_total_time - gpu_accmulation_time
882 883 884 885
        if gpu_total_time == 0:
            gpu_ratio = 0
        else:
            gpu_ratio = float(other_gpu_time) / gpu_total_time
C
chenjian 已提交
886 887
        row_values = [
            '  Others', '-', '{} / - / - / - / {}'.format(
888
                format_time(other_time, unit=time_unit),
C
chenjian 已提交
889
                format_ratio(float(other_time) / total_time)),
C
chenjian 已提交
890
            '{} / - / - / - / {}'.format(
891
                format_time(other_gpu_time, unit=time_unit),
892
                format_ratio(gpu_ratio))
C
chenjian 已提交
893
        ]
C
chenjian 已提交
894 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
        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 已提交
929
        append(header_sep)
C
chenjian 已提交
930 931 932 933 934 935 936 937
        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 已提交
938 939 940 941
        append('')
        append('')

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

C
chenjian 已提交
952
        DEFAULT_COLUMN_WIDTH = 25
C
chenjian 已提交
953 954 955 956 957 958 959 960 961 962 963 964 965
        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 已提交
966 967 968 969 970 971
        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 已提交
972
        row_values = [
973 974
            'ProfileStep',
            format_time(total_time, unit=time_unit),
C
chenjian 已提交
975 976 977 978
            format_ratio(float(total_time) / total_time)
        ]
        append(row_format.format(*row_values))
        row_values = [
979 980
            '  Communication',
            format_time(communication_time, unit=time_unit),
C
chenjian 已提交
981 982 983 984 985
            format_ratio(float(communication_time) / total_time)
        ]
        append(row_format.format(*row_values))

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

        row_values = [
993 994
            '  Overlap',
            format_time(overlap_time, unit=time_unit),
C
chenjian 已提交
995 996 997 998 999
            format_ratio(float(overlap_time) / total_time)
        ]
        append(row_format.format(*row_values))
        append(header_sep)
        append(
C
chenjian 已提交
1000 1001 1002
            "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 已提交
1003 1004 1005 1006 1007 1008 1009 1010 1011 1012 1013 1014
            "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 已提交
1015 1016
    ###### Print Operator Summary Report ######
    if statistic_data.event_summary.items:
C
chenjian 已提交
1017 1018
        all_row_values = []
        name_column_width = 52
C
chenjian 已提交
1019 1020 1021 1022 1023 1024 1025
        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 已提交
1026
            all_row_values.append("Thread: {}".format(thread_id))
C
chenjian 已提交
1027
            if sorted_by == SortedKeys.CPUTotal:
1028 1029 1030
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].cpu_time,
                                      reverse=True)
C
chenjian 已提交
1031
            elif sorted_by == SortedKeys.CPUAvg:
1032 1033 1034
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].avg_cpu_time,
                                      reverse=True)
C
chenjian 已提交
1035
            elif sorted_by == SortedKeys.CPUMax:
1036 1037 1038
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].max_cpu_time,
                                      reverse=True)
C
chenjian 已提交
1039
            elif sorted_by == SortedKeys.CPUMin:
1040 1041
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].min_cpu_time)
C
chenjian 已提交
1042
            elif sorted_by == SortedKeys.GPUTotal:
1043 1044 1045
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].general_gpu_time,
                                      reverse=True)
C
chenjian 已提交
1046
            elif sorted_by == SortedKeys.GPUAvg:
1047 1048 1049
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].avg_general_gpu_time,
                                      reverse=True)
C
chenjian 已提交
1050
            elif sorted_by == SortedKeys.GPUMax:
1051 1052 1053
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].max_general_gpu_time,
                                      reverse=True)
C
chenjian 已提交
1054
            elif sorted_by == SortedKeys.GPUMin:
1055 1056
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].min_general_gpu_time)
1057 1058 1059 1060 1061 1062
            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 已提交
1063 1064

            for name, item in sorted_items:
1065 1066 1067 1068 1069 1070 1071 1072
                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 已提交
1073 1074
                row_values = [
                    name, item.call, '{} / {} / {} / {} / {}'.format(
1075 1076 1077 1078
                        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),
1079
                        format_ratio(cpu_ratio)),
C
chenjian 已提交
1080
                    '{} / {} / {} / {} / {}'.format(
1081 1082 1083 1084
                        format_time(item.general_gpu_time, unit=time_unit),
                        format_time(item.avg_general_gpu_time, unit=time_unit),
                        format_time(item.max_general_gpu_time, unit=time_unit),
                        format_time(item.min_general_gpu_time, unit=time_unit),
1085
                        format_ratio(gpu_ratio))
C
chenjian 已提交
1086
                ]
C
chenjian 已提交
1087
                all_row_values.append(row_values)
C
chenjian 已提交
1088 1089 1090
                if op_detail:
                    for innerop_name, innerop_node in item.operator_inners.items(
                    ):
1091 1092 1093 1094 1095 1096 1097 1098 1099 1100
                        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 已提交
1101 1102 1103
                        if len(innerop_name) + 2 > name_column_width:
                            innerop_name = innerop_name[:name_column_width - 5]
                            innerop_name += "..."
C
chenjian 已提交
1104 1105 1106
                        row_values = [
                            '  {}'.format(innerop_name), innerop_node.call,
                            '{} / {} / {} / {} / {}'.format(
1107 1108 1109 1110 1111 1112 1113 1114
                                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),
1115
                                format_ratio(cpu_ratio)),
C
chenjian 已提交
1116
                            '{} / {} / {} / {} / {}'.format(
1117 1118 1119 1120 1121 1122 1123 1124
                                format_time(innerop_node.general_gpu_time,
                                            unit=time_unit),
                                format_time(innerop_node.avg_general_gpu_time,
                                            unit=time_unit),
                                format_time(innerop_node.max_general_gpu_time,
                                            unit=time_unit),
                                format_time(innerop_node.min_general_gpu_time,
                                            unit=time_unit),
1125
                                format_ratio(gpu_ratio))
C
chenjian 已提交
1126
                        ]
C
chenjian 已提交
1127
                        all_row_values.append(row_values)
C
chenjian 已提交
1128
                        for device_node_name, device_node in innerop_node.devices.items(
C
chenjian 已提交
1129
                        ):
1130 1131 1132 1133
                            if innerop_node.general_gpu_time == 0:
                                gpu_ratio = 0
                            else:
                                gpu_ratio = float(
1134 1135
                                    device_node.gpu_time
                                ) / innerop_node.general_gpu_time
C
chenjian 已提交
1136 1137 1138 1139 1140 1141 1142
                            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),
C
chenjian 已提交
1143
                                device_node.call, '- / - / - / - / -',
C
chenjian 已提交
1144
                                '{} / {} / {} / {} / {}'.format(
1145 1146 1147 1148 1149 1150 1151 1152
                                    format_time(device_node.gpu_time,
                                                unit=time_unit),
                                    format_time(device_node.avg_gpu_time,
                                                unit=time_unit),
                                    format_time(device_node.max_gpu_time,
                                                unit=time_unit),
                                    format_time(device_node.min_gpu_time,
                                                unit=time_unit),
1153
                                    format_ratio(gpu_ratio))
C
chenjian 已提交
1154
                            ]
C
chenjian 已提交
1155
                            all_row_values.append(row_values)
C
chenjian 已提交
1156
                    for device_node_name, device_node in item.devices.items():
1157 1158 1159 1160 1161
                        if item.general_gpu_time == 0:
                            gpu_ratio = 0
                        else:
                            gpu_ratio = float(
                                device_node.gpu_time) / item.general_gpu_time
C
chenjian 已提交
1162 1163 1164 1165 1166 1167
                        if len(device_node_name) + 2 > name_column_width:
                            device_node_name = device_node_name[:
                                                                name_column_width
                                                                - 5]
                            device_node_name += "..."
                        row_values = [
C
chenjian 已提交
1168
                            '  {}'.format(device_node_name), device_node.call,
C
chenjian 已提交
1169 1170
                            '- / - / - / - / -',
                            '{} / {} / {} / {} / {}'.format(
1171 1172 1173 1174 1175 1176 1177 1178
                                format_time(device_node.gpu_time,
                                            unit=time_unit),
                                format_time(device_node.avg_gpu_time,
                                            unit=time_unit),
                                format_time(device_node.max_gpu_time,
                                            unit=time_unit),
                                format_time(device_node.min_gpu_time,
                                            unit=time_unit),
1179
                                format_ratio(gpu_ratio))
C
chenjian 已提交
1180
                        ]
C
chenjian 已提交
1181 1182 1183 1184 1185 1186 1187 1188 1189 1190 1191 1192 1193 1194 1195
                        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 已提交
1196 1197 1198 1199 1200 1201 1202 1203
        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 已提交
1204 1205 1206
        add_column(calltime_width)
        add_column(cpu_data_description_width)
        add_column(gpu_data_description_width)
C
chenjian 已提交
1207 1208 1209 1210 1211 1212

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

        # construct table string
C
chenjian 已提交
1213
        append(add_title(line_length, "Operator Summary"))
C
chenjian 已提交
1214 1215 1216 1217
        append('Time unit: {}'.format(time_unit))
        append(header_sep)
        append(row_format.format(*headers))
        append(header_sep)
C
chenjian 已提交
1218 1219 1220 1221 1222 1223 1224 1225 1226
        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('')

1227 1228 1229 1230 1231
    ###### 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:
1232 1233 1234
            sorted_items = sorted(kernel_items.items(),
                                  key=lambda x: x[1].avg_gpu_time,
                                  reverse=True)
1235
        elif sorted_by == SortedKeys.GPUMax:
1236 1237 1238
            sorted_items = sorted(kernel_items.items(),
                                  key=lambda x: x[1].max_gpu_time,
                                  reverse=True)
1239
        elif sorted_by == SortedKeys.GPUMin:
1240 1241
            sorted_items = sorted(kernel_items.items(),
                                  key=lambda x: x[1].min_gpu_time)
1242
        else:
1243 1244 1245
            sorted_items = sorted(kernel_items.items(),
                                  key=lambda x: x[1].gpu_time,
                                  reverse=True)
1246 1247 1248 1249 1250 1251 1252 1253 1254 1255 1256 1257 1258

        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(
1259 1260 1261 1262
                    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),
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
                    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)
C
chenjian 已提交
1296
        kernel_name_pattern = re.compile('(.+?)(<.*>)(\(.*\))')
1297
        for row_values in all_row_values:
C
chenjian 已提交
1298 1299 1300
            match = kernel_name_pattern.match(row_values[0])
            if match:
                name = match.group(1) + match.group(2)
1301 1302 1303 1304 1305 1306 1307 1308 1309 1310 1311
            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 已提交
1312 1313 1314
    ###### Print Memory Manipulation Summary Report ######
    if statistic_data.event_summary.memory_manipulation_items:
        all_row_values = []
C
chenjian 已提交
1315
        memory_manipulation_items = statistic_data.event_summary.memory_manipulation_items
1316 1317
        gpu_total_time = statistic_data.event_summary.model_perspective_items[
            'ProfileStep'].general_gpu_time
C
chenjian 已提交
1318
        for name, item in memory_manipulation_items.items():
1319 1320 1321 1322
            if gpu_total_time == 0:
                gpu_ratio = 0
            else:
                gpu_ratio = float(item.general_gpu_time) / gpu_total_time
C
chenjian 已提交
1323 1324 1325 1326
            row_values = [
                name,
                item.call,
                '{} / {} / {} / {} / {}'.format(
1327 1328 1329 1330
                    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),
C
chenjian 已提交
1331 1332
                    format_ratio(float(item.cpu_time) / total_time)),
                '{} / {} / {} / {} / {}'.format(
1333 1334 1335 1336
                    format_time(item.general_gpu_time, unit=time_unit),
                    format_time(item.avg_general_gpu_time, unit=time_unit),
                    format_time(item.max_general_gpu_time, unit=time_unit),
                    format_time(item.min_general_gpu_time, unit=time_unit),
1337
                    format_ratio(gpu_ratio)),
C
chenjian 已提交
1338
            ]
C
chenjian 已提交
1339 1340
            all_row_values.append(row_values)

C
chenjian 已提交
1341 1342 1343 1344
        headers = [
            'Name', 'Calls', 'CPU Total / Avg / Max / Min / Ratio(%)',
            'GPU Total / Avg / Max / Min / Ratio(%)'
        ]
C
chenjian 已提交
1345 1346 1347 1348 1349 1350 1351 1352 1353 1354 1355 1356 1357 1358 1359 1360
        # 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 已提交
1361 1362 1363 1364
        row_format_list = [""]
        header_sep_list = [""]
        line_length_list = [-SPACING_SIZE]
        add_column(name_column_width)
C
chenjian 已提交
1365 1366 1367
        add_column(calltime_width)
        add_column(cpu_data_description_width)
        add_column(gpu_data_description_width)
C
chenjian 已提交
1368 1369 1370 1371 1372 1373

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

        # construct table string
C
chenjian 已提交
1374
        append(add_title(line_length, "Memory Manipulation Summary"))
C
chenjian 已提交
1375 1376 1377 1378
        append('Time unit: {}'.format(time_unit))
        append(header_sep)
        append(row_format.format(*headers))
        append(header_sep)
C
chenjian 已提交
1379 1380 1381 1382 1383 1384 1385 1386
        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 = []
1387 1388
        gpu_total_time = statistic_data.event_summary.model_perspective_items[
            'ProfileStep'].general_gpu_time
C
chenjian 已提交
1389 1390 1391 1392 1393 1394 1395 1396
        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 已提交
1397
            all_row_values.append("Thread: {}".format(thread_id))
C
chenjian 已提交
1398
            if sorted_by == SortedKeys.CPUTotal:
1399 1400 1401
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].cpu_time,
                                      reverse=True)
C
chenjian 已提交
1402
            elif sorted_by == SortedKeys.CPUAvg:
1403 1404 1405
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].avg_cpu_time,
                                      reverse=True)
C
chenjian 已提交
1406
            elif sorted_by == SortedKeys.CPUMax:
1407 1408 1409
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].max_cpu_time,
                                      reverse=True)
C
chenjian 已提交
1410
            elif sorted_by == SortedKeys.CPUMin:
1411 1412
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].min_cpu_time)
C
chenjian 已提交
1413
            elif sorted_by == SortedKeys.GPUTotal:
1414 1415 1416
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].general_gpu_time,
                                      reverse=True)
C
chenjian 已提交
1417
            elif sorted_by == SortedKeys.GPUAvg:
1418 1419 1420
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].avg_general_gpu_time,
                                      reverse=True)
C
chenjian 已提交
1421
            elif sorted_by == SortedKeys.GPUMax:
1422 1423 1424
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].max_general_gpu_time,
                                      reverse=True)
C
chenjian 已提交
1425
            elif sorted_by == SortedKeys.GPUMin:
1426 1427
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].min_general_gpu_time)
C
chenjian 已提交
1428 1429

            for name, item in sorted_items:
1430 1431 1432 1433
                if gpu_total_time == 0:
                    gpu_ratio = 0
                else:
                    gpu_ratio = float(item.general_gpu_time) / gpu_total_time
C
chenjian 已提交
1434 1435 1436 1437
                row_values = [
                    name,
                    item.call,
                    '{} / {} / {} / {} / {}'.format(
1438 1439 1440 1441
                        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),
C
chenjian 已提交
1442 1443
                        format_ratio(float(item.cpu_time) / total_time)),
                    '{} / {} / {} / {} / {}'.format(
1444 1445 1446 1447
                        format_time(item.general_gpu_time, unit=time_unit),
                        format_time(item.avg_general_gpu_time, unit=time_unit),
                        format_time(item.max_general_gpu_time, unit=time_unit),
                        format_time(item.min_general_gpu_time, unit=time_unit),
1448
                        format_ratio(gpu_ratio)),
C
chenjian 已提交
1449
                ]
C
chenjian 已提交
1450 1451 1452 1453 1454 1455 1456 1457 1458 1459 1460 1461 1462 1463 1464 1465 1466 1467 1468 1469 1470 1471 1472 1473 1474 1475 1476 1477 1478 1479 1480 1481 1482 1483 1484 1485 1486 1487 1488 1489 1490 1491 1492 1493 1494 1495 1496
                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 已提交
1497
                append(row_format.format(*row_values))
C
chenjian 已提交
1498 1499 1500
        append('')
        append('')

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