From 732b4f00671ca87d5e528022deb61f5d2aca0332 Mon Sep 17 00:00:00 2001 From: Darren Ranalli Date: Tue, 14 Oct 2008 01:52:51 +0000 Subject: [PATCH] print profile stats as percentages, makes profile CPU-independent --- direct/src/showbase/ProfileSession.py | 57 ++++++++++++++++++++++++++- direct/src/task/TaskProfiler.py | 38 ++++++++---------- 2 files changed, 73 insertions(+), 22 deletions(-) diff --git a/direct/src/showbase/ProfileSession.py b/direct/src/showbase/ProfileSession.py index 9cce1b8cea..3d02a05499 100755 --- a/direct/src/showbase/ProfileSession.py +++ b/direct/src/showbase/ProfileSession.py @@ -9,6 +9,61 @@ import pstats from StringIO import StringIO 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 print_stats(self, *amount): + for filename in self.files: + print filename + if self.files: print + indent = ' ' * 8 + for func in self.top_level: + print indent, func_get_function_name(func) + + print indent, self.total_calls, "function calls", + if self.total_calls != self.prim_calls: + print "(%d primitive calls)" % self.prim_calls, + # DCR + #print "in %.3f CPU seconds" % self.total_tt + print "in %s CPU milliseconds" % (self.total_tt * 1000.) + print + width, list = self.get_print_list(amount) + if list: + self.print_title() + for func in list: + self.print_line(func) + print + print + return self + + @staticmethod + def f8(x): + return "%7.2f%%" % (x*100.) + + @staticmethod + def func_std_string(func_name): # match what old profile produced + return "%s:%d(%s)" % func_name + + def print_line(self, func): + cc, nc, tt, ct, callers = self.stats[func] + c = str(nc) + d = self.total_tt + f8 = PercentStats.f8 + if nc != cc: + c = c + '/' + str(cc) + print c.rjust(9), + print f8(tt/d), + if nc == 0: + print ' '*8, + else: + print f8((tt/nc)/d), + print f8(ct/d), + if cc == 0: + print ' '*8, + else: + print f8((ct/cc)/d), + print PercentStats.func_std_string(func) + class ProfileSession: # class that encapsulates a profile of a single callable using Python's standard # 'profile' module @@ -161,7 +216,7 @@ class ProfileSession: if self._stats is None: for filename in self._filenames: self._restoreRamFile(filename) - self._stats = pstats.Stats(*self._filenames) + self._stats = PercentStats(*self._filenames) self._statFileCounter = len(self._filenames) for filename in self._filenames: self._discardRamFile(filename) diff --git a/direct/src/task/TaskProfiler.py b/direct/src/task/TaskProfiler.py index 9cfe581730..3f90df0a75 100755 --- a/direct/src/task/TaskProfiler.py +++ b/direct/src/task/TaskProfiler.py @@ -34,23 +34,21 @@ class TaskTracker: def _checkSpike(self, session): duration = session.getDuration() isSpike = False - # was it long enough to show up on a printout? - if duration >= .001: - # do we have enough samples? - if self.getNumDurationSamples() > self.MinSamples: - # was this a spike? - if duration > (self.getAvgDuration() * self.SpikeThreshold): - isSpike = True - avgSession = self.getAvgSession() - maxNSSession = self.getMaxNonSpikeSession() - self.notify.info('task CPU spike profile (%s):\n' - '== AVERAGE (%s seconds)\n%s\n' - '== LONGEST NON-SPIKE (%s seconds)\n%s\n' - '== SPIKE (%s seconds)\n%s' % ( - self._namePrefix, - avgSession.getDuration(), avgSession.getResults(), - maxNSSession.getDuration(), maxNSSession.getResults(), - duration, session.getResults())) + # do we have enough samples? + if self.getNumDurationSamples() > self.MinSamples: + # was this a spike? + 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())) return isSpike def addProfileSession(self, session): isSpike = self._checkSpike(session) @@ -100,12 +98,10 @@ class TaskTracker: def log(self): if self._avgSession: self.notify.info('task CPU profile (%s):\n' - '== AVERAGE (%s seconds)\n%s\n' - '== LONGEST NON-SPIKE (%s seconds)\n%s' % ( + '== AVERAGE\n%s\n' + '== LONGEST NON-SPIKE\n%s' % ( self._namePrefix, - self._avgSession.getDuration(), self._avgSession.getResults(), - self._maxNonSpikeSession.getDuration(), self._maxNonSpikeSession.getResults(), )) else: