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())
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()) 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
def __init__(self): self._enableFC = FunctionCall(self._setEnabled, taskMgr.getProfileTasksSV()) # table of task name pattern to TaskTracker self._namePrefix2tracker = {} self._task = None
class TaskProfiler: # this does intermittent profiling of tasks running on the system # if a task has a spike in execution time, the profile of the spike is logged notify = directNotify.newCategory("TaskProfiler") def __init__(self): self._enableFC = FunctionCall(self._setEnabled, taskMgr.getProfileTasksSV()) # table of task name pattern to TaskTracker self._namePrefix2tracker = {} self._task = None def destroy(self): if taskMgr.getProfileTasks(): self._setEnabled(False) self._enableFC.destroy() for tracker in self._namePrefix2tracker.itervalues(): tracker.destroy() del self._namePrefix2tracker del self._task @staticmethod def GetDefaultSpikeThreshold(): return config.GetFloat('profile-task-spike-threshold', 5.) @staticmethod def SetSpikeThreshold(spikeThreshold): TaskTracker.SpikeThreshold = spikeThreshold @staticmethod def GetSpikeThreshold(): return TaskTracker.SpikeThreshold def logProfiles(self, name=None): if name: name = name.lower() for namePrefix, tracker in self._namePrefix2tracker.iteritems(): if (name and (name not in namePrefix.lower())): continue tracker.log() def flush(self, name): if name: name = name.lower() # flush stored task profiles for namePrefix, tracker in self._namePrefix2tracker.iteritems(): if (name and (name not in namePrefix.lower())): continue tracker.flush() def _setEnabled(self, enabled): if enabled: self.notify.info('task profiler started') self._taskName = 'profile-tasks-%s' % id(self) taskMgr.add(self._doProfileTasks, self._taskName, priority=-200) else: taskMgr.remove(self._taskName) del self._taskName self.notify.info('task profiler stopped') def _doProfileTasks(self, task=None): # gather data from the previous frame # set up for the next frame if (self._task is not None) and taskMgr._hasProfiledDesignatedTask(): session = taskMgr._getLastTaskProfileSession() # if we couldn't profile, throw this result out if session.profileSucceeded(): namePrefix = self._task.getNamePrefix() if namePrefix not in self._namePrefix2tracker: self._namePrefix2tracker[namePrefix] = TaskTracker(namePrefix) tracker = self._namePrefix2tracker[namePrefix] tracker.addProfileSession(session) # set up the next task self._task = taskMgr._getRandomTask() taskMgr._setProfileTask(self._task) return task.cont
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()) 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