1/*
2 * Copyright (C) 2012 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 *      http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17#include "timing_logger.h"
18
19#include "common_runtime_test.h"
20
21namespace art {
22
23class TimingLoggerTest : public CommonRuntimeTest {};
24
25// TODO: Negative test cases (improper pairing of EndSplit, etc.)
26
27TEST_F(TimingLoggerTest, StartEnd) {
28  const char* split1name = "First Split";
29  TimingLogger logger("StartEnd", true, false);
30  logger.StartTiming(split1name);
31  logger.EndTiming();  // Ends split1.
32  const auto& timings = logger.GetTimings();
33  EXPECT_EQ(2U, timings.size());  // Start, End splits
34  EXPECT_TRUE(timings[0].IsStartTiming());
35  EXPECT_STREQ(timings[0].GetName(), split1name);
36  EXPECT_TRUE(timings[1].IsEndTiming());
37}
38
39
40TEST_F(TimingLoggerTest, StartNewEnd) {
41  const char* split1name = "First Split";
42  const char* split2name = "Second Split";
43  const char* split3name = "Third Split";
44  TimingLogger logger("StartNewEnd", true, false);
45  logger.StartTiming(split1name);
46  logger.NewTiming(split2name);
47  logger.NewTiming(split3name);
48  logger.EndTiming();
49  // Get the timings and verify that they are sane.
50  const auto& timings = logger.GetTimings();
51  // 6 timings in the timing logger at this point.
52  EXPECT_EQ(6U, timings.size());
53  EXPECT_TRUE(timings[0].IsStartTiming());
54  EXPECT_STREQ(timings[0].GetName(), split1name);
55  EXPECT_TRUE(timings[1].IsEndTiming());
56  EXPECT_TRUE(timings[2].IsStartTiming());
57  EXPECT_STREQ(timings[2].GetName(), split2name);
58  EXPECT_TRUE(timings[3].IsEndTiming());
59  EXPECT_TRUE(timings[4].IsStartTiming());
60  EXPECT_STREQ(timings[4].GetName(), split3name);
61  EXPECT_TRUE(timings[5].IsEndTiming());
62}
63
64TEST_F(TimingLoggerTest, StartNewEndNested) {
65  const char* name1 = "First Split";
66  const char* name2 = "Second Split";
67  const char* name3 = "Third Split";
68  const char* name4 = "Fourth Split";
69  const char* name5 = "Fifth Split";
70  TimingLogger logger("StartNewEndNested", true, false);
71  logger.StartTiming(name1);
72  logger.NewTiming(name2);  // Ends timing1.
73  logger.StartTiming(name3);
74  logger.StartTiming(name4);
75  logger.NewTiming(name5);  // Ends timing4.
76  logger.EndTiming();  // Ends timing5.
77  logger.EndTiming();  // Ends timing3.
78  logger.EndTiming();  // Ends timing2.
79  const auto& timings = logger.GetTimings();
80  EXPECT_EQ(10U, timings.size());
81  size_t idx_1 = logger.FindTimingIndex(name1, 0);
82  size_t idx_2 = logger.FindTimingIndex(name2, 0);
83  size_t idx_3 = logger.FindTimingIndex(name3, 0);
84  size_t idx_4 = logger.FindTimingIndex(name4, 0);
85  size_t idx_5 = logger.FindTimingIndex(name5, 0);
86  size_t idx_6 = logger.FindTimingIndex("Not found", 0);
87  EXPECT_NE(idx_1, TimingLogger::kIndexNotFound);
88  EXPECT_NE(idx_2, TimingLogger::kIndexNotFound);
89  EXPECT_NE(idx_3, TimingLogger::kIndexNotFound);
90  EXPECT_NE(idx_4, TimingLogger::kIndexNotFound);
91  EXPECT_NE(idx_5, TimingLogger::kIndexNotFound);
92  EXPECT_EQ(idx_6, TimingLogger::kIndexNotFound);
93  TimingLogger::TimingData data = logger.CalculateTimingData();
94  EXPECT_STREQ(timings[idx_1].GetName(), name1);
95  EXPECT_STREQ(timings[idx_2].GetName(), name2);
96  EXPECT_STREQ(timings[idx_3].GetName(), name3);
97  EXPECT_STREQ(timings[idx_4].GetName(), name4);
98  EXPECT_STREQ(timings[idx_5].GetName(), name5);
99}
100
101
102TEST_F(TimingLoggerTest, Scoped) {
103  const char* outersplit = "Outer Split";
104  const char* innersplit1 = "Inner Split 1";
105  const char* innerinnersplit1 = "Inner Inner Split 1";
106  const char* innersplit2 = "Inner Split 2";
107  TimingLogger logger("Scoped", true, false);
108  {
109    TimingLogger::ScopedTiming outer(outersplit, &logger);
110    {
111      TimingLogger::ScopedTiming inner1(innersplit1, &logger);
112      {
113        TimingLogger::ScopedTiming innerinner1(innerinnersplit1, &logger);
114      }  // Ends innerinnersplit1.
115    }  // Ends innersplit1.
116    {
117      TimingLogger::ScopedTiming inner2(innersplit2, &logger);
118    }  // Ends innersplit2.
119  }  // Ends outersplit.
120  const size_t idx_outersplit = logger.FindTimingIndex(outersplit, 0);
121  const size_t idx_innersplit1 = logger.FindTimingIndex(innersplit1, 0);
122  const size_t idx_innerinnersplit1 = logger.FindTimingIndex(innerinnersplit1, 0);
123  const size_t idx_innersplit2 = logger.FindTimingIndex(innersplit2, 0);
124  const auto& timings = logger.GetTimings();
125  EXPECT_EQ(8U, timings.size());  // 4 start timings and 4 end timings.
126  EXPECT_GE(timings[idx_innerinnersplit1].GetTime(), timings[idx_innersplit1].GetTime());
127  EXPECT_GE(timings[idx_innersplit2].GetTime(), timings[idx_innersplit1].GetTime());
128  TimingLogger::TimingData data(logger.CalculateTimingData());
129  EXPECT_GE(data.GetTotalTime(idx_outersplit), data.GetTotalTime(idx_innerinnersplit1));
130  EXPECT_GE(data.GetTotalTime(idx_outersplit),
131            data.GetTotalTime(idx_innersplit1) + data.GetTotalTime(idx_innersplit2));
132  EXPECT_GE(data.GetTotalTime(idx_innersplit1), data.GetTotalTime(idx_innerinnersplit1));
133}
134
135
136TEST_F(TimingLoggerTest, ScopedAndExplicit) {
137  const char* outersplit = "Outer Split";
138  const char* innersplit = "Inner Split";
139  const char* innerinnersplit1 = "Inner Inner Split 1";
140  const char* innerinnersplit2 = "Inner Inner Split 2";
141  TimingLogger logger("Scoped", true, false);
142  logger.StartTiming(outersplit);
143  {
144    TimingLogger::ScopedTiming inner(innersplit, &logger);
145    logger.StartTiming(innerinnersplit1);
146    logger.NewTiming(innerinnersplit2);  // Ends innerinnersplit1.
147    logger.EndTiming();
148  }  // Ends innerinnersplit2, then innersplit.
149  logger.EndTiming();  // Ends outersplit.
150  const size_t idx_outersplit = logger.FindTimingIndex(outersplit, 0);
151  const size_t idx_innersplit = logger.FindTimingIndex(innersplit, 0);
152  const size_t idx_innerinnersplit1 = logger.FindTimingIndex(innerinnersplit1, 0);
153  const size_t idx_innerinnersplit2 = logger.FindTimingIndex(innerinnersplit2, 0);
154  const auto& timings = logger.GetTimings();
155  EXPECT_EQ(8U, timings.size());
156  EXPECT_LE(timings[idx_outersplit].GetTime(), timings[idx_innersplit].GetTime());
157  EXPECT_LE(timings[idx_innersplit].GetTime(), timings[idx_innerinnersplit1].GetTime());
158  EXPECT_LE(timings[idx_innerinnersplit1].GetTime(), timings[idx_innerinnersplit2].GetTime());
159}
160
161}  // namespace art
162