diff options
| author | Mathieu Chartier <mathieuc@google.com> | 2014-06-20 10:37:54 -0700 |
|---|---|---|
| committer | Mathieu Chartier <mathieuc@google.com> | 2014-06-24 13:45:05 -0700 |
| commit | f5997b4d3f889569d5a2b724d83d764bfbb8d106 (patch) | |
| tree | f0d3b3890a604a8b3c4c87c0f408f86df041690e /runtime/base/histogram-inl.h | |
| parent | 9658d24deaa9bd07781bfac860d2a6dd89066d55 (diff) | |
| download | art-f5997b4d3f889569d5a2b724d83d764bfbb8d106.zip art-f5997b4d3f889569d5a2b724d83d764bfbb8d106.tar.gz art-f5997b4d3f889569d5a2b724d83d764bfbb8d106.tar.bz2 | |
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
Diffstat (limited to 'runtime/base/histogram-inl.h')
| -rw-r--r-- | runtime/base/histogram-inl.h | 20 |
1 files changed, 10 insertions, 10 deletions
diff --git a/runtime/base/histogram-inl.h b/runtime/base/histogram-inl.h index 7c09999..4c18ce4 100644 --- a/runtime/base/histogram-inl.h +++ b/runtime/base/histogram-inl.h @@ -164,18 +164,18 @@ inline void Histogram<Value>::PrintBins(std::ostream& os, const CumulativeData& template <class Value> inline void Histogram<Value>::PrintConfidenceIntervals(std::ostream &os, double interval, const CumulativeData& data) const { + static constexpr size_t kFractionalDigits = 3; DCHECK_GT(interval, 0); DCHECK_LT(interval, 1.0); - - double per_0 = (1.0 - interval) / 2.0; - double per_1 = per_0 + interval; - TimeUnit unit = GetAppropriateTimeUnit(Mean() * kAdjust); - os << Name() << ":\tSum: "; - os << PrettyDuration(Sum() * kAdjust) << " "; - os << (interval * 100) << "% C.I. " << FormatDuration(Percentile(per_0, data) * kAdjust, unit); - os << "-" << FormatDuration(Percentile(per_1, data) * kAdjust, unit) << " "; - os << "Avg: " << FormatDuration(Mean() * kAdjust, unit) << " Max: "; - os << FormatDuration(Max() * kAdjust, unit) << "\n"; + const double per_0 = (1.0 - interval) / 2.0; + const double per_1 = per_0 + interval; + const TimeUnit unit = GetAppropriateTimeUnit(Mean() * kAdjust); + os << Name() << ":\tSum: " << PrettyDuration(Sum() * kAdjust) << " " + << (interval * 100) << "% C.I. " << FormatDuration(Percentile(per_0, data) * kAdjust, unit, + kFractionalDigits) + << "-" << FormatDuration(Percentile(per_1, data) * kAdjust, unit, kFractionalDigits) << " " + << "Avg: " << FormatDuration(Mean() * kAdjust, unit, kFractionalDigits) << " Max: " + << FormatDuration(Max() * kAdjust, unit, kFractionalDigits) << "\n"; } template <class Value> |