From f5997b4d3f889569d5a2b724d83d764bfbb8d106 Mon Sep 17 00:00:00 2001 From: Mathieu Chartier Date: Fri, 20 Jun 2014 10:37:54 -0700 Subject: 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 --- runtime/utils_test.cc | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) (limited to 'runtime/utils_test.cc') diff --git a/runtime/utils_test.cc b/runtime/utils_test.cc index 4a1e477bbd..7cd5980c44 100644 --- a/runtime/utils_test.cc +++ b/runtime/utils_test.cc @@ -171,14 +171,15 @@ TEST_F(UtilsTest, PrettyDuration) { EXPECT_EQ("10s", PrettyDuration(10 * one_sec)); EXPECT_EQ("100s", PrettyDuration(100 * one_sec)); EXPECT_EQ("1.001s", PrettyDuration(1 * one_sec + one_ms)); - EXPECT_EQ("1.000001s", PrettyDuration(1 * one_sec + one_us)); - EXPECT_EQ("1.000000001s", PrettyDuration(1 * one_sec + 1)); + EXPECT_EQ("1.000001s", PrettyDuration(1 * one_sec + one_us, 6)); + EXPECT_EQ("1.000000001s", PrettyDuration(1 * one_sec + 1, 9)); + EXPECT_EQ("1.000s", PrettyDuration(1 * one_sec + one_us, 3)); EXPECT_EQ("1ms", PrettyDuration(1 * one_ms)); EXPECT_EQ("10ms", PrettyDuration(10 * one_ms)); EXPECT_EQ("100ms", PrettyDuration(100 * one_ms)); EXPECT_EQ("1.001ms", PrettyDuration(1 * one_ms + one_us)); - EXPECT_EQ("1.000001ms", PrettyDuration(1 * one_ms + 1)); + EXPECT_EQ("1.000001ms", PrettyDuration(1 * one_ms + 1, 6)); EXPECT_EQ("1us", PrettyDuration(1 * one_us)); EXPECT_EQ("10us", PrettyDuration(10 * one_us)); -- cgit v1.2.3-59-g8ed1b