added task profiler

direct/src/showbase/PythonUtil.py

@@ -30,7 +30,8 @@ __all__ = ['enumerate', 'unique', 'indent', 'nonRepeatingRandomList',
 'nullGen', 'loopGen', 'makeFlywheelGen', 'flywheel', 'choice',
 'printStack', 'printReverseStack', 'listToIndex2item', 'listToItem2index',
 'pandaBreak','pandaTrace','formatTimeCompact','DestructiveScratchPad',
-'deeptype',]
+'deeptype','getProfileResultString','StdoutCapture','StdoutPassthrough',
+'Averager',]
 
 import types
 import string
@@ -794,12 +795,47 @@ def binaryRepr(number, max_length = 32):
     digits = digits [digits.index (1):]
     return string.join (map (repr, digits), '')
 
+class StdoutCapture:
+    # redirects stdout to a string
+    def __init__(self):
+        self._oldStdout = sys.stdout
+        sys.stdout = self
+        self._string = ''
+    def destroy(self):
+        sys.stdout = self._oldStdout
+        del self._oldStdout
+
+    def getString(self):
+        return self._string
+
+    # internal
+    def write(self, string):
+        self._string = ''.join([self._string, string])
+
+class StdoutPassthrough(StdoutCapture):
+    # like StdoutCapture but also allows output to go through to the OS as normal
+
+    # internal
+    def write(self, string):
+        self._string = ''.join([self._string, string])
+        self._oldStdout.write(string)
+
 # constant profile defaults
 PyUtilProfileDefaultFilename = 'profiledata'
 PyUtilProfileDefaultLines = 80
 PyUtilProfileDefaultSorts = ['cumulative', 'time', 'calls']
 
-def profile(callback, name, terse):
+_ProfileResultStr = ''
+
+def getProfileResultString():
+    # if you called profile with 'log' not set to True,
+    # you can call this function to get the results as
+    # a string
+    global _ProfileResultStr
+    return _ProfileResultStr
+
+def profile(callback, name, terse, log=True):
+    global _ProfileResultStr
     import __builtin__
     if 'globalProfileFunc' in __builtin__.__dict__:
         # rats. Python profiler is not re-entrant...
@@ -811,10 +847,20 @@ def profile(callback, name, terse):
             ))
         return
     __builtin__.globalProfileFunc = callback
-    print '***** START PROFILE: %s *****' % name
+    __builtin__.globalProfileResult = [None]
-    startProfile(cmd='globalProfileFunc()', callInfo=(not terse))
+    prefix = '***** START PROFILE: %s *****' % name
-    print '***** END PROFILE: %s *****' % name
+    if log:
+        print prefix
+    startProfile(cmd='globalProfileResult[0]=globalProfileFunc()', callInfo=(not terse), silent=not log)
+    suffix = '***** END PROFILE: %s *****' % name
+    if log:
+        print suffix
+    else:
+        _ProfileResultStr = '%s\n%s\n%s' % (prefix, _ProfileResultStr, suffix)
+    result = globalProfileResult[0]
     del __builtin__.__dict__['globalProfileFunc']
+    del __builtin__.__dict__['globalProfileResult']
+    return result
 
 def profiled(category=None, terse=False):
     """ decorator for profiling functions
@@ -883,12 +929,14 @@ def startProfile(filename=PyUtilProfileDefaultFilename,
     filename = '%s.%s' % (filename, randUint31())
     import profile
     profile.run(cmd, filename)
-    if not silent:
+    if silent:
+        extractProfile(filename, lines, sorts, callInfo)
+    else:
         printProfile(filename, lines, sorts, callInfo)
     import os
     os.remove(filename)
 
-# call this to see the results again
+# call these to see the results again, as a string or in the log
 def printProfile(filename=PyUtilProfileDefaultFilename,
                  lines=PyUtilProfileDefaultLines,
                  sorts=PyUtilProfileDefaultSorts,
@@ -903,6 +951,18 @@ def printProfile(filename=PyUtilProfileDefaultFilename,
             s.print_callees(lines)
             s.print_callers(lines)
 
+# same args as printProfile
+def extractProfile(*args, **kArgs):
+    global _ProfileResultStr
+    # capture print output
+    sc = StdoutCapture()
+    # print the profile output, redirected to the result string
+    printProfile(*args, **kArgs)
+    # make a copy of the print output
+    _ProfileResultStr = sc.getString()
+    # restore stdout to what it was before
+    sc.destroy()
+
 def getSetterName(valueName, prefix='set'):
     # getSetterName('color') -> 'setColor'
     # getSetterName('color', 'get') -> 'getColor'
@@ -927,8 +987,14 @@ class Functor:
         self._function = function
         self._args = args
         self._kargs = kargs
+        if hasattr(self._function, '__name__'):
             self.__name__ = self._function.__name__
+        else:
+            self.__name__ = str(itype(self._function))
+        if hasattr(self._function, '__doc__'):
             self.__doc__ = self._function.__doc__
+        else:
+            self.__doc__ = self.__name__
 
     def destroy(self):
         del self._function
@@ -1714,6 +1780,19 @@ def average(*args):
         val += arg
     return val / len(args)
 
+class Averager:
+    def __init__(self, name):
+        self._name = name
+        self._total = 0.
+        self._count = 0
+    def addValue(self, value):
+        self._total += value
+        self._count += 1
+    def getAverage(self):
+        return self._total / self._count
+    def getCount(self):
+        return self._count
+
 def addListsByValue(a, b):
     """
     returns a new array containing the sums of the two array arguments

direct/src/task/Task.py

@@ -19,6 +19,7 @@ import time
 import fnmatch
 import string
 import signal
+import random
 try:
     Dtool_PreloadDLL("libp3heapq")
     from libp3heapq import heappush, heappop, heapify
@@ -161,6 +162,13 @@ class Task:
         self.time = currentTime - self.starttime
         self.frame = currentFrame - self.startframe
 
+    def getNamePattern(self, taskName=None):
+        # get a version of the task name that doesn't contain any numbers
+        digits = '0123456789'
+        if taskName is None:
+            taskName = self.name
+        return ''.join([c for c in taskName if c not in digits])
+
     def setupPStats(self):
         if __debug__ and TaskManager.taskTimerVerbose and not self.pstats:
             # Get the PStats name for the task.  By convention,
@@ -358,6 +366,8 @@ class TaskManager:
     # multiple of average frame duration
     DefTaskDurationWarningThreshold = 40.
 
+    _DidTests = False
+
     def __init__(self):
         self.running = 0
         self.stepping = 0
@@ -370,6 +380,12 @@ class TaskManager:
         self._profileFrames = False
         self.MaxEpockSpeed = 1.0/30.0;   
 
+        # this will be set when it's safe to import StateVar
+        self._profileTasks = None
+        self._taskProfiler = None
+        self._profileTaskId = None
+        self._profileDt = None
+        self._lastProfileResultString = None
 
         # We copy this value in from __builtins__ when it gets set.
         # But since the TaskManager might have to run before it gets
@@ -404,6 +420,8 @@ class TaskManager:
         self.add(self.__doLaterProcessor, "doLaterProcessor", -10)
 
     def destroy(self):
+        if self._taskProfiler:
+            self._taskProfiler.destroy()
         del self.nameDict
         del self.trueClock
         del self.globalClock
@@ -722,15 +740,27 @@ class TaskManager:
 
     def __executeTask(self, task):
         task.setCurrentTimeFrame(self.currentTime, self.currentFrame)
+
+        doProfile = (task.id == self._profileTaskId)
+            
         if not self.taskTimerVerbose:
             startTime = self.trueClock.getShortTime()
             
             # don't record timing info
+            if doProfile:
+                ret = profile(Functor(task, *task.extraArgs),
+                              'TASK_PROFILE:%s' % task.name, True, log=False)
+            else:
                 ret = task(*task.extraArgs)
             endTime = self.trueClock.getShortTime()
             
             # Record the dt
             dt = endTime - startTime
+            if doProfile:
+                # if we profiled, record the measured duration but don't pollute the task's
+                # normal duration
+                self._profileDt = dt
+                dt = task.avgDt
             task.dt = dt
 
         else:
@@ -738,6 +768,10 @@ class TaskManager:
             if task.pstats:
                 task.pstats.start()
             startTime = self.trueClock.getShortTime()
+            if doProfile:
+                ret = profile(Functor(task, *task.extraArgs),
+                              'profiled-task-%s' % task.name, True, log=False)
+            else:
                 ret = task(*task.extraArgs)
             endTime = self.trueClock.getShortTime()
             if task.pstats:
@@ -745,6 +779,11 @@ class TaskManager:
 
             # Record the dt
             dt = endTime - startTime
+            if doProfile:
+                # if we profiled, record the measured duration but don't pollute the task's
+                # normal duration
+                self._profileDt = dt
+                dt = task.avgDt
             task.dt = dt
 
             # See if this is the new max
@@ -758,6 +797,9 @@ class TaskManager:
             else:
                 task.avgDt = 0
 
+        if doProfile:
+            self._lastProfileResultString = self._getProfileResultString()
+
         # warn if the task took too long
         if self.warnTaskDuration and self.globalClock:
             avgFrameRate = self.globalClock.getAverageFrameRate()
@@ -889,6 +931,65 @@ class TaskManager:
             result = self.step(*args, **kArgs)
         return result
 
+    def getProfileTasks(self):
+        return self._profileTasks.get()
+
+    def getProfileTasksSV(self):
+        return self._profileTasks
+
+    def setProfileTasks(self, profileTasks):
+        self._profileTasks.set(profileTasks)
+        if (not self._taskProfiler) and profileTasks:
+            # import here due to import dependencies
+            from direct.task.TaskProfiler import TaskProfiler
+            self._taskProfiler = TaskProfiler()
+
+    def _setProfileTask(self, task):
+        self._profileTaskId = task.id
+        self._profileDt = None
+        self._lastProfileResultString = None
+
+    def _getTaskProfileDt(self):
+        return self._profileDt
+
+    def _getLastProfileResultString(self):
+        return self._lastProfileResultString
+
+    def _getRandomTask(self):
+        numTasks = 0
+        for name in self.nameDict.iterkeys():
+            numTasks += len(self.nameDict[name])
+        numDoLaters = len(self.__doLaterList)
+        if random.random() < (numDoLaters / float(numTasks + numDoLaters)):
+            # grab a doLater that will most likely trigger in the next frame
+            tNow = globalClock.getFrameTime()
+            avgFrameRate = globalClock.getAverageFrameRate()
+            if avgFrameRate < .00001:
+                avgFrameDur = 0.
+            else:
+                avgFrameDur = (1. / globalClock.getAverageFrameRate())
+            tNext = tNow + avgFrameDur
+            # binary search to find doLaters that are likely to trigger on the next frame
+            curIndex = int(numDoLaters / 2)
+            rangeStart = 0
+            rangeEnd = numDoLaters
+            while True:
+                if tNext < self.__doLaterList[curIndex].wakeTime:
+                    rangeEnd = curIndex
+                else:
+                    rangeStart = curIndex
+                prevIndex = curIndex
+                curIndex = int((rangeStart + rangeEnd) / 2)
+                if curIndex == prevIndex:
+                    break
+            index = curIndex
+            task = self.__doLaterList[random.randrange(index+1)]
+        else:
+            # grab a task
+            name = random.choice(self.nameDict.keys())
+            task = random.choice(self.nameDict[name])
+        return task
+
     def step(self):
         # assert TaskManager.notify.debug('step: begin')
         self.currentTime, self.currentFrame = self.__getTimeFrame()
@@ -952,6 +1053,16 @@ class TaskManager:
 
 
     def run(self):
+        # do things that couldn't be done earlier because of import dependencies
+        if (not TaskManager._DidTests) and __debug__:
+            TaskManager._DidTests = True
+            self._runTests()
+
+        if not self._profileTasks:
+            from direct.fsm.StatePush import StateVar
+            self._profileTasks = StateVar(False)
+            self.setProfileTasks(getBase().config.GetBool('profile-task-spikes', 0))
+
         # Set the clock to have last frame's time in case we were
         # Paused at the prompt for a long time
         if self.globalClock:
@@ -1279,21 +1390,8 @@ class TaskManager:
             dtfmt % (totalAvgDt*1000),))
         return cont
 
-
+    def _runTests(self):
-
+        if __debug__:
-# These constants are moved to the top level of the module,
-# to make it easier for legacy code.  In general though, putting
-# constants at the top level of a module is deprecated.
-
-exit  = Task.exit
-done  = Task.done
-cont  = Task.cont
-again = Task.again
-
-
-if __debug__:
-    # keep everything in a function namespace so it's easier to clean up
-    def runTests():
             tm = TaskManager()
             # looks like nothing runs on the first frame...?
             # step to get past the first frame
@@ -1779,8 +1877,19 @@ if __debug__:
             tm.destroy()
             del tm
 
-    runTests()
+
-    del runTests
+# These constants are moved to the top level of the module,
+# to make it easier for legacy code.  In general though, putting
+# constants at the top level of a module is deprecated.
+
+exit  = Task.exit
+done  = Task.done
+cont  = Task.cont
+again = Task.again
+
+
+if __debug__:
+    pass # 'if __debug__' is hint for CVS diff output
 
 """