187 lines
7.9 KiB
Python
187 lines
7.9 KiB
Python
|
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 range(len(self._logSchedule)):
|
||
|
|
e = self._logSchedule[i]
|
||
|
|
for j in range(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.values():
|
||
|
|
session.release()
|
||
|
|
del self._period2aggregateProfile
|
||
|
|
for task in self._id2task.values():
|
||
|
|
task.remove()
|
||
|
|
del self._id2task
|
||
|
|
for session in self._id2session.values():
|
||
|
|
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 = next(gen)
|
||
|
|
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 range(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
|