def _ProfileScope(self, profileScopeName):
"""
A context manager that measures the execution time between enter and
exit and stores the elapsed time in the class' metrics dictionary.
"""
stopwatch = Tf.Stopwatch()
collector = Trace.Collector()
try:
stopwatch.Start()
collector.enabled = True
collector.BeginEvent(profileScopeName)
yield
finally:
collector.EndEvent(profileScopeName)
collector.enabled = False
stopwatch.Stop()
elapsedTime = stopwatch.seconds
self._profileScopeMetrics[profileScopeName] = elapsedTime
Tf.Status('%s: %f' % (profileScopeName, elapsedTime))
traceFilePath = os.path.join(self._testDir,
'%s.trace' % profileScopeName)
Trace.Reporter.globalReporter.Report(traceFilePath)
collector.Clear()
Trace.Reporter.globalReporter.ClearTree()
def Run(self):
'''
The main entry point to launch a process using UsdView.
'''
parser = argparse.ArgumentParser(prog=sys.argv[0],
description=self.GetHelpDescription())
traceCollector = None
with Timer() as totalTimer:
self.RegisterPositionals(parser)
self.RegisterOptions(parser)
arg_parse_result = self.ParseOptions(parser)
self.ValidateOptions(arg_parse_result)
if arg_parse_result.traceToFile:
from pxr import Trace
traceCollector = Trace.Collector()
traceCollector.pythonTracingEnabled = True
traceCollector.enabled = True
self.__LaunchProcess(arg_parse_result)
if traceCollector:
traceCollector.enabled = False
if arg_parse_result.timing and arg_parse_result.quitAfterStartup:
totalTimer.PrintTime('open and close usdview')
if traceCollector:
Trace.Reporter.globalReporter.ReportChromeTracingToFile(
arg_parse_result.traceToFile)
def testFunc():
gc = Trace.Collector()
gc.BeginEvent('Custom Paired Event')
testFunc2()
gc.EndEvent('Custom Paired Event')
def test_Reporter(self):
gc = Trace.Collector()
gr = Trace.Reporter.globalReporter
gr.shouldAdjustForOverheadAndNoise = False
# Create a call graph with manually specified times so that the times in the
# report graph can be validated.
def A():
ts = 0.0
gc.BeginEventAtTime('A', ts)
for i in range(3):
ts = B(ts)
ts += 1 # Simulate 1 ms of work
gc.EndEventAtTime('A', ts)
def B(ts):
gc.BeginEventAtTime('B', ts)
for i in range(4):
ts = C(ts)
ts += 1 # Simulate 1 ms of work
gc.EndEventAtTime('B', ts)
return ts
def C(ts):
gc.BeginEventAtTime('C', ts)
ts += 1 # Simulate 1 ms of work
gc.EndEventAtTime('C', ts)
return ts
gc.enabled = True
A()
gc.enabled = False
gr.Report()
aNodes = GetNodesByKey(gr, 'A')
self.assertEqual(len(aNodes), 1)
self.assertEqual(aNodes[0].count, 1)
self.assertAlmostEqual(aNodes[0].inclusiveTime, 16.0, delta=1e-4)
self.assertAlmostEqual(aNodes[0].exclusiveTime, 1.0, delta=1e-4)
bNodes = GetNodesByKey(gr, 'B')
self.assertEqual(len(bNodes), 1)
self.assertEqual(bNodes[0].count, 3)
self.assertAlmostEqual(bNodes[0].inclusiveTime, 15.0, delta=1e-4)
self.assertAlmostEqual(bNodes[0].exclusiveTime, 3.0, delta=1e-4)
cNodes = GetNodesByKey(gr, 'C')
self.assertEqual(len(cNodes), 1)
self.assertEqual(cNodes[0].count, 12)
self.assertAlmostEqual(cNodes[0].inclusiveTime, 12.0, delta=1e-4)
self.assertAlmostEqual(cNodes[0].exclusiveTime, 12.0, delta=1e-4)
#
def WriteReport(reporter, collector, filename):
# We report twice, the first time to stdout, and the second time to
# a file that we will compare against a baseline. The reason
# we output to stdout is because we want to make sure that repeatedly
# calling Report on the same tree will not change the output, and because it
# is easier to see all the output in one place in the test results.
reporter.Report()
reporter.Report(filename)
reporter.ClearTree()
collector.Clear()
# ----------------------------------------------------------------------------
gc = Trace.Collector()
gr = Trace.Reporter.globalReporter
gr.shouldAdjustForOverheadAndNoise = False
gc.enabled = True
gr.foldRecursiveCalls = True
# ----------------------------------------------------------------------------
# A test for recursion where we are nested 5 levels deep.
gc.BeginEventAtTime('Begin', 0.0) # Begin
gc.BeginEventAtTime('Begin', 0.0) # Begin
gc.BeginEventAtTime('Begin', 0.0) # Begin
gc.BeginEventAtTime('Begin', 0.0) # Begin
gc.BeginEventAtTime('Begin', 0.0) # Begin
gc.EndEventAtTime('Begin', 1.0)
def test_Trace(self):
gc = Trace.Collector()
self.assertIsInstance(gc, Trace.Collector)
self.assertEqual(gc, Trace.Collector())
gr = Trace.Reporter.globalReporter
self.assertIsInstance(gr, Trace.Reporter)
if not os.getenv('PXR_ENABLE_GLOBAL_TRACE', False):
self.assertEqual(gc.enabled, False)
self.assertEqual(gc.EndEvent('Begin'), 0)
gc.enabled = True
else:
self.assertEqual(gc.enabled, True)
# begin and end.
gc.BeginEvent('Begin')
gc.BeginEvent('Begin')
gc.BeginEvent('Begin')
gc.EndEvent('Begin')
gc.EndEvent('Begin')
gc.EndEvent('Begin')
gc.enabled = False
# this shouldn't add any events
gc.BeginEvent('Begin')
gc.EndEvent('Begin')
gc.enabled = True
gr.UpdateAggregateTree()
beginNodes = GetNodesByKey(gr, 'Begin')
print len(beginNodes)
self.assertEqual(len(beginNodes), 3)
for eventNode in beginNodes:
self.assertEqual(eventNode.key, 'Begin')
self.assertTrue(eventNode.exclusiveTime > 0 and \
eventNode.inclusiveTime > 0)
gc.Clear()
gr.ClearTree()
self.assertEqual(len(GetNodesByKey(gr, 'Begin')), 0)
## The following is more example usage than a test.... It is left in to
## show usage and to exercise the python decorators.
class Test:
@Trace.TraceMethod
def __init__(self, arg):
self.__arg = arg
@Trace.TraceMethod
def Func(self):
pass
@Trace.TraceFunction
def testFunc2():
t = Test(1.234)
t.Func()
@Trace.TraceFunction
def testFunc():
gc = Trace.Collector()
gc.BeginEvent('Custom Paired Event')
testFunc2()
gc.EndEvent('Custom Paired Event')
testFunc()
gr.ClearTree()
Trace.TestAuto()
gr.UpdateAggregateTree()
# Should have generated a top-level event
autoNodes = GetNodesByKey(gr, 'TestAuto')
self.assertEqual(len(autoNodes), 1)
self.assertEqual(autoNodes[0].key, 'TestAuto')
self.assertTrue(autoNodes[0].exclusiveTime > 0)
self.assertTrue(autoNodes[0].inclusiveTime > 0)
gr.ClearTree()
Trace.TestNesting()
gr.Report()
# Should have generated a top-level event
nestingNodes = GetNodesByKey(gr, 'TestNesting')
self.assertEqual(len(nestingNodes), 1)
self.assertEqual(nestingNodes[0].key, 'TestNesting')
self.assertTrue(nestingNodes[0].exclusiveTime > 0)
self.assertTrue(nestingNodes[0].inclusiveTime > 0)
Trace.TestNesting()
gr.UpdateAggregateTree()
rootNode = gr.aggregateTreeRoot
# code cover and check some of the exposed parts of EventNode
for child in rootNode.children:
print "inc: ", "%.3f" % child.inclusiveTime
print "exc: ", "%.3f" % child.exclusiveTime
print "cnt: ", "%d" % child.count
child.expanded = True
self.assertTrue(child.expanded)
gr.Report(len(rootNode.children))
gr.ClearTree()
gc.Clear()
Trace.TestCreateEvents()
pythonEvent = 'PYTHON_EVENT'
gc.BeginEvent(pythonEvent)
gc.EndEvent(pythonEvent)
gr.UpdateAggregateTree()
self.assertEqual(len(GetNodesByKey(gr, Trace.GetTestEventName())), 1)
gr.ReportTimes()
gc.BeginEvent('Foo')
gc.BeginEvent('Bar')
gc.BeginEvent('Foo')
gc.EndEvent('Foo')
gc.EndEvent('Bar')
gc.EndEvent('Foo')
gr.Report()
gc.enabled = False
gr.Report()
self.assertEqual(gc.EndEvent("BadEvent"), 0)
gc.enabled = True
# Also try a local reporter and scope
lr = Trace.Reporter('local reporter')
self.assertEqual(lr.GetLabel(), 'local reporter')
gc.BeginEvent("LocalScope")
gc.EndEvent("LocalScope")
gc.enabled = False
lr.Report()
gc.enabled = True
sleepTime = 1.0
b = gc.BeginEvent("Test tuple")
time.sleep(sleepTime)
e = gc.EndEvent("Test tuple")
elapsedSeconds = Trace.GetElapsedSeconds(b, e)
gr.Report()
self.assertTrue(abs(elapsedSeconds - sleepTime) < 0.05)
print ""
if args.cmd and args.file:
print("Only one of -c or FILE may be specified", file=sys.stderr)
sys.exit(1)
from pxr import Trace
env = {}
# Create a Main function that is traced so we always capture a useful
# top-level scope.
if args.file:
@Trace.TraceFunction
def Main():
exec(compile(open(args.file).read(), args.file, 'exec'), env)
else:
@Trace.TraceFunction
def Main():
exec(args.cmd, env)
try:
Trace.Collector().enabled = True
Main()
finally:
Trace.Collector().enabled = False
if args.output is not None:
Trace.Reporter.globalReporter.Report(args.output)
else:
Trace.Reporter.globalReporter.Report()
