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 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 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 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 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 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 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
