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
diff --git a/runtime/base/timing_logger.cc b/runtime/base/timing_logger.cc
index bf6fd17..dfb0220 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 @@
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 @@
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 @@
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 0f00a04..0998837 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 @@
// 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 @@
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 @@
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 @@
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 09ad7fd..4fe9be6 100644
--- a/runtime/common_test.h
+++ b/runtime/common_test.h
@@ -473,7 +473,7 @@
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 1684664..0f566c9 100644
--- a/runtime/gc/collector/garbage_collector.h
+++ b/runtime/gc/collector/garbage_collector.h
@@ -64,7 +64,7 @@
void RegisterPause(uint64_t nano_length);
- base::NewTimingLogger& GetTimings() {
+ base::TimingLogger& GetTimings() {
return timings_;
}
@@ -101,7 +101,7 @@
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 c8e6032..0cbd6fb 100644
--- a/runtime/gc/collector/mark_sweep.cc
+++ b/runtime/gc/collector/mark_sweep.cc
@@ -1509,7 +1509,7 @@
// 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 1c18188..b0ba8b6 100644
--- a/runtime/gc/heap.cc
+++ b/runtime/gc/heap.cc
@@ -1131,7 +1131,7 @@
<< 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 @@
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::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 b7b2e84..b71c2bc 100644
--- a/runtime/gc/heap.h
+++ b/runtime/gc/heap.h
@@ -379,7 +379,7 @@
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 @@
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 75eead4..92ee1f8 100644
--- a/runtime/image_test.cc
+++ b/runtime/image_test.cc
@@ -44,7 +44,7 @@
{
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 3f2e43e..217e2d8 100644
--- a/runtime/oat_test.cc
+++ b/runtime/oat_test.cc
@@ -77,7 +77,7 @@
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 @@
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));