From 232583858c58a4f020c7a3c010941d41ee49c616 Mon Sep 17 00:00:00 2001 From: Darren Ranalli Date: Tue, 14 Oct 2008 21:07:07 +0000 Subject: [PATCH] show timings as percentages, don't display max-non-spike profiles, output easier to scan --- direct/src/showbase/ProfileSession.py | 45 +++++++++++++++------- direct/src/task/TaskProfiler.py | 55 +++++++-------------------- 2 files changed, 46 insertions(+), 54 deletions(-) diff --git a/direct/src/showbase/ProfileSession.py b/direct/src/showbase/ProfileSession.py index 3d02a05499..e066425d35 100755 --- a/direct/src/showbase/ProfileSession.py +++ b/direct/src/showbase/ProfileSession.py @@ -12,6 +12,11 @@ import marshal class PercentStats(pstats.Stats): # prints more useful output when sampled durations are shorter than a millisecond # lots of this is copied from Python's pstats.py + def setTotalTime(self, tt): + # use this to set 'total time' to base time percentages on + # allows profiles to show timing based on percentages of duration of another profile + self._totalTime = tt + def print_stats(self, *amount): for filename in self.files: print filename @@ -26,6 +31,8 @@ class PercentStats(pstats.Stats): # DCR #print "in %.3f CPU seconds" % self.total_tt print "in %s CPU milliseconds" % (self.total_tt * 1000.) + if self._totalTime != self.total_tt: + print indent, 'percentages are of %s CPU milliseconds' % (self._totalTime * 1000) print width, list = self.get_print_list(amount) if list: @@ -33,12 +40,15 @@ class PercentStats(pstats.Stats): for func in list: self.print_line(func) print - print + # DCR + #print return self - @staticmethod - def f8(x): - return "%7.2f%%" % (x*100.) + def f8(self, x): + if self._totalTime == 0.: + # profiling was too quick for clock resolution... + return ' Inf%' + return "%7.2f%%" % ((x*100.) / self._totalTime) @staticmethod def func_std_string(func_name): # match what old profile produced @@ -47,21 +57,23 @@ class PercentStats(pstats.Stats): def print_line(self, func): cc, nc, tt, ct, callers = self.stats[func] c = str(nc) - d = self.total_tt - f8 = PercentStats.f8 + # DCR + f8 = self.f8 if nc != cc: c = c + '/' + str(cc) print c.rjust(9), - print f8(tt/d), + print f8(tt), if nc == 0: print ' '*8, else: - print f8((tt/nc)/d), - print f8(ct/d), + print f8(tt/nc), + print f8(ct), if cc == 0: print ' '*8, else: - print f8((ct/cc)/d), + print f8(ct/cc), + # DCR + #print func_std_string(func) print PercentStats.func_std_string(func) class ProfileSession: @@ -204,9 +216,10 @@ class ProfileSession: del self._filename2ramFile[filename] def getResults(self, - lines=80, + lines=200, sorts=['cumulative', 'time', 'calls'], - callInfo=False): + callInfo=False, + totalTime=None): if not self.profileSucceeded(): output = '%s: profiler already running, could not profile' % self._name else: @@ -232,11 +245,15 @@ class ProfileSession: # throw out any cached result strings self._resultCache = {} + if totalTime is None: + totalTime = self._stats.total_tt + # 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)) + totalTime = float(totalTime) + k = str((lines, sorts, callInfo, totalTime)) if k in self._resultCache: # we've already created this output string, get it from the cache output = self._resultCache[k] @@ -248,6 +265,8 @@ class ProfileSession: # print the info to stdout s = self._stats + # make sure our percentages are relative to the correct total time + s.setTotalTime(totalTime) for sort in sorts: s.sort_stats(sort) s.print_stats(lines) diff --git a/direct/src/task/TaskProfiler.py b/direct/src/task/TaskProfiler.py index 3f90df0a75..fb048d431d 100755 --- a/direct/src/task/TaskProfiler.py +++ b/direct/src/task/TaskProfiler.py @@ -11,7 +11,6 @@ class TaskTracker: self._namePrefix = namePrefix self._durationAverager = Averager('%s-durationAverager' % namePrefix) self._avgSession = None - self._maxNonSpikeSession = None if TaskTracker.MinSamples is None: # number of samples required before spikes start getting identified TaskTracker.MinSamples = config.GetInt('profile-task-spike-min-samples', 30) @@ -25,10 +24,7 @@ class TaskTracker: self._durationAverager.reset() if self._avgSession: self._avgSession.release() - if self._maxNonSpikeSession: - self._maxNonSpikeSession.release() self._avgSession = None - self._maxNonSpikeSession = None def getNamePrefix(self, namePrefix): return self._namePrefix def _checkSpike(self, session): @@ -40,51 +36,33 @@ class TaskTracker: if duration > (self.getAvgDuration() * self.SpikeThreshold): isSpike = True avgSession = self.getAvgSession() - maxNSSession = self.getMaxNonSpikeSession() - self.notify.info('task CPU spike profile (%s):\n' - '== AVERAGE\n%s\n' - '== LONGEST NON-SPIKE\n%s\n' - '== SPIKE\n%s' % ( - self._namePrefix, - avgSession.getResults(), - maxNSSession.getResults(), - session.getResults())) + s = '\n%s task CPU spike profile (%s) %s\n' % ('=' * 30, self._namePrefix, '=' * 30) + s += ('~' * 60) + '\n' + for sorts in (['cumulative'], ['time'], ['calls']): + s += ('-- AVERAGE --\n%s' + '-- SPIKE --\n%s' % ( + avgSession.getResults(sorts=sorts, totalTime=duration), + session.getResults(sorts=sorts))) + self.notify.info(s) return isSpike def addProfileSession(self, session): isSpike = self._checkSpike(session) duration = session.getDuration() self._durationAverager.addValue(duration) - if self.getNumDurationSamples() == self.MinSamples: - # if we just collected enough samples to check for spikes, see if - # our max 'non-spike' session collected so far counts as a spike - # and if so, log it - if self._checkSpike(self._maxNonSpikeSession): - self._maxNonSpikeSession = self._avgSession storeAvg = True - storeMaxNS = True if self._avgSession is not None: avgDur = self.getAvgDuration() if abs(self._avgSession.getDuration() - avgDur) < abs(duration - avgDur): # current avg data is more average than this new sample, keep the data we've # already got stored storeAvg = False - if isSpike: - storeMaxNS = False - else: - if (self._maxNonSpikeSession is not None and - self._maxNonSpikeSession.getDuration() > duration): - storeMaxNS = False if storeAvg: if self._avgSession: self._avgSession.release() session.acquire() self._avgSession = session - if storeMaxNS: - if self._maxNonSpikeSession: - self._maxNonSpikeSession.release() - session.acquire() - self._maxNonSpikeSession = session + def getAvgDuration(self): return self._durationAverager.getAverage() def getNumDurationSamples(self): @@ -92,18 +70,13 @@ class TaskTracker: def getAvgSession(self): # returns profile session for closest-to-average sample return self._avgSession - def getMaxNonSpikeSession(self): - # returns profile session for closest-to-average sample - return self._maxNonSpikeSession def log(self): if self._avgSession: - self.notify.info('task CPU profile (%s):\n' - '== AVERAGE\n%s\n' - '== LONGEST NON-SPIKE\n%s' % ( - self._namePrefix, - self._avgSession.getResults(), - self._maxNonSpikeSession.getResults(), - )) + s = 'task CPU profile (%s):\n' % self._namePrefix + s += ('~' * 60) + '\n' + for sorts in (['cumulative'], ['time'], ['calls']): + s += self._avgSession.getResults(sorts=sorts) + self.notify.info(s) else: self.notify.info('task CPU profile (%s): no data collected' % self._namePrefix)