diff options
author | 2013-07-24 15:02:53 -0700 | |
---|---|---|
committer | 2013-07-25 16:20:22 -0700 | |
commit | 6f28d91aab952e3244fbb4e707fa38f85538f374 (patch) | |
tree | 4ad68f49a154598599bc80d4596b7ee64e5923cc | |
parent | 41a41fdfc5d38f1b389d5e6cf1a945c96170d3ed (diff) |
Add systrace support to NewTimingLogger, migrate compiler timing logging to NewTimingLogger
Rpleaced old TimingLogger by NewTimingLogger, renamed NewTimingLogger to TimingLogger, added systrace support to TimingLogger.
Tests passing, phone booting, systrace working.
Change-Id: I2aeffb8bcb7f0fd979d8a2a3a8bcfbaa02413679
-rw-r--r-- | compiler/driver/compiler_driver.cc | 41 | ||||
-rw-r--r-- | compiler/driver/compiler_driver.h | 26 | ||||
-rw-r--r-- | compiler/driver/compiler_driver_test.cc | 2 | ||||
-rw-r--r-- | dex2oat/dex2oat.cc | 22 | ||||
-rw-r--r-- | runtime/base/timing_logger.cc | 77 | ||||
-rw-r--r-- | runtime/base/timing_logger.h | 35 | ||||
-rw-r--r-- | runtime/common_test.h | 2 | ||||
-rw-r--r-- | runtime/gc/collector/garbage_collector.h | 4 | ||||
-rw-r--r-- | runtime/gc/collector/mark_sweep.cc | 2 | ||||
-rw-r--r-- | runtime/gc/heap.cc | 6 | ||||
-rw-r--r-- | runtime/gc/heap.h | 4 | ||||
-rw-r--r-- | runtime/image_test.cc | 2 | ||||
-rw-r--r-- | runtime/oat_test.cc | 4 |
13 files changed, 83 insertions, 144 deletions
diff --git a/compiler/driver/compiler_driver.cc b/compiler/driver/compiler_driver.cc index c2a1312354..2aa2a98efb 100644 --- a/compiler/driver/compiler_driver.cc +++ b/compiler/driver/compiler_driver.cc @@ -495,7 +495,7 @@ const std::vector<uint8_t>* CompilerDriver::CreateInterpreterToQuickEntry() cons void CompilerDriver::CompileAll(jobject class_loader, const std::vector<const DexFile*>& dex_files, - TimingLogger& timings) { + base::TimingLogger& timings) { DCHECK(!Runtime::Current()->IsStarted()); UniquePtr<ThreadPool> thread_pool(new ThreadPool(thread_count_)); PreCompile(class_loader, dex_files, *thread_pool.get(), timings); @@ -528,7 +528,7 @@ static bool IsDexToDexCompilationAllowed(mirror::ClassLoader* class_loader, return klass->IsVerified(); } -void CompilerDriver::CompileOne(const mirror::AbstractMethod* method, TimingLogger& timings) { +void CompilerDriver::CompileOne(const mirror::AbstractMethod* method, base::TimingLogger& timings) { DCHECK(!Runtime::Current()->IsStarted()); Thread* self = Thread::Current(); jobject jclass_loader; @@ -572,7 +572,7 @@ void CompilerDriver::CompileOne(const mirror::AbstractMethod* method, TimingLogg } void CompilerDriver::Resolve(jobject class_loader, const std::vector<const DexFile*>& dex_files, - ThreadPool& thread_pool, TimingLogger& timings) { + ThreadPool& thread_pool, base::TimingLogger& timings) { for (size_t i = 0; i != dex_files.size(); ++i) { const DexFile* dex_file = dex_files[i]; CHECK(dex_file != NULL); @@ -581,7 +581,7 @@ void CompilerDriver::Resolve(jobject class_loader, const std::vector<const DexFi } void CompilerDriver::PreCompile(jobject class_loader, const std::vector<const DexFile*>& dex_files, - ThreadPool& thread_pool, TimingLogger& timings) { + ThreadPool& thread_pool, base::TimingLogger& timings) { LoadImageClasses(timings); Resolve(class_loader, dex_files, thread_pool, timings); @@ -666,12 +666,13 @@ static bool RecordImageClassesVisitor(mirror::Class* klass, void* arg) } // Make a list of descriptors for classes to include in the image -void CompilerDriver::LoadImageClasses(TimingLogger& timings) +void CompilerDriver::LoadImageClasses(base::TimingLogger& timings) LOCKS_EXCLUDED(Locks::mutator_lock_) { if (image_classes_.get() == NULL) { return; } + timings.NewSplit("LoadImageClasses"); // Make a first class to load all classes explicitly listed in the file Thread* self = Thread::Current(); ScopedObjectAccess soa(self); @@ -726,7 +727,6 @@ void CompilerDriver::LoadImageClasses(TimingLogger& timings) class_linker->VisitClasses(RecordImageClassesVisitor, image_classes_.get()); CHECK_NE(image_classes_->size(), 0U); - timings.AddSplit("LoadImageClasses"); } static void MaybeAddToImageClasses(mirror::Class* klass, CompilerDriver::DescriptorSet* image_classes) @@ -758,11 +758,13 @@ void CompilerDriver::FindClinitImageClassesCallback(mirror::Object* object, void MaybeAddToImageClasses(object->GetClass(), compiler_driver->image_classes_.get()); } -void CompilerDriver::UpdateImageClasses(TimingLogger& timings) { +void CompilerDriver::UpdateImageClasses(base::TimingLogger& timings) { if (image_classes_.get() == NULL) { return; } + timings.NewSplit("UpdateImageClasses"); + // Update image_classes_ with classes for objects created by <clinit> methods. Thread* self = Thread::Current(); const char* old_cause = self->StartAssertNoThreadSuspension("ImageWriter"); @@ -772,7 +774,6 @@ void CompilerDriver::UpdateImageClasses(TimingLogger& timings) { heap->FlushAllocStack(); heap->GetLiveBitmap()->Walk(FindClinitImageClassesCallback, this); self->EndAssertNoThreadSuspension(old_cause); - timings.AddSplit("UpdateImageClasses"); } void CompilerDriver::RecordClassStatus(ClassReference ref, CompiledClass* compiled_class) { @@ -1551,22 +1552,22 @@ static void ResolveType(const ParallelCompilationManager* manager, size_t type_i } void CompilerDriver::ResolveDexFile(jobject class_loader, const DexFile& dex_file, - ThreadPool& thread_pool, TimingLogger& timings) { + ThreadPool& thread_pool, base::TimingLogger& timings) { ClassLinker* class_linker = Runtime::Current()->GetClassLinker(); // TODO: we could resolve strings here, although the string table is largely filled with class // and method names. + timings.NewSplit(strdup(("Resolve " + dex_file.GetLocation() + " Types").c_str())); ParallelCompilationManager context(class_linker, class_loader, this, &dex_file, thread_pool); context.ForAll(0, dex_file.NumTypeIds(), ResolveType, thread_count_); - timings.AddSplit("Resolve " + dex_file.GetLocation() + " Types"); + timings.NewSplit(strdup(("Resolve " + dex_file.GetLocation() + " MethodsAndFields").c_str())); context.ForAll(0, dex_file.NumClassDefs(), ResolveClassFieldsAndMethods, thread_count_); - timings.AddSplit("Resolve " + dex_file.GetLocation() + " MethodsAndFields"); } void CompilerDriver::Verify(jobject class_loader, const std::vector<const DexFile*>& dex_files, - ThreadPool& thread_pool, TimingLogger& timings) { + ThreadPool& thread_pool, base::TimingLogger& timings) { for (size_t i = 0; i != dex_files.size(); ++i) { const DexFile* dex_file = dex_files[i]; CHECK(dex_file != NULL); @@ -1620,11 +1621,11 @@ static void VerifyClass(const ParallelCompilationManager* manager, size_t class_ } void CompilerDriver::VerifyDexFile(jobject class_loader, const DexFile& dex_file, - ThreadPool& thread_pool, TimingLogger& timings) { + ThreadPool& thread_pool, base::TimingLogger& timings) { + timings.NewSplit(strdup(("Verify " + dex_file.GetLocation()).c_str())); 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_); - timings.AddSplit("Verify " + dex_file.GetLocation()); } static const char* class_initializer_black_list[] = { @@ -2116,7 +2117,8 @@ static void InitializeClass(const ParallelCompilationManager* manager, size_t cl } void CompilerDriver::InitializeClasses(jobject jni_class_loader, const DexFile& dex_file, - ThreadPool& thread_pool, TimingLogger& timings) { + ThreadPool& thread_pool, base::TimingLogger& timings) { + timings.NewSplit(strdup(("InitializeNoClinit " + dex_file.GetLocation()).c_str())); #ifndef NDEBUG for (size_t i = 0; i < arraysize(class_initializer_black_list); ++i) { const char* descriptor = class_initializer_black_list[i]; @@ -2126,12 +2128,11 @@ void CompilerDriver::InitializeClasses(jobject jni_class_loader, const DexFile& ClassLinker* class_linker = Runtime::Current()->GetClassLinker(); ParallelCompilationManager context(class_linker, jni_class_loader, this, &dex_file, thread_pool); context.ForAll(0, dex_file.NumClassDefs(), InitializeClass, thread_count_); - timings.AddSplit("InitializeNoClinit " + dex_file.GetLocation()); } void CompilerDriver::InitializeClasses(jobject class_loader, const std::vector<const DexFile*>& dex_files, - ThreadPool& thread_pool, TimingLogger& timings) { + ThreadPool& thread_pool, base::TimingLogger& timings) { for (size_t i = 0; i != dex_files.size(); ++i) { const DexFile* dex_file = dex_files[i]; CHECK(dex_file != NULL); @@ -2140,7 +2141,7 @@ void CompilerDriver::InitializeClasses(jobject class_loader, } void CompilerDriver::Compile(jobject class_loader, const std::vector<const DexFile*>& dex_files, - ThreadPool& thread_pool, TimingLogger& timings) { + ThreadPool& thread_pool, base::TimingLogger& timings) { for (size_t i = 0; i != dex_files.size(); ++i) { const DexFile* dex_file = dex_files[i]; CHECK(dex_file != NULL); @@ -2220,10 +2221,10 @@ void CompilerDriver::CompileClass(const ParallelCompilationManager* manager, siz } void CompilerDriver::CompileDexFile(jobject class_loader, const DexFile& dex_file, - ThreadPool& thread_pool, TimingLogger& timings) { + ThreadPool& thread_pool, base::TimingLogger& timings) { + timings.NewSplit(strdup(("Compile " + dex_file.GetLocation()).c_str())); ParallelCompilationManager context(NULL, class_loader, this, &dex_file, thread_pool); context.ForAll(0, dex_file.NumClassDefs(), CompilerDriver::CompileClass, thread_count_); - timings.AddSplit("Compile " + dex_file.GetLocation()); } void CompilerDriver::CompileMethod(const DexFile::CodeItem* code_item, uint32_t access_flags, diff --git a/compiler/driver/compiler_driver.h b/compiler/driver/compiler_driver.h index f3f72dd3c7..a7a47ed876 100644 --- a/compiler/driver/compiler_driver.h +++ b/compiler/driver/compiler_driver.h @@ -78,11 +78,11 @@ class CompilerDriver { ~CompilerDriver(); void CompileAll(jobject class_loader, const std::vector<const DexFile*>& dex_files, - TimingLogger& timings) + base::TimingLogger& timings) LOCKS_EXCLUDED(Locks::mutator_lock_); // Compile a single Method - void CompileOne(const mirror::AbstractMethod* method, TimingLogger& timings) + void CompileOne(const mirror::AbstractMethod* method, base::TimingLogger& timings) SHARED_LOCKS_REQUIRED(Locks::mutator_lock_); InstructionSet GetInstructionSet() const { @@ -284,42 +284,42 @@ class CompilerDriver { SHARED_LOCKS_REQUIRED(Locks::mutator_lock_); void PreCompile(jobject class_loader, const std::vector<const DexFile*>& dex_files, - ThreadPool& thread_pool, TimingLogger& timings) + ThreadPool& thread_pool, base::TimingLogger& timings) LOCKS_EXCLUDED(Locks::mutator_lock_); - void LoadImageClasses(TimingLogger& timings); + void LoadImageClasses(base::TimingLogger& timings); // Attempt to resolve all type, methods, fields, and strings // referenced from code in the dex file following PathClassLoader // ordering semantics. void Resolve(jobject class_loader, const std::vector<const DexFile*>& dex_files, - ThreadPool& thread_pool, TimingLogger& timings) + ThreadPool& thread_pool, base::TimingLogger& timings) LOCKS_EXCLUDED(Locks::mutator_lock_); void ResolveDexFile(jobject class_loader, const DexFile& dex_file, - ThreadPool& thread_pool, TimingLogger& timings) + ThreadPool& thread_pool, base::TimingLogger& timings) LOCKS_EXCLUDED(Locks::mutator_lock_); void Verify(jobject class_loader, const std::vector<const DexFile*>& dex_files, - ThreadPool& thread_pool, TimingLogger& timings); + ThreadPool& thread_pool, base::TimingLogger& timings); void VerifyDexFile(jobject class_loader, const DexFile& dex_file, - ThreadPool& thread_pool, TimingLogger& timings) + ThreadPool& thread_pool, base::TimingLogger& timings) LOCKS_EXCLUDED(Locks::mutator_lock_); void InitializeClasses(jobject class_loader, const std::vector<const DexFile*>& dex_files, - ThreadPool& thread_pool, TimingLogger& timings) + ThreadPool& thread_pool, base::TimingLogger& timings) LOCKS_EXCLUDED(Locks::mutator_lock_); void InitializeClasses(jobject class_loader, const DexFile& dex_file, - ThreadPool& thread_pool, TimingLogger& timings) + ThreadPool& thread_pool, base::TimingLogger& timings) LOCKS_EXCLUDED(Locks::mutator_lock_, compiled_classes_lock_); - void UpdateImageClasses(TimingLogger& timings); + void UpdateImageClasses(base::TimingLogger& timings); static void FindClinitImageClassesCallback(mirror::Object* object, void* arg) SHARED_LOCKS_REQUIRED(Locks::mutator_lock_); void Compile(jobject class_loader, const std::vector<const DexFile*>& dex_files, - ThreadPool& thread_pool, TimingLogger& timings); + ThreadPool& thread_pool, base::TimingLogger& timings); void CompileDexFile(jobject class_loader, const DexFile& dex_file, - ThreadPool& thread_pool, TimingLogger& timings) + ThreadPool& thread_pool, base::TimingLogger& timings) LOCKS_EXCLUDED(Locks::mutator_lock_); void CompileMethod(const DexFile::CodeItem* code_item, uint32_t access_flags, InvokeType invoke_type, uint32_t class_def_idx, uint32_t method_idx, diff --git a/compiler/driver/compiler_driver_test.cc b/compiler/driver/compiler_driver_test.cc index 78cacaf08e..b06a3180fb 100644 --- a/compiler/driver/compiler_driver_test.cc +++ b/compiler/driver/compiler_driver_test.cc @@ -36,7 +36,7 @@ namespace art { class CompilerDriverTest : public CommonTest { protected: void CompileAll(jobject class_loader) LOCKS_EXCLUDED(Locks::mutator_lock_) { - TimingLogger timings("CompilerDriverTest::CompileAll", false); + base::TimingLogger timings("CompilerDriverTest::CompileAll", false, false); compiler_driver_->CompileAll(class_loader, Runtime::Current()->GetCompileTimeClassPath(class_loader), timings); diff --git a/dex2oat/dex2oat.cc b/dex2oat/dex2oat.cc index 1a6a98a2af..fb6f775675 100644 --- a/dex2oat/dex2oat.cc +++ b/dex2oat/dex2oat.cc @@ -230,7 +230,7 @@ class Dex2Oat { bool image, UniquePtr<CompilerDriver::DescriptorSet>& image_classes, bool dump_stats, - TimingLogger& timings) + base::TimingLogger& timings) SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) { // SirtRef and ClassLoader creation needs to come after Runtime::Create jobject class_loader = NULL; @@ -263,11 +263,11 @@ class Dex2Oat { Thread::Current()->TransitionFromRunnableToSuspended(kNative); - timings.AddSplit("dex2oat Setup"); driver->CompileAll(class_loader, dex_files, timings); Thread::Current()->TransitionFromSuspendedToRunnable(); + timings.NewSplit("dex2oat OatWriter"); std::string image_file_location; uint32_t image_file_location_oat_checksum = 0; uint32_t image_file_location_oat_data_begin = 0; @@ -287,13 +287,11 @@ class Dex2Oat { image_file_location_oat_data_begin, image_file_location, driver.get()); - timings.AddSplit("dex2oat OatWriter"); if (!driver->WriteElf(android_root, is_host, dex_files, oat_writer, oat_file)) { LOG(ERROR) << "Failed to write ELF file " << oat_file->GetPath(); return NULL; } - timings.AddSplit("dex2oat ElfWriter"); return driver.release(); } @@ -563,7 +561,7 @@ const unsigned int WatchDog::kWatchDogWarningSeconds; const unsigned int WatchDog::kWatchDogTimeoutSeconds; static int dex2oat(int argc, char** argv) { - TimingLogger timings("compiler", false); + base::TimingLogger timings("compiler", false, false); InitLogging(argv); @@ -928,6 +926,7 @@ static int dex2oat(int argc, char** argv) { } } + timings.StartSplit("dex2oat Setup"); UniquePtr<const CompilerDriver> compiler(dex2oat->CreateOatFile(boot_image_option, host_prefix.get(), android_root, @@ -998,13 +997,13 @@ static int dex2oat(int argc, char** argv) { // Elf32_Phdr.p_vaddr values by the desired base address. // if (image) { + timings.NewSplit("dex2oat ImageWriter"); Thread::Current()->TransitionFromRunnableToSuspended(kNative); bool image_creation_success = dex2oat->CreateImageFile(image_filename, image_base, oat_unstripped, oat_location, *compiler.get()); - timings.AddSplit("dex2oat ImageWriter"); Thread::Current()->TransitionFromSuspendedToRunnable(); if (!image_creation_success) { return EXIT_FAILURE; @@ -1014,7 +1013,7 @@ static int dex2oat(int argc, char** argv) { if (is_host) { if (dump_timings && timings.GetTotalNs() > MsToNs(1000)) { - LOG(INFO) << Dumpable<TimingLogger>(timings); + LOG(INFO) << Dumpable<base::TimingLogger>(timings); } return EXIT_SUCCESS; } @@ -1022,6 +1021,7 @@ static int dex2oat(int argc, char** argv) { // If we don't want to strip in place, copy from unstripped location to stripped location. // We need to strip after image creation because FixupElf needs to use .strtab. if (oat_unstripped != oat_stripped) { + timings.NewSplit("dex2oat OatFile copy"); oat_file.reset(); UniquePtr<File> in(OS::OpenFile(oat_unstripped.c_str(), false)); UniquePtr<File> out(OS::OpenFile(oat_stripped.c_str(), true)); @@ -1036,23 +1036,25 @@ static int dex2oat(int argc, char** argv) { CHECK(write_ok); } oat_file.reset(out.release()); - timings.AddSplit("dex2oat OatFile copy"); LOG(INFO) << "Oat file copied successfully (stripped): " << oat_stripped; } #if ART_USE_PORTABLE_COMPILER // We currently only generate symbols on Portable + timings.NewSplit("dex2oat ElfStripper"); // Strip unneeded sections for target off_t seek_actual = lseek(oat_file->Fd(), 0, SEEK_SET); CHECK_EQ(0, seek_actual); ElfStripper::Strip(oat_file.get()); - timings.AddSplit("dex2oat ElfStripper"); + // We wrote the oat file successfully, and want to keep it. LOG(INFO) << "Oat file written successfully (stripped): " << oat_location; #endif // ART_USE_PORTABLE_COMPILER + timings.EndSplit(); + if (dump_timings && timings.GetTotalNs() > MsToNs(1000)) { - LOG(INFO) << Dumpable<TimingLogger>(timings); + LOG(INFO) << Dumpable<base::TimingLogger>(timings); } return EXIT_SUCCESS; } diff --git a/runtime/base/timing_logger.cc b/runtime/base/timing_logger.cc index bf6fd17a49..dfb0220d46 100644 --- a/runtime/base/timing_logger.cc +++ b/runtime/base/timing_logger.cc @@ -14,6 +14,11 @@ * limitations under the License. */ + +#define ATRACE_TAG ATRACE_TAG_DALVIK +#include <stdio.h> +#include <cutils/trace.h> + #include "timing_logger.h" #include "base/logging.h" @@ -26,49 +31,6 @@ namespace art { -void TimingLogger::Reset() { - times_.clear(); - labels_.clear(); - AddSplit(""); -} - -TimingLogger::TimingLogger(const std::string &name, bool precise) - : name_(name), - precise_(precise) { - AddSplit(""); -} - -void TimingLogger::AddSplit(const std::string &label) { - times_.push_back(NanoTime()); - labels_.push_back(label); -} - -uint64_t TimingLogger::GetTotalNs() const { - return times_.back() - times_.front(); -} - -void TimingLogger::Dump(std::ostream &os) const { - uint64_t largest_time = 0; - os << name_ << ": begin\n"; - for (size_t i = 1; i < times_.size(); ++i) { - uint64_t delta_time = times_[i] - times_[i - 1]; - largest_time = std::max(largest_time, delta_time); - } - // Compute which type of unit we will use for printing the timings. - TimeUnit tu = GetAppropriateTimeUnit(largest_time); - uint64_t divisor = GetNsToTimeUnitDivisor(tu); - for (size_t i = 1; i < times_.size(); ++i) { - uint64_t delta_time = times_[i] - times_[i - 1]; - if (!precise_ && divisor >= 1000) { - // Make the fraction 0. - delta_time -= delta_time % (divisor / 1000); - } - os << name_ << ": " << std::setw(8) << FormatDuration(delta_time, tu) << " " - << labels_[i] << "\n"; - } - os << name_ << ": end, " << NsToMs(GetTotalNs()) << " ms\n"; -} - CumulativeLogger::CumulativeLogger(const std::string& name) : name_(name), lock_name_("CumulativeLoggerLock" + name), @@ -112,17 +74,8 @@ uint64_t CumulativeLogger::GetTotalTime() const { return total; } -void CumulativeLogger::AddLogger(const TimingLogger &logger) { - MutexLock mu(Thread::Current(), lock_); - DCHECK_EQ(logger.times_.size(), logger.labels_.size()); - for (size_t i = 1; i < logger.times_.size(); ++i) { - const uint64_t delta_time = logger.times_[i] - logger.times_[i - 1]; - const std::string &label = logger.labels_[i]; - AddPair(label, delta_time); - } -} -void CumulativeLogger::AddNewLogger(const base::NewTimingLogger &logger) { +void CumulativeLogger::AddLogger(const base::TimingLogger &logger) { MutexLock mu(Thread::Current(), lock_); const std::vector<std::pair<uint64_t, const char*> >& splits = logger.GetSplits(); typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It; @@ -183,51 +136,55 @@ void CumulativeLogger::DumpHistogram(std::ostream &os) { namespace base { -NewTimingLogger::NewTimingLogger(const char* name, bool precise, bool verbose) +TimingLogger::TimingLogger(const char* name, bool precise, bool verbose) : name_(name), precise_(precise), verbose_(verbose), current_split_(NULL), current_split_start_ns_(0) { } -void NewTimingLogger::Reset() { +void TimingLogger::Reset() { current_split_ = NULL; current_split_start_ns_ = 0; splits_.clear(); } -void NewTimingLogger::StartSplit(const char* new_split_label) { +void TimingLogger::StartSplit(const char* new_split_label) { DCHECK(current_split_ == NULL); if (verbose_) { LOG(INFO) << "Begin: " << new_split_label; } current_split_ = new_split_label; + ATRACE_BEGIN(current_split_); current_split_start_ns_ = NanoTime(); } // Ends the current split and starts the one given by the label. -void NewTimingLogger::NewSplit(const char* new_split_label) { +void TimingLogger::NewSplit(const char* new_split_label) { DCHECK(current_split_ != NULL); uint64_t current_time = NanoTime(); uint64_t split_time = current_time - current_split_start_ns_; + ATRACE_END(); splits_.push_back(std::pair<uint64_t, const char*>(split_time, current_split_)); if (verbose_) { LOG(INFO) << "End: " << current_split_ << " " << PrettyDuration(split_time) << "\n" << "Begin: " << new_split_label; } current_split_ = new_split_label; + ATRACE_BEGIN(current_split_); current_split_start_ns_ = current_time; } -void NewTimingLogger::EndSplit() { +void TimingLogger::EndSplit() { DCHECK(current_split_ != NULL); uint64_t current_time = NanoTime(); uint64_t split_time = current_time - current_split_start_ns_; + ATRACE_END(); if (verbose_) { LOG(INFO) << "End: " << current_split_ << " " << PrettyDuration(split_time); } splits_.push_back(std::pair<uint64_t, const char*>(split_time, current_split_)); } -uint64_t NewTimingLogger::GetTotalNs() const { +uint64_t TimingLogger::GetTotalNs() const { uint64_t total_ns = 0; typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It; for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) { @@ -237,7 +194,7 @@ uint64_t NewTimingLogger::GetTotalNs() const { return total_ns; } -void NewTimingLogger::Dump(std::ostream &os) const { +void TimingLogger::Dump(std::ostream &os) const { uint64_t longest_split = 0; uint64_t total_ns = 0; typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It; diff --git a/runtime/base/timing_logger.h b/runtime/base/timing_logger.h index 0f00a046e5..0998837517 100644 --- a/runtime/base/timing_logger.h +++ b/runtime/base/timing_logger.h @@ -26,27 +26,8 @@ namespace art { -class CumulativeLogger; - -class TimingLogger { - public: - explicit TimingLogger(const std::string& name, bool precise); - void AddSplit(const std::string& label); - void Dump(std::ostream& os) const; - void Reset(); - uint64_t GetTotalNs() const; - - protected: - const std::string name_; - const bool precise_; - std::vector<uint64_t> times_; - std::vector<std::string> labels_; - - friend class CumulativeLogger; -}; - namespace base { - class NewTimingLogger; + class TimingLogger; } // namespace base class CumulativeLogger { @@ -62,8 +43,7 @@ class CumulativeLogger { // Allow the name to be modified, particularly when the cumulative logger is a field within a // parent class that is unable to determine the "name" of a sub-class. void SetName(const std::string& name); - void AddLogger(const TimingLogger& logger) LOCKS_EXCLUDED(lock_); - void AddNewLogger(const base::NewTimingLogger& logger) LOCKS_EXCLUDED(lock_); + void AddLogger(const base::TimingLogger& logger) LOCKS_EXCLUDED(lock_); private: void AddPair(const std::string &label, uint64_t delta_time) @@ -84,16 +64,15 @@ class CumulativeLogger { namespace base { // A replacement to timing logger that know when a split starts for the purposes of logging. -// TODO: replace uses of TimingLogger with base::NewTimingLogger. -class NewTimingLogger { +class TimingLogger { public: - explicit NewTimingLogger(const char* name, bool precise, bool verbose); + explicit TimingLogger(const char* name, bool precise, bool verbose); // Clears current splits and labels. void Reset(); // Starts a split, a split shouldn't be in progress. - void StartSplit(const char* new_split_label); + void StartSplit(const char* new_split_label); // Ends the current split and starts the one given by the label. void NewSplit(const char* new_split_label); @@ -111,7 +90,7 @@ class NewTimingLogger { protected: // The name of the timing logger. - const std::string name_; + const char* name_; // Do we want to print the exactly recorded split (true) or round down to the time unit being // used (false). @@ -130,7 +109,7 @@ class NewTimingLogger { std::vector<std::pair<uint64_t, const char*> > splits_; private: - DISALLOW_COPY_AND_ASSIGN(NewTimingLogger); + DISALLOW_COPY_AND_ASSIGN(TimingLogger); }; } // namespace base diff --git a/runtime/common_test.h b/runtime/common_test.h index 09ad7fd7b7..4fe9be6d8f 100644 --- a/runtime/common_test.h +++ b/runtime/common_test.h @@ -473,7 +473,7 @@ class CommonTest : public testing::Test { void CompileMethod(mirror::AbstractMethod* method) SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) { CHECK(method != NULL); - TimingLogger timings("CommonTest::CompileMethod", false); + base::TimingLogger timings("CommonTest::CompileMethod", false, false); compiler_driver_->CompileOne(method, timings); MakeExecutable(method); } diff --git a/runtime/gc/collector/garbage_collector.h b/runtime/gc/collector/garbage_collector.h index 1684664eff..0f566c954b 100644 --- a/runtime/gc/collector/garbage_collector.h +++ b/runtime/gc/collector/garbage_collector.h @@ -64,7 +64,7 @@ class GarbageCollector { void RegisterPause(uint64_t nano_length); - base::NewTimingLogger& GetTimings() { + base::TimingLogger& GetTimings() { return timings_; } @@ -101,7 +101,7 @@ class GarbageCollector { const bool verbose_; uint64_t duration_ns_; - base::NewTimingLogger timings_; + base::TimingLogger timings_; // Cumulative statistics. uint64_t total_time_ns_; diff --git a/runtime/gc/collector/mark_sweep.cc b/runtime/gc/collector/mark_sweep.cc index c8e60322d6..0cbd6fb267 100644 --- a/runtime/gc/collector/mark_sweep.cc +++ b/runtime/gc/collector/mark_sweep.cc @@ -1509,7 +1509,7 @@ void MarkSweep::FinishPhase() { // Update the cumulative loggers. cumulative_timings_.Start(); - cumulative_timings_.AddNewLogger(timings_); + cumulative_timings_.AddLogger(timings_); cumulative_timings_.End(); // Clear all of the spaces' mark bitmaps. diff --git a/runtime/gc/heap.cc b/runtime/gc/heap.cc index 1c1818873a..b0ba8b6874 100644 --- a/runtime/gc/heap.cc +++ b/runtime/gc/heap.cc @@ -1131,7 +1131,7 @@ collector::GcType Heap::CollectGarbageInternal(collector::GcType gc_type, GcCaus << PrettySize(total_memory) << ", " << "paused " << pause_string.str() << " total " << PrettyDuration((duration / 1000) * 1000); if (VLOG_IS_ON(heap)) { - LOG(INFO) << Dumpable<base::NewTimingLogger>(collector->GetTimings()); + LOG(INFO) << Dumpable<base::TimingLogger>(collector->GetTimings()); } } @@ -1149,7 +1149,7 @@ collector::GcType Heap::CollectGarbageInternal(collector::GcType gc_type, GcCaus return gc_type; } -void Heap::UpdateAndMarkModUnion(collector::MarkSweep* mark_sweep, base::NewTimingLogger& timings, +void Heap::UpdateAndMarkModUnion(collector::MarkSweep* mark_sweep, base::TimingLogger& timings, collector::GcType gc_type) { if (gc_type == collector::kGcTypeSticky) { // Don't need to do anything for mod union table in this case since we are only scanning dirty @@ -1441,7 +1441,7 @@ void Heap::SwapStacks() { } } -void Heap::ProcessCards(base::NewTimingLogger& timings) { +void Heap::ProcessCards(base::TimingLogger& timings) { // Clear cards and keep track of cards cleared in the mod-union table. typedef std::vector<space::ContinuousSpace*>::iterator It; for (It it = continuous_spaces_.begin(), end = continuous_spaces_.end(); it != end; ++it) { diff --git a/runtime/gc/heap.h b/runtime/gc/heap.h index b7b2e84942..b71c2bc421 100644 --- a/runtime/gc/heap.h +++ b/runtime/gc/heap.h @@ -379,7 +379,7 @@ class Heap { EXCLUSIVE_LOCKS_REQUIRED(Locks::heap_bitmap_lock_); // Update and mark mod union table based on gc type. - void UpdateAndMarkModUnion(collector::MarkSweep* mark_sweep, base::NewTimingLogger& timings, + void UpdateAndMarkModUnion(collector::MarkSweep* mark_sweep, base::TimingLogger& timings, collector::GcType gc_type) EXCLUSIVE_LOCKS_REQUIRED(Locks::heap_bitmap_lock_); @@ -472,7 +472,7 @@ class Heap { void SwapStacks(); // Clear cards and update the mod union table. - void ProcessCards(base::NewTimingLogger& timings); + void ProcessCards(base::TimingLogger& timings); // All-known continuous spaces, where objects lie within fixed bounds. std::vector<space::ContinuousSpace*> continuous_spaces_; diff --git a/runtime/image_test.cc b/runtime/image_test.cc index 75eead4d8f..92ee1f83c6 100644 --- a/runtime/image_test.cc +++ b/runtime/image_test.cc @@ -44,7 +44,7 @@ TEST_F(ImageTest, WriteRead) { { jobject class_loader = NULL; ClassLinker* class_linker = Runtime::Current()->GetClassLinker(); - TimingLogger timings("ImageTest::WriteRead", false); + base::TimingLogger timings("ImageTest::WriteRead", false, false); compiler_driver_->CompileAll(class_loader, class_linker->GetBootClassPath(), timings); ScopedObjectAccess soa(Thread::Current()); diff --git a/runtime/oat_test.cc b/runtime/oat_test.cc index 3f2e43e985..217e2d8743 100644 --- a/runtime/oat_test.cc +++ b/runtime/oat_test.cc @@ -77,7 +77,7 @@ TEST_F(OatTest, WriteRead) { compiler_driver_.reset(new CompilerDriver(compiler_backend, kThumb2, false, NULL, 2, true)); jobject class_loader = NULL; if (compile) { - TimingLogger timings("OatTest::WriteRead", false); + base::TimingLogger timings("OatTest::WriteRead", false, false); compiler_driver_->CompileAll(class_loader, class_linker->GetBootClassPath(), timings); } @@ -96,7 +96,7 @@ TEST_F(OatTest, WriteRead) { ASSERT_TRUE(success); if (compile) { // OatWriter strips the code, regenerate to compare - TimingLogger timings("CommonTest::WriteRead", false); + base::TimingLogger timings("CommonTest::WriteRead", false, false); compiler_driver_->CompileAll(class_loader, class_linker->GetBootClassPath(), timings); } UniquePtr<OatFile> oat_file(OatFile::Open(tmp.GetFilename(), tmp.GetFilename(), NULL, false)); |