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 
21 namespace art {
22 
23 class TimingLoggerTest : public CommonRuntimeTest {};
24 
25 // TODO: Negative test cases (improper pairing of EndSplit, etc.)
26 
TEST_F(TimingLoggerTest,StartEnd)27 TEST_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 
TEST_F(TimingLoggerTest,StartNewEnd)40 TEST_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 
TEST_F(TimingLoggerTest,StartNewEndNested)64 TEST_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 
TEST_F(TimingLoggerTest,Scoped)102 TEST_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 
TEST_F(TimingLoggerTest,ScopedAndExplicit)136 TEST_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 
TEST_F(TimingLoggerTest,ThreadCpuAndMonotonic)161 TEST_F(TimingLoggerTest, ThreadCpuAndMonotonic) {
162   TimingLogger mon_logger("Scoped", true, false, TimingLogger::TimingKind::kMonotonic);
163   TimingLogger cpu_logger("Scoped", true, false, TimingLogger::TimingKind::kThreadCpu);
164   mon_logger.StartTiming("MON");
165   cpu_logger.StartTiming("CPU");
166 
167   sleep(2);
168 
169   cpu_logger.EndTiming();
170   mon_logger.EndTiming();
171   uint64_t mon_timing = mon_logger.GetTimings()[1].GetTime() - mon_logger.GetTimings()[0].GetTime();
172   uint64_t cpu_timing = cpu_logger.GetTimings()[1].GetTime() - cpu_logger.GetTimings()[0].GetTime();
173   EXPECT_LT(cpu_timing, MsToNs(1000u));
174   EXPECT_GT(mon_timing, MsToNs(1000u));
175   EXPECT_LT(cpu_timing, mon_timing);
176 }
177 
178 }  // namespace art
179