From f5997b4d3f889569d5a2b724d83d764bfbb8d106 Mon Sep 17 00:00:00 2001 From: Mathieu Chartier Date: Fri, 20 Jun 2014 10:37:54 -0700 Subject: More advanced timing loggers. The new timing loggers have lower overhead since they only push into a vector. The new format has two types, a start timing and a stop timing. You can thing of these as brackets associated with a timestamp. It uses these to construct various statistics when needed, such as: Total time, exclusive time, and nesting depth. Changed PrettyDuration to have a default of 3 digits after the decimal point. Exaple of a GC dump with exclusive / total times and indenting: I/art (23546): GC iteration timing logger [Exclusive time] [Total time] I/art (23546): 0ms InitializePhase I/art (23546): 0.305ms/167.746ms MarkingPhase I/art (23546): 0ms BindBitmaps I/art (23546): 0ms FindDefaultSpaceBitmap I/art (23546): 0ms/1.709ms ProcessCards I/art (23546): 0.183ms ImageModUnionClearCards I/art (23546): 0.916ms ZygoteModUnionClearCards I/art (23546): 0.610ms AllocSpaceClearCards I/art (23546): 1.373ms AllocSpaceClearCards I/art (23546): 0.305ms/6.318ms MarkRoots I/art (23546): 2.106ms MarkRootsCheckpoint I/art (23546): 0.153ms MarkNonThreadRoots I/art (23546): 4.287ms MarkConcurrentRoots I/art (23546): 43.461ms UpdateAndMarkImageModUnionTable I/art (23546): 0ms/112.712ms RecursiveMark I/art (23546): 112.712ms ProcessMarkStack I/art (23546): 0.610ms/2.777ms PreCleanCards I/art (23546): 0.305ms/0.855ms ProcessCards I/art (23546): 0.153ms ImageModUnionClearCards I/art (23546): 0.610ms ZygoteModUnionClearCards I/art (23546): 0.610ms AllocSpaceClearCards I/art (23546): 0.549ms AllocSpaceClearCards I/art (23546): 0.549ms MarkRootsCheckpoint I/art (23546): 0.610ms MarkNonThreadRoots I/art (23546): 0ms MarkConcurrentRoots I/art (23546): 0.610ms ScanGrayImageSpaceObjects I/art (23546): 0.305ms ScanGrayZygoteSpaceObjects I/art (23546): 0.305ms ScanGrayAllocSpaceObjects I/art (23546): 1.129ms ScanGrayAllocSpaceObjects I/art (23546): 0ms ProcessMarkStack I/art (23546): 0ms/0.977ms (Paused)PausePhase I/art (23546): 0.244ms ReMarkRoots I/art (23546): 0.672ms (Paused)ScanGrayObjects I/art (23546): 0ms (Paused)ProcessMarkStack I/art (23546): 0ms/0.610ms SwapStacks I/art (23546): 0.610ms RevokeAllThreadLocalAllocationStacks I/art (23546): 0ms PreSweepingGcVerification I/art (23546): 0ms/10.621ms ReclaimPhase I/art (23546): 0.610ms/0.702ms ProcessReferences I/art (23546): 0.214ms/0.641ms EnqueueFinalizerReferences I/art (23546): 0.427ms ProcessMarkStack I/art (23546): 0.488ms SweepSystemWeaks I/art (23546): 0.824ms/9.400ms Sweep I/art (23546): 0ms SweepMallocSpace I/art (23546): 0.214ms SweepZygoteSpace I/art (23546): 0.122ms SweepMallocSpace I/art (23546): 6.226ms SweepMallocSpace I/art (23546): 0ms SweepMallocSpace I/art (23546): 2.144ms SweepLargeObjects I/art (23546): 0.305ms SwapBitmaps I/art (23546): 0ms UnBindBitmaps I/art (23546): 0.275ms FinishPhase I/art (23546): GC iteration timing logger: end, 178.971ms Change-Id: Ia55b65609468f212b3cd65cda66b843da42be645 --- compiler/image_test.cc | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) (limited to 'compiler/image_test.cc') diff --git a/compiler/image_test.cc b/compiler/image_test.cc index 92be147a40..e8bbaef1e9 100644 --- a/compiler/image_test.cc +++ b/compiler/image_test.cc @@ -64,7 +64,7 @@ TEST_F(ImageTest, WriteRead) { jobject class_loader = NULL; ClassLinker* class_linker = Runtime::Current()->GetClassLinker(); TimingLogger timings("ImageTest::WriteRead", false, false); - timings.StartSplit("CompileAll"); + TimingLogger::ScopedTiming t("CompileAll", &timings); if (kUsePortableCompiler) { // TODO: we disable this for portable so the test executes in a reasonable amount of time. // We shouldn't need to do this. @@ -75,6 +75,7 @@ TEST_F(ImageTest, WriteRead) { } compiler_driver_->CompileAll(class_loader, class_linker->GetBootClassPath(), &timings); + t.NewTiming("WriteElf"); ScopedObjectAccess soa(Thread::Current()); OatWriter oat_writer(class_linker->GetBootClassPath(), 0, 0, "", compiler_driver_.get(), &timings); @@ -84,7 +85,6 @@ TEST_F(ImageTest, WriteRead) { &oat_writer, oat_file.GetFile()); ASSERT_TRUE(success); - timings.EndSplit(); } } // Workound bug that mcld::Linker::emit closes oat_file by reopening as dup_oat. -- cgit v1.2.3-59-g8ed1b