working FrameProfiler

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 = {}
 

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

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:
+            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:
-            print 'FrameProfiler disabled'
+            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

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()