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
diff --git a/compiler/common_compiler_test.h b/compiler/common_compiler_test.h
index 5050d4e..45cf2fb 100644
--- a/compiler/common_compiler_test.h
+++ b/compiler/common_compiler_test.h
@@ -371,10 +371,10 @@
void CompileMethod(mirror::ArtMethod* method) SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) {
CHECK(method != nullptr);
TimingLogger timings("CommonTest::CompileMethod", false, false);
- timings.StartSplit("CompileOne");
+ TimingLogger::ScopedTiming t(__FUNCTION__, &timings);
compiler_driver_->CompileOne(method, &timings);
+ TimingLogger::ScopedTiming t2("MakeExecutable", &timings);
MakeExecutable(method);
- timings.EndSplit();
}
void CompileDirectMethod(Handle<mirror::ClassLoader> class_loader, const char* class_name,
diff --git a/compiler/dex/frontend.cc b/compiler/dex/frontend.cc
index 0845656..72990b4 100644
--- a/compiler/dex/frontend.cc
+++ b/compiler/dex/frontend.cc
@@ -114,19 +114,20 @@
void CompilationUnit::StartTimingSplit(const char* label) {
if (compiler_driver->GetDumpPasses()) {
- timings.StartSplit(label);
+ timings.StartTiming(label);
}
}
void CompilationUnit::NewTimingSplit(const char* label) {
if (compiler_driver->GetDumpPasses()) {
- timings.NewSplit(label);
+ timings.EndTiming();
+ timings.StartTiming(label);
}
}
void CompilationUnit::EndTiming() {
if (compiler_driver->GetDumpPasses()) {
- timings.EndSplit();
+ timings.EndTiming();
if (enable_debug & (1 << kDebugTimings)) {
LOG(INFO) << "TIMINGS " << PrettyMethod(method_idx, *dex_file);
LOG(INFO) << Dumpable<TimingLogger>(timings);
diff --git a/compiler/driver/compiler_driver.cc b/compiler/driver/compiler_driver.cc
index 4a331fc..96625c5 100644
--- a/compiler/driver/compiler_driver.cc
+++ b/compiler/driver/compiler_driver.cc
@@ -697,7 +697,7 @@
return;
}
- timings->NewSplit("LoadImageClasses");
+ TimingLogger::ScopedTiming t("LoadImageClasses", timings);
// Make a first class to load all classes explicitly listed in the file
Thread* self = Thread::Current();
ScopedObjectAccess soa(self);
@@ -794,8 +794,7 @@
void CompilerDriver::UpdateImageClasses(TimingLogger* timings) {
if (IsImage()) {
- timings->NewSplit("UpdateImageClasses");
-
+ TimingLogger::ScopedTiming t("UpdateImageClasses", timings);
// Update image_classes_ with classes for objects created by <clinit> methods.
Thread* self = Thread::Current();
const char* old_cause = self->StartAssertNoThreadSuspension("ImageWriter");
@@ -1606,11 +1605,11 @@
if (IsImage()) {
// For images we resolve all types, such as array, whereas for applications just those with
// classdefs are resolved by ResolveClassFieldsAndMethods.
- timings->NewSplit("Resolve Types");
+ TimingLogger::ScopedTiming t("Resolve Types", timings);
context.ForAll(0, dex_file.NumTypeIds(), ResolveType, thread_count_);
}
- timings->NewSplit("Resolve MethodsAndFields");
+ TimingLogger::ScopedTiming t("Resolve MethodsAndFields", timings);
context.ForAll(0, dex_file.NumClassDefs(), ResolveClassFieldsAndMethods, thread_count_);
}
@@ -1672,7 +1671,7 @@
void CompilerDriver::VerifyDexFile(jobject class_loader, const DexFile& dex_file,
ThreadPool* thread_pool, TimingLogger* timings) {
- timings->NewSplit("Verify Dex File");
+ TimingLogger::ScopedTiming t("Verify Dex File", timings);
ClassLinker* class_linker = Runtime::Current()->GetClassLinker();
ParallelCompilationManager context(class_linker, class_loader, this, &dex_file, thread_pool);
context.ForAll(0, dex_file.NumClassDefs(), VerifyClass, thread_count_);
@@ -1765,7 +1764,7 @@
void CompilerDriver::InitializeClasses(jobject jni_class_loader, const DexFile& dex_file,
ThreadPool* thread_pool, TimingLogger* timings) {
- timings->NewSplit("InitializeNoClinit");
+ TimingLogger::ScopedTiming t("InitializeNoClinit", timings);
ClassLinker* class_linker = Runtime::Current()->GetClassLinker();
ParallelCompilationManager context(class_linker, jni_class_loader, this, &dex_file, thread_pool);
size_t thread_count;
@@ -1877,7 +1876,7 @@
void CompilerDriver::CompileDexFile(jobject class_loader, const DexFile& dex_file,
ThreadPool* thread_pool, TimingLogger* timings) {
- timings->NewSplit("Compile Dex File");
+ TimingLogger::ScopedTiming t("Compile Dex File", timings);
ParallelCompilationManager context(Runtime::Current()->GetClassLinker(), class_loader, this,
&dex_file, thread_pool);
context.ForAll(0, dex_file.NumClassDefs(), CompilerDriver::CompileClass, thread_count_);
diff --git a/compiler/driver/compiler_driver_test.cc b/compiler/driver/compiler_driver_test.cc
index ca956aa..5325a68 100644
--- a/compiler/driver/compiler_driver_test.cc
+++ b/compiler/driver/compiler_driver_test.cc
@@ -38,12 +38,12 @@
protected:
void CompileAll(jobject class_loader) LOCKS_EXCLUDED(Locks::mutator_lock_) {
TimingLogger timings("CompilerDriverTest::CompileAll", false, false);
- timings.StartSplit("CompileAll");
+ TimingLogger::ScopedTiming t(__FUNCTION__, &timings);
compiler_driver_->CompileAll(class_loader,
Runtime::Current()->GetCompileTimeClassPath(class_loader),
&timings);
+ t.NewTiming("MakeAllExecutable");
MakeAllExecutable(class_loader);
- timings.EndSplit();
}
void EnsureCompiled(jobject class_loader, const char* class_name, const char* method,
diff --git a/compiler/image_test.cc b/compiler/image_test.cc
index 92be147..e8bbaef 100644
--- a/compiler/image_test.cc
+++ b/compiler/image_test.cc
@@ -64,7 +64,7 @@
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 @@
}
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 @@
&oat_writer,
oat_file.GetFile());
ASSERT_TRUE(success);
- timings.EndSplit();
}
}
// Workound bug that mcld::Linker::emit closes oat_file by reopening as dup_oat.
diff --git a/compiler/oat_writer.cc b/compiler/oat_writer.cc
index 4590880..e1b6992 100644
--- a/compiler/oat_writer.cc
+++ b/compiler/oat_writer.cc
@@ -91,31 +91,31 @@
size_oat_class_method_offsets_(0) {
size_t offset;
{
- TimingLogger::ScopedSplit split("InitOatHeader", timings);
+ TimingLogger::ScopedTiming split("InitOatHeader", timings);
offset = InitOatHeader();
}
{
- TimingLogger::ScopedSplit split("InitOatDexFiles", timings);
+ TimingLogger::ScopedTiming split("InitOatDexFiles", timings);
offset = InitOatDexFiles(offset);
}
{
- TimingLogger::ScopedSplit split("InitDexFiles", timings);
+ TimingLogger::ScopedTiming split("InitDexFiles", timings);
offset = InitDexFiles(offset);
}
{
- TimingLogger::ScopedSplit split("InitOatClasses", timings);
+ TimingLogger::ScopedTiming split("InitOatClasses", timings);
offset = InitOatClasses(offset);
}
{
- TimingLogger::ScopedSplit split("InitOatMaps", timings);
+ TimingLogger::ScopedTiming split("InitOatMaps", timings);
offset = InitOatMaps(offset);
}
{
- TimingLogger::ScopedSplit split("InitOatCode", timings);
+ TimingLogger::ScopedTiming split("InitOatCode", timings);
offset = InitOatCode(offset);
}
{
- TimingLogger::ScopedSplit split("InitOatCodeDexFiles", timings);
+ TimingLogger::ScopedTiming split("InitOatCodeDexFiles", timings);
offset = InitOatCodeDexFiles(offset);
}
size_ = offset;