Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 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 | |
Brian Carlstrom | a1ce1fe | 2014-02-24 23:23:58 -0800 | [diff] [blame] | 19 | #include "common_runtime_test.h" |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 20 | |
| 21 | namespace art { |
| 22 | |
Brian Carlstrom | a1ce1fe | 2014-02-24 23:23:58 -0800 | [diff] [blame] | 23 | class TimingLoggerTest : public CommonRuntimeTest {}; |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 24 | |
| 25 | // TODO: Negative test cases (improper pairing of EndSplit, etc.) |
| 26 | |
| 27 | TEST_F(TimingLoggerTest, StartEnd) { |
| 28 | const char* split1name = "First Split"; |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 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()); |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 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"; |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 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()); |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 62 | } |
| 63 | |
| 64 | TEST_F(TimingLoggerTest, StartNewEndNested) { |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 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); |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 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"; |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 107 | TimingLogger logger("Scoped", true, false); |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 108 | { |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 109 | TimingLogger::ScopedTiming outer(outersplit, &logger); |
| 110 | { |
| 111 | TimingLogger::ScopedTiming inner1(innersplit1, &logger); |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 112 | { |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 113 | TimingLogger::ScopedTiming innerinner1(innerinnersplit1, &logger); |
| 114 | } // Ends innerinnersplit1. |
| 115 | } // Ends innersplit1. |
| 116 | { |
| 117 | TimingLogger::ScopedTiming inner2(innersplit2, &logger); |
| 118 | } // Ends innersplit2. |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 119 | } // Ends outersplit. |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 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)); |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 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"; |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 141 | TimingLogger logger("Scoped", true, false); |
| 142 | logger.StartTiming(outersplit); |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 143 | { |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 144 | TimingLogger::ScopedTiming inner(innersplit, &logger); |
| 145 | logger.StartTiming(innerinnersplit1); |
| 146 | logger.NewTiming(innerinnersplit2); // Ends innerinnersplit1. |
| 147 | logger.EndTiming(); |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 148 | } // Ends innerinnersplit2, then innersplit. |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 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()); |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 159 | } |
| 160 | |
| 161 | } // namespace art |