Profiling Kratos with LineProfile

Profiling Kratos with LineProfile

This page details the steps to follow in order to profile Kratos with a python line profiler. Please be aware that this is an intrusive process, and you will have to modify some of your code.

Obtaining the profiler: You can find the python line profiler an all the relevant information here: https://github.com/pyutils/line_profiler.

If you prefer only to install it just:

python -m pip install line_profiler

Preparing your code.

The python line profiler needs to know beforehand which functions are you interested in debugger. In that sense, it is helpful that you already have a slight idea on what sections of your code are interested on.

In order to mark such parts, you will have to use the @profile decorator. A example is presented below:

@profile
def my_function():
    var = calculate()
    ...  etc  ...

Unfortunately, this process will make your code break if you try to run it without the profiler. We are working on integrating a mechanism that solved this inside Kratos, but in the meantime we recommend you to use a launcher script to run your code. This will allow to ignore the decorators without removing them from the code if you intend to run the code normally.

Such launcher script have to look like this:

import os
import sys
import builtins
import line_profiler

prof = line_profiler.LineProfiler()

builtins.__dict__['profile'] = prof

exec(open(sys.argv[1]).read())

with open("profile_"+str(os.getpid())+".prof", "w+") as prof_file:
    prof.print_stats(prof_file)

print("Profile output written in:", "profile_"+str(os.getpid())+".prof")

We do recommend to launch your case with this launcher as well if you intend to run with MPI, as it will automatically generate a different report for every process. An example of an invocation call will look like this:

Serial

python profiler.py MainKratos.py

Distributed

mpirun -np [N] --output-filename profile python profiler.py MainKratos.py

Analyzing output

Parser.py

import os
import re
import sys


def ReadValueAs(type, item):
    return type(item) if item.strip() != "" else ""

def ReadBlock(my_file, json_object):
    total_time = my_file.readline()             # Total time or end of file

    if total_time == "" or total_time == "\n":
        return True
    else:
        profiled_file = my_file.readline().rstrip().split(" ")[1]
        profiled_function = my_file.readline().split(" ")[1]

        my_file.readline()                   # Space
        my_file.readline()                   # Headings
        my_file.readline()                   # ========

        stop = False

        function_lines = {}

        if profiled_file not in json_object:
            json_object[profiled_file] = {}

        while not stop:
            profile_line = my_file.readline()

            if profile_line == "" or profile_line == "\n":
                stop = True
            else:
                json_line = {"Line":None, "Hits":None, "Time":None, "Per Hit":None, "% Time":None, "Line Content":None}

                # This may need some tunning. I am not sure how to correctly detect the separators here.
                column_size = 48
                line_items = re.split(r'\s+', profile_line[0:column_size].strip())

                # Has info
                if len(line_items) == 5:
                    json_line["Line"]           = ReadValueAs(int,   line_items[0])
                    json_line["Hits"]           = ReadValueAs(int,   line_items[1])
                    json_line["Time"]           = ReadValueAs(float, line_items[2])
                    json_line["Per Hit"]        = ReadValueAs(float, line_items[3])
                    json_line["% Time"]         = ReadValueAs(float, line_items[4])

                    json_line["Line Content"]   = profile_line[column_size:-1].rstrip()

                    function_lines[json_line["Line"]] = json_line

        json_object[profiled_file][profiled_function] = function_lines

        return False

def ParseFile(filename):
    json_object = {}

    with open(filename, "r") as parse_file:
        timer_unit = parse_file.readline()          # Timer
        parse_file.readline()                       # Space

        is_end_block = False

        while not is_end_block:
            is_end_block = ReadBlock(parse_file, json_object)    # Block Content

    return json_object

def ComputeTotalTime(trace):
    total_time = 0.0

    for filename in trace:
        for function in trace[filename]:
            for line in trace[filename][function]:
                if trace[filename][function][line]["Time"] != '':
                    total_time += trace[filename][function][line]["Time"]

    return total_time

Analyzer.py

import parser

profile_outputs = {
    2: parser.ParseFile("profile-2"),
    4: parser.ParseFile("profile-4"),
    8: parser.ParseFile("profile-8"),
    16: parser.ParseFile("profile-16"),
    32: parser.ParseFile("profile-32"),
    64: parser.ParseFile("profile-64"),
    128: parser.ParseFile("profile-128")
}

def CalculateTotalSpeedUp(input_files, ref):
    speedups = {}
    for proc in input_files:
        speedups[proc] = parser.ComputeTotalTime(input_files[proc])

    for proc in input_files:
        if(proc != ref):
            speedups[proc] = speedups[ref]/speedups[proc]
    speedups[ref] = 1
    
    print(speedups)

def CalculateSpeedUpByLine(input_files, ref):
    speedups = {}
    for proc in input_files:
        trace = input_files[proc]
        for filename in trace:
            for function in trace[filename]:
                for line in trace[filename][function]:
                    if trace[filename][function][line]["Time"] != '' and trace[filename][function][line]["Time"] != 0.0:
                        trace[filename][function][line]["SpeedUp"] = input_files[ref][filename][function][line]["Time"] / input_files[proc][filename][function][line]["Time"]

def ExtractExpensiveLines(input_files, max_core_num, max_line_count, check_criteria):
    most_relevant_entry_lines = []

    trace = input_files[max_core_num]
    for filename in trace:
        for function in trace[filename]:
            for line in trace[filename][function]:
                if trace[filename][function][line][check_criteria] != '':
                    most_relevant_entry_lines.append({"Line": trace[filename][function][line], "Function":function, "File":filename})

    most_relevant_entry_lines.sort(key=lambda x: x["Line"][check_criteria], reverse=True)

    return most_relevant_entry_lines[0:max_line_count]


def GenerateFieldTable(input_files, function_lines, field, min_procs, max_procs, scale_to_min_procs):
    for e_line in function_lines:

        file_name = e_line["File"]
        function_name = e_line["Function"]
        function_line = e_line["Line"]

        buffer = str(file_name.split("/")[-1])+":"+str(function_name)+":"+str(function_line["Line"])+":"+str(function_line["Line Content"])
        
        for proc in input_files:
            trace = input_files[proc]
            value = trace[file_name][function_name][function_line["Line"]][field]

            if field == "SpeedUp" and scale_to_min_procs:
                value = value * min_procs

            buffer += "|" + str(value)

        buffer += "|" + str(input_files[max_procs][file_name][function_name][function_line["Line"]]["Time"]/1e6)
        buffer += "|" + str(input_files[max_procs][file_name][function_name][function_line["Line"]]["Hits"])

        print(buffer)

min_procs = 1
max_procs = 4

CalculateSpeedUpByLine(profile_outputs, min_procs)

most_relevant_entry_lines = ExtractExpensiveLines(profile_outputs, max_procs, 20, "Time")

GenerateFieldTable(profile_outputs, most_relevant_entry_lines, "SpeedUp", min_procs, max_procs, True)
CalculateTotalSpeedUp(profile_outputs, min_procs)