From 7d9cd570dc52fe5a386362d7afc8367228937671 Mon Sep 17 00:00:00 2001 From: Darren Ranalli Date: Fri, 31 Oct 2008 21:10:31 +0000 Subject: [PATCH] working FrameProfiler --- direct/src/showbase/ProfileSession.py | 88 ++++++++++++------- direct/src/showbase/PythonUtil.py | 65 +++++++++++++- direct/src/task/FrameProfiler.py | 117 +++++++++++++++++++++++++- direct/src/task/TaskProfiler.py | 3 +- 4 files changed, 234 insertions(+), 39 deletions(-) diff --git a/direct/src/showbase/ProfileSession.py b/direct/src/showbase/ProfileSession.py index 8027c4655c..dc5e59a481 100755 --- a/direct/src/showbase/ProfileSession.py +++ b/direct/src/showbase/ProfileSession.py @@ -18,6 +18,11 @@ class PercentStats(pstats.Stats): # allows profiles to show timing based on percentages of duration of another profile self._totalTime = tt + def add(self, *args, **kArgs): + pstats.Stats.add(self, *args, **kArgs) + # DCR -- don't need to record filenames + self.files = [] + def print_stats(self, *amount): for filename in self.files: print filename @@ -95,9 +100,22 @@ class ProfileSession: self._logAfterProfile = logAfterProfile self._filenameBase = 'profileData-%s-%s' % (self._name, id(self)) self._refCount = 0 + # if true, accumulate profile results every time we run + # if false, throw out old results every time we run + self._aggregate = False + self._lines = 200 + self._sorts = ['cumulative', 'time', 'calls'] + self._callInfo = False + self._totalTime = None self._reset() self.acquire() + def getReference(self): + # call this when you want to store a new reference to this session that will + # manage its acquire/release reference count independently of an existing reference + self.acquire() + return self + def acquire(self): self._refCount += 1 def release(self): @@ -126,13 +144,6 @@ class ProfileSession: self._filename2ramFile = {} self._stats = None self._resultCache = {} - # if true, accumulate profile results every time we run - # if false, throw out old results every time we run - self._aggregate = False - self._lines = 200 - self._sorts = ['cumulative', 'time', 'calls'] - self._callInfo = False - self._totalTime = None def _getNextFilename(self): filename = '%s-%s' % (self._filenameBase, self._filenameCounter) @@ -147,15 +158,16 @@ class ProfileSession: self._reset() # if we're already profiling, just run the func and don't profile - if 'globalProfileFunc' in __builtin__.__dict__: + if 'globalProfileSessionFunc' in __builtin__.__dict__: + self.notify.warning('could not profile %s' % self._func) result = self._func() if self._duration is None: self._duration = 0. else: # put the function in the global namespace so that profile can find it assert callable(self._func) - __builtin__.globalProfileFunc = self._func - __builtin__.globalProfileResult = [None] + __builtin__.globalProfileSessionFunc = self._func + __builtin__.globalProfileSessionResult = [None] # set up the RAM file self._filenames.append(self._getNextFilename()) @@ -164,7 +176,7 @@ class ProfileSession: # do the profiling Profile = profile.Profile - statement = 'globalProfileResult[0]=globalProfileFunc()' + statement = 'globalProfileSessionResult[0]=globalProfileSessionFunc()' sort = -1 retVal = None @@ -196,9 +208,9 @@ class ProfileSession: _removeProfileCustomFuncs(filename) # clean up the globals - result = globalProfileResult[0] - del __builtin__.__dict__['globalProfileFunc'] - del __builtin__.__dict__['globalProfileResult'] + result = globalProfileSessionResult[0] + del __builtin__.__dict__['globalProfileSessionFunc'] + del __builtin__.__dict__['globalProfileSessionResult'] self._successfulProfiles += 1 @@ -268,6 +280,35 @@ class ProfileSession: def getTotalTime(self): return self._totalTime + def aggregate(self, other): + # pull in stats from another ProfileSession + other._compileStats() + self._compileStats() + self._stats.add(other._stats) + + def _compileStats(self): + # make sure our stats object exists and is up-to-date + statsChanged = (self._statFileCounter < len(self._filenames)) + + if self._stats is None: + for filename in self._filenames: + self._restoreRamFile(filename) + self._stats = PercentStats(*self._filenames) + self._statFileCounter = len(self._filenames) + for filename in self._filenames: + self._discardRamFile(filename) + else: + while self._statFileCounter < len(self._filenames): + filename = self._filenames[self._statFileCounter] + self._restoreRamFile(filename) + self._stats.add(filename) + self._discardRamFile(filename) + + if statsChanged: + self._stats.strip_dirs() + + return statsChanged + def getResults(self, lines=Default, sorts=Default, @@ -285,25 +326,8 @@ class ProfileSession: if totalTime is Default: totalTime = self._totalTime - # make sure our stats object exists and is up-to-date - statsChanged = (self._statFileCounter < len(self._filenames)) - - if self._stats is None: - for filename in self._filenames: - self._restoreRamFile(filename) - self._stats = PercentStats(*self._filenames) - self._statFileCounter = len(self._filenames) - for filename in self._filenames: - self._discardRamFile(filename) - else: - while self._statFileCounter < len(self._filenames): - filename = self._filenames[self._statFileCounter] - self._restoreRamFile(filename) - self._stats.add(filename) - self._discardRamFile(filename) - + statsChanged = self._compileStats() if statsChanged: - self._stats.strip_dirs() # throw out any cached result strings self._resultCache = {} diff --git a/direct/src/showbase/PythonUtil.py b/direct/src/showbase/PythonUtil.py index 30cb836bd5..b9c9861dd1 100644 --- a/direct/src/showbase/PythonUtil.py +++ b/direct/src/showbase/PythonUtil.py @@ -31,7 +31,7 @@ __all__ = ['enumerate', 'unique', 'indent', 'nonRepeatingRandomList', 'printStack', 'printReverseStack', 'listToIndex2item', 'listToItem2index', 'pandaBreak','pandaTrace','formatTimeCompact','DestructiveScratchPad', 'deeptype','getProfileResultString','StdoutCapture','StdoutPassthrough', -'Averager', 'getRepository', ] +'Averager', 'getRepository', 'formatTimeExact', ] import types import string @@ -2188,7 +2188,11 @@ def normalDistrib(a, b, gauss=random.gauss): Returns random number between a and b, using gaussian distribution, with mean=avg(a, b), and a standard deviation that fits ~99.7% of the curve - between a and b. Outlying results are clipped to a and b. + between a and b. + + For ease of use, outlying results are re-computed until result is in [a, b] + This should fit the remaining .3% of the curve that lies outside [a, b] + uniformly onto the curve inside [a, b] ------------------------------------------------------------------------ http://www-stat.stanford.edu/~naras/jsm/NormalDensity/NormalDensity.html @@ -2208,7 +2212,10 @@ def normalDistrib(a, b, gauss=random.gauss): In calculating our standard deviation, we divide (b-a) by 6, since the 99.7% figure includes 3 standard deviations _on_either_side_ of the mean. """ - return max(a, min(b, gauss((a+b)*.5, (b-a)/6.))) + while True: + r = gauss((a+b)*.5, (b-a)/6.) + if (r >= a) and (r <= b): + return r def weightedRand(valDict, rng=random.random): """ @@ -3629,6 +3636,54 @@ def formatTimeCompact(seconds): result += '%ss' % seconds return result +if __debug__: + ftc = formatTimeCompact + assert ftc(0) == '0s' + assert ftc(1) == '1s' + assert ftc(60) == '1m0s' + assert ftc(64) == '1m4s' + assert ftc(60*60) == '1h0m0s' + assert ftc(24*60*60) == '1d0h0m0s' + assert ftc(24*60*60 + 2*60*60 + 34*60 + 12) == '1d2h34m12s' + del ftc + +def formatTimeExact(seconds): + # like formatTimeCompact but leaves off '0 seconds', '0 minutes' etc. for + # times that are e.g. 1 hour, 3 days etc. + # returns string in format '1d3h22m43s' + result = '' + a = int(seconds) + seconds = a % 60 + a /= 60 + if a > 0: + minutes = a % 60 + a /= 60 + if a > 0: + hours = a % 24 + a /= 24 + if a > 0: + days = a + result += '%sd' % days + if hours or minutes or seconds: + result += '%sh' % hours + if minutes or seconds: + result += '%sm' % minutes + if seconds or result == '': + result += '%ss' % seconds + return result + +if __debug__: + fte = formatTimeExact + assert fte(0) == '0s' + assert fte(1) == '1s' + assert fte(2) == '2s' + assert fte(61) == '1m1s' + assert fte(60) == '1m' + assert fte(60*60) == '1h' + assert fte(24*60*60) == '1d' + assert fte((24*60*60) + (2 * 60)) == '1d0h2m' + del fte + class AlphabetCounter: # object that produces 'A', 'B', 'C', ... 'AA', 'AB', etc. def __init__(self): @@ -3733,6 +3788,9 @@ class Default: # useful for keyword arguments to virtual methods pass +def isInteger(n): + return type(n) in (types.IntType, types.LongType) + import __builtin__ __builtin__.Functor = Functor __builtin__.Stack = Stack @@ -3784,3 +3842,4 @@ __builtin__.HierarchyException = HierarchyException __builtin__.pdir = pdir __builtin__.deeptype = deeptype __builtin__.Default = Default +__builtin__.isInteger = isInteger diff --git a/direct/src/task/FrameProfiler.py b/direct/src/task/FrameProfiler.py index 9bd44c4ad3..11b4f85731 100755 --- a/direct/src/task/FrameProfiler.py +++ b/direct/src/task/FrameProfiler.py @@ -1,10 +1,39 @@ from direct.directnotify.DirectNotifyGlobal import directNotify from direct.fsm.StatePush import FunctionCall +from direct.showbase.PythonUtil import formatTimeExact, normalDistrib class FrameProfiler: notify = directNotify.newCategory('FrameProfiler') + # for precision, all times related to the profile/log schedule are stored as integers + Minute = 60 + Hour = 60 * Minute + Day = 24 * Hour + def __init__(self): + Hour = FrameProfiler.Hour + # how long to wait between frame profiles + self._period = 2 * FrameProfiler.Minute + # used to prevent profile from being taken exactly every 'period' seconds + self._jitterMagnitude = self._period * .75 + # when to log output + # each entry must be an integer multiple of all previous entries + # as well as an integer multiple of the period + self._logSchedule = [ 1 * FrameProfiler.Hour, + 4 * FrameProfiler.Hour, + 12 * FrameProfiler.Hour, + 1 * FrameProfiler.Day, + ] # day schedule proceeds as 1, 2, 4, 8 days, etc. + for t in self._logSchedule: + assert isInteger(t) + # make sure the period is evenly divisible into each element of the log schedule + assert (t % self._period) == 0 + # make sure each element of the schedule is evenly divisible into each subsequent element + for i in xrange(len(self._logSchedule)): + e = self._logSchedule[i] + for j in xrange(i, len(self._logSchedule)): + assert (self._logSchedule[j] % e) == 0 + assert isInteger(self._period) self._enableFC = FunctionCall(self._setEnabled, taskMgr.getProfileFramesSV()) def destroy(self): @@ -13,6 +42,90 @@ class FrameProfiler: def _setEnabled(self, enabled): if enabled: - print 'FrameProfiler enabled' + self._startTime = globalClock.getFrameTime() + self._profileCounter = 0 + self._jitter = None + self._period2aggregateProfile = {} + self._lastSession = None + # don't profile process startup + self._task = taskMgr.doMethodLater(self._period, self._startProfiling, + 'FrameProfilerStart-%s' % serialNum()) else: - print 'FrameProfiler disabled' + self._task.remove() + del self._task + for session in self._period2aggregateProfile.itervalues: + session.release() + del self._period2aggregateProfile + if self._lastSession: + self._lastSession.release() + del self._lastSession + + def _startProfiling(self, task): + self._scheduleNextProfile() + return task.done + + def _scheduleNextProfile(self): + self._profileCounter += 1 + self._timeElapsed = self._profileCounter * self._period + assert isInteger(self._timeElapsed) + time = self._startTime + self._timeElapsed + + # vary the actual delay between profiles by a random amount to prevent interaction + # with periodic events + jitter = self._jitter + if jitter is None: + jitter = normalDistrib(-self._jitterMagnitude, self._jitterMagnitude) + time += jitter + else: + time -= jitter + jitter = None + self._jitter = jitter + + self._lastSession = taskMgr.getProfileSession('FrameProfile-%s' % serialNum()) + taskMgr.profileFrames(num=1, session=self._lastSession) + + delay = max(time - globalClock.getFrameTime(), 0.) + self._task = taskMgr.doMethodLater(delay, self._frameProfileTask, + 'FrameProfiler-%s' % serialNum()) + + def _frameProfileTask(self, task): + if self._lastSession: + p2ap = self._period2aggregateProfile + # always add this profile to the first aggregated profile + period = self._logSchedule[0] + if period not in self._period2aggregateProfile: + self._lastSession.setLines(500) + p2ap[period] = self._lastSession.getReference() + else: + p2ap[period].aggregate(self._lastSession) + # log profiles when it's time, and aggregate them upwards into the + # next-larger profile + for period in self._logSchedule: + if (self._timeElapsed % period) == 0: + ap = p2ap[period] + self.notify.info('aggregate profile of sampled frames over last %s\n%s' % + (formatTimeExact(period), ap.getResults())) + # aggregate this profile into the next larger profile + nextPeriod = period * 2 + # make sure the next larger log period is in the schedule + if period == self._logSchedule[-1]: + self._logSchedule.append(nextPeriod) + if nextPeriod not in p2ap: + p2ap[nextPeriod] = p2ap[period].getReference() + else: + p2ap[nextPeriod].aggregate(p2ap[period]) + # this profile is now represented in the next larger profile + # throw it out + p2ap[period].release() + del p2ap[period] + else: + # current time is not divisible evenly into selected period, and all higher + # periods are multiples of this one + break + + # always release the last-recorded profile + self._lastSession.release() + self._lastSession = None + + self._scheduleNextProfile() + return task.done diff --git a/direct/src/task/TaskProfiler.py b/direct/src/task/TaskProfiler.py index 921bb5849b..7569e3dce4 100755 --- a/direct/src/task/TaskProfiler.py +++ b/direct/src/task/TaskProfiler.py @@ -65,8 +65,7 @@ class TaskTracker: if storeAvg: if self._avgSession: self._avgSession.release() - session.acquire() - self._avgSession = session + self._avgSession = session.getReference() def getAvgDuration(self): return self._durationAverager.getAverage()