from direct.directnotify.DirectNotifyGlobal import directNotify from direct.fsm.StatePush import FunctionCall from direct.showbase.PythonUtil import formatTimeExact, normalDistrib from direct.task import Task class FrameProfiler: notify = directNotify.newCategory('FrameProfiler') # because of precision requirements, 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 if config.GetBool('frequent-frame-profiles', 0): self._period = 1 * 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. if config.GetBool('frequent-frame-profiles', 0): self._logSchedule = [ 1 * FrameProfiler.Minute, 4 * FrameProfiler.Minute, 12 * FrameProfiler.Minute, 24 * FrameProfiler.Minute, ] 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()) self._enableFC.pushCurrentState() def destroy(self): self._enableFC.set(False) self._enableFC.destroy() def _setEnabled(self, enabled): if enabled: self.notify.info('frame profiler started') self._startTime = globalClock.getFrameTime() self._profileCounter = 0 self._jitter = None self._period2aggregateProfile = {} self._id2session = {} self._id2task = {} # don't profile process startup self._task = taskMgr.doMethodLater(self._period, self._scheduleNextProfileDoLater, 'FrameProfilerStart-%s' % serialNum()) else: self._task.remove() del self._task for session in self._period2aggregateProfile.itervalues: session.release() del self._period2aggregateProfile for task in self._id2task.itervalues(): task.remove() del self._id2task for session in self._id2session.itervalues(): session.release() del self._id2session self.notify.info('frame profiler stopped') def _scheduleNextProfileDoLater(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: time -= jitter jitter = None self._jitter = jitter sessionId = serialNum() session = taskMgr.getProfileSession('FrameProfile-%s' % sessionId) self._id2session[sessionId] = session taskMgr.profileFrames(num=1, session=session, callback=Functor( self._analyzeResults, sessionId)) # schedule the next profile delay = max(time - globalClock.getFrameTime(), 0.) self._task = taskMgr.doMethodLater(delay, self._scheduleNextProfileDoLater, 'FrameProfiler-%s' % serialNum()) def _analyzeResults(self, sessionId): # do the analysis in a task 1) to separate the processing from the profiled frame, # and 2) to get the processing to show up in a named task instead of in the taskMgr self._id2task[sessionId] = taskMgr.add( Functor(self._doAnalysis, sessionId), 'FrameProfilerAnalysis-%s' % sessionId) def _doAnalysis(self, sessionId, task): if hasattr(task, '_generator'): gen = task._generator else: gen = self._doAnalysisGen(sessionId) task._generator = gen result = gen.next() if result == Task.done: del task._generator return result def _doAnalysisGen(self, sessionId): # generator to limit max number of profile loggings per frame p2ap = self._period2aggregateProfile self._id2task.pop(sessionId) session = self._id2session.pop(sessionId) if session.profileSucceeded(): # always add this profile to the first aggregated profile period = self._logSchedule[0] if period not in self._period2aggregateProfile: p2ap[period] = session.getReference() else: p2ap[period].aggregate(session) else: self.notify.warning('frame profile did not succeed') session.release() session = None counter = 0 # log profiles when it's time, and aggregate them upwards into the # next-longer profile for pi in xrange(len(self._logSchedule)): period = self._logSchedule[pi] if (self._timeElapsed % period) == 0: if period in p2ap: # delay until the next frame if we've already processed N profiles this frame if counter >= 3: counter = 0 yield Task.cont self.notify.info('aggregate profile of sampled frames over last %s\n%s' % (formatTimeExact(period), p2ap[period].getResults())) counter += 1 # aggregate this profile into the next larger profile nextIndex = pi + 1 if nextIndex >= len(self._logSchedule): # if we're adding a new period to the end of the log period table, # set it to double the duration of the current longest period nextPeriod = period * 2 self._logSchedule.append(nextPeriod) else: nextPeriod = self._logSchedule[nextIndex] 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 yield Task.done