profiler_statistic.py 69.6 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
from paddle.fluid.core import TracerEventType, TracerMemEventType
C
chenjian 已提交
19

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
C
chenjian 已提交
82 83 84 85 86 87 88

    def cal_statistic(self):
        for child in self.children_node:
            child.cal_statistic()
        for rt in self.runtime_node:
            rt.cal_statistic()
        self.cpu_time = self.hostnode.end_ns - self.hostnode.start_ns
89
        self.self_cpu_time = self.cpu_time
C
chenjian 已提交
90 91
        for child in self.children_node:
            self.gpu_time += child.gpu_time
C
chenjian 已提交
92
            self.general_gpu_time += child.general_gpu_time
C
chenjian 已提交
93 94 95 96 97
            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 已提交
98 99
            self.general_gpu_time += rt.general_gpu_time
            self.self_general_gpu_time += rt.general_gpu_time
C
chenjian 已提交
100
        for device in self.hostnode.device_node:
C
chenjian 已提交
101 102 103 104 105
            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 已提交
106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132

    @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 已提交
133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149
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 已提交
150 151 152 153 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
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(
196 197
            lambda: collections.defaultdict(
                list))  # GPU events should be divided into different devices
C
chenjian 已提交
198 199 200 201 202 203 204 205 206 207 208 209 210
        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(
211 212
                lambda: collections.defaultdict(lambda: collections.defaultdict(
                    list)))  # device_id/type/stream_id
C
chenjian 已提交
213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233
            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():
234 235
                        time_ranges = merge_self_ranges(time_ranges,
                                                        is_sorted=False)
C
chenjian 已提交
236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257
                        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 已提交
258 259 260 261 262 263 264 265 266 267 268 269
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 已提交
270 271
        self.cpu_calls = 0
        self.gpu_calls = 0
C
chenjian 已提交
272 273 274 275 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

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


C
chenjian 已提交
332 333 334 335 336 337
class EventSummary:
    r"""
    Analyse operator event in profiling data, correlate with its device event.
    """

    class DeviceItem:
338

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

C
chenjian 已提交
363 364 365 366 367 368 369 370 371 372 373
        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 已提交
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

C
chenjian 已提交
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

C
chenjian 已提交
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)
C
chenjian 已提交
418
            self.add_general_gpu_time(node.general_gpu_time)
C
chenjian 已提交
419
            for child in node.children_node:
C
chenjian 已提交
420 421 422 423 424
                if child.type != TracerEventType.Operator:
                    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)
C
chenjian 已提交
425 426 427

            for runtimenode in node.runtime_node:
                for devicenode in runtimenode.device_node:
428 429 430 431
                    name = devicenode.name
                    if name not in self.devices:
                        self.devices[name] = EventSummary.DeviceItem(name)
                    self.devices[name].add_item(devicenode)
C
chenjian 已提交
432 433

    class GeneralItem:
434

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

        @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 已提交
456 457 458 459
        @property
        def avg_general_gpu_time(self):
            return self.general_gpu_time / self.call

C
chenjian 已提交
460 461 462 463 464 465 466 467 468 469 470 471 472 473
        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 已提交
474 475 476 477 478 479 480
        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 已提交
481 482 483 484 485 486 487
        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 已提交
488
            self.add_general_gpu_time(node.general_gpu_time)
C
chenjian 已提交
489 490 491 492 493 494 495 496 497 498

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

    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:
518 519
                        if host_statistic_node.type == TracerEventType.PythonUserDefined:
                            self.add_userdefined_item(host_statistic_node)
520
            self.add_kernel_item(host_statistic_nodes[0])
C
chenjian 已提交
521 522 523 524 525 526 527 528 529 530 531 532

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

    def add_operator_item(self, operator_node):
        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 已提交
584 585
        elif model_perspective_node.type == TracerEventType.ProfileStep:
            name = 'ProfileStep'
C
chenjian 已提交
586 587 588 589 590 591
        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)

592 593 594 595 596 597 598 599 600
    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 已提交
601

602 603 604 605 606 607 608 609 610 611 612 613 614 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
class MemorySummary:
    r"""
    Analyse memory events in profiling data.
    """

    class MemoryItem:

        def __init__(self, event_name, place, memory_type='Allocated'):
            self.event_name = event_name
            self.place = place
            self.allocation_count = 0
            self.free_count = 0
            self.allocation_size = 0
            self.free_size = 0
            self.increase_size = 0
            self.memory_type = memory_type

        def add_memory_record(self, size, allocation_type):
            if allocation_type == TracerMemEventType.Allocate or allocation_type == TracerMemEventType.ReservedAllocate:
                self.allocation_count += 1
                self.allocation_size += size

            elif allocation_type == TracerMemEventType.Free or allocation_type == TracerMemEventType.ReservedFree:
                self.free_count += 1
                self.free_size -= size  # size is sign(-) when free.

            else:
                print("No corresponding type.")
            self.increase_size = self.allocation_size - self.free_size

    def __init__(self):
        self.allocated_items = collections.defaultdict(
            dict)  # for memory summary, device type: event
        self.reserved_items = collections.defaultdict(
            dict)  # for memory summary, device type: event
        self.peak_allocation_values = collections.defaultdict(int)
        self.peak_reserved_values = collections.defaultdict(int)

    def _analyse_node_memory(self, event_name, node):
        for memnode in node.mem_node:  # self mem node
            if memnode.type == TracerMemEventType.Allocate or memnode.type == TracerMemEventType.Free:
                if event_name not in self.allocated_items[memnode.place]:
                    self.allocated_items[
                        memnode.place][event_name] = MemorySummary.MemoryItem(
                            event_name, memnode.place, 'Allocated')
                self.allocated_items[
                    memnode.place][event_name].add_memory_record(
                        memnode.increase_bytes, memnode.type)
            elif memnode.type == TracerMemEventType.ReservedAllocate or memnode.type == TracerMemEventType.ReservedFree:
                if event_name not in self.reserved_items[memnode.place]:
                    self.reserved_items[
                        memnode.place][event_name] = MemorySummary.MemoryItem(
                            event_name, memnode.place, 'Reserved')
                self.reserved_items[
                    memnode.place][event_name].add_memory_record(
                        memnode.increase_bytes, memnode.type)
            self.peak_allocation_values[memnode.place] = max(
                self.peak_allocation_values[memnode.place],
                memnode.peak_allocated)
            self.peak_reserved_values[memnode.place] = max(
                self.peak_reserved_values[memnode.place], memnode.peak_reserved)

    def parse(self, nodetrees):
        r"""
        Analyse memory event in the nodetress.
        """
        thread2hostnodes = traverse_tree(nodetrees)
        for threadid, host_nodes in thread2hostnodes.items():
            for host_node in host_nodes[1:]:  #skip root node
                if host_node.type == TracerEventType.OperatorInner:
                    continue
                if host_node.type == TracerEventType.Operator:
                    for child in host_node.children_node:
                        self._analyse_node_memory(host_node.name, child)
                self._analyse_node_memory(host_node.name, host_node)


C
chenjian 已提交
679 680 681 682 683 684 685 686 687 688
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 已提交
689
        self.distributed_summary = DistributedSummary()
690
        self.memory_summary = MemorySummary()
C
chenjian 已提交
691 692
        self.time_range_summary.parse(node_trees)
        self.event_summary.parse(node_trees)
C
chenjian 已提交
693
        self.distributed_summary.parse(node_trees)
694
        self.memory_summary.parse(node_trees)
C
chenjian 已提交
695 696 697 698 699 700 701 702 703 704 705 706 707 708 709 710 711 712 713 714 715 716 717 718 719 720 721 722 723 724 725 726 727 728 729 730 731 732 733 734 735 736 737 738 739 740 741 742 743 744 745 746 747 748 749 750 751 752 753 754 755 756 757 758 759 760 761 762 763 764 765 766 767 768 769 770


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 = [
771 772 773
        'CPU(Process)',
        format_ratio(float(
            statistic_data.extra_info['Process Cpu Utilization']))
C
chenjian 已提交
774 775 776
    ]
    append(row_format.format(*row_values))
    row_values = [
777 778
        'CPU(System)',
        format_ratio(float(statistic_data.extra_info['System Cpu Utilization']))
C
chenjian 已提交
779 780 781 782 783 784 785 786 787 788 789 790 791 792
    ]
    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 已提交
793
        "GPU Utilization = Current process GPU time / elapsed time.")
C
chenjian 已提交
794 795 796 797 798 799 800 801
    append('-' * line_length)
    append('')
    append('')

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

    ###### Print Overview Summary ######
C
chenjian 已提交
802
    headers = ['Event Type', 'Calls', 'CPU Time', 'Ratio (%)']
C
chenjian 已提交
803 804 805 806 807 808 809 810 811 812 813 814 815 816 817 818 819 820 821 822
    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 已提交
823 824 825 826 827
    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 已提交
828 829
    for event_type, value in statistic_data.time_range_summary.CPUTimeRangeSum.items(
    ):
C
chenjian 已提交
830 831 832 833 834
        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 已提交
835 836 837
        cpu_call_times[
            TracerEventType.
            Communication] = statistic_data.distributed_summary.cpu_calls
C
chenjian 已提交
838

C
chenjian 已提交
839 840 841 842 843 844 845 846 847
    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
848 849 850
            cpu_type_time[
                event_type] = statistic_data.event_summary.model_perspective_items[
                    event_type_name].cpu_time
C
chenjian 已提交
851

C
chenjian 已提交
852 853 854 855 856 857 858 859
    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 已提交
860 861 862
    if statistic_data.distributed_summary.gpu_communication_range:
        gpu_type_time[TracerEventType.Communication] = sum_ranges(
            statistic_data.distributed_summary.gpu_communication_range)
C
chenjian 已提交
863 864 865
        gpu_call_times[
            TracerEventType.
            Communication] = statistic_data.distributed_summary.gpu_calls
C
chenjian 已提交
866

867 868 869
    sorted_items = sorted(cpu_type_time.items(),
                          key=lambda x: x[1],
                          reverse=True)
C
chenjian 已提交
870 871 872
    event_type, time = sorted_items[0]
    row_values = [
        '{}'.format(str(event_type).split('.')[1]), cpu_call_times[event_type],
873 874
        format_time(time, unit=time_unit),
        format_ratio(float(time) / total_time)
C
chenjian 已提交
875 876 877
    ]
    append(row_format.format(*row_values))
    for event_type, time in sorted_items[1:]:
C
chenjian 已提交
878
        row_values = [
C
chenjian 已提交
879
            '  {}'.format(str(event_type).split('.')[1]),
880 881 882
            cpu_call_times[event_type],
            format_time(time, unit=time_unit),
            format_ratio(float(time) / total_time)
C
chenjian 已提交
883 884 885
        ]
        append(row_format.format(*row_values))
    append(header_sep)
C
chenjian 已提交
886
    headers = ['', 'Calls', 'GPU Time', 'Ratio (%)']
C
chenjian 已提交
887 888 889 890
    append(row_format.format(*headers))
    append(header_sep)
    for event_type, time in gpu_type_time.items():
        row_values = [
C
chenjian 已提交
891
            '  {}'.format(str(event_type).split('.')[1]),
892 893 894
            gpu_call_times[event_type],
            format_time(time, unit=time_unit),
            format_ratio(float(time) / total_time)
C
chenjian 已提交
895 896 897 898 899 900 901 902 903 904 905 906 907 908 909 910 911 912 913 914
        ]
        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 已提交
915 916
    ###### Print Model Summary Report ######
    model_perspective_items = statistic_data.event_summary.model_perspective_items
C
chenjian 已提交
917
    if len(model_perspective_items) > 1:
C
chenjian 已提交
918 919
        all_row_values = []
        accmulation_time = 0
C
chenjian 已提交
920
        gpu_accmulation_time = 0
921
        gpu_total_time = statistic_data.event_summary.model_perspective_items[
922
            'ProfileStep'].gpu_time
C
chenjian 已提交
923 924 925 926
        for name in [
                'ProfileStep', 'Dataloader', 'Forward', 'Backward',
                'Optimization'
        ]:
C
chenjian 已提交
927 928
            if name in model_perspective_items:
                item = model_perspective_items[name]
929 930 931
                if gpu_total_time == 0:
                    gpu_ratio = 0
                else:
932
                    gpu_ratio = float(item.gpu_time) / gpu_total_time
C
chenjian 已提交
933 934
                name = '{}'.format(
                    name) if 'ProfileStep' in name else '  {}'.format(name)
C
chenjian 已提交
935
                row_values = [
C
chenjian 已提交
936
                    '{}'.format(name), item.call,
C
chenjian 已提交
937
                    '{} / {} / {} / {} / {}'.format(
938 939 940 941
                        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 已提交
942 943
                        format_ratio(float(item.cpu_time) / total_time)),
                    '{} / {} / {} / {} / {}'.format(
944 945 946 947
                        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),
948
                        format_ratio(gpu_ratio))
C
chenjian 已提交
949
                ]
C
chenjian 已提交
950
                all_row_values.append(row_values)
C
chenjian 已提交
951 952
                if 'ProfileStep' not in name:
                    accmulation_time += item.cpu_time
953
                    gpu_accmulation_time += item.gpu_time
C
chenjian 已提交
954 955

        other_time = total_time - accmulation_time
C
chenjian 已提交
956
        other_gpu_time = gpu_total_time - gpu_accmulation_time
957 958 959 960
        if gpu_total_time == 0:
            gpu_ratio = 0
        else:
            gpu_ratio = float(other_gpu_time) / gpu_total_time
C
chenjian 已提交
961 962
        row_values = [
            '  Others', '-', '{} / - / - / - / {}'.format(
963
                format_time(other_time, unit=time_unit),
C
chenjian 已提交
964
                format_ratio(float(other_time) / total_time)),
C
chenjian 已提交
965
            '{} / - / - / - / {}'.format(
966
                format_time(other_gpu_time, unit=time_unit),
967
                format_ratio(gpu_ratio))
C
chenjian 已提交
968
        ]
C
chenjian 已提交
969 970 971 972 973 974 975 976 977 978 979 980 981 982 983 984 985 986 987 988 989 990 991 992 993 994 995 996 997 998 999 1000 1001 1002 1003
        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 已提交
1004
        append(header_sep)
C
chenjian 已提交
1005 1006 1007 1008 1009 1010 1011 1012
        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 已提交
1013 1014 1015 1016
        append('')
        append('')

    ###### Print Distribution Summary Report ######
C
chenjian 已提交
1017
    if statistic_data.distributed_summary.communication_range:
C
chenjian 已提交
1018 1019 1020 1021 1022 1023 1024 1025 1026
        headers = [
            'Name',
            'Total Time',
            'Ratio (%)',
        ]
        row_format_list = [""]
        header_sep_list = [""]
        line_length_list = [-SPACING_SIZE]

C
chenjian 已提交
1027
        DEFAULT_COLUMN_WIDTH = 25
C
chenjian 已提交
1028 1029 1030 1031 1032 1033 1034 1035 1036 1037 1038 1039 1040
        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 已提交
1041 1042 1043 1044 1045 1046
        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 已提交
1047
        row_values = [
1048 1049
            'ProfileStep',
            format_time(total_time, unit=time_unit),
C
chenjian 已提交
1050 1051 1052 1053
            format_ratio(float(total_time) / total_time)
        ]
        append(row_format.format(*row_values))
        row_values = [
1054 1055
            '  Communication',
            format_time(communication_time, unit=time_unit),
C
chenjian 已提交
1056 1057 1058 1059 1060
            format_ratio(float(communication_time) / total_time)
        ]
        append(row_format.format(*row_values))

        row_values = [
1061 1062
            '  Computation',
            format_time(computation_time, unit=time_unit),
C
chenjian 已提交
1063 1064 1065 1066 1067
            format_ratio(float(computation_time) / total_time)
        ]
        append(row_format.format(*row_values))

        row_values = [
1068 1069
            '  Overlap',
            format_time(overlap_time, unit=time_unit),
C
chenjian 已提交
1070 1071 1072 1073 1074
            format_ratio(float(overlap_time) / total_time)
        ]
        append(row_format.format(*row_values))
        append(header_sep)
        append(
C
chenjian 已提交
1075 1076 1077
            "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 已提交
1078 1079 1080 1081 1082 1083 1084 1085 1086 1087 1088 1089
            "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 已提交
1090 1091
    ###### Print Operator Summary Report ######
    if statistic_data.event_summary.items:
C
chenjian 已提交
1092 1093
        all_row_values = []
        name_column_width = 52
C
chenjian 已提交
1094 1095 1096 1097 1098 1099 1100
        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 已提交
1101
            all_row_values.append("Thread: {}".format(thread_id))
C
chenjian 已提交
1102
            if sorted_by == SortedKeys.CPUTotal:
1103 1104 1105
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].cpu_time,
                                      reverse=True)
C
chenjian 已提交
1106
            elif sorted_by == SortedKeys.CPUAvg:
1107 1108 1109
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].avg_cpu_time,
                                      reverse=True)
C
chenjian 已提交
1110
            elif sorted_by == SortedKeys.CPUMax:
1111 1112 1113
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].max_cpu_time,
                                      reverse=True)
C
chenjian 已提交
1114
            elif sorted_by == SortedKeys.CPUMin:
1115 1116
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].min_cpu_time)
C
chenjian 已提交
1117
            elif sorted_by == SortedKeys.GPUTotal:
1118 1119 1120
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].general_gpu_time,
                                      reverse=True)
C
chenjian 已提交
1121
            elif sorted_by == SortedKeys.GPUAvg:
1122 1123 1124
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].avg_general_gpu_time,
                                      reverse=True)
C
chenjian 已提交
1125
            elif sorted_by == SortedKeys.GPUMax:
1126 1127 1128
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].max_general_gpu_time,
                                      reverse=True)
C
chenjian 已提交
1129
            elif sorted_by == SortedKeys.GPUMin:
1130 1131
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].min_general_gpu_time)
1132 1133 1134 1135 1136 1137
            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 已提交
1138 1139

            for name, item in sorted_items:
1140 1141 1142 1143 1144 1145 1146 1147
                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 已提交
1148 1149
                row_values = [
                    name, item.call, '{} / {} / {} / {} / {}'.format(
1150 1151 1152 1153
                        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),
1154
                        format_ratio(cpu_ratio)),
C
chenjian 已提交
1155
                    '{} / {} / {} / {} / {}'.format(
1156 1157 1158 1159
                        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),
1160
                        format_ratio(gpu_ratio))
C
chenjian 已提交
1161
                ]
C
chenjian 已提交
1162
                all_row_values.append(row_values)
C
chenjian 已提交
1163 1164 1165
                if op_detail:
                    for innerop_name, innerop_node in item.operator_inners.items(
                    ):
1166 1167 1168 1169 1170 1171 1172 1173 1174 1175
                        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 已提交
1176 1177 1178
                        if len(innerop_name) + 2 > name_column_width:
                            innerop_name = innerop_name[:name_column_width - 5]
                            innerop_name += "..."
C
chenjian 已提交
1179 1180 1181
                        row_values = [
                            '  {}'.format(innerop_name), innerop_node.call,
                            '{} / {} / {} / {} / {}'.format(
1182 1183 1184 1185 1186 1187 1188 1189
                                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),
1190
                                format_ratio(cpu_ratio)),
C
chenjian 已提交
1191
                            '{} / {} / {} / {} / {}'.format(
1192 1193 1194 1195 1196 1197 1198 1199
                                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),
1200
                                format_ratio(gpu_ratio))
C
chenjian 已提交
1201
                        ]
C
chenjian 已提交
1202
                        all_row_values.append(row_values)
C
chenjian 已提交
1203
                        for device_node_name, device_node in innerop_node.devices.items(
C
chenjian 已提交
1204
                        ):
1205 1206 1207 1208
                            if innerop_node.general_gpu_time == 0:
                                gpu_ratio = 0
                            else:
                                gpu_ratio = float(
1209 1210
                                    device_node.gpu_time
                                ) / innerop_node.general_gpu_time
C
chenjian 已提交
1211 1212 1213 1214 1215 1216 1217
                            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 已提交
1218
                                device_node.call, '- / - / - / - / -',
C
chenjian 已提交
1219
                                '{} / {} / {} / {} / {}'.format(
1220 1221 1222 1223 1224 1225 1226 1227
                                    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),
1228
                                    format_ratio(gpu_ratio))
C
chenjian 已提交
1229
                            ]
C
chenjian 已提交
1230
                            all_row_values.append(row_values)
C
chenjian 已提交
1231
                    for device_node_name, device_node in item.devices.items():
1232 1233 1234 1235 1236
                        if item.general_gpu_time == 0:
                            gpu_ratio = 0
                        else:
                            gpu_ratio = float(
                                device_node.gpu_time) / item.general_gpu_time
C
chenjian 已提交
1237 1238 1239 1240 1241 1242
                        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 已提交
1243
                            '  {}'.format(device_node_name), device_node.call,
C
chenjian 已提交
1244 1245
                            '- / - / - / - / -',
                            '{} / {} / {} / {} / {}'.format(
1246 1247 1248 1249 1250 1251 1252 1253
                                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),
1254
                                format_ratio(gpu_ratio))
C
chenjian 已提交
1255
                        ]
C
chenjian 已提交
1256 1257 1258 1259 1260 1261 1262 1263 1264 1265 1266 1267 1268 1269 1270
                        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 已提交
1271 1272 1273 1274 1275 1276 1277 1278
        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 已提交
1279 1280 1281
        add_column(calltime_width)
        add_column(cpu_data_description_width)
        add_column(gpu_data_description_width)
C
chenjian 已提交
1282 1283 1284 1285 1286 1287

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

        # construct table string
C
chenjian 已提交
1288
        append(add_title(line_length, "Operator Summary"))
C
chenjian 已提交
1289 1290 1291 1292
        append('Time unit: {}'.format(time_unit))
        append(header_sep)
        append(row_format.format(*headers))
        append(header_sep)
C
chenjian 已提交
1293 1294 1295 1296 1297 1298 1299 1300 1301
        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('')

1302 1303 1304 1305 1306
    ###### 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:
1307 1308 1309
            sorted_items = sorted(kernel_items.items(),
                                  key=lambda x: x[1].avg_gpu_time,
                                  reverse=True)
1310
        elif sorted_by == SortedKeys.GPUMax:
1311 1312 1313
            sorted_items = sorted(kernel_items.items(),
                                  key=lambda x: x[1].max_gpu_time,
                                  reverse=True)
1314
        elif sorted_by == SortedKeys.GPUMin:
1315 1316
            sorted_items = sorted(kernel_items.items(),
                                  key=lambda x: x[1].min_gpu_time)
1317
        else:
1318 1319 1320
            sorted_items = sorted(kernel_items.items(),
                                  key=lambda x: x[1].gpu_time,
                                  reverse=True)
1321 1322 1323 1324 1325 1326 1327 1328 1329 1330 1331 1332 1333

        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(
1334 1335 1336 1337
                    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),
1338 1339 1340 1341 1342 1343 1344 1345 1346 1347 1348 1349 1350 1351 1352 1353 1354 1355 1356 1357 1358 1359 1360 1361 1362 1363 1364 1365 1366 1367 1368 1369 1370
                    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 已提交
1371
        kernel_name_pattern = re.compile('(.+?)(<.*>)(\(.*\))')
1372
        for row_values in all_row_values:
C
chenjian 已提交
1373 1374 1375
            match = kernel_name_pattern.match(row_values[0])
            if match:
                name = match.group(1) + match.group(2)
1376 1377 1378 1379 1380 1381 1382 1383 1384 1385 1386
            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 已提交
1387 1388 1389
    ###### Print Memory Manipulation Summary Report ######
    if statistic_data.event_summary.memory_manipulation_items:
        all_row_values = []
C
chenjian 已提交
1390
        memory_manipulation_items = statistic_data.event_summary.memory_manipulation_items
1391 1392
        gpu_total_time = statistic_data.event_summary.model_perspective_items[
            'ProfileStep'].general_gpu_time
C
chenjian 已提交
1393
        for name, item in memory_manipulation_items.items():
1394 1395 1396 1397
            if gpu_total_time == 0:
                gpu_ratio = 0
            else:
                gpu_ratio = float(item.general_gpu_time) / gpu_total_time
C
chenjian 已提交
1398 1399 1400 1401
            row_values = [
                name,
                item.call,
                '{} / {} / {} / {} / {}'.format(
1402 1403 1404 1405
                    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 已提交
1406 1407
                    format_ratio(float(item.cpu_time) / total_time)),
                '{} / {} / {} / {} / {}'.format(
1408 1409 1410 1411
                    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),
1412
                    format_ratio(gpu_ratio)),
C
chenjian 已提交
1413
            ]
C
chenjian 已提交
1414 1415
            all_row_values.append(row_values)

C
chenjian 已提交
1416 1417 1418 1419
        headers = [
            'Name', 'Calls', 'CPU Total / Avg / Max / Min / Ratio(%)',
            'GPU Total / Avg / Max / Min / Ratio(%)'
        ]
C
chenjian 已提交
1420 1421 1422 1423 1424 1425 1426 1427 1428 1429 1430 1431 1432 1433 1434 1435
        # 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 已提交
1436 1437 1438 1439
        row_format_list = [""]
        header_sep_list = [""]
        line_length_list = [-SPACING_SIZE]
        add_column(name_column_width)
C
chenjian 已提交
1440 1441 1442
        add_column(calltime_width)
        add_column(cpu_data_description_width)
        add_column(gpu_data_description_width)
C
chenjian 已提交
1443 1444 1445 1446 1447 1448

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

        # construct table string
C
chenjian 已提交
1449
        append(add_title(line_length, "Memory Manipulation Summary"))
C
chenjian 已提交
1450 1451 1452 1453
        append('Time unit: {}'.format(time_unit))
        append(header_sep)
        append(row_format.format(*headers))
        append(header_sep)
C
chenjian 已提交
1454 1455 1456 1457 1458 1459 1460 1461
        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 = []
1462 1463
        gpu_total_time = statistic_data.event_summary.model_perspective_items[
            'ProfileStep'].general_gpu_time
C
chenjian 已提交
1464 1465 1466 1467 1468 1469 1470 1471
        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 已提交
1472
            all_row_values.append("Thread: {}".format(thread_id))
C
chenjian 已提交
1473
            if sorted_by == SortedKeys.CPUTotal:
1474 1475 1476
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].cpu_time,
                                      reverse=True)
C
chenjian 已提交
1477
            elif sorted_by == SortedKeys.CPUAvg:
1478 1479 1480
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].avg_cpu_time,
                                      reverse=True)
C
chenjian 已提交
1481
            elif sorted_by == SortedKeys.CPUMax:
1482 1483 1484
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].max_cpu_time,
                                      reverse=True)
C
chenjian 已提交
1485
            elif sorted_by == SortedKeys.CPUMin:
1486 1487
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].min_cpu_time)
C
chenjian 已提交
1488
            elif sorted_by == SortedKeys.GPUTotal:
1489 1490 1491
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].general_gpu_time,
                                      reverse=True)
C
chenjian 已提交
1492
            elif sorted_by == SortedKeys.GPUAvg:
1493 1494 1495
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].avg_general_gpu_time,
                                      reverse=True)
C
chenjian 已提交
1496
            elif sorted_by == SortedKeys.GPUMax:
1497 1498 1499
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].max_general_gpu_time,
                                      reverse=True)
C
chenjian 已提交
1500
            elif sorted_by == SortedKeys.GPUMin:
1501 1502
                sorted_items = sorted(items.items(),
                                      key=lambda x: x[1].min_general_gpu_time)
C
chenjian 已提交
1503 1504

            for name, item in sorted_items:
1505 1506 1507 1508
                if gpu_total_time == 0:
                    gpu_ratio = 0
                else:
                    gpu_ratio = float(item.general_gpu_time) / gpu_total_time
C
chenjian 已提交
1509 1510 1511 1512
                row_values = [
                    name,
                    item.call,
                    '{} / {} / {} / {} / {}'.format(
1513 1514 1515 1516
                        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 已提交
1517 1518
                        format_ratio(float(item.cpu_time) / total_time)),
                    '{} / {} / {} / {} / {}'.format(
1519 1520 1521 1522
                        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),
1523
                        format_ratio(gpu_ratio)),
C
chenjian 已提交
1524
                ]
C
chenjian 已提交
1525 1526 1527 1528 1529 1530 1531 1532 1533 1534 1535 1536 1537 1538 1539 1540 1541 1542 1543 1544 1545 1546 1547 1548 1549 1550 1551 1552 1553 1554 1555 1556 1557 1558 1559 1560 1561 1562 1563 1564 1565 1566 1567 1568 1569 1570 1571
                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 已提交
1572
                append(row_format.format(*row_values))
C
chenjian 已提交
1573 1574 1575
        append('')
        append('')

1576 1577 1578 1579 1580 1581 1582 1583 1584 1585 1586 1587 1588 1589 1590 1591 1592 1593 1594 1595 1596 1597 1598 1599 1600 1601 1602 1603 1604 1605 1606 1607 1608 1609 1610 1611 1612 1613 1614 1615 1616 1617 1618 1619 1620 1621 1622 1623 1624 1625 1626 1627 1628 1629 1630 1631 1632 1633 1634 1635 1636 1637 1638 1639 1640 1641 1642 1643 1644 1645 1646 1647
    ###### Print Memory Summary Report ######
    if statistic_data.memory_summary.allocated_items or statistic_data.memory_summary.reserved_items:
        for device_type, memory_events in statistic_data.memory_summary.allocated_items.items(
        ):
            all_row_values = []
            sorted_items = sorted(memory_events.items(),
                                  key=lambda x: x[1].increase_size,
                                  reverse=True)

            for event_name, item in sorted_items:
                row_values = [
                    event_name, item.memory_type, item.allocation_count,
                    item.free_count, item.allocation_size, item.free_size,
                    item.increase_size
                ]
                all_row_values.append(row_values)

            sorted_reserved_items = sorted(statistic_data.memory_summary.
                                           reserved_items[device_type].items(),
                                           key=lambda x: x[1].increase_size,
                                           reverse=True)
            for event_name, item in sorted_reserved_items:
                row_values = [
                    event_name, item.memory_type, item.allocation_count,
                    item.free_count, item.allocation_size, item.free_size,
                    item.increase_size
                ]
                all_row_values.append(row_values)

            # Calculate the column width
            headers = [
                'Name', 'Type', 'Allocation Count', 'Free Count',
                'Allocation Size', 'Free Size', 'Increased Size'
            ]
            row_format_list = [""]
            header_sep_list = [""]
            line_length_list = [-SPACING_SIZE]
            name_column_width = 50
            number_column_width = 15
            add_column(name_column_width)
            add_column(12)
            add_column(number_column_width)
            add_column(number_column_width)
            add_column(number_column_width)
            add_column(number_column_width)
            add_column(number_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,
                          "Memory Summary - {}".format(device_type)))
            append('Peak Allocated Memory: {}'.format(
                statistic_data.memory_summary.
                peak_allocation_values[device_type]))
            append('Peak Reserved Memory: {}'.format(
                statistic_data.memory_summary.peak_reserved_values[device_type])
                   )
            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:
                    append(row_format.format(*row_values))
            append('')
            append('')

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