groundwork for FrameProfiler

direct/src/showbase/ProfileSession.py

@@ -1,4 +1,5 @@
 from pandac.libpandaexpressModules import TrueClock
+from direct.directnotify.DirectNotifyGlobal import directNotify
 from direct.showbase.PythonUtil import (
     StdoutCapture, _installProfileCustomFuncs,_removeProfileCustomFuncs,
     _profileWithoutGarbageLeak, _getProfileResultFileInfo, _setProfileResultsFileInfo,
@@ -84,15 +85,14 @@ class ProfileSession:
     # 
     # implementation sidesteps memory leak in Python profile module,
     # and redirects file output to RAM file for efficiency
-    DefaultFilename = 'profilesession'
-    DefaultLines = 80
-    DefaultSorts = ['cumulative', 'time', 'calls']
-
     TrueClock = TrueClock.getGlobalPtr()
     
-    def __init__(self, func, name):
+    notify = directNotify.newCategory("ProfileSession")
+
+    def __init__(self, name, func=None, logAfterProfile=False):
         self._func = func
         self._name = name
+        self._logAfterProfile = logAfterProfile
         self._filenameBase = 'profileData-%s-%s' % (self._name, id(self))
         self._refCount = 0
         self._reset()
@@ -126,17 +126,24 @@ 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)
         self._filenameCounter += 1
         return filename
 
-    def run(self, aggregate=True):
+    def run(self):
         # make sure this instance doesn't get destroyed inside self._func
         self.acquire()
 
-        if not aggregate:
+        if not self._aggregate:
             self._reset()
 
         # if we're already profiling, just run the func and don't profile
@@ -146,6 +153,7 @@ class ProfileSession:
                 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]
 
@@ -194,6 +202,9 @@ class ProfileSession:
 
             self._successfulProfiles += 1
             
+            if self._logAfterProfile:
+                self.notify.info(self.getResults())
+
         self.release()
         return result
 
@@ -214,15 +225,66 @@ class ProfileSession:
         _removeProfileCustomFuncs(filename)
         # and discard it
         del self._filename2ramFile[filename]
+
+    def setName(self, name):
+        self._name = name
+    def getName(self):
+        return self._name
+
+    def setFunc(self, func):
+        self._func = func
+    def getFunc(self):
+        return self._func
+
+    def setAggregate(self, aggregate):
+        self._aggregate = aggregate
+    def getAggregate(self):
+        return self._aggregate
+
+    def setLogAfterProfile(self, logAfterProfile):
+        self._logAfterProfile = logAfterProfile
+    def getLogAfterProfile(self):
+        return self._logAfterProfile
     
+    def setLines(self, lines):
+        self._lines = lines
+    def getLines(self):
+        return self._lines
+
+    def setSorts(self, sorts):
+        self._sorts = sorts
+    def getSorts(self):
+        return self._sorts
+
+    def setShowCallInfo(self, showCallInfo):
+        self._showCallInfo = showCallInfo
+    def getShowCallInfo(self):
+        return self._showCallInfo
+
+    def setTotalTime(self, totalTime=None):
+        self._totalTime = totalTime
+    def resetTotalTime(self):
+        self._totalTime = None
+    def getTotalTime(self):
+        return self._totalTime
+
     def getResults(self,
-                   lines=200,
-                   sorts=['cumulative', 'time', 'calls'],
-                   callInfo=False,
-                   totalTime=None):
+                   lines=Default,
+                   sorts=Default,
+                   callInfo=Default,
+                   totalTime=Default):
         if not self.profileSucceeded():
             output = '%s: profiler already running, could not profile' % self._name
         else:
+            if lines is Default:
+                lines = self._lines
+            if sorts is Default:
+                sorts = self._sorts
+            if callInfo is Default:
+                callInfo = self._callInfo
+            if totalTime is Default:
+                totalTime = self._totalTime
+            
             # make sure our stats object exists and is up-to-date
             statsChanged = (self._statFileCounter < len(self._filenames))
 

direct/src/showbase/PythonUtil.py

@@ -3751,6 +3751,10 @@ def pandaBreak(dotpath, linenum, temporary = 0, cond = None):
             filename="%s\\%s"%(filename,d)
         globalPdb.set_break(filename+".py", linenum, temporary, cond)
             
+class Default:
+    # represents 'use the default value'
+    # useful for keyword arguments to virtual methods
+    pass
 
 import __builtin__
 __builtin__.Functor = Functor
@@ -3802,3 +3806,4 @@ __builtin__.logBlock = logBlock
 __builtin__.HierarchyException = HierarchyException
 __builtin__.pdir = pdir
 __builtin__.deeptype = deeptype
+__builtin__.Default = Default

direct/src/task/TaskNew.py

@@ -111,12 +111,12 @@ class TaskManager:
         self.fKeyboardInterrupt = False
         self.interruptCount = 0
 
-        self._profileFrames = False
+        self._frameProfileQueue = Queue()
 
-        # this will be set when it's safe to import StateVar
+        # this will be set when it's safe to import StateVar 
         self._profileTasks = None
         self._taskProfiler = None
-        self._profileInfo = ScratchPad(
+        self._taskProfileInfo = ScratchPad(
             taskId = None,
             profiled = False,
             session = None,
@@ -130,6 +130,7 @@ class TaskManager:
         self.setProfileTasks(ConfigVariableBool('profile-task-spikes', 0).getValue())
 
     def destroy(self):
+        self._frameProfileQueue.clear()
         self.mgr.cleanup()
 
     def setClock(self, clockObject):
@@ -441,9 +442,14 @@ class TaskManager:
             self.running = True
             while self.running:
                 try:
-                    if self._profileFrames:
-                        self._profileFrames = False
-                        self._doProfiledFrames()
+                    if len(self._frameProfileQueue):
+                        numFrames, session = self._frameProfileQueue.pop()
+                        def _profileFunc(numFrames=numFrames):
+                            self._doProfiledFrames(numFrames)
+                        session.setFunc(_profileFunc)
+                        print '** profiling %s frames' % numFrames
+                        session.run()
+                        _profileFunc = None
                     else:
                         self.step()
                 except KeyboardInterrupt:
@@ -522,17 +528,22 @@ class TaskManager:
         from direct.tkpanels import TaskManagerPanel
         return TaskManagerPanel.TaskManagerPanel(self)
 
-    def profileFrames(self, num=None):
-        self._profileFrames = True
+    def getProfileSession(self, name=None):
+        # call to get a profile session that you can modify before passing to profileFrames()
+        if name is None:
+            name = 'taskMgrFrameProfile'
+        return ProfileSession(name)
+
+    def profileFrames(self, num=None, session=None):
         if num is None:
             num = 1
-        self._profileFrameCount = num
+        if session is None:
+            session = self.getProfileSession()
+        self._frameProfileQueue.push((num, session))
 
-    @profiled()
-    def _doProfiledFrames(self, *args, **kArgs):
-        print '** profiling %s frames' % self._profileFrameCount
-        for i in xrange(self._profileFrameCount):
-            result = self.step(*args, **kArgs)
+    def _doProfiledFrames(self, numFrames):
+        for i in xrange(numFrames):
+            result = self.step()
         return result
 
     def getProfileTasks(self):
@@ -557,10 +568,10 @@ class TaskManager:
             self._taskProfiler.flush(name)
 
     def _setProfileTask(self, task):
-        if self._profileInfo.session:
-            self._profileInfo.session.release()
-            self._profileInfo.session = None
-        self._profileInfo = ScratchPad(
+        if self._taskProfileInfo.session:
+            self._taskProfileInfo.session.release()
+            self._taskProfileInfo.session = None
+        self._taskProfileInfo = ScratchPad(
             taskFunc = task.getFunction(),
             taskArgs = task.getArgs(),
             task = task,
@@ -571,7 +582,7 @@ class TaskManager:
         # Temporarily replace the task's own function with our
         # _profileTask method.
         task.setFunction(self._profileTask)
-        task.setArgs([self._profileInfo], True)
+        task.setArgs([self._taskProfileInfo], True)
 
     def _profileTask(self, profileInfo, task):
         # This is called instead of the task function when we have
@@ -590,8 +601,8 @@ class TaskManager:
         task.setArgs(taskArgs, appendTask)
         task.setFunction(profileInfo.taskFunc)
 
-        profileSession = ProfileSession(Functor(profileInfo.taskFunc, *profileInfo.taskArgs),
-                                        'profiled-task-%s' % task.getName())
+        profileSession = ProfileSession('profiled-task-%s' % task.getName(),
+                                        Functor(profileInfo.taskFunc, *profileInfo.taskArgs))
         ret = profileSession.run()
 
         # set these values *after* profiling in case we're profiling the TaskProfiler
@@ -602,10 +613,10 @@ class TaskManager:
 
     def _hasProfiledDesignatedTask(self):
         # have we run a profile of the designated task yet?
-        return self._profileInfo.profiled
+        return self._taskProfileInfo.profiled
 
-    def _getLastProfileSession(self):
-        return self._profileInfo.session
+    def _getLastTaskProfileSession(self):
+        return self._taskProfileInfo.session
 
     def _getRandomTask(self):
         # Figure out when the next frame is likely to expire, so we

direct/src/task/TaskOrig.py

@@ -409,13 +409,13 @@ class TaskManager:
         # List of tasks scheduled to execute in the future
         self.__doLaterList = []
 
-        self._profileFrames = False
+        self._frameProfileQueue = Queue()
         self.MaxEpockSpeed = 1.0/30.0;   
 
         # this will be set when it's safe to import StateVar
         self._profileTasks = None
         self._taskProfiler = None
-        self._profileInfo = ScratchPad(
+        self._taskProfileInfo = ScratchPad(
             taskId = None,
             profiled = False,
             session = None,
@@ -458,6 +458,7 @@ class TaskManager:
         pass
 
     def destroy(self):
+        self._frameProfileQueue.clear()
         if self._doLaterTask:
             self._doLaterTask.remove()
         if self._taskProfiler:
@@ -799,9 +800,9 @@ class TaskManager:
     def __executeTask(self, task):
         task.setCurrentTimeFrame(self.currentTime, self.currentFrame)
         
-        # cache reference to profile info here, self._profileInfo might get swapped out
+        # cache reference to profile info here, self._taskProfileInfo might get swapped out
         # by the task when it runs
-        profileInfo = self._profileInfo
+        profileInfo = self._taskProfileInfo
         doProfile = (task.id == profileInfo.taskId)
         # don't profile the same task twice in a row
         doProfile = doProfile and (not profileInfo.profiled)
@@ -811,8 +812,8 @@ class TaskManager:
             
             # don't record timing info
             if doProfile:
-                profileSession = ProfileSession(Functor(task, *task.extraArgs),
-                                                'TASK_PROFILE:%s' % task.name)
+                profileSession = ProfileSession('TASK_PROFILE:%s' % task.name,
+                                                Functor(task, *task.extraArgs))
                 ret = profileSession.run()
                 # set these values *after* profiling in case we're profiling the TaskProfiler
                 profileInfo.session = profileSession
@@ -834,8 +835,8 @@ class TaskManager:
                 task.pstats.start()
             startTime = self.trueClock.getShortTime()
             if doProfile:
-                profileSession = ProfileSession(Functor(task, *task.extraArgs),
-                                                'profiled-task-%s' % task.name)
+                profileSession = ProfileSession('profiled-task-%s' % task.name,
+                                                Functor(task, *task.extraArgs))
                 ret = profileSession.run()
                 # set these values *after* profiling in case we're profiling the TaskProfiler
                 profileInfo.session = profileSession
@@ -963,11 +964,18 @@ class TaskManager:
                     self.__addNewTask(task)
         self.pendingTaskDict.clear()
 
-    def profileFrames(self, num=None):
-        self._profileFrames = True
+    def getProfileSession(self, name=None):
+        # call to get a profile session that you can modify before passing to profileFrames()
+        if name is None:
+            name = 'taskMgrFrameProfile'
+        return ProfileSession(name)
+
+    def profileFrames(self, num=None, session=None):
         if num is None:
             num = 1
-        self._profileFrameCount = num
+        if session is None:
+            session = self.getProfileSession()
+        self._frameProfileQueue.push((num, session))
     
 
     # in the event we want to do frame time managment.. this is the function to 
@@ -987,11 +995,9 @@ class TaskManager:
             delta = minFinTime - self.globalClock.getRealTime();
     
 
-    @profiled()
-    def _doProfiledFrames(self, *args, **kArgs):
-        print '** profiling %s frames' % self._profileFrameCount
-        for i in xrange(self._profileFrameCount):
-            result = self.step(*args, **kArgs)
+    def _doProfiledFrames(self, numFrames):
+        for i in xrange(numFrames):
+            result = self.step()
         return result
 
     def getProfileTasks(self):
@@ -1016,10 +1022,10 @@ class TaskManager:
             self._taskProfiler.flush(name)
 
     def _setProfileTask(self, task):
-        if self._profileInfo.session:
-            self._profileInfo.session.release()
-            self._profileInfo.session = None
-        self._profileInfo = ScratchPad(
+        if self._taskProfileInfo.session:
+            self._taskProfileInfo.session.release()
+            self._taskProfileInfo.session = None
+        self._taskProfileInfo = ScratchPad(
             taskId = task.id,
             profiled = False,
             session = None,
@@ -1027,10 +1033,10 @@ class TaskManager:
 
     def _hasProfiledDesignatedTask(self):
         # have we run a profile of the designated task yet?
-        return self._profileInfo.profiled
+        return self._taskProfileInfo.profiled
 
-    def _getLastProfileSession(self):
-        return self._profileInfo.session
+    def _getLastTaskProfileSession(self):
+        return self._taskProfileInfo.session
 
     def _getRandomTask(self):
         numTasks = 0
@@ -1159,9 +1165,14 @@ class TaskManager:
             self.running = 1
             while self.running:
                 try:
-                    if self._profileFrames:
-                        self._profileFrames = False
-                        self._doProfiledFrames()
+                    if len(self._frameProfileQueue):
+                        numFrames, session = self._frameProfileQueue.pop()
+                        def _profileFunc(numFrames=numFrames):
+                            self._doProfiledFrames(numFrames)
+                        session.setFunc(_profileFunc)
+                        print '** profiling %s frames' % numFrames
+                        session.run()
+                        _profileFunc = None
                     else:
                         self.step()
                 except KeyboardInterrupt:

direct/src/task/TaskProfiler.py

@@ -134,7 +134,7 @@ class TaskProfiler:
         # gather data from the previous frame
         # set up for the next frame
         if (self._task is not None) and taskMgr._hasProfiledDesignatedTask():
-            session = taskMgr._getLastProfileSession()
+            session = taskMgr._getLastTaskProfileSession()
             # if we couldn't profile, throw this result out
             if session.profileSucceeded():
                 namePrefix = self._task.getNamePrefix()