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

    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
        for child in self.children_node:
            self.gpu_time += child.gpu_time
C
chenjian 已提交
91
            self.general_gpu_time += child.general_gpu_time
C
chenjian 已提交
92 93 94 95 96
            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 已提交
97 98
            self.general_gpu_time += rt.general_gpu_time
            self.self_general_gpu_time += rt.general_gpu_time
C
chenjian 已提交
99
        for device in self.hostnode.device_node:
C
chenjian 已提交
100 101 102 103 104
            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 已提交
105 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

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

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


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

    class DeviceItem:
337

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

C
chenjian 已提交
362 363 364 365 366 367 368 369 370 371 372
        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 已提交
373 374 375
            self.general_gpu_time = 0
            self.min_general_gpu_time = float('inf')
            self.max_general_gpu_time = 0
C
chenjian 已提交
376 377 378 379 380 381 382 383 384

        @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 已提交
385 386 387 388
        @property
        def avg_general_gpu_time(self):
            return self.general_gpu_time / self.call

C
chenjian 已提交
389 390 391 392 393 394 395 396 397 398 399 400 401 402
        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 已提交
403 404 405 406 407 408 409
        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 已提交
410 411 412 413 414 415 416
        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 已提交
417
            self.add_general_gpu_time(node.general_gpu_time)
C
chenjian 已提交
418
            for child in node.children_node:
C
chenjian 已提交
419 420 421 422 423
                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 已提交
424 425 426

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

    class GeneralItem:
433

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

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

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

    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
498
        self.kernel_items = {}  # for kernel summary
C
chenjian 已提交
499 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:
                        self.add_userdefined_item(host_statistic_node)
518
            self.add_kernel_item(host_statistic_nodes[0])
C
chenjian 已提交
519 520 521 522 523 524 525 526 527 528 529 530

        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 已提交
531 532
                        if child.type == TracerEventType.ProfileStep:
                            self.add_model_perspective_item(child)
C
chenjian 已提交
533 534 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
                        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 已提交
582 583
        elif model_perspective_node.type == TracerEventType.ProfileStep:
            name = 'ProfileStep'
C
chenjian 已提交
584 585 586 587 588 589
        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)

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

600 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
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 已提交
677 678 679 680 681 682 683 684 685 686
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 已提交
687
        self.distributed_summary = DistributedSummary()
688
        self.memory_summary = MemorySummary()
C
chenjian 已提交
689 690
        self.time_range_summary.parse(node_trees)
        self.event_summary.parse(node_trees)
C
chenjian 已提交
691
        self.distributed_summary.parse(node_trees)
692
        self.memory_summary.parse(node_trees)
C
chenjian 已提交
693 694 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


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

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

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

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

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

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

        other_time = total_time - accmulation_time
C
chenjian 已提交
954
        other_gpu_time = gpu_total_time - gpu_accmulation_time
955 956 957 958
        if gpu_total_time == 0:
            gpu_ratio = 0
        else:
            gpu_ratio = float(other_gpu_time) / gpu_total_time
C
chenjian 已提交
959 960
        row_values = [
            '  Others', '-', '{} / - / - / - / {}'.format(
961
                format_time(other_time, unit=time_unit),
C
chenjian 已提交
962
                format_ratio(float(other_time) / total_time)),
C
chenjian 已提交
963
            '{} / - / - / - / {}'.format(
964
                format_time(other_gpu_time, unit=time_unit),
965
                format_ratio(gpu_ratio))
C
chenjian 已提交
966
        ]
C
chenjian 已提交
967 968 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
        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 已提交
1002
        append(header_sep)
C
chenjian 已提交
1003 1004 1005 1006 1007 1008 1009 1010
        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 已提交
1011 1012 1013 1014
        append('')
        append('')

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

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

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

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

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

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

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

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

        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(
1332 1333 1334 1335
                    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),
1336 1337 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
                    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 已提交
1369
        kernel_name_pattern = re.compile('(.+?)(<.*>)(\(.*\))')
1370
        for row_values in all_row_values:
C
chenjian 已提交
1371 1372 1373
            match = kernel_name_pattern.match(row_values[0])
            if match:
                name = match.group(1) + match.group(2)
1374 1375 1376 1377 1378 1379 1380 1381 1382 1383 1384
            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 已提交
1385 1386 1387
    ###### Print Memory Manipulation Summary Report ######
    if statistic_data.event_summary.memory_manipulation_items:
        all_row_values = []
C
chenjian 已提交
1388
        memory_manipulation_items = statistic_data.event_summary.memory_manipulation_items
1389 1390
        gpu_total_time = statistic_data.event_summary.model_perspective_items[
            'ProfileStep'].general_gpu_time
C
chenjian 已提交
1391
        for name, item in memory_manipulation_items.items():
1392 1393 1394 1395
            if gpu_total_time == 0:
                gpu_ratio = 0
            else:
                gpu_ratio = float(item.general_gpu_time) / gpu_total_time
C
chenjian 已提交
1396 1397 1398 1399
            row_values = [
                name,
                item.call,
                '{} / {} / {} / {} / {}'.format(
1400 1401 1402 1403
                    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 已提交
1404 1405
                    format_ratio(float(item.cpu_time) / total_time)),
                '{} / {} / {} / {} / {}'.format(
1406 1407 1408 1409
                    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),
1410
                    format_ratio(gpu_ratio)),
C
chenjian 已提交
1411
            ]
C
chenjian 已提交
1412 1413
            all_row_values.append(row_values)

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

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

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

            for name, item in sorted_items:
1503 1504 1505 1506
                if gpu_total_time == 0:
                    gpu_ratio = 0
                else:
                    gpu_ratio = float(item.general_gpu_time) / gpu_total_time
C
chenjian 已提交
1507 1508 1509 1510
                row_values = [
                    name,
                    item.call,
                    '{} / {} / {} / {} / {}'.format(
1511 1512 1513 1514
                        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 已提交
1515 1516
                        format_ratio(float(item.cpu_time) / total_time)),
                    '{} / {} / {} / {} / {}'.format(
1517 1518 1519 1520
                        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),
1521
                        format_ratio(gpu_ratio)),
C
chenjian 已提交
1522
                ]
C
chenjian 已提交
1523 1524 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
                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 已提交
1570
                append(row_format.format(*row_values))
C
chenjian 已提交
1571 1572 1573
        append('')
        append('')

1574 1575 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
    ###### 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 已提交
1646
    return ''.join(result)