cmakeLogToCacheGrind.py 3.27 KB
Newer Older
Marco Clemencic's avatar
Marco Clemencic committed
1
2
3
4
5
6
7
#!/usr/bin/env python
'''
This script allows to parse a log file coming from the instrumentation of the
Gaudi cmake process (See Instrument.cmake) and create an other file
understandable by kcachegrind for easy visualization of where we spend time in
cmake.
'''
8
from __future__ import print_function
9
10
import sys

Marco Clemencic's avatar
Marco Clemencic committed
11

12
def usage():
Gitlab CI's avatar
Gitlab CI committed
13
14
15
    print(
        "Invalid arguments\nProper syntax is :\n  %s <log file> <callgrind file>"
        % sys.argv[0])
16

Marco Clemencic's avatar
Marco Clemencic committed
17

18
19
20
21
22
23
24
25
if len(sys.argv) != 3:
    usage()
    sys.exit(-1)

# dictionary storinf function calls
# actuall a dictionnary of dictionnaries, with top level key
# storing caller name, second level key storing callee name
# and values storing a tuple (nb calls, total time spent in calls)
Marco Clemencic's avatar
Marco Clemencic committed
26
calls = {'main': {}}
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49

# dictionnary of total time spent in functions
timeSpentInfunc = {}

# currrent call stack
# used for transforming the list of log entries into a graph of calls
callStack = []

# sum of total time spent
totalcost = 0

# Here we go through the log lines starting with 'TIMING'
# and get time info. We then update the calls and timeSpentInfunc
# dictionnaries
for line in open(sys.argv[1]).readlines():
    if not line.startswith('TIMING'):
        continue
    key, func, time = line.split()[2:]
    if key == 'STARTIME':
        callStack.append((func, int(time)))
    elif key == 'ENDTIME':
        sfunc, stime = callStack.pop()
        if sfunc != func:
50
            print('Mismatch START/END for %s/%s' % (sfunc, func))
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
            sys.exit()
        deltatime = int(time) - stime
        # add time spent to this function
        if func not in timeSpentInfunc:
            timeSpentInfunc[func] = 0
        timeSpentInfunc[func] += deltatime
        # count callbacks and time spent in upper function
        if callStack:
            caller = callStack[-1][0]
        else:
            caller = 'main'
            # totalcost
            totalcost += deltatime
        if caller not in calls:
            calls[caller] = {}
        if func not in calls[caller]:
            calls[caller][func] = (0, 0)
        nbCalls, timeSpent = calls[caller][func]
Marco Clemencic's avatar
Marco Clemencic committed
69
70
        calls[caller][func] = (nbCalls + 1, timeSpent + deltatime)

71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93

def writeCalls(func, callees):
    '''writes the callgrind entry for a given function given its
    name and a dictionnary of callees -> (nb calls, time spent)'''
    output.write('fn=%s\n' % func)
    # compute time spent in this function
    # excluding time spend in callees
    if func in timeSpentInfunc:
        tottime = timeSpentInfunc[func]
        for cfunc in callees:
            tottime -= callees[cfunc][1]
        output.write('0 %d \n' % tottime)
    else:
        output.write('0 0 \n')
    # print callees and nb calls/time spent
    # for each of them
    for cfunc in callees:
        nb, time = callees[cfunc]
        output.write('cfn=%s\n' % cfunc)
        output.write('calls=%d 0\n' % nb)
        output.write('0 %d\n' % time)
    output.write('\n')

Marco Clemencic's avatar
Marco Clemencic committed
94

95
96
97
98
99
100
101
102
103
104
105
106
# create output callgrind file
output = open(sys.argv[2], 'w')
output.write('events: Cycles\n')
output.write('summary: %d\n' % totalcost)
output.write('fl=GaudiProjectConfig.cmake\n')
for func in calls:
    writeCalls(func, calls[func])
for func in timeSpentInfunc:
    if func not in calls:
        output.write('fn=%s\n' % func)
        output.write('0 %d\n' % timeSpentInfunc[func])
output.close()