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()