script to parse performance logger

[taiya]

Example of execution, I also attach the python script and the input data below. I quite despise the "mis" notation you have adopted :P

Example execution

~/Developer: ./parselog.py -i example.log -s 1
Context                                     **median (ms)**    mean(ms)    max(ms)
----------------------------------------  -----------------  ----------  ---------
Worker::depth_constraints                            501.00      552.00     709.00
Worker::track                                        302.47      302.50     336.36
Worker::depth_track                                  256.06      248.69     286.10
Worker::depth_compute_update                         255.50      248.07     285.54
Worker::silhouette_constraints                       226.50      238.75     279.00
Worker::render_offscreen()::(cloud)                  203.00      204.00     238.00
Worker::silhouette_track                              55.16       55.06      55.31
Worker::silhouette_compute_update                     54.87       54.75      54.96
Worker::render_offscreen()                            13.10       12.92      20.12
Worker::render_offscreen()::(render)                   7.08        8.94      18.15
Worker::render_offscreen()::(fetch+flip)               1.88        2.56       4.83

Python script:

#!/usr/local/bin/python3.4
import sys
if not sys.version_info[:2] == (3,4):
    print("Error, I need python 3.4");
import re
import statistics
import getopt
from tabulate import tabulate # pip3 inst all tabulate!!

def main():
    # default parameters
    inputfile='htrack_performance.log'
    sortby=0

    # Parse command line options
    opts, args = getopt.getopt(sys.argv[1:],'hi:s:')
    for opt, arg in opts:
        if opt == '-h':
            print('Examples:')
            print('    parselog.py -i performance.log')
            print('    parselog.py -i performance.log -s 1')
            sys.exit(0)
        elif opt in ('-i', '--ifile'):
           inputfile = arg
        elif opt in ('-s', '--sort'):
           sortby = int(arg)

    # https://docs.python.org/2/howto/regex.html
    # \[ : [ is a meta char and needs to be escaped 
    # (.*?) : match everything in a non-greedy way and capture it.
    expr = re.compile('\[(.*?)\]')

    data = dict()
    for line in open(inputfile, 'r'):
        # print '\n\n-----';
        strings = expr.findall(line)
        assert(len(strings)>1)
        key = strings[0];
        val = strings[1];
        vals = val.partition(' ')
        unit = vals[2]

        # brings everything on the same scale (ms)
        num_ms = float(vals[0])
        if unit=='mis':
            num_ms = num_ms/1000.0    

        # append time to dictionary entry
        if key in data:
            data[key].append(num_ms)
        else:
            data[key] = [num_ms]

    #--- to sort the data
    # import operator
    # for key in sorted(data, key=operator.itemgetter(0), reverse=True):

    #--- create the table
    table = [];
    for key in sorted(data):
        # compute statistics
        _med = statistics.median(data[key])
        _avg = statistics.mean(data[key])
        _max = max(data[key])
        table.append((key, _med, _avg, _max))

    #--- sort it
    table = sorted(table, key=lambda val: val[sortby], reverse=True)

    #--- create a pretty table
    header= ["Context","median (ms)", "mean(ms)","max(ms)"]
    header[sortby] = '**'+header[sortby]+'**' 
    # print('Table sorted by: ', header[sortby])
    print( tabulate(table, headers=header, floatfmt=".2f") )

if __name__ == "__main__":
    main()

Test data

Executed [GUI] in [4.728 ms]
Executed [Extract] in [172 mis]
Executed [GUI] in [11.663 ms]
Executed [TOTAL] in [11.987 ms]
Executed [GUI] in [4.107 ms]
Executed [Extract] in [214 mis]
Executed [GUI] in [4.317 ms]
Executed [TOTAL] in [4.637 ms]
Executed [GUI] in [3.414 ms]
Executed [Extract] in [261 mis]
Executed [GUI] in [4.607 ms]
Executed [TOTAL] in [4.984 ms]
Executed [GUI] in [3.565 ms]
Executed [Extract] in [262 mis]
Executed [GUI] in [4.355 ms]
Executed [TOTAL] in [4.737 ms]
Executed [GUI] in [3.414 ms]
Executed [Extract] in [260 mis]
Executed [GUI] in [4.783 ms]
Executed [TOTAL] in [5.161 ms]
Executed [Worker::render_offscreen()::(render)] in [6.447 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [4.831 ms]
Executed [Worker::render_offscreen()::(cloud)] in [238 mis]
Executed [Worker::render_offscreen()] in [16.02 ms]
Executed [Worker::depth_constraints] in [709 mis]
Executed [Worker::depth_compute_update] in [195.755 ms]
Executed [Worker::depth_track] in [196.535 ms]
Executed [Worker::silhouette_constraints] in [279 mis]
Executed [Worker::silhouette_compute_update] in [54.964 ms]
Executed [Worker::silhouette_track] in [55.314 ms]
Executed [Worker::track] in [268.69 ms]
Executed [Worker::render_offscreen()::(render)] in [7.711 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [2.094 ms]
Executed [Worker::render_offscreen()::(cloud)] in [233 mis]
Executed [Worker::render_offscreen()] in [10.189 ms]
Executed [Worker::depth_constraints] in [497 mis]
Executed [Worker::depth_compute_update] in [236.066 ms]
Executed [Worker::depth_track] in [236.629 ms]
Executed [Worker::silhouette_constraints] in [223 mis]
Executed [Worker::silhouette_compute_update] in [54.868 ms]
Executed [Worker::silhouette_track] in [55.159 ms]
Executed [Worker::track] in [302.468 ms]
Executed [Worker::render_offscreen()::(render)] in [3.438 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [1.647 ms]
Executed [Worker::render_offscreen()::(cloud)] in [172 mis]
Executed [Worker::render_offscreen()] in [5.353 ms]
Executed [Worker::depth_constraints] in [500 mis]
Executed [Worker::depth_compute_update] in [274.938 ms]
Executed [Worker::depth_track] in [275.494 ms]
Executed [Worker::silhouette_constraints] in [229 mis]
Executed [Worker::silhouette_compute_update] in [54.415 ms]
Executed [Worker::silhouette_track] in [54.71 ms]
Executed [Worker::track] in [336.355 ms]
Executed [Worker::render_offscreen()::(render)] in [18.153 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [1.656 ms]
Executed [Worker::render_offscreen()::(cloud)] in [173 mis]
Executed [Worker::render_offscreen()] in [20.124 ms]
Executed [Worker::depth_constraints] in [502 mis]
Executed [Worker::depth_compute_update] in [285.537 ms]
Executed [Worker::depth_track] in [286.098 ms]
Executed [Worker::silhouette_constraints] in [224 mis]
Executed [Worker::silhouette_compute_update] in [56.235 ms]
Executed [Worker::silhouette_track] in [56.523 ms]
Executed [Worker::track] in [363.38 ms]
Executed [Worker::render_offscreen()::(render)] in [20.867 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [1.89 ms]
Executed [Worker::render_offscreen()::(cloud)] in [173 mis]
Executed [Worker::render_offscreen()] in [23.081 ms]
Executed [Worker::depth_constraints] in [506 mis]
Executed [Worker::depth_compute_update] in [287.973 ms]
Executed [Worker::depth_track] in [288.543 ms]
Executed [Worker::silhouette_constraints] in [231 mis]
Executed [Worker::silhouette_compute_update] in [55.648 ms]
Executed [Worker::silhouette_track] in [55.943 ms]
Executed [Worker::track] in [368.252 ms]
Executed [Worker::render_offscreen()::(render)] in [16.56 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [1.606 ms]
Executed [Worker::render_offscreen()::(cloud)] in [173 mis]
Executed [Worker::render_offscreen()] in [18.48 ms]
Executed [Worker::depth_constraints] in [506 mis]
Executed [Worker::depth_compute_update] in [296.215 ms]
Executed [Worker::depth_track] in [296.786 ms]
Executed [Worker::silhouette_constraints] in [222 mis]
Executed [Worker::silhouette_compute_update] in [57.944 ms]
Executed [Worker::silhouette_track] in [58.24 ms]
Executed [Worker::track] in [374.008 ms]
Executed [Worker::render_offscreen()::(render)] in [3.461 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [1.476 ms]
Executed [Worker::render_offscreen()::(cloud)] in [172 mis]
Executed [Worker::render_offscreen()] in [5.219 ms]
Executed [Worker::depth_constraints] in [547 mis]
Executed [Worker::depth_compute_update] in [302.653 ms]
Executed [Worker::depth_track] in [303.268 ms]
Executed [Worker::silhouette_constraints] in [238 mis]
Executed [Worker::silhouette_compute_update] in [58.187 ms]
Executed [Worker::silhouette_track] in [58.491 ms]
Executed [Worker::track] in [367.805 ms]
Executed [Worker::render_offscreen()::(render)] in [21.972 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [1.867 ms]
Executed [Worker::render_offscreen()::(cloud)] in [254 mis]
Executed [Worker::render_offscreen()] in [24.253 ms]
Executed [Worker::depth_constraints] in [788 mis]
Executed [Worker::depth_compute_update] in [305.426 ms]
Executed [Worker::depth_track] in [306.287 ms]
Executed [Worker::silhouette_constraints] in [227 mis]
Executed [Worker::silhouette_compute_update] in [56.601 ms]
Executed [Worker::silhouette_track] in [56.894 ms]
Executed [Worker::track] in [388.088 ms]
Executed [Worker::render_offscreen()::(render)] in [13.666 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [1.543 ms]
Executed [Worker::render_offscreen()::(cloud)] in [189 mis]
Executed [Worker::render_offscreen()] in [15.501 ms]
Executed [Worker::depth_constraints] in [521 mis]
Executed [Worker::depth_compute_update] in [306.341 ms]
Executed [Worker::depth_track] in [306.926 ms]
Executed [Worker::silhouette_constraints] in [229 mis]
Executed [Worker::silhouette_compute_update] in [57.647 ms]
Executed [Worker::silhouette_track] in [57.941 ms]
Executed [Worker::track] in [381.022 ms]
Executed [Worker::render_offscreen()::(render)] in [14.648 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [2.023 ms]
Executed [Worker::render_offscreen()::(cloud)] in [182 mis]
Executed [Worker::render_offscreen()] in [16.994 ms]
Executed [Worker::depth_constraints] in [505 mis]
Executed [Worker::depth_compute_update] in [308.832 ms]
Executed [Worker::depth_track] in [309.403 ms]
Executed [Worker::silhouette_constraints] in [232 mis]
Executed [Worker::silhouette_compute_update] in [57.754 ms]
Executed [Worker::silhouette_track] in [58.05 ms]
Executed [Worker::track] in [384.963 ms]
Executed [Worker::render_offscreen()::(render)] in [7.833 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [1.949 ms]
Executed [Worker::render_offscreen()::(cloud)] in [260 mis]
Executed [Worker::render_offscreen()] in [10.188 ms]
Executed [Worker::depth_constraints] in [550 mis]
Executed [Worker::depth_compute_update] in [314.116 ms]
Executed [Worker::depth_track] in [314.731 ms]
Executed [Worker::silhouette_constraints] in [224 mis]
Executed [Worker::silhouette_compute_update] in [57.545 ms]
Executed [Worker::silhouette_track] in [57.832 ms]
Executed [Worker::track] in [383.617 ms]
Executed [Worker::render_offscreen()::(render)] in [4.594 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [1.865 ms]
Executed [Worker::render_offscreen()::(cloud)] in [185 mis]
Executed [Worker::render_offscreen()] in [6.743 ms]
Executed [Worker::depth_constraints] in [527 mis]
Executed [Worker::depth_compute_update] in [314.964 ms]
Executed [Worker::depth_track] in [315.573 ms]
Executed [Worker::silhouette_constraints] in [226 mis]
Executed [Worker::silhouette_compute_update] in [57.673 ms]
Executed [Worker::silhouette_track] in [57.965 ms]
Executed [Worker::track] in [380.822 ms]
Executed [Worker::render_offscreen()::(render)] in [5.98 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [1.535 ms]
Executed [Worker::render_offscreen()::(cloud)] in [244 mis]
Executed [Worker::render_offscreen()] in [7.897 ms]
Executed [Worker::depth_constraints] in [538 mis]
Executed [Worker::depth_compute_update] in [312.99 ms]
Executed [Worker::depth_track] in [313.606 ms]
Executed [Worker::silhouette_constraints] in [233 mis]
Executed [Worker::silhouette_compute_update] in [58.352 ms]
Executed [Worker::silhouette_track] in [58.651 ms]
Executed [Worker::track] in [380.701 ms]
Executed [Worker::render_offscreen()::(render)] in [6.829 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [1.812 ms]
Executed [Worker::render_offscreen()::(cloud)] in [247 mis]
Executed [Worker::render_offscreen()] in [9.026 ms]
Executed [Worker::depth_constraints] in [554 mis]
Executed [Worker::depth_compute_update] in [318.266 ms]
Executed [Worker::depth_track] in [318.896 ms]
Executed [Worker::silhouette_constraints] in [227 mis]
Executed [Worker::silhouette_compute_update] in [58.18 ms]
Executed [Worker::silhouette_track] in [58.471 ms]
Executed [Worker::track] in [387.046 ms]
Executed [Worker::render_offscreen()::(render)] in [22.051 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [1.683 ms]
Executed [Worker::render_offscreen()::(cloud)] in [222 mis]
Executed [Worker::render_offscreen()] in [24.107 ms]
Executed [Worker::depth_constraints] in [651 mis]
Executed [Worker::depth_compute_update] in [320.784 ms]
Executed [Worker::depth_track] in [321.502 ms]
Executed [Worker::silhouette_constraints] in [239 mis]
Executed [Worker::silhouette_compute_update] in [61.306 ms]
Executed [Worker::silhouette_track] in [61.613 ms]
Executed [Worker::track] in [407.741 ms]
Executed [Worker::render_offscreen()::(render)] in [7.974 ms]
Executed [Worker::render_offscreen()::(fetch+flip)] in [1.755 ms]
Executed [Worker::render_offscreen()::(cloud)] in [256 mis]
Executed [Worker::render_offscreen()] in [10.14 ms]
Executed [Worker::depth_constraints] in [551 mis]
Executed [Worker::depth_compute_update] in [320.252 ms]
Executed [Worker::depth_track] in [320.868 ms]
Executed [Worker::silhouette_constraints] in [226 mis]
Executed [Worker::silhouette_compute_update] in [59.361 ms]
Executed [Worker::silhouette_track] in [59.654 ms]
Executed [Worker::track] in [391.198 ms]
Executed [Worker::render_offscreen()::(render)] in [689 mis]
Executed [Worker::render_offscreen()::(fetch+flip)] in [2.102 ms]
Executed [Worker::render_offscreen()::(cloud)] in [284 mis]
Executed [Worker::render_offscreen()] in [3.231 ms]
Executed [Worker::depth_constraints] in [677 mis]
Executed [Worker::depth_compute_update] in [305.432 ms]
Executed [Worker::depth_track] in [306.195 ms]
Executed [Worker::silhouette_constraints] in [225 mis]
Executed [Worker::silhouette_compute_update] in [59.098 ms]
Executed [Worker::silhouette_track] in [59.389 ms]
Executed [Worker::track] in [369.375 ms]
Executed [Worker::render_offscreen()::(render)] in [924 mis]
Executed [Worker::render_offscreen()::(fetch+flip)] in [2.235 ms]
Executed [Worker::render_offscreen()::(cloud)] in [289 mis]
Executed [Worker::render_offscreen()] in [3.598 ms]
Executed [Worker::depth_constraints] in [779 mis]
Executed [Worker::depth_compute_update] in [305.801 ms]
Executed [Worker::depth_track] in [306.672 ms]
Executed [Worker::silhouette_constraints] in [226 mis]
Executed [Worker::silhouette_compute_update] in [57.039 ms]
Executed [Worker::silhouette_track] in [57.329 ms]
Executed [Worker::track] in [368.115 ms]
Executed [Worker::render_offscreen()::(render)] in [845 mis]
Executed [Worker::render_offscreen()::(fetch+flip)] in [2.618 ms]
Executed [Worker::render_offscreen()::(cloud)] in [277 mis]
Executed [Worker::render_offscreen()] in [3.91 ms]
Executed [Worker::depth_constraints] in [678 mis]
Executed [Worker::depth_compute_update] in [306.325 ms]
Executed [Worker::depth_track] in [307.08 ms]
Executed [Worker::silhouette_constraints] in [226 mis]
Executed [Worker::silhouette_compute_update] in [56.659 ms]
Executed [Worker::silhouette_track] in [56.948 ms]
Executed [Worker::track] in [368.467 ms]
Executed [Worker::render_offscreen()::(render)] in [840 mis]
Executed [Worker::render_offscreen()::(fetch+flip)] in [2.173 ms]
Executed [Worker::render_offscreen()::(cloud)] in [290 mis]
Executed [Worker::render_offscreen()] in [3.467 ms]
Executed [Worker::depth_constraints] in [801 mis]
Executed [Worker::depth_compute_update] in [309.781 ms]
Executed [Worker::depth_track] in [310.71 ms]
Executed [Worker::silhouette_constraints] in [229 mis]
Executed [Worker::silhouette_compute_update] in [57.329 ms]
Executed [Worker::silhouette_track] in [57.624 ms]
Executed [Worker::track] in [372.346 ms]
Executed [Worker::render_offscreen()::(render)] in [939 mis]
Executed [Worker::render_offscreen()::(fetch+flip)] in [2.49 ms]
Executed [Worker::render_offscreen()::(cloud)] in [288 mis]
Executed [Worker::render_offscreen()] in [3.878 ms]
Executed [Worker::depth_constraints] in [717 mis]
Executed [Worker::depth_compute_update] in [302.32 ms]
Executed [Worker::depth_track] in [303.11 ms]
Executed [Worker::silhouette_constraints] in [221 mis]
Executed [Worker::silhouette_compute_update] in [55.997 ms]
Executed [Worker::silhouette_track] in [56.284 ms]
Executed [Worker::track] in [363.782 ms]
Executed [Worker::render_offscreen()::(render)] in [847 mis]
Executed [Worker::render_offscreen()::(fetch+flip)] in [2.546 ms]
Executed [Worker::render_offscreen()::(cloud)] in [279 mis]
Executed [Worker::render_offscreen()] in [3.832 ms]
Executed [Worker::depth_constraints] in [674 mis]
Executed [Worker::depth_compute_update] in [303.744 ms]
Executed [Worker::depth_track] in [304.496 ms]
Executed [Worker::silhouette_constraints] in [224 mis]
Executed [Worker::silhouette_compute_update] in [56.86 ms]
Executed [Worker::silhouette_track] in [57.148 ms]
Executed [Worker::track] in [365.985 ms]

[easylogging]

I dont understand what is this ticket about. Can you put details on what are you

[taiya]

You offer performance logging, but no way of having cumulative statistics for the recorded times. This script parses a performance log file from easylogging++ and computes mean/average/max, etc statistics. It's not really a question.. perhaps you find it useful.

[easylogging]

Anyone interested should be able to have a look at this - will add a reference in README later and then close this

[easylogging]

Added in v9.79+