Systrace fixups and refactoring for TimingLogger
Fixed systrace bounds for timing logger in GC. Refactored CumulativeLogger a bit to
allow for multiple identical entries. Added ScopedSplit, now composes with explicit
start/end/new splits. Adds some unit tests.
Bug: 10036801
Change-Id: If0afb88b48ec3a1e19462ed354babb274a9517a7
diff --git a/runtime/base/timing_logger.h b/runtime/base/timing_logger.h
index 0998837..8649a96 100644
--- a/runtime/base/timing_logger.h
+++ b/runtime/base/timing_logger.h
@@ -23,6 +23,7 @@
#include <string>
#include <vector>
+#include <map>
namespace art {
@@ -32,6 +33,9 @@
class CumulativeLogger {
public:
+ typedef std::map<std::string, Histogram<uint64_t> *> Histograms;
+ typedef std::map<std::string, Histogram<uint64_t> *>::const_iterator HistogramsIterator;
+
explicit CumulativeLogger(const std::string& name);
void prepare_stats();
~CumulativeLogger();
@@ -51,11 +55,10 @@
void DumpHistogram(std::ostream &os) EXCLUSIVE_LOCKS_REQUIRED(lock_);
uint64_t GetTotalTime() const;
static const uint64_t kAdjust = 1000;
- std::vector<Histogram<uint64_t> *> histograms_ GUARDED_BY(lock_);
+ Histograms histograms_ GUARDED_BY(lock_);
std::string name_;
const std::string lock_name_;
mutable Mutex lock_ DEFAULT_MUTEX_ACQUIRED_AFTER;
- size_t index_ GUARDED_BY(lock_);
size_t iterations_ GUARDED_BY(lock_);
DISALLOW_COPY_AND_ASSIGN(CumulativeLogger);
@@ -63,16 +66,22 @@
namespace base {
-// A replacement to timing logger that know when a split starts for the purposes of logging.
+
+// A timing logger that knows when a split starts for the purposes of logging tools, like systrace.
class TimingLogger {
public:
+ // Splits are nanosecond times and split names.
+ typedef std::pair<uint64_t, const char*> SplitTiming;
+ typedef std::vector<SplitTiming> SplitTimings;
+ typedef std::vector<SplitTiming>::const_iterator SplitsIterator;
+
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);
+ // Starts a split
+ 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);
@@ -84,10 +93,53 @@
void Dump(std::ostream& os) const;
- const std::vector<std::pair<uint64_t, const char*> >& GetSplits() const {
+ // Scoped timing splits that can be nested and composed with the explicit split
+ // starts and ends.
+ class ScopedSplit {
+ public:
+ explicit ScopedSplit(const char* label, TimingLogger* timing_logger);
+
+ ~ScopedSplit();
+
+ friend class TimingLogger;
+
+ private:
+ // Pauses timing of the split, usually due to nesting of another split.
+ void Pause();
+
+ // Unpauses timing of the split, usually because a nested split has ended.
+ void UnPause();
+
+ // Used by new split to swap splits in place in a ScopedSplit instance.
+ void TailInsertSplit(const char* label);
+
+ // The scoped split immediately enclosing this split. Essentially, we get a
+ // stack of nested splits through this field.
+ ScopedSplit* enclosing_split_;
+
+ // Was this created via TimingLogger's StartSplit?
+ bool explicit_;
+
+ // The split's name.
+ const char* label_;
+
+ // The current split's latest start time. (It may have been paused and restarted.)
+ uint64_t start_ns_;
+
+ // The running time, outside of pauses.
+ uint64_t running_ns_;
+
+ // The timing logger holding this split.
+ TimingLogger* timing_logger_;
+
+ DISALLOW_COPY_AND_ASSIGN(ScopedSplit);
+ };
+
+ const SplitTimings& GetSplits() const {
return splits_;
}
+ friend class ScopedSplit;
protected:
// The name of the timing logger.
const char* name_;
@@ -99,14 +151,11 @@
// Verbose logging.
const bool verbose_;
- // The name of the current split.
- const char* current_split_;
+ // The current scoped split is also the 'top' of the stack of splits in progress.
+ ScopedSplit* current_split_;
- // The nanosecond time the current split started on.
- uint64_t current_split_start_ns_;
-
- // Splits are nanosecond times and split names.
- std::vector<std::pair<uint64_t, const char*> > splits_;
+ // Splits that have ended.
+ SplitTimings splits_;
private:
DISALLOW_COPY_AND_ASSIGN(TimingLogger);