strace_io_stats.py

#!/usr/bin/env python3
#
# Strace output I/O analyzer.
#
# Copyright (c) 2017-2019 HLRS, University of Stuttgart.
# This software is published under the terms of the BSD license.
#
# Contact: Christoph Niethammer <niethammer@hlrs.de>
#
# usage:
# --------
# Generate trace with strace wrapper
#   ./strace-wrapper.sh ./my_app [APP OPTIONS]
# or use the strace-wrapper.sh for MPI parallel programs like
#   mpirun [MPI OPTIONS] ./strace-wrapper.sh ./my_app [APP OPTIONS]
# which will generate a set of strace log files, one for each process.
#

import os
import sys

try:
    import optparse
    import re
    import logging
    import statistics
except ImportError as e:
    print("python 3.4 or greater required, found %s" % sys.version)
    raise ImportError(e)


def print_output_section_title(title):
    print("-" * 78 + "\n" + title + ":\n" + "-" * 78)


def print_output_section_footer(title):
    print("-" * 78 + "\n")


def print_file_statistics(filedata, formatstr, properties):
    values = [filedata[p] for p in properties]
    print(formatstr.format(*values))


def write_io_details(data, filename):
    """!@brief Write io statistics to file
    @param data      Dict containing pairs of the form {size: time}
    @param filename  Name of output file
    """
    stats = dict()
    for size, time in data:
        if size not in stats:
            stats[size] = []
        stats[size].append(time)
    with open(filename, "w+") as f:
        f.write(
            ",".join(
                [
                    "size",
                    "count",
                    "time_tot",
                    "time_min",
                    "time_max",
                    "time_median",
                    "bw_avg",
                    "bw_min",
                    "bw_max",
                ]
            )
            + "\n"
        )
        for size in sorted(stats.keys()):
            count = len(stats[size])
            t_tot = sum(stats[size])
            t_min = min(stats[size])
            t_max = max(stats[size])
            t_median = statistics.median_high(stats[size])
            f.write(
                ",".join(
                    map(
                        str,
                        [
                            size,
                            count,
                            t_tot,
                            t_min,
                            t_max,
                            t_median,
                            size * count / t_tot,
                            size / t_max,
                            size / t_min,
                        ],
                    )
                )
                + "\n"
            )


def write_open_details(filedata, filename):
    with open(filename, "w+") as f:
        f.write(",".join(["opened_from", "count"]) + "\n")
        for open_from, count in filedata["open_from"].items():
            f.write(",".join(map(str, [open_from, count])) + "\n")


def save_file_details(filedata):
    """!@brief Save write and read statistics for the given filedata to files
    @param filedata  filedata object
    """
    filename = filedata["filename"]
    # stats for writes
    writestat_file = filename.replace("/", "__") + ".write.stat.txt"
    writestat_data = zip(filedata["write_sizes"], filedata["write_times"])
    write_io_details(writestat_data, writestat_file)
    # stats for reads
    readstat_file = filename.replace("/", "__") + ".read.stat.txt"
    readstat_data = zip(filedata["read_sizes"], filedata["read_times"])
    write_io_details(readstat_data, readstat_file)
    # stats for opens
    openstat_file = filename.replace("/", "__") + ".open.stat.txt"
    write_open_details(filedata, openstat_file)


def new_file_access_stats_entry(filename):
    data = dict()
    data["filename"] = filename
    data["open_times"] = []
    data["open_modes"] = []
    data["open_fds"] = []
    data["open_from"] = dict()
    data["write_times"] = []
    data["write_sizes"] = []
    data["read_times"] = []
    data["read_sizes"] = []
    data["close_times"] = []
    # cache values for sorting and output
    data["write_time"] = 0.0
    data["write_count"] = 0
    data["write_size"] = 0.0
    data["read_time"] = 0.0
    data["read_count"] = 0
    data["read_size"] = 0.0
    data["open_time"] = 0.0
    data["open_count"] = 0
    data["open_from_count"] = 0
    data["close_time"] = 0.0
    data["close_count"] = 0
    return data


class OpenFileTracker:
    def __init__(self):
        self.open_files = dict()

    def register_open(self, filename, fd):
        self.open_files[fd] = filename

    def register_close(self, fd):
        del self.open_files[fd]

    def is_open(self, fd):
        return fd in self.open_files

    def get_filename(self, fd):
        return self.open_files[fd]

    def get_open_files(self):
        return self.open_files


def parseInputFiles(inputfiles):
    open_file_tracker = OpenFileTracker()
    file_access_stats = dict()
    unknown_calls = dict()

    open_file_tracker.register_open("stdin", 0)
    file_access_stats["stdin"] = new_file_access_stats_entry("stdin")
    open_file_tracker.register_open("stdout", 1)
    file_access_stats["stdout"] = new_file_access_stats_entry("stdout")
    open_file_tracker.register_open("stderr", 2)
    file_access_stats["stderr"] = new_file_access_stats_entry("stderr")

    num_ignored_lines = 0
    unfinished = dict()

    for inputfile in inputfiles:
        logging.info("Processing " + str(inputfile) + " ...")
        with open(inputfile, "r") as fh:
            for lineno, line in enumerate(fh):
                # logging.debug("LINE {0}: {1}".format(lineno, line.strip()))
                if "ERESTARTSYS" in line:
                    continue
                if "exit_group" in line:
                    break

                if "<unfinished ...>" in line:
                    pid = int(line.split()[0])
                    unfinished[pid] = line[: -len(" <unfinished ...>")].rstrip()
                    continue
                elif " resumed> " in line:
                    pid = int(line.split()[0])
                    rest = line[line.find(" resumed> ") + len(" resumed> ") :].rstrip()
                    line = unfinished[pid] + rest
                    del unfinished[pid]
                if "execve" in line:
                    # logging.debug("execve")
                    match = re.search(
                        r"(?P<difftime>[0-9]+\.[0-9]+) execve\((.*)\).*= (?P<fd>-?[0-9]+).*<(?P<open_time>[0-9]+\.[0-9]+)>",
                        line,
                    )
                    if match:
                        continue
                elif "dup2(" in line:
                    # logging.debug("dup2:")
                    match = re.search(
                        r"(?P<difftime>[0-9]+\.[0-9]+) dup2\((?P<fd1>[0-9]+), (?P<fd2>[0-9]+)\).*= (?P<fd>-?[0-9]+).*<(?P<open_time>[0-9]+\.[0-9]+)>",
                        line,
                    )
                    # logging.debug("{0}".format(match.groupdict()))
                    fd1 = int(match.group("fd1"))
                    fd = int(match.group("fd"))
                    if fd == -1:
                        continue
                    filename = open_file_tracker.get_filename(fd1)
                    open_file_tracker.register_open(filename, fd)
                    if filename not in file_access_stats:
                        file_access_stats[filename] = new_file_access_stats_entry(
                            filename
                        )
                    file_access_stats[filename]["open_times"].append(
                        float(match.group("open_time"))
                    )
                    file_access_stats[filename]["open_modes"].append(
                        file_access_stats[filename]["open_modes"][-1]
                    )
                    file_access_stats[filename]["open_fds"].append(fd)
                    if inputfile not in file_access_stats[filename]["open_from"]:
                        file_access_stats[filename]["open_from"][inputfile] = 0
                    file_access_stats[filename]["open_from"][inputfile] = (
                        file_access_stats[filename]["open_from"][inputfile] + 1
                    )
                elif "open(" in line:
                    # logging.debug("OPEN:")
                    match = re.search(
                        r"(?P<difftime>[0-9]+\.[0-9]+) open\(\"(?P<filename>.*)\", (?P<mode>.*)\).*= (?P<fd>-?[0-9]+).*<(?P<open_time>[0-9]+\.[0-9]+)>",
                        line,
                    )
                    # logging.debug("{0}".format(match.groupdict()))
                    fd = int(match.group("fd"))
                    if fd == -1:
                        continue
                    filename = match.group("filename")
                    open_file_tracker.register_open(filename, fd)
                    if filename not in file_access_stats:
                        file_access_stats[filename] = new_file_access_stats_entry(
                            filename
                        )
                    file_access_stats[filename]["open_times"].append(
                        float(match.group("open_time"))
                    )
                    file_access_stats[filename]["open_modes"].append(
                        match.group("mode")
                    )
                    file_access_stats[filename]["open_fds"].append(fd)
                    if inputfile not in file_access_stats[filename]["open_from"]:
                        file_access_stats[filename]["open_from"][inputfile] = 0
                    file_access_stats[filename]["open_from"][inputfile] = (
                        file_access_stats[filename]["open_from"][inputfile] + 1
                    )
                elif "openat(" in line:
                    # logging.debug("OPEN:")
                    match = re.search(
                        r"(?P<difftime>[0-9]+\.[0-9]+) openat\((?P<dirfd>.*), \"(?P<filename>.*)\", (?P<mode>.*)\).*= (?P<fd>-?[0-9]+).*<(?P<open_time>[0-9]+\.[0-9]+)>",
                        line,
                    )
                    # logging.debug("{0}".format(match.groupdict()))
                    fd = int(match.group("fd"))
                    if fd == -1:
                        continue
                    filename = match.group("filename")
                    dirfd = match.group("dirfd")
                    if dirfd != "AT_FDCWD" and not os.path.isabs(filename):
                        filename = (
                            open_file_tracker.get_filename(int(dirfd)) + "/" + filename
                        )
                    open_file_tracker.register_open(filename, fd)
                    if filename not in file_access_stats:
                        file_access_stats[filename] = new_file_access_stats_entry(
                            filename
                        )
                    file_access_stats[filename]["open_times"].append(
                        float(match.group("open_time"))
                    )
                    file_access_stats[filename]["open_modes"].append(
                        match.group("mode")
                    )
                    file_access_stats[filename]["open_fds"].append(fd)
                    if inputfile not in file_access_stats[filename]["open_from"]:
                        file_access_stats[filename]["open_from"][inputfile] = 0
                    file_access_stats[filename]["open_from"][inputfile] = (
                        file_access_stats[filename]["open_from"][inputfile] + 1
                    )
                elif "fcntl(" in line:
                    # logging.debug("fcntl:")
                    match = re.search(
                        r"(?P<difftime>[0-9]+\.[0-9]+) fcntl\((?P<fd1>[0-9]+), .*, (?P<fd2>[0-9]+)\).*= (?P<ret>-?[0-9]+).*<(?P<open_time>[0-9]+\.[0-9]+)>",
                        line,
                    )
                    # logging.debug("{0}".format(match.groupdict()))
                    if not match:
                        continue
                    fd1 = int(match.group("fd1"))
                    fd2 = int(match.group("fd2"))
                    if int(match.group("ret")) == -1:
                        continue
                    filename = open_file_tracker.get_filename(fd1)
                    open_file_tracker.register_open(filename, fd2)
                    if filename not in file_access_stats:
                        file_access_stats[filename] = new_file_access_stats_entry(
                            filename
                        )
                    file_access_stats[filename]["open_times"].append(
                        float(match.group("open_time"))
                    )
                    file_access_stats[filename]["open_modes"].append(
                        file_access_stats[filename]["open_modes"][-1]
                    )
                    file_access_stats[filename]["open_fds"].append(fd)
                    if inputfile not in file_access_stats[filename]["open_from"]:
                        file_access_stats[filename]["open_from"][inputfile] = 0
                    file_access_stats[filename]["open_from"][inputfile] = (
                        file_access_stats[filename]["open_from"][inputfile] + 1
                    )
                elif "eventfd2(" in line:
                    # logging.debug("OPEN EVENTFD:")
                    match = re.search(
                        r"(?P<difftime>[0-9]+\.[0-9]+) eventfd2\((?P<mode>.*)\).*= (?P<fd>-?[0-9]+).*<(?P<open_time>[0-9]+\.[0-9]+)>",
                        line,
                    )
                    # logging.debug("{0}".format(match.groupdict()))
                    fd = int(match.group("fd"))
                    if fd == -1:
                        continue
                    filename = "<eventfd>"
                    open_file_tracker.register_open(filename, fd)
                    if filename not in file_access_stats:
                        file_access_stats[filename] = new_file_access_stats_entry(
                            filename
                        )
                    file_access_stats[filename]["open_times"].append(
                        float(match.group("open_time"))
                    )
                    file_access_stats[filename]["open_modes"].append(
                        match.group("mode")
                    )
                    file_access_stats[filename]["open_fds"].append(fd)
                elif "socket(" in line:
                    # logging.debug("OPEN SOCKET:")
                    match = re.search(
                        r"(?P<difftime>[0-9]+\.[0-9]+) socket\((?P<mode>.*)\).*= (?P<fd>-?[0-9]+).*<(?P<open_time>[0-9]+\.[0-9]+)>",
                        line,
                    )
                    # logging.debug("{0}".format(match.groupdict()))
                    fd = int(match.group("fd"))
                    if fd == -1:
                        continue
                    filename = "<socket>"
                    open_file_tracker.register_open(filename, fd)
                    if filename not in file_access_stats:
                        file_access_stats[filename] = new_file_access_stats_entry(
                            filename
                        )
                    file_access_stats[filename]["open_times"].append(
                        float(match.group("open_time"))
                    )
                    file_access_stats[filename]["open_modes"].append(
                        match.group("mode")
                    )
                    file_access_stats[filename]["open_fds"].append(fd)
                elif "socketpair(" in line:
                    # logging.debug("OPEN SOCKET PAIR:")
                    match = re.search(
                        r"(?P<difftime>[0-9]+\.[0-9]+) socketpair\((?P<mode>.*), \[(?P<fd1>[0-9]+), (?P<fd2>[0-9]+)\]\).*= (?P<ret>-?[0-9]+).*<(?P<open_time>[0-9]+\.[0-9]+)>",
                        line,
                    )
                    # logging.debug("{0}".format(match.groupdict()))
                    fd1 = int(match.group("fd1"))
                    fd2 = int(match.group("fd2"))
                    if match.group("ret") == -1:
                        continue
                    filename = "<socket>"
                    open_file_tracker.register_open(filename, fd1)
                    open_file_tracker.register_open(filename, fd2)
                    if filename not in file_access_stats:
                        file_access_stats[filename] = new_file_access_stats_entry(
                            filename
                        )
                    file_access_stats[filename]["open_times"].append(
                        float(match.group("open_time"))
                    )
                    file_access_stats[filename]["open_modes"].append(
                        match.group("mode")
                    )
                    file_access_stats[filename]["open_fds"].append([fd1, fd2])
                elif "pipe(" in line:
                    # logging.debug("OPEN PIPE:")
                    match = re.search(
                        r"(?P<difftime>[0-9]+\.[0-9]+) pipe\(\[(?P<fd1>[0-9]+), (?P<fd2>[0-9]+)\]\).*= (?P<ret>-?[0-9]+).*<(?P<open_time>[0-9]+\.[0-9]+)>",
                        line,
                    )
                    # logging.debug("{0}".format(match.groupdict()))
                    fd1 = int(match.group("fd1"))
                    fd2 = int(match.group("fd2"))
                    if match.group("ret") == -1:
                        continue
                    filename = "<pipe>"
                    open_file_tracker.register_open(filename, fd1)
                    open_file_tracker.register_open(filename, fd2)
                    if filename not in file_access_stats:
                        file_access_stats[filename] = new_file_access_stats_entry(
                            filename
                        )
                    file_access_stats[filename]["open_times"].append(
                        float(match.group("open_time"))
                    )
                    file_access_stats[filename]["open_fds"].append([fd1, fd2])
                elif "close(" in line:
                    # logging.debug("CLOSE:")
                    match = re.search(
                        r"(?P<difftime>[0-9]+\.[0-9]+) close\((?P<fd>[0-9]+)\).*= (?P<ret>-?[0-9]+).*<(?P<close_time>[0-9]+\.[0-9]+)>",
                        line,
                    )
                    # logging.debug("{0}".format(match.groupdict()))
                    fd = int(match.group("fd"))
                    if not open_file_tracker.is_open(fd):
                        logging.warning(
                            "Closing unrecognized file descriptor {0}".format(fd)
                        )
                        continue
                    filename = open_file_tracker.get_filename(fd)
                    file_access_stats[filename]["close_times"].append(
                        float(match.group("close_time"))
                    )
                    open_file_tracker.register_close(fd)
                elif (
                    "write(" in line or "writev(" in line or "write64(" in line
                ) and not "process_vm_writev" in line:
                    # logging.debug("WRITE(V)(:")
                    match = re.search(
                        r"(?P<difftime>[0-9]+\.[0-9]+) p?write(?:64|v)?\((?P<fd>[0-9]+), ?.*, (?P<size>[0-9]+)\).*= (?P<write_size>-?[0-9]+).*<(?P<write_time>[0-9]+\.[0-9]+)>",
                        line,
                    )
                    # logging.debug("{0}".format(match.groupdict()))
                    fd = int(match.group("fd"))
                    if open_file_tracker.is_open(fd):
                        filename = open_file_tracker.get_filename(fd)
                        file_access_stats[filename]["write_times"].append(
                            float(match.group("write_time"))
                        )
                        file_access_stats[filename]["write_sizes"].append(
                            int(match.group("write_size"))
                        )
                    else:
                        logging.warning(
                            "No Open file found for file descriptor {}".format(fd)
                        )
                elif (
                    "read(" in line or "readv(" in line or "read64(" in line
                ) and not "process_vm_readv" in line:
                    # logging.debug("READ(V):")
                    match = re.search(
                        r"(?P<difftime>[0-9]+\.[0-9]+) p?read(?:64|v)?\((?P<fd>[0-9]+), ?.*, (?P<size>[0-9]+)\).*= (?P<read_size>-?[0-9]+).*<(?P<read_time>[0-9]+\.[0-9]+)>",
                        line,
                    )
                    # logging.debug("{0}".format(match.groupdict()))
                    fd = int(match.group("fd"))
                    if open_file_tracker.is_open(fd):
                        filename = open_file_tracker.get_filename(fd)
                        file_access_stats[filename]["read_times"].append(
                            float(match.group("read_time"))
                        )
                        file_access_stats[filename]["read_sizes"].append(
                            int(match.group("read_size"))
                        )
                    else:
                        logging.warning(
                            "No Open file found for file descriptor {}".format(fd)
                        )
                else:
                    logging.debug("Unknown line type: '{}'".format(line.strip()))
                    num_ignored_lines = num_ignored_lines + 1
                    match = re.search(
                        r"(?P<difftime>[0-9]+\.[0-9]+) (?P<func>.*?)\(.*\).*=.*<(?P<time>[0-9]+\.[0-9]+)>",
                        line,
                    )
                    if match != None:
                        # logging.debug('{0}'.format(match.groupdict()))
                        callname = match.group("func")
                        calltime = float(match.group("time"))
                        # logging.warning("Unknown call to {0} took {1}".format(callname, calltime))
                        if callname not in unknown_calls:
                            unknown_calls[callname] = dict()
                            unknown_calls[callname]["times"] = []
                            unknown_calls[callname]["count"] = 0
                        unknown_calls[callname]["times"].append(calltime)
                        unknown_calls[callname]["count"] = (
                            unknown_calls[callname]["count"] + 1
                        )

    if num_ignored_lines > 0:
        logging.warning("Number of ignored lines: {0}".format(num_ignored_lines))
    if open_file_tracker.is_open(0):
        logging.warning("Ignoring open sdtin[0]")
        open_file_tracker.register_close(0)
    if open_file_tracker.is_open(1):
        logging.warning("Ignoring open sdtout[1]")
        open_file_tracker.register_close(1)
    if open_file_tracker.is_open(2):
        logging.warning("Ignoring open sdterr[2]")
        open_file_tracker.register_close(2)
    open_files = open_file_tracker.get_open_files()
    if open_files:
        logging.warning("There are open files at the end of file processing:")
        for fd in open_files.keys():
            logging.warning("  " + open_files[fd] + "[" + str(fd) + "]")

    return file_access_stats, unknown_calls


def calc_file_access_stats(file_access_stats):
    for filename in file_access_stats.keys():
        file_access_stats[filename]["write_time"] = sum(
            file_access_stats[filename]["write_times"], 0.0
        )
        file_access_stats[filename]["write_count"] = len(
            file_access_stats[filename]["write_times"]
        )
        file_access_stats[filename]["write_size"] = sum(
            file_access_stats[filename]["write_sizes"]
        )
        file_access_stats[filename]["read_time"] = sum(
            file_access_stats[filename]["read_times"], 0.0
        )
        file_access_stats[filename]["read_count"] = len(
            file_access_stats[filename]["read_times"]
        )
        file_access_stats[filename]["read_size"] = sum(
            file_access_stats[filename]["read_sizes"]
        )
        file_access_stats[filename]["open_time"] = sum(
            file_access_stats[filename]["open_times"], 0.0
        )
        file_access_stats[filename]["open_count"] = len(
            file_access_stats[filename]["open_times"]
        )
        file_access_stats[filename]["close_time"] = sum(
            file_access_stats[filename]["close_times"], 0.0
        )
        file_access_stats[filename]["close_count"] = len(
            file_access_stats[filename]["close_times"]
        )
        file_access_stats[filename]["open_from_count"] = len(
            file_access_stats[filename]["open_from"]
        )


def main():
    optparser = optparse.OptionParser(
        "usage: %prog [options] STRACE_LOG ...", version="%prog 0.1"
    )
    optparser.add_option(
        "--loglevel",
        help="enable verbose output. Supported leveles: CRITICAL, ERROR, WARNING, INFO, DEBUG",
        action="store",
        type="string",
        metavar="LEVEL",
        dest="loglevel",
        default="ERROR",
    )
    optparser.add_option(
        "--filter-files",
        help="filter for a specific file",
        action="store",
        type="string",
        metavar="REGEX",
        dest="filter_files",
        default=".*",
    )
    optparser.add_option(
        "--file-details",
        help="save detailed stats for each file",
        action="store_true",
        dest="file_details",
        default=False,
    )
    all_properties = [
        "write_time",
        "write_count",
        "write_size",
        "read_time",
        "read_count",
        "read_size",
        "open_time",
        "open_count",
        "open_from_count",
        "close_time",
        "close_count",
    ]
    optparser.add_option(
        "--format",
        help="Comma separated list of fields to include in the output. Supported fields are {} and 'all'. (Default: %default)".format(
            ", ".join(all_properties)
        ),
        dest="format",
        default="write_time,write_count,write_size,read_time,read_count,read_size,open_time,open_count,open_from_count",
    )
    optparser.add_option(
        "--unknown-call-stats",
        help="print statistics about untracked calls",
        action="store_true",
        dest="unknown_call_stats",
        default=False,
    )
    optparser.add_option(
        "--sort-by",
        help="Sort results by property, defaults to first column specified in format",
        action="store",
        type="string",
        metavar="STRING",
        dest="sort_by",
        default="write_time",
    )
    (options, args) = optparser.parse_args()
    numeric_loglevel = getattr(logging, options.loglevel.upper(), None)
    if not isinstance(numeric_loglevel, int):
        raise ValueError("Invalid log level: {0}".format(options.loglevel))
    logging.basicConfig(format="%(levelname)s: %(message)s", level=numeric_loglevel)

    file_access_stats, unknown_calls = parseInputFiles(args)
    calc_file_access_stats(file_access_stats)

    properties = options.format.split(",")
    if "all" in properties:
        properties = all_properties
    formatstr = ""
    headerstr = ""
    for i, property in enumerate(properties):
        if i:
            formatstr += " "
            headerstr += " "
        if len(property) <= 8:
            headerstr += "{:>.8}".format(property)
        else:
            headerstr += property
        if property.endswith("_time") or property == "time":
            formatstr += "{" + str(i) + ":>" + str(max(8, len(property))) + ".6}"
        else:
            formatstr += "{" + str(i) + ":>" + str(max(8, len(property))) + "}"
    formatstr = formatstr + " {{{0}}}".format(len(properties))
    properties.append("filename")
    headerstr += " filename"

    sort_by = properties[0]
    if options.sort_by not in all_properties:
        logging.error(
            "Unknown sort-by value '{0}'. Falling back to '{1}'".format(
                options.sort_by, sort_by
            )
        )
    else:
        sort_by = options.sort_by
    sorted_filenames = sorted(
        file_access_stats.values(), reverse=True, key=lambda k: k[sort_by]
    )

    print_output_section_title("I/O STATISTICS (sorted by {0})".format(sort_by))
    print(headerstr)
    for filedata in sorted_filenames:
        filename = filedata["filename"]
        if re.match(options.filter_files, filename):
            print_file_statistics(file_access_stats[filename], formatstr, properties)
            if options.file_details:
                save_file_details(file_access_stats[filename])
    print_output_section_footer("I/O STATISTICS")

    if options.unknown_call_stats:
        print_output_section_title("HIDDEN STATISTICS (sorted by time)")
        unknown_call_times = dict()
        for callname in unknown_calls.keys():
            unknown_call_times[callname] = sum(unknown_calls[callname]["times"])
        print("{0:16} {1:>12} {2:>12}".format("callname", "count", "time"))
        for callname, time in sorted(unknown_call_times.items()):
            print(
                "{0:16} {1:>12} {2:>12.9}".format(
                    callname, unknown_calls[callname]["count"], time
                )
            )
        print_output_section_footer("HIDDEN STATISTICS")


if __name__ == "__main__":
    main()