forked from mpirvu/Utils
-
Notifications
You must be signed in to change notification settings - Fork 0
/
ComputeTimeProfiling.py
165 lines (151 loc) · 8.44 KB
/
ComputeTimeProfiling.py
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
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
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
# Script that takes an OpenJ9 verbose log and, for
# each method, computes the time spent in profiling mode
# Caveat: the key for the main dictionary is the method name,
# so if several different methods with the same name exist in
# the system (because of different class loaders), the script
# mai produce incorrect results.
# Author: Marius Pirvu
import re # for regular expressions
import sys # for accessing parameters and exit
profilingTimeThreshold = 2000 # ms. Method spending more than this in profiling, will be printed
# We will keep a dictionary where the key is the method name and the value
# is a list of hashes. Those hashes have 4 keys
# 1. 'optLevel': The opt level of the compilation (includes "profiling" for profiling compilations)
# 2. 'tStart': Time when compilation started (ms)
# 3. 'tComp': Duration of compilation (usec)
# 4. 'success': True for successful compilation and False for failures
def printMethodCompHistory(methodName, compList):
print("Compilation history for", methodName)
for comp in compList:
tStart = comp.get('tStart', 0)
tComp = comp.get('tComp', 0)
success = comp.get('success', False)
print("\t{s} {optLvl:14s} tStart:{t1:8d} ms tComp:{t2:8d} usec tEnd:{t3:8d}".format(s="+" if success else "!",
optLvl=comp['optLevel'], t1=tStart, t2=tComp, t3=tStart + tComp//1000))
'''
Parse an OpenJ9 verbose log obtained with -Xjit:verbose={compilePerformance}
and populate a dictionary called 'methodHash' that has the structure described above
'''
def parseVlog(vlog, methodHash):
# (cold) Compiling java/lang/Double.longBitsToDouble(J)D OrdinaryMethod j9m=0000000000097B18 t=20 compThreadID=0 memLimit=262144 KB freePhysicalMemory=75755 MB
compStartPattern = re.compile('^ \((.+)\) Compiling (\S+) .+ t=(\d+)')
# + (cold) sun/reflect/Reflection.getCallerClass()Ljava/lang/Class; @ 00007FB21300003C-00007FB213000167 OrdinaryMethod - Q_SZ=1 Q_SZI=1 QW=2 j9m=000000000004D1D8 bcsz=2 JNI time=995us mem=[region=704 system=2048]KB compThreadID=0 CpuLoad=163%(10%avg) JvmCpu=0%
compEndPattern = re.compile('^\+ \((.+)\) (\S+) .*time=(\d+)us')
# ! (profiled hot) java/util/zip/ZipInputStream.read([BII)I time=27214us compilationEnforceProfiling memLimit=262144 KB freePhysicalMemory=72199 MB mem=[region=4224 system=16384]KB
compFailPattern = re.compile('^\! \((.+)\) (\S+) .*time=(\d+)us')
# TODO: look for other patterns of failures
# Parse the vlog
for line in vlog:
# Skip over DLT compilations because they can go in parallel with other 'ordinary' compilations
if " DLT" in line:
continue
compEnd = compEndPattern.match(line)
compFail = compFailPattern.match(line)
opt = ""
methodName = ""
usec = 0
success = True
if compEnd or compFail:
if compEnd:
# First group is the opt level
opt = compEnd.group(1)
methodName = compEnd.group(2)
usec = int(compEnd.group(3))
else:
opt = compFail.group(1)
methodName = compFail.group(2)
usec = int(compFail.group(3))
success = False
# add the method to my hash
assert methodName in methodHash, "Compilation end without a compilation start for line: {l}".format(l=line)
compList = methodHash[methodName]
# Last entry in the compilation list must have the compStart populated, but not the compTime
assert compList, "compList must not be empty for method {m}".format(m=methodName)
lastEntry = compList[-1] # This is a dictionary with 4 keys
assert 'tStart' in lastEntry, "We must have seen the compilation start for method {m}".format(m=methodName)
assert 'tComp' not in lastEntry, "We must not have seen another compilation end for method {m}".format(m=methodName)
lastEntry['optLevel'] = opt # update the opt level
lastEntry['tComp'] = usec
lastEntry['success'] = success
else:
m = compStartPattern.match(line)
if m:
# First group is the opt level
opt = m.group(1)
methodName = m.group(2)
ms = int(m.group(3))
# add the method to my hash
if methodName not in methodHash: # First compilation for this method
methodHash[methodName] = [{'optLevel':opt, 'tStart':ms}]
else:
compList = methodHash[methodName]
# Check that last entry for this method has both the end and the start of the compilation
assert 'tComp' in compList[-1], "lastEntry for this method must be a compilation with start and end. Line: {l}".format(l=line)
compList.append({'optLevel':opt, 'tStart':ms})
def printStatsHeader():
print(" \tSamples\tTOTAL(sec)\tMIN(ms)\tAVG(ms)\tMAX(ms)")
def printStats(name, dataList):
numSamples = len(dataList)
sumValue = sum(dataList)
meanValue = sumValue/numSamples
minValue = min(dataList)
maxValue = max(dataList)
print("{name}\t{n:7d}\t{s:8.0f}\t{min:7.0f}\t{avg:7.0f}\t{max:7.0f}".format(name=name, n=numSamples, s=sumValue/1000, min=minValue, avg=meanValue, max=maxValue))
'''
Walk the give method hash and for each method determine
1. If the method remains in profiling (last successful compilation is profiling)
2. How much time is spent in profiling mode
If time spent in profiling exceeds the given threshold, print that method name
'''
def walkMethodHash(methodHash, profTimeThreshold):
timesSpentProfiling = [] # one entry for each method that spent time in profiling mode
for method in methodHash:
compList = methodHash[method]
prevCompWasProfiling = False
profilingTime = 0 # Reset
atLeastOneProfilingComp = False
for compilation in compList:
if 'tComp' in compilation: # We have a compilation end
opt = compilation['optLevel'] # Will throw if it doesn't exist
if "profiled" in opt: # This is a profiling compilation
tEnd = compilation['tStart'] + compilation['tComp']//1000 # convert to ms
if compilation['success']: # successful profiling compilation
tLastProfComp = tEnd
prevCompWasProfiling = True
atLeastOneProfilingComp = True
else: # Non-profiling compilation
# Was the previous compilation a profiling one?
if prevCompWasProfiling:
tEnd = compilation['tStart'] + compilation['tComp']//1000 # convert to ms
if tEnd < tLastProfComp:
print("Time goes backwards for method:", method)
print("tLastProfComp =", tLastProfComp, " tEnd =", tEnd)
printMethodCompHistory(method, compList)
#exit(-1)
else:
profilingTime += tEnd - tLastProfComp
# If this non-profiling compilation ended successfuly we reset 'prevCompWasProfiling`
# Otherwise, we keep it because we still have a profiling method executing
if compilation['success']:
prevCompWasProfiling = False
else:
print("Compilation start without compilation end for method:", method)
if prevCompWasProfiling:
print("Stuck in profiling for method", method)
printMethodCompHistory(method, compList)
if atLeastOneProfilingComp:
timesSpentProfiling.append(profilingTime)
if profilingTime > profTimeThreshold:
print("Spent", profilingTime, "ms profiling for method", method)
printStatsHeader()
printStats("Time-Spent-Profiling-ms", timesSpentProfiling)
# Get the name of vlog
if len(sys.argv) < 2:
print ("Program must have an argument: the name of the vlog\n")
sys.exit(-1)
# Open my file in read only mode with line buffering
vlogFileName = str(sys.argv[1])
Vlog = open(vlogFileName, 'r', 1)
methodHash = {}
parseVlog(Vlog, methodHash)
walkMethodHash(methodHash, profilingTimeThreshold)