handle case where profile is already running

This commit is contained in:
Darren Ranalli 2008-10-03 18:15:44 +00:00
parent 1e09da24a5
commit 26a541c244
2 changed files with 116 additions and 85 deletions

View File

@ -27,9 +27,11 @@ class ProfileSession:
self._func = func self._func = func
self._name = name self._name = name
self._filename = 'profileData-%s-%s' % (self._name, id(self)) self._filename = 'profileData-%s-%s' % (self._name, id(self))
self._profileSucceeded = False
self._wallClockDur = None self._wallClockDur = None
self._ramFile = None self._ramFile = None
self._refCount = 0 self._refCount = 0
self._resultCache = {}
self.acquire() self.acquire()
def acquire(self): def acquire(self):
@ -45,97 +47,124 @@ class ProfileSession:
del self._filename del self._filename
del self._wallClockDur del self._wallClockDur
del self._ramFile del self._ramFile
del self._resultCache
def run(self): def run(self):
# make sure this instance doesn't get destroyed inside self._func # make sure this instance doesn't get destroyed inside self._func
self.acquire() self.acquire()
# put the function in the global namespace so that profile can find it self._profileSucceeded = False
assert 'globalProfileFunc' not in __builtin__.__dict__
__builtin__.globalProfileFunc = self._func
__builtin__.globalProfileResult = [None]
# set up the RAM file # if we're already profiling, just run the func and don't profile
_installProfileCustomFuncs(self._filename) if 'globalProfileFunc' in __builtin__.__dict__:
result = self._func()
self._wallClockDur = 0.
else:
# put the function in the global namespace so that profile can find it
__builtin__.globalProfileFunc = self._func
__builtin__.globalProfileResult = [None]
# do the profiling # set up the RAM file
Profile = profile.Profile _installProfileCustomFuncs(self._filename)
statement = 'globalProfileResult[0]=globalProfileFunc()'
sort = -1
retVal = None
# this is based on profile.run, the code is replicated here to allow us to # do the profiling
# eliminate a memory leak Profile = profile.Profile
prof = Profile() statement = 'globalProfileResult[0]=globalProfileFunc()'
# try to get wall-clock duration that is as accurate as possible sort = -1
startT = self.TrueClock.getShortTime() retVal = None
try:
prof = prof.run(statement)
except SystemExit:
pass
# try to get wall-clock duration that is as accurate as possible
endT = self.TrueClock.getShortTime()
# this has to be run immediately after profiling for the timings to be accurate
# tell the Profile object to generate output to the RAM file
prof.dump_stats(self._filename)
dur = endT - startT # this is based on profile.run, the code is replicated here to allow us to
# eliminate a memory leak
prof = Profile()
# try to get wall-clock duration that is as accurate as possible
startT = self.TrueClock.getShortTime()
try:
prof = prof.run(statement)
except SystemExit:
pass
# try to get wall-clock duration that is as accurate as possible
endT = self.TrueClock.getShortTime()
# this has to be run immediately after profiling for the timings to be accurate
# tell the Profile object to generate output to the RAM file
prof.dump_stats(self._filename)
# eliminate the memory leak dur = endT - startT
del prof.dispatcher
# and store the results # eliminate the memory leak
self._wallClockDur = dur del prof.dispatcher
# store the RAM file for later # and store the results
self._ramFile = _getProfileResultFileInfo(self._filename) self._wallClockDur = dur
# clean up the RAM file support
_removeProfileCustomFuncs(self._filename)
# clean up the globals # store the RAM file for later
result = globalProfileResult[0] self._ramFile = _getProfileResultFileInfo(self._filename)
del __builtin__.__dict__['globalProfileFunc'] # clean up the RAM file support
del __builtin__.__dict__['globalProfileResult'] _removeProfileCustomFuncs(self._filename)
# clean up the globals
result = globalProfileResult[0]
del __builtin__.__dict__['globalProfileFunc']
del __builtin__.__dict__['globalProfileResult']
self._profileSucceeded = True
self.release() self.release()
return result return result
def getWallClockDuration(self): def getWallClockDuration(self):
# this might not be accurate, it may include time taken up by other processes # this might not be accurate, it may include time taken up by other processes
return self._wallClockDur return self._wallClockDur
def profileSucceeded(self):
return self._profileSucceeded
def getResults(self, def getResults(self,
lines=80, lines=80,
sorts=['cumulative', 'time', 'calls'], sorts=['cumulative', 'time', 'calls'],
callInfo=False): callInfo=False):
# set up the RAM file if not self._profileSucceeded:
_installProfileCustomFuncs(self._filename) output = '%s: profiler already running, could not profile' % self._name
# install the stored RAM file from self.run() else:
_setProfileResultsFileInfo(self._filename, self._ramFile) # make sure the arguments will hash efficiently if callers provide different types
lines = int(lines)
sorts = list(sorts)
callInfo = bool(callInfo)
k = str((lines, sorts, callInfo))
if k in self._resultCache:
# we've already created this output string, get it from the cache
output = self._resultCache[k]
else:
# set up the RAM file
_installProfileCustomFuncs(self._filename)
# install the stored RAM file from self.run()
_setProfileResultsFileInfo(self._filename, self._ramFile)
# now extract human-readable output from the RAM file # now extract human-readable output from the RAM file
# capture print output to a string # capture print output to a string
sc = StdoutCapture() sc = StdoutCapture()
# print the info to stdout # print the info to stdout
s = pstats.Stats(self._filename) s = pstats.Stats(self._filename)
s.strip_dirs() s.strip_dirs()
for sort in sorts: for sort in sorts:
s.sort_stats(sort) s.sort_stats(sort)
s.print_stats(lines) s.print_stats(lines)
if callInfo: if callInfo:
s.print_callees(lines) s.print_callees(lines)
s.print_callers(lines) s.print_callers(lines)
# make a copy of the print output
output = sc.getString()
# restore stdout to what it was before # make a copy of the print output
sc.destroy() output = sc.getString()
# clean up the RAM file support # restore stdout to what it was before
_removeProfileCustomFuncs(self._filename) sc.destroy()
# clean up the RAM file support
_removeProfileCustomFuncs(self._filename)
# cache this result
self._resultCache[k] = output
return output return output

View File

@ -129,30 +129,32 @@ class TaskProfiler:
# set up for the next frame # set up for the next frame
if (self._task is not None) and taskMgr._hasProfiledDesignatedTask(): if (self._task is not None) and taskMgr._hasProfiledDesignatedTask():
session = taskMgr._getLastProfileSession() session = taskMgr._getLastProfileSession()
sessionDur = session.getWallClockDuration() # if we couldn't profile, throw this result out
namePattern = self._task.getNamePattern() if session.profileSucceeded():
if namePattern not in self._namePattern2tracker: sessionDur = session.getWallClockDuration()
self._namePattern2tracker[namePattern] = TaskTracker(namePattern) namePattern = self._task.getNamePattern()
tracker = self._namePattern2tracker[namePattern] if namePattern not in self._namePattern2tracker:
isSpike = False self._namePattern2tracker[namePattern] = TaskTracker(namePattern)
# do we have enough samples? tracker = self._namePattern2tracker[namePattern]
if tracker.getNumDurationSamples() > self._minSamples: isSpike = False
# was this a spike? # do we have enough samples?
if sessionDur > (tracker.getAvgDuration() * self._spikeThreshold): if tracker.getNumDurationSamples() > self._minSamples:
print 'sessionDur=%s' % sessionDur # was this a spike?
print 'avgDur=%s' % tracker.getAvgDuration() if sessionDur > (tracker.getAvgDuration() * self._spikeThreshold):
isSpike = True print 'sessionDur=%s' % sessionDur
avgSession = tracker.getAvgSession() print 'avgDur=%s' % tracker.getAvgDuration()
maxNSSession = tracker.getMaxNonSpikeSession() isSpike = True
self.notify.info('task CPU spike profile (%s):\n' avgSession = tracker.getAvgSession()
'== AVERAGE (%s wall-clock seconds)\n%s\n' maxNSSession = tracker.getMaxNonSpikeSession()
'== LONGEST NON-SPIKE (%s wall-clock seconds)\n%s\n' self.notify.info('task CPU spike profile (%s):\n'
'== SPIKE (%s wall-clock seconds)\n%s' % ( '== AVERAGE (%s wall-clock seconds)\n%s\n'
namePattern, '== LONGEST NON-SPIKE (%s wall-clock seconds)\n%s\n'
avgSession.getWallClockDuration(), avgSession.getResults(), '== SPIKE (%s wall-clock seconds)\n%s' % (
maxNSSession.getWallClockDuration(), maxNSSession.getResults(), namePattern,
sessionDur, session.getResults())) avgSession.getWallClockDuration(), avgSession.getResults(),
tracker.addProfileSession(session, isSpike) maxNSSession.getWallClockDuration(), maxNSSession.getResults(),
sessionDur, session.getResults()))
tracker.addProfileSession(session, isSpike)
# set up the next task # set up the next task
self._task = taskMgr._getRandomTask() self._task = taskMgr._getRandomTask()