diff options
-rw-r--r-- | liblog/tests/Android.mk | 7 | ||||
-rw-r--r-- | liblog/tests/benchmark.h | 147 | ||||
-rw-r--r-- | liblog/tests/benchmark_main.cpp | 247 | ||||
-rw-r--r-- | liblog/tests/liblog_benchmark.cpp | 288 |
4 files changed, 133 insertions, 556 deletions
diff --git a/liblog/tests/Android.mk b/liblog/tests/Android.mk index 39b52ac35..cfa849ba4 100644 --- a/liblog/tests/Android.mk +++ b/liblog/tests/Android.mk | |||
@@ -24,13 +24,12 @@ test_module_prefix := liblog- | |||
24 | test_tags := tests | 24 | test_tags := tests |
25 | 25 | ||
26 | benchmark_c_flags := \ | 26 | benchmark_c_flags := \ |
27 | -Ibionic/tests \ | 27 | -Wall \ |
28 | -Wall -Wextra \ | 28 | -Wextra \ |
29 | -Werror \ | 29 | -Werror \ |
30 | -fno-builtin \ | 30 | -fno-builtin \ |
31 | 31 | ||
32 | benchmark_src_files := \ | 32 | benchmark_src_files := \ |
33 | benchmark_main.cpp \ | ||
34 | liblog_benchmark.cpp | 33 | liblog_benchmark.cpp |
35 | 34 | ||
36 | # Build benchmarks for the device. Run with: | 35 | # Build benchmarks for the device. Run with: |
@@ -41,7 +40,7 @@ LOCAL_MODULE_TAGS := $(test_tags) | |||
41 | LOCAL_CFLAGS += $(benchmark_c_flags) | 40 | LOCAL_CFLAGS += $(benchmark_c_flags) |
42 | LOCAL_SHARED_LIBRARIES += liblog libm libbase | 41 | LOCAL_SHARED_LIBRARIES += liblog libm libbase |
43 | LOCAL_SRC_FILES := $(benchmark_src_files) | 42 | LOCAL_SRC_FILES := $(benchmark_src_files) |
44 | include $(BUILD_NATIVE_TEST) | 43 | include $(BUILD_NATIVE_BENCHMARK) |
45 | 44 | ||
46 | # ----------------------------------------------------------------------------- | 45 | # ----------------------------------------------------------------------------- |
47 | # Unit tests. | 46 | # Unit tests. |
diff --git a/liblog/tests/benchmark.h b/liblog/tests/benchmark.h deleted file mode 100644 index e9280f63e..000000000 --- a/liblog/tests/benchmark.h +++ /dev/null | |||
@@ -1,147 +0,0 @@ | |||
1 | /* | ||
2 | * Copyright (C) 2012-2014 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 <stdint.h> | ||
18 | #include <stdio.h> | ||
19 | #include <stdlib.h> | ||
20 | #include <string.h> | ||
21 | |||
22 | #include <vector> | ||
23 | |||
24 | #ifndef BIONIC_BENCHMARK_H_ | ||
25 | #define BIONIC_BENCHMARK_H_ | ||
26 | |||
27 | namespace testing { | ||
28 | |||
29 | class Benchmark; | ||
30 | template <typename T> class BenchmarkWantsArg; | ||
31 | template <typename T> class BenchmarkWithArg; | ||
32 | |||
33 | void BenchmarkRegister(Benchmark* bm); | ||
34 | int PrettyPrintInt(char* str, int len, unsigned int arg); | ||
35 | |||
36 | class Benchmark { | ||
37 | public: | ||
38 | Benchmark(const char* name, void (*fn)(int)) : name_(strdup(name)), fn_(fn) { | ||
39 | BenchmarkRegister(this); | ||
40 | } | ||
41 | explicit Benchmark(const char* name) : name_(strdup(name)), fn_(NULL) {} | ||
42 | |||
43 | virtual ~Benchmark() { | ||
44 | free(name_); | ||
45 | } | ||
46 | |||
47 | const char* Name() { return name_; } | ||
48 | virtual const char* ArgName() { return NULL; } | ||
49 | virtual void RunFn(int iterations) { fn_(iterations); } | ||
50 | |||
51 | protected: | ||
52 | char* name_; | ||
53 | |||
54 | private: | ||
55 | void (*fn_)(int); | ||
56 | }; | ||
57 | |||
58 | template <typename T> | ||
59 | class BenchmarkWantsArgBase : public Benchmark { | ||
60 | public: | ||
61 | BenchmarkWantsArgBase(const char* name, void (*fn)(int, T)) : Benchmark(name) { | ||
62 | fn_arg_ = fn; | ||
63 | } | ||
64 | |||
65 | BenchmarkWantsArgBase<T>* Arg(const char* arg_name, T arg) { | ||
66 | BenchmarkRegister(new BenchmarkWithArg<T>(name_, fn_arg_, arg_name, arg)); | ||
67 | return this; | ||
68 | } | ||
69 | |||
70 | protected: | ||
71 | virtual void RunFn(int) { printf("can't run arg benchmark %s without arg\n", Name()); } | ||
72 | void (*fn_arg_)(int, T); | ||
73 | }; | ||
74 | |||
75 | template <typename T> | ||
76 | class BenchmarkWithArg : public BenchmarkWantsArg<T> { | ||
77 | public: | ||
78 | BenchmarkWithArg(const char* name, void (*fn)(int, T), const char* arg_name, T arg) : | ||
79 | BenchmarkWantsArg<T>(name, fn), arg_(arg) { | ||
80 | arg_name_ = strdup(arg_name); | ||
81 | } | ||
82 | |||
83 | virtual ~BenchmarkWithArg() { | ||
84 | free(arg_name_); | ||
85 | } | ||
86 | |||
87 | virtual const char* ArgName() { return arg_name_; } | ||
88 | |||
89 | protected: | ||
90 | virtual void RunFn(int iterations) { BenchmarkWantsArg<T>::fn_arg_(iterations, arg_); } | ||
91 | |||
92 | private: | ||
93 | T arg_; | ||
94 | char* arg_name_; | ||
95 | }; | ||
96 | |||
97 | template <typename T> | ||
98 | class BenchmarkWantsArg : public BenchmarkWantsArgBase<T> { | ||
99 | public: | ||
100 | BenchmarkWantsArg<T>(const char* name, void (*fn)(int, T)) : | ||
101 | BenchmarkWantsArgBase<T>(name, fn) { } | ||
102 | }; | ||
103 | |||
104 | template <> | ||
105 | class BenchmarkWantsArg<int> : public BenchmarkWantsArgBase<int> { | ||
106 | public: | ||
107 | BenchmarkWantsArg<int>(const char* name, void (*fn)(int, int)) : | ||
108 | BenchmarkWantsArgBase<int>(name, fn) { } | ||
109 | |||
110 | BenchmarkWantsArg<int>* Arg(int arg) { | ||
111 | char arg_name[100]; | ||
112 | PrettyPrintInt(arg_name, sizeof(arg_name), arg); | ||
113 | BenchmarkRegister(new BenchmarkWithArg<int>(name_, fn_arg_, arg_name, arg)); | ||
114 | return this; | ||
115 | } | ||
116 | }; | ||
117 | |||
118 | static inline Benchmark* BenchmarkFactory(const char* name, void (*fn)(int)) { | ||
119 | return new Benchmark(name, fn); | ||
120 | } | ||
121 | |||
122 | template <typename T> | ||
123 | static inline BenchmarkWantsArg<T>* BenchmarkFactory(const char* name, void (*fn)(int, T)) { | ||
124 | return new BenchmarkWantsArg<T>(name, fn); | ||
125 | } | ||
126 | |||
127 | } // namespace testing | ||
128 | |||
129 | template <typename T> | ||
130 | static inline void BenchmarkAddArg(::testing::Benchmark* b, const char* name, T arg) { | ||
131 | ::testing::BenchmarkWantsArg<T>* ba; | ||
132 | ba = static_cast< ::testing::BenchmarkWantsArg<T>* >(b); | ||
133 | ba->Arg(name, arg); | ||
134 | } | ||
135 | |||
136 | void SetBenchmarkBytesProcessed(uint64_t); | ||
137 | void ResetBenchmarkTiming(void); | ||
138 | void StopBenchmarkTiming(void); | ||
139 | void StartBenchmarkTiming(void); | ||
140 | void StartBenchmarkTiming(uint64_t); | ||
141 | void StopBenchmarkTiming(uint64_t); | ||
142 | |||
143 | #define BENCHMARK(f) \ | ||
144 | static ::testing::Benchmark* _benchmark_##f __attribute__((unused)) = /* NOLINT */ \ | ||
145 | (::testing::Benchmark*)::testing::BenchmarkFactory(#f, f) /* NOLINT */ | ||
146 | |||
147 | #endif // BIONIC_BENCHMARK_H_ | ||
diff --git a/liblog/tests/benchmark_main.cpp b/liblog/tests/benchmark_main.cpp deleted file mode 100644 index 7367f1b52..000000000 --- a/liblog/tests/benchmark_main.cpp +++ /dev/null | |||
@@ -1,247 +0,0 @@ | |||
1 | /* | ||
2 | * Copyright (C) 2012-2014 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 <benchmark.h> | ||
18 | |||
19 | #include <inttypes.h> | ||
20 | #include <math.h> | ||
21 | #include <regex.h> | ||
22 | #include <stdio.h> | ||
23 | #include <stdlib.h> | ||
24 | |||
25 | #include <map> | ||
26 | #include <string> | ||
27 | #include <vector> | ||
28 | |||
29 | static uint64_t gBytesProcessed; | ||
30 | static uint64_t gBenchmarkTotalTimeNs; | ||
31 | static uint64_t gBenchmarkTotalTimeNsSquared; | ||
32 | static uint64_t gBenchmarkNum; | ||
33 | static uint64_t gBenchmarkStartTimeNs; | ||
34 | |||
35 | typedef std::vector< ::testing::Benchmark*> BenchmarkList; | ||
36 | static BenchmarkList* gBenchmarks; | ||
37 | |||
38 | static int Round(int n) { | ||
39 | int base = 1; | ||
40 | while (base * 10 < n) { | ||
41 | base *= 10; | ||
42 | } | ||
43 | if (n < 2 * base) { | ||
44 | return 2 * base; | ||
45 | } | ||
46 | if (n < 5 * base) { | ||
47 | return 5 * base; | ||
48 | } | ||
49 | return 10 * base; | ||
50 | } | ||
51 | |||
52 | static uint64_t NanoTime() { | ||
53 | struct timespec t; | ||
54 | t.tv_sec = t.tv_nsec = 0; | ||
55 | clock_gettime(CLOCK_MONOTONIC, &t); | ||
56 | return static_cast<uint64_t>(t.tv_sec) * 1000000000ULL + t.tv_nsec; | ||
57 | } | ||
58 | |||
59 | namespace testing { | ||
60 | |||
61 | int PrettyPrintInt(char* str, int len, unsigned int arg) { | ||
62 | if (arg >= (1 << 30) && arg % (1 << 30) == 0) { | ||
63 | return snprintf(str, len, "%uGi", arg / (1 << 30)); | ||
64 | } else if (arg >= (1 << 20) && arg % (1 << 20) == 0) { | ||
65 | return snprintf(str, len, "%uMi", arg / (1 << 20)); | ||
66 | } else if (arg >= (1 << 10) && arg % (1 << 10) == 0) { | ||
67 | return snprintf(str, len, "%uKi", arg / (1 << 10)); | ||
68 | } else if (arg >= 1000000000 && arg % 1000000000 == 0) { | ||
69 | return snprintf(str, len, "%uG", arg / 1000000000); | ||
70 | } else if (arg >= 1000000 && arg % 1000000 == 0) { | ||
71 | return snprintf(str, len, "%uM", arg / 1000000); | ||
72 | } else if (arg >= 1000 && arg % 1000 == 0) { | ||
73 | return snprintf(str, len, "%uK", arg / 1000); | ||
74 | } else { | ||
75 | return snprintf(str, len, "%u", arg); | ||
76 | } | ||
77 | } | ||
78 | |||
79 | bool ShouldRun(Benchmark* b, int argc, char* argv[]) { | ||
80 | if (argc == 1) { | ||
81 | return true; // With no arguments, we run all benchmarks. | ||
82 | } | ||
83 | // Otherwise, we interpret each argument as a regular expression and | ||
84 | // see if any of our benchmarks match. | ||
85 | for (int i = 1; i < argc; i++) { | ||
86 | regex_t re; | ||
87 | if (regcomp(&re, argv[i], 0) != 0) { | ||
88 | fprintf(stderr, "couldn't compile \"%s\" as a regular expression!\n", | ||
89 | argv[i]); | ||
90 | exit(EXIT_FAILURE); | ||
91 | } | ||
92 | int match = regexec(&re, b->Name(), 0, NULL, 0); | ||
93 | regfree(&re); | ||
94 | if (match != REG_NOMATCH) { | ||
95 | return true; | ||
96 | } | ||
97 | } | ||
98 | return false; | ||
99 | } | ||
100 | |||
101 | void BenchmarkRegister(Benchmark* b) { | ||
102 | if (gBenchmarks == NULL) { | ||
103 | gBenchmarks = new BenchmarkList; | ||
104 | } | ||
105 | gBenchmarks->push_back(b); | ||
106 | } | ||
107 | |||
108 | void RunRepeatedly(Benchmark* b, int iterations) { | ||
109 | gBytesProcessed = 0; | ||
110 | ResetBenchmarkTiming(); | ||
111 | uint64_t StartTimeNs = NanoTime(); | ||
112 | b->RunFn(iterations); | ||
113 | // Catch us if we fail to log anything. | ||
114 | if ((gBenchmarkTotalTimeNs == 0) && (StartTimeNs != 0) && | ||
115 | (gBenchmarkStartTimeNs == 0)) { | ||
116 | gBenchmarkTotalTimeNs = NanoTime() - StartTimeNs; | ||
117 | } | ||
118 | } | ||
119 | |||
120 | void Run(Benchmark* b) { | ||
121 | // run once in case it's expensive | ||
122 | unsigned iterations = 1; | ||
123 | uint64_t s = NanoTime(); | ||
124 | RunRepeatedly(b, iterations); | ||
125 | s = NanoTime() - s; | ||
126 | while (s < 2e9 && gBenchmarkTotalTimeNs < 1e9 && iterations < 1e9) { | ||
127 | unsigned last = iterations; | ||
128 | if (gBenchmarkTotalTimeNs / iterations == 0) { | ||
129 | iterations = 1e9; | ||
130 | } else { | ||
131 | iterations = 1e9 / (gBenchmarkTotalTimeNs / iterations); | ||
132 | } | ||
133 | iterations = | ||
134 | std::max(last + 1, std::min(iterations + iterations / 2, 100 * last)); | ||
135 | iterations = Round(iterations); | ||
136 | s = NanoTime(); | ||
137 | RunRepeatedly(b, iterations); | ||
138 | s = NanoTime() - s; | ||
139 | } | ||
140 | |||
141 | char throughput[100]; | ||
142 | throughput[0] = '\0'; | ||
143 | if (gBenchmarkTotalTimeNs > 0 && gBytesProcessed > 0) { | ||
144 | double mib_processed = static_cast<double>(gBytesProcessed) / 1e6; | ||
145 | double seconds = static_cast<double>(gBenchmarkTotalTimeNs) / 1e9; | ||
146 | snprintf(throughput, sizeof(throughput), " %8.2f MiB/s", | ||
147 | mib_processed / seconds); | ||
148 | } | ||
149 | |||
150 | char full_name[100]; | ||
151 | snprintf(full_name, sizeof(full_name), "%s%s%s", b->Name(), | ||
152 | b->ArgName() ? "/" : "", b->ArgName() ? b->ArgName() : ""); | ||
153 | |||
154 | uint64_t mean = gBenchmarkTotalTimeNs / iterations; | ||
155 | uint64_t sdev = 0; | ||
156 | if (gBenchmarkNum == iterations) { | ||
157 | mean = gBenchmarkTotalTimeNs / gBenchmarkNum; | ||
158 | uint64_t nXvariance = gBenchmarkTotalTimeNsSquared * gBenchmarkNum - | ||
159 | (gBenchmarkTotalTimeNs * gBenchmarkTotalTimeNs); | ||
160 | sdev = (sqrt((double)nXvariance) / gBenchmarkNum / gBenchmarkNum) + 0.5; | ||
161 | } | ||
162 | if (mean > (10000 * sdev)) { | ||
163 | printf("%-25s %10" PRIu64 " %10" PRIu64 "%s\n", full_name, | ||
164 | static_cast<uint64_t>(iterations), mean, throughput); | ||
165 | } else { | ||
166 | printf("%-25s %10" PRIu64 " %10" PRIu64 "(\317\203%" PRIu64 ")%s\n", | ||
167 | full_name, static_cast<uint64_t>(iterations), mean, sdev, throughput); | ||
168 | } | ||
169 | fflush(stdout); | ||
170 | } | ||
171 | |||
172 | } // namespace testing | ||
173 | |||
174 | void SetBenchmarkBytesProcessed(uint64_t x) { | ||
175 | gBytesProcessed = x; | ||
176 | } | ||
177 | |||
178 | void ResetBenchmarkTiming() { | ||
179 | gBenchmarkStartTimeNs = 0; | ||
180 | gBenchmarkTotalTimeNs = 0; | ||
181 | gBenchmarkTotalTimeNsSquared = 0; | ||
182 | gBenchmarkNum = 0; | ||
183 | } | ||
184 | |||
185 | void StopBenchmarkTiming(void) { | ||
186 | if (gBenchmarkStartTimeNs != 0) { | ||
187 | int64_t diff = NanoTime() - gBenchmarkStartTimeNs; | ||
188 | gBenchmarkTotalTimeNs += diff; | ||
189 | gBenchmarkTotalTimeNsSquared += diff * diff; | ||
190 | ++gBenchmarkNum; | ||
191 | } | ||
192 | gBenchmarkStartTimeNs = 0; | ||
193 | } | ||
194 | |||
195 | void StartBenchmarkTiming(void) { | ||
196 | if (gBenchmarkStartTimeNs == 0) { | ||
197 | gBenchmarkStartTimeNs = NanoTime(); | ||
198 | } | ||
199 | } | ||
200 | |||
201 | void StopBenchmarkTiming(uint64_t NanoTime) { | ||
202 | if (gBenchmarkStartTimeNs != 0) { | ||
203 | int64_t diff = NanoTime - gBenchmarkStartTimeNs; | ||
204 | gBenchmarkTotalTimeNs += diff; | ||
205 | gBenchmarkTotalTimeNsSquared += diff * diff; | ||
206 | if (NanoTime != 0) { | ||
207 | ++gBenchmarkNum; | ||
208 | } | ||
209 | } | ||
210 | gBenchmarkStartTimeNs = 0; | ||
211 | } | ||
212 | |||
213 | void StartBenchmarkTiming(uint64_t NanoTime) { | ||
214 | if (gBenchmarkStartTimeNs == 0) { | ||
215 | gBenchmarkStartTimeNs = NanoTime; | ||
216 | } | ||
217 | } | ||
218 | |||
219 | int main(int argc, char* argv[]) { | ||
220 | if (gBenchmarks->empty()) { | ||
221 | fprintf(stderr, "No benchmarks registered!\n"); | ||
222 | exit(EXIT_FAILURE); | ||
223 | } | ||
224 | |||
225 | bool need_header = true; | ||
226 | for (auto b : *gBenchmarks) { | ||
227 | if (ShouldRun(b, argc, argv)) { | ||
228 | if (need_header) { | ||
229 | printf("%-25s %10s %10s\n", "", "iterations", "ns/op"); | ||
230 | fflush(stdout); | ||
231 | need_header = false; | ||
232 | } | ||
233 | Run(b); | ||
234 | } | ||
235 | } | ||
236 | |||
237 | if (need_header) { | ||
238 | fprintf(stderr, "No matching benchmarks!\n"); | ||
239 | fprintf(stderr, "Available benchmarks:\n"); | ||
240 | for (auto b : *gBenchmarks) { | ||
241 | fprintf(stderr, " %s\n", b->Name()); | ||
242 | } | ||
243 | exit(EXIT_FAILURE); | ||
244 | } | ||
245 | |||
246 | return 0; | ||
247 | } | ||
diff --git a/liblog/tests/liblog_benchmark.cpp b/liblog/tests/liblog_benchmark.cpp index c4bf95962..706a0f6ae 100644 --- a/liblog/tests/liblog_benchmark.cpp +++ b/liblog/tests/liblog_benchmark.cpp | |||
@@ -25,12 +25,13 @@ | |||
25 | #include <unordered_set> | 25 | #include <unordered_set> |
26 | 26 | ||
27 | #include <android-base/file.h> | 27 | #include <android-base/file.h> |
28 | #include <benchmark/benchmark.h> | ||
28 | #include <cutils/sockets.h> | 29 | #include <cutils/sockets.h> |
29 | #include <log/event_tag_map.h> | 30 | #include <log/event_tag_map.h> |
30 | #include <log/log_transport.h> | 31 | #include <log/log_transport.h> |
31 | #include <private/android_logger.h> | 32 | #include <private/android_logger.h> |
32 | 33 | ||
33 | #include "benchmark.h" | 34 | BENCHMARK_MAIN(); |
34 | 35 | ||
35 | // enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and | 36 | // enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and |
36 | // non-syscall libs. Since we are benchmarking, or using this in the emergency | 37 | // non-syscall libs. Since we are benchmarking, or using this in the emergency |
@@ -51,15 +52,11 @@ | |||
51 | * the log at high pressure. Expect this to be less than double the process | 52 | * the log at high pressure. Expect this to be less than double the process |
52 | * wakeup time (2ms?) | 53 | * wakeup time (2ms?) |
53 | */ | 54 | */ |
54 | static void BM_log_maximum_retry(int iters) { | 55 | static void BM_log_maximum_retry(benchmark::State& state) { |
55 | StartBenchmarkTiming(); | 56 | while (state.KeepRunning()) { |
56 | 57 | LOG_FAILURE_RETRY(__android_log_print( | |
57 | for (int i = 0; i < iters; ++i) { | 58 | ANDROID_LOG_INFO, "BM_log_maximum_retry", "%zu", state.iterations())); |
58 | LOG_FAILURE_RETRY( | ||
59 | __android_log_print(ANDROID_LOG_INFO, "BM_log_maximum_retry", "%d", i)); | ||
60 | } | 59 | } |
61 | |||
62 | StopBenchmarkTiming(); | ||
63 | } | 60 | } |
64 | BENCHMARK(BM_log_maximum_retry); | 61 | BENCHMARK(BM_log_maximum_retry); |
65 | 62 | ||
@@ -68,14 +65,11 @@ BENCHMARK(BM_log_maximum_retry); | |||
68 | * at high pressure. Expect this to be less than double the process wakeup | 65 | * at high pressure. Expect this to be less than double the process wakeup |
69 | * time (2ms?) | 66 | * time (2ms?) |
70 | */ | 67 | */ |
71 | static void BM_log_maximum(int iters) { | 68 | static void BM_log_maximum(benchmark::State& state) { |
72 | StartBenchmarkTiming(); | 69 | while (state.KeepRunning()) { |
73 | 70 | __android_log_print(ANDROID_LOG_INFO, "BM_log_maximum", "%zu", | |
74 | for (int i = 0; i < iters; ++i) { | 71 | state.iterations()); |
75 | __android_log_print(ANDROID_LOG_INFO, "BM_log_maximum", "%d", i); | ||
76 | } | 72 | } |
77 | |||
78 | StopBenchmarkTiming(); | ||
79 | } | 73 | } |
80 | BENCHMARK(BM_log_maximum); | 74 | BENCHMARK(BM_log_maximum); |
81 | 75 | ||
@@ -87,26 +81,28 @@ static void set_log_default() { | |||
87 | android_set_log_transport(LOGGER_DEFAULT); | 81 | android_set_log_transport(LOGGER_DEFAULT); |
88 | } | 82 | } |
89 | 83 | ||
90 | static void BM_log_maximum_null(int iters) { | 84 | static void BM_log_maximum_null(benchmark::State& state) { |
91 | set_log_null(); | 85 | set_log_null(); |
92 | BM_log_maximum(iters); | 86 | BM_log_maximum(state); |
93 | set_log_default(); | 87 | set_log_default(); |
94 | } | 88 | } |
95 | BENCHMARK(BM_log_maximum_null); | 89 | BENCHMARK(BM_log_maximum_null); |
96 | 90 | ||
97 | /* | 91 | /* |
98 | * Measure the time it takes to collect the time using | 92 | * Measure the time it takes to collect the time using |
99 | * discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming()) | 93 | * discrete acquisition (state.PauseTiming() to state.ResumeTiming()) |
100 | * under light load. Expect this to be a syscall period (2us) or | 94 | * under light load. Expect this to be a syscall period (2us) or |
101 | * data read time if zero-syscall. | 95 | * data read time if zero-syscall. |
102 | * | 96 | * |
103 | * vdso support in the kernel and the library can allow | 97 | * vdso support in the kernel and the library can allow |
104 | * clock_gettime to be zero-syscall. | 98 | * clock_gettime to be zero-syscall, but there there does remain some |
99 | * benchmarking overhead to pause and resume; assumptions are both are | ||
100 | * covered. | ||
105 | */ | 101 | */ |
106 | static void BM_clock_overhead(int iters) { | 102 | static void BM_clock_overhead(benchmark::State& state) { |
107 | for (int i = 0; i < iters; ++i) { | 103 | while (state.KeepRunning()) { |
108 | StartBenchmarkTiming(); | 104 | state.PauseTiming(); |
109 | StopBenchmarkTiming(); | 105 | state.ResumeTiming(); |
110 | } | 106 | } |
111 | } | 107 | } |
112 | BENCHMARK(BM_clock_overhead); | 108 | BENCHMARK(BM_clock_overhead); |
@@ -114,9 +110,10 @@ BENCHMARK(BM_clock_overhead); | |||
114 | /* | 110 | /* |
115 | * Measure the time it takes to submit the android logging data to pstore | 111 | * Measure the time it takes to submit the android logging data to pstore |
116 | */ | 112 | */ |
117 | static void BM_pmsg_short(int iters) { | 113 | static void BM_pmsg_short(benchmark::State& state) { |
118 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); | 114 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); |
119 | if (pstore_fd < 0) { | 115 | if (pstore_fd < 0) { |
116 | state.SkipWithError("/dev/pmsg0"); | ||
120 | return; | 117 | return; |
121 | } | 118 | } |
122 | 119 | ||
@@ -175,13 +172,12 @@ static void BM_pmsg_short(int iters) { | |||
175 | newVec[2].iov_base = &buffer; | 172 | newVec[2].iov_base = &buffer; |
176 | newVec[2].iov_len = sizeof(buffer); | 173 | newVec[2].iov_len = sizeof(buffer); |
177 | 174 | ||
178 | StartBenchmarkTiming(); | 175 | while (state.KeepRunning()) { |
179 | for (int i = 0; i < iters; ++i) { | ||
180 | ++snapshot; | 176 | ++snapshot; |
181 | buffer.payload.data = htole32(snapshot); | 177 | buffer.payload.data = htole32(snapshot); |
182 | writev(pstore_fd, newVec, nr); | 178 | writev(pstore_fd, newVec, nr); |
183 | } | 179 | } |
184 | StopBenchmarkTiming(); | 180 | state.PauseTiming(); |
185 | close(pstore_fd); | 181 | close(pstore_fd); |
186 | } | 182 | } |
187 | BENCHMARK(BM_pmsg_short); | 183 | BENCHMARK(BM_pmsg_short); |
@@ -190,9 +186,10 @@ BENCHMARK(BM_pmsg_short); | |||
190 | * Measure the time it takes to submit the android logging data to pstore | 186 | * Measure the time it takes to submit the android logging data to pstore |
191 | * best case aligned single block. | 187 | * best case aligned single block. |
192 | */ | 188 | */ |
193 | static void BM_pmsg_short_aligned(int iters) { | 189 | static void BM_pmsg_short_aligned(benchmark::State& state) { |
194 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); | 190 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); |
195 | if (pstore_fd < 0) { | 191 | if (pstore_fd < 0) { |
192 | state.SkipWithError("/dev/pmsg0"); | ||
196 | return; | 193 | return; |
197 | } | 194 | } |
198 | 195 | ||
@@ -228,7 +225,8 @@ static void BM_pmsg_short_aligned(int iters) { | |||
228 | memset(buf, 0, sizeof(buf)); | 225 | memset(buf, 0, sizeof(buf)); |
229 | struct packet* buffer = (struct packet*)(((uintptr_t)buf + 7) & ~7); | 226 | struct packet* buffer = (struct packet*)(((uintptr_t)buf + 7) & ~7); |
230 | if (((uintptr_t)&buffer->pmsg_header) & 7) { | 227 | if (((uintptr_t)&buffer->pmsg_header) & 7) { |
231 | fprintf(stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters); | 228 | fprintf(stderr, "&buffer=0x%p iterations=%zu\n", &buffer->pmsg_header, |
229 | state.iterations()); | ||
232 | } | 230 | } |
233 | 231 | ||
234 | buffer->pmsg_header.magic = LOGGER_MAGIC; | 232 | buffer->pmsg_header.magic = LOGGER_MAGIC; |
@@ -247,15 +245,14 @@ static void BM_pmsg_short_aligned(int iters) { | |||
247 | uint32_t snapshot = 0; | 245 | uint32_t snapshot = 0; |
248 | buffer->payload.payload.data = htole32(snapshot); | 246 | buffer->payload.payload.data = htole32(snapshot); |
249 | 247 | ||
250 | StartBenchmarkTiming(); | 248 | while (state.KeepRunning()) { |
251 | for (int i = 0; i < iters; ++i) { | ||
252 | ++snapshot; | 249 | ++snapshot; |
253 | buffer->payload.payload.data = htole32(snapshot); | 250 | buffer->payload.payload.data = htole32(snapshot); |
254 | write(pstore_fd, &buffer->pmsg_header, | 251 | write(pstore_fd, &buffer->pmsg_header, |
255 | sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t) + | 252 | sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t) + |
256 | sizeof(android_log_event_int_t)); | 253 | sizeof(android_log_event_int_t)); |
257 | } | 254 | } |
258 | StopBenchmarkTiming(); | 255 | state.PauseTiming(); |
259 | close(pstore_fd); | 256 | close(pstore_fd); |
260 | } | 257 | } |
261 | BENCHMARK(BM_pmsg_short_aligned); | 258 | BENCHMARK(BM_pmsg_short_aligned); |
@@ -264,9 +261,10 @@ BENCHMARK(BM_pmsg_short_aligned); | |||
264 | * Measure the time it takes to submit the android logging data to pstore | 261 | * Measure the time it takes to submit the android logging data to pstore |
265 | * best case aligned single block. | 262 | * best case aligned single block. |
266 | */ | 263 | */ |
267 | static void BM_pmsg_short_unaligned1(int iters) { | 264 | static void BM_pmsg_short_unaligned1(benchmark::State& state) { |
268 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); | 265 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); |
269 | if (pstore_fd < 0) { | 266 | if (pstore_fd < 0) { |
267 | state.SkipWithError("/dev/pmsg0"); | ||
270 | return; | 268 | return; |
271 | } | 269 | } |
272 | 270 | ||
@@ -302,7 +300,8 @@ static void BM_pmsg_short_unaligned1(int iters) { | |||
302 | memset(buf, 0, sizeof(buf)); | 300 | memset(buf, 0, sizeof(buf)); |
303 | struct packet* buffer = (struct packet*)((((uintptr_t)buf + 7) & ~7) + 1); | 301 | struct packet* buffer = (struct packet*)((((uintptr_t)buf + 7) & ~7) + 1); |
304 | if ((((uintptr_t)&buffer->pmsg_header) & 7) != 1) { | 302 | if ((((uintptr_t)&buffer->pmsg_header) & 7) != 1) { |
305 | fprintf(stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters); | 303 | fprintf(stderr, "&buffer=0x%p iterations=%zu\n", &buffer->pmsg_header, |
304 | state.iterations()); | ||
306 | } | 305 | } |
307 | 306 | ||
308 | buffer->pmsg_header.magic = LOGGER_MAGIC; | 307 | buffer->pmsg_header.magic = LOGGER_MAGIC; |
@@ -321,15 +320,14 @@ static void BM_pmsg_short_unaligned1(int iters) { | |||
321 | uint32_t snapshot = 0; | 320 | uint32_t snapshot = 0; |
322 | buffer->payload.payload.data = htole32(snapshot); | 321 | buffer->payload.payload.data = htole32(snapshot); |
323 | 322 | ||
324 | StartBenchmarkTiming(); | 323 | while (state.KeepRunning()) { |
325 | for (int i = 0; i < iters; ++i) { | ||
326 | ++snapshot; | 324 | ++snapshot; |
327 | buffer->payload.payload.data = htole32(snapshot); | 325 | buffer->payload.payload.data = htole32(snapshot); |
328 | write(pstore_fd, &buffer->pmsg_header, | 326 | write(pstore_fd, &buffer->pmsg_header, |
329 | sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t) + | 327 | sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t) + |
330 | sizeof(android_log_event_int_t)); | 328 | sizeof(android_log_event_int_t)); |
331 | } | 329 | } |
332 | StopBenchmarkTiming(); | 330 | state.PauseTiming(); |
333 | close(pstore_fd); | 331 | close(pstore_fd); |
334 | } | 332 | } |
335 | BENCHMARK(BM_pmsg_short_unaligned1); | 333 | BENCHMARK(BM_pmsg_short_unaligned1); |
@@ -338,9 +336,10 @@ BENCHMARK(BM_pmsg_short_unaligned1); | |||
338 | * Measure the time it takes to submit the android logging data to pstore | 336 | * Measure the time it takes to submit the android logging data to pstore |
339 | * best case aligned single block. | 337 | * best case aligned single block. |
340 | */ | 338 | */ |
341 | static void BM_pmsg_long_aligned(int iters) { | 339 | static void BM_pmsg_long_aligned(benchmark::State& state) { |
342 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); | 340 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); |
343 | if (pstore_fd < 0) { | 341 | if (pstore_fd < 0) { |
342 | state.SkipWithError("/dev/pmsg0"); | ||
344 | return; | 343 | return; |
345 | } | 344 | } |
346 | 345 | ||
@@ -376,7 +375,8 @@ static void BM_pmsg_long_aligned(int iters) { | |||
376 | memset(buf, 0, sizeof(buf)); | 375 | memset(buf, 0, sizeof(buf)); |
377 | struct packet* buffer = (struct packet*)(((uintptr_t)buf + 7) & ~7); | 376 | struct packet* buffer = (struct packet*)(((uintptr_t)buf + 7) & ~7); |
378 | if (((uintptr_t)&buffer->pmsg_header) & 7) { | 377 | if (((uintptr_t)&buffer->pmsg_header) & 7) { |
379 | fprintf(stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters); | 378 | fprintf(stderr, "&buffer=0x%p iterations=%zu\n", &buffer->pmsg_header, |
379 | state.iterations()); | ||
380 | } | 380 | } |
381 | 381 | ||
382 | buffer->pmsg_header.magic = LOGGER_MAGIC; | 382 | buffer->pmsg_header.magic = LOGGER_MAGIC; |
@@ -395,13 +395,12 @@ static void BM_pmsg_long_aligned(int iters) { | |||
395 | uint32_t snapshot = 0; | 395 | uint32_t snapshot = 0; |
396 | buffer->payload.payload.data = htole32(snapshot); | 396 | buffer->payload.payload.data = htole32(snapshot); |
397 | 397 | ||
398 | StartBenchmarkTiming(); | 398 | while (state.KeepRunning()) { |
399 | for (int i = 0; i < iters; ++i) { | ||
400 | ++snapshot; | 399 | ++snapshot; |
401 | buffer->payload.payload.data = htole32(snapshot); | 400 | buffer->payload.payload.data = htole32(snapshot); |
402 | write(pstore_fd, &buffer->pmsg_header, LOGGER_ENTRY_MAX_PAYLOAD); | 401 | write(pstore_fd, &buffer->pmsg_header, LOGGER_ENTRY_MAX_PAYLOAD); |
403 | } | 402 | } |
404 | StopBenchmarkTiming(); | 403 | state.PauseTiming(); |
405 | close(pstore_fd); | 404 | close(pstore_fd); |
406 | } | 405 | } |
407 | BENCHMARK(BM_pmsg_long_aligned); | 406 | BENCHMARK(BM_pmsg_long_aligned); |
@@ -410,9 +409,10 @@ BENCHMARK(BM_pmsg_long_aligned); | |||
410 | * Measure the time it takes to submit the android logging data to pstore | 409 | * Measure the time it takes to submit the android logging data to pstore |
411 | * best case aligned single block. | 410 | * best case aligned single block. |
412 | */ | 411 | */ |
413 | static void BM_pmsg_long_unaligned1(int iters) { | 412 | static void BM_pmsg_long_unaligned1(benchmark::State& state) { |
414 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); | 413 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); |
415 | if (pstore_fd < 0) { | 414 | if (pstore_fd < 0) { |
415 | state.SkipWithError("/dev/pmsg0"); | ||
416 | return; | 416 | return; |
417 | } | 417 | } |
418 | 418 | ||
@@ -448,7 +448,8 @@ static void BM_pmsg_long_unaligned1(int iters) { | |||
448 | memset(buf, 0, sizeof(buf)); | 448 | memset(buf, 0, sizeof(buf)); |
449 | struct packet* buffer = (struct packet*)((((uintptr_t)buf + 7) & ~7) + 1); | 449 | struct packet* buffer = (struct packet*)((((uintptr_t)buf + 7) & ~7) + 1); |
450 | if ((((uintptr_t)&buffer->pmsg_header) & 7) != 1) { | 450 | if ((((uintptr_t)&buffer->pmsg_header) & 7) != 1) { |
451 | fprintf(stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters); | 451 | fprintf(stderr, "&buffer=0x%p iterations=%zu\n", &buffer->pmsg_header, |
452 | state.iterations()); | ||
452 | } | 453 | } |
453 | 454 | ||
454 | buffer->pmsg_header.magic = LOGGER_MAGIC; | 455 | buffer->pmsg_header.magic = LOGGER_MAGIC; |
@@ -467,22 +468,20 @@ static void BM_pmsg_long_unaligned1(int iters) { | |||
467 | uint32_t snapshot = 0; | 468 | uint32_t snapshot = 0; |
468 | buffer->payload.payload.data = htole32(snapshot); | 469 | buffer->payload.payload.data = htole32(snapshot); |
469 | 470 | ||
470 | StartBenchmarkTiming(); | 471 | while (state.KeepRunning()) { |
471 | for (int i = 0; i < iters; ++i) { | ||
472 | ++snapshot; | 472 | ++snapshot; |
473 | buffer->payload.payload.data = htole32(snapshot); | 473 | buffer->payload.payload.data = htole32(snapshot); |
474 | write(pstore_fd, &buffer->pmsg_header, LOGGER_ENTRY_MAX_PAYLOAD); | 474 | write(pstore_fd, &buffer->pmsg_header, LOGGER_ENTRY_MAX_PAYLOAD); |
475 | } | 475 | } |
476 | StopBenchmarkTiming(); | 476 | state.PauseTiming(); |
477 | close(pstore_fd); | 477 | close(pstore_fd); |
478 | } | 478 | } |
479 | BENCHMARK(BM_pmsg_long_unaligned1); | 479 | BENCHMARK(BM_pmsg_long_unaligned1); |
480 | 480 | ||
481 | /* | 481 | /* |
482 | * Measure the time it takes to form sprintf plus time using | 482 | * Measure the time it takes to form sprintf plus time using |
483 | * discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming()) | 483 | * discrete acquisition under light load. Expect this to be a syscall period |
484 | * under light load. Expect this to be a syscall period (2us) or sprintf | 484 | * (2us) or sprintf time if zero-syscall time. |
485 | * time if zero-syscall time. | ||
486 | */ | 485 | */ |
487 | /* helper function */ | 486 | /* helper function */ |
488 | static void test_print(const char* fmt, ...) { | 487 | static void test_print(const char* fmt, ...) { |
@@ -498,58 +497,55 @@ static void test_print(const char* fmt, ...) { | |||
498 | #define logd_sleep() usleep(50) // really allow logd to catch up | 497 | #define logd_sleep() usleep(50) // really allow logd to catch up |
499 | 498 | ||
500 | /* performance test */ | 499 | /* performance test */ |
501 | static void BM_sprintf_overhead(int iters) { | 500 | static void BM_sprintf_overhead(benchmark::State& state) { |
502 | for (int i = 0; i < iters; ++i) { | 501 | while (state.KeepRunning()) { |
503 | StartBenchmarkTiming(); | 502 | test_print("BM_sprintf_overhead:%zu", state.iterations()); |
504 | test_print("BM_sprintf_overhead:%d", i); | 503 | state.PauseTiming(); |
505 | StopBenchmarkTiming(); | ||
506 | logd_yield(); | 504 | logd_yield(); |
505 | state.ResumeTiming(); | ||
507 | } | 506 | } |
508 | } | 507 | } |
509 | BENCHMARK(BM_sprintf_overhead); | 508 | BENCHMARK(BM_sprintf_overhead); |
510 | 509 | ||
511 | /* | 510 | /* |
512 | * Measure the time it takes to submit the android printing logging call | 511 | * Measure the time it takes to submit the android printing logging call |
513 | * using discrete acquisition discrete acquisition (StartBenchmarkTiming() -> | 512 | * using discrete acquisition discrete acquisition under light load. Expect |
514 | * StopBenchmarkTiming()) under light load. Expect this to be a dozen or so | 513 | * this to be a dozen or so syscall periods (40us) plus time to run *printf |
515 | * syscall periods (40us) plus time to run *printf | ||
516 | */ | 514 | */ |
517 | static void BM_log_print_overhead(int iters) { | 515 | static void BM_log_print_overhead(benchmark::State& state) { |
518 | for (int i = 0; i < iters; ++i) { | 516 | while (state.KeepRunning()) { |
519 | StartBenchmarkTiming(); | 517 | __android_log_print(ANDROID_LOG_INFO, "BM_log_overhead", "%zu", |
520 | __android_log_print(ANDROID_LOG_INFO, "BM_log_overhead", "%d", i); | 518 | state.iterations()); |
521 | StopBenchmarkTiming(); | 519 | state.PauseTiming(); |
522 | logd_yield(); | 520 | logd_yield(); |
521 | state.ResumeTiming(); | ||
523 | } | 522 | } |
524 | } | 523 | } |
525 | BENCHMARK(BM_log_print_overhead); | 524 | BENCHMARK(BM_log_print_overhead); |
526 | 525 | ||
527 | /* | 526 | /* |
528 | * Measure the time it takes to submit the android event logging call | 527 | * Measure the time it takes to submit the android event logging call |
529 | * using discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming()) | 528 | * using discrete acquisition under light load. Expect this to be a long path |
530 | * under light load. Expect this to be a long path to logger to convert the | 529 | * to logger to convert the unknown tag (0) into a tagname (less than 200us). |
531 | * unknown tag (0) into a tagname (less than 200us). | ||
532 | */ | 530 | */ |
533 | static void BM_log_event_overhead(int iters) { | 531 | static void BM_log_event_overhead(benchmark::State& state) { |
534 | for (unsigned long long i = 0; i < (unsigned)iters; ++i) { | 532 | for (int64_t i = 0; state.KeepRunning(); ++i) { |
535 | StartBenchmarkTiming(); | ||
536 | // log tag number 0 is not known, nor shall it ever be known | 533 | // log tag number 0 is not known, nor shall it ever be known |
537 | __android_log_btwrite(0, EVENT_TYPE_LONG, &i, sizeof(i)); | 534 | __android_log_btwrite(0, EVENT_TYPE_LONG, &i, sizeof(i)); |
538 | StopBenchmarkTiming(); | 535 | state.PauseTiming(); |
539 | logd_yield(); | 536 | logd_yield(); |
537 | state.ResumeTiming(); | ||
540 | } | 538 | } |
541 | } | 539 | } |
542 | BENCHMARK(BM_log_event_overhead); | 540 | BENCHMARK(BM_log_event_overhead); |
543 | 541 | ||
544 | /* | 542 | /* |
545 | * Measure the time it takes to submit the android event logging call | 543 | * Measure the time it takes to submit the android event logging call |
546 | * using discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming()) | 544 | * using discrete acquisition under light load with a known logtag. Expect |
547 | * under light load with a known logtag. Expect this to be a dozen or so | 545 | * this to be a dozen or so syscall periods (less than 40us) |
548 | * syscall periods (less than 40us) | ||
549 | */ | 546 | */ |
550 | static void BM_log_event_overhead_42(int iters) { | 547 | static void BM_log_event_overhead_42(benchmark::State& state) { |
551 | for (unsigned long long i = 0; i < (unsigned)iters; ++i) { | 548 | for (int64_t i = 0; state.KeepRunning(); ++i) { |
552 | StartBenchmarkTiming(); | ||
553 | // In system/core/logcat/event.logtags: | 549 | // In system/core/logcat/event.logtags: |
554 | // # These are used for testing, do not modify without updating | 550 | // # These are used for testing, do not modify without updating |
555 | // # tests/framework-tests/src/android/util/EventLogFunctionalTest.java. | 551 | // # tests/framework-tests/src/android/util/EventLogFunctionalTest.java. |
@@ -557,40 +553,42 @@ static void BM_log_event_overhead_42(int iters) { | |||
557 | // # system/core/liblog/tests/liblog_test.cpp | 553 | // # system/core/liblog/tests/liblog_test.cpp |
558 | // 42 answer (to life the universe etc|3) | 554 | // 42 answer (to life the universe etc|3) |
559 | __android_log_btwrite(42, EVENT_TYPE_LONG, &i, sizeof(i)); | 555 | __android_log_btwrite(42, EVENT_TYPE_LONG, &i, sizeof(i)); |
560 | StopBenchmarkTiming(); | 556 | state.PauseTiming(); |
561 | logd_yield(); | 557 | logd_yield(); |
558 | state.ResumeTiming(); | ||
562 | } | 559 | } |
563 | } | 560 | } |
564 | BENCHMARK(BM_log_event_overhead_42); | 561 | BENCHMARK(BM_log_event_overhead_42); |
565 | 562 | ||
566 | static void BM_log_event_overhead_null(int iters) { | 563 | static void BM_log_event_overhead_null(benchmark::State& state) { |
567 | set_log_null(); | 564 | set_log_null(); |
568 | BM_log_event_overhead(iters); | 565 | BM_log_event_overhead(state); |
569 | set_log_default(); | 566 | set_log_default(); |
570 | } | 567 | } |
571 | BENCHMARK(BM_log_event_overhead_null); | 568 | BENCHMARK(BM_log_event_overhead_null); |
572 | 569 | ||
573 | /* | 570 | /* |
574 | * Measure the time it takes to submit the android event logging call | 571 | * Measure the time it takes to submit the android event logging call |
575 | * using discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming()) | 572 | * using discrete acquisition under very-light load (<1% CPU utilization). |
576 | * under very-light load (<1% CPU utilization). | ||
577 | */ | 573 | */ |
578 | static void BM_log_light_overhead(int iters) { | 574 | static void BM_log_light_overhead(benchmark::State& state) { |
579 | for (unsigned long long i = 0; i < (unsigned)iters; ++i) { | 575 | for (int64_t i = 0; state.KeepRunning(); ++i) { |
580 | StartBenchmarkTiming(); | ||
581 | __android_log_btwrite(0, EVENT_TYPE_LONG, &i, sizeof(i)); | 576 | __android_log_btwrite(0, EVENT_TYPE_LONG, &i, sizeof(i)); |
582 | StopBenchmarkTiming(); | 577 | state.PauseTiming(); |
583 | usleep(10000); | 578 | usleep(10000); |
579 | state.ResumeTiming(); | ||
584 | } | 580 | } |
585 | } | 581 | } |
586 | BENCHMARK(BM_log_light_overhead); | 582 | BENCHMARK(BM_log_light_overhead); |
587 | 583 | ||
588 | static void BM_log_light_overhead_null(int iters) { | 584 | static void BM_log_light_overhead_null(benchmark::State& state) { |
589 | set_log_null(); | 585 | set_log_null(); |
590 | BM_log_light_overhead(iters); | 586 | BM_log_light_overhead(state); |
591 | set_log_default(); | 587 | set_log_default(); |
592 | } | 588 | } |
593 | BENCHMARK(BM_log_light_overhead_null); | 589 | // Default gets out of hand for this test, so we set a reasonable number of |
590 | // iterations for a timely result. | ||
591 | BENCHMARK(BM_log_light_overhead_null)->Iterations(500); | ||
594 | 592 | ||
595 | static void caught_latency(int /*signum*/) { | 593 | static void caught_latency(int /*signum*/) { |
596 | unsigned long long v = 0xDEADBEEFA55A5AA5ULL; | 594 | unsigned long long v = 0xDEADBEEFA55A5AA5ULL; |
@@ -614,10 +612,12 @@ static const int alarm_time = 3; | |||
614 | 612 | ||
615 | /* | 613 | /* |
616 | * Measure the time it takes for the logd posting call to acquire the | 614 | * Measure the time it takes for the logd posting call to acquire the |
617 | * timestamp to place into the internal record. Expect this to be less than | 615 | * timestamp to place into the internal record. Expect this to be less than |
618 | * 4 syscalls (3us). | 616 | * 4 syscalls (3us). This test uses manual injection of timing because it is |
617 | * comparing the timestamp at send, and then picking up the corresponding log | ||
618 | * end-to-end long path from logd to see what actual timestamp was submitted. | ||
619 | */ | 619 | */ |
620 | static void BM_log_latency(int iters) { | 620 | static void BM_log_latency(benchmark::State& state) { |
621 | pid_t pid = getpid(); | 621 | pid_t pid = getpid(); |
622 | 622 | ||
623 | struct logger_list* logger_list = | 623 | struct logger_list* logger_list = |
@@ -631,7 +631,8 @@ static void BM_log_latency(int iters) { | |||
631 | signal(SIGALRM, caught_latency); | 631 | signal(SIGALRM, caught_latency); |
632 | alarm(alarm_time); | 632 | alarm(alarm_time); |
633 | 633 | ||
634 | for (int j = 0, i = 0; i < iters && j < 10 * iters; ++i, ++j) { | 634 | for (size_t j = 0; state.KeepRunning() && j < 10 * state.iterations(); ++j) { |
635 | retry: // We allow transitory errors (logd overloaded) to be retried. | ||
635 | log_time ts; | 636 | log_time ts; |
636 | LOG_FAILURE_RETRY((ts = log_time(CLOCK_REALTIME), | 637 | LOG_FAILURE_RETRY((ts = log_time(CLOCK_REALTIME), |
637 | android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)))); | 638 | android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)))); |
@@ -642,7 +643,7 @@ static void BM_log_latency(int iters) { | |||
642 | alarm(alarm_time); | 643 | alarm(alarm_time); |
643 | 644 | ||
644 | if (ret <= 0) { | 645 | if (ret <= 0) { |
645 | iters = i; | 646 | state.SkipWithError("android_logger_list_read"); |
646 | break; | 647 | break; |
647 | } | 648 | } |
648 | if ((log_msg.entry.len != (4 + 1 + 8)) || | 649 | if ((log_msg.entry.len != (4 + 1 + 8)) || |
@@ -658,7 +659,7 @@ static void BM_log_latency(int iters) { | |||
658 | log_time tx(eventData + 4 + 1); | 659 | log_time tx(eventData + 4 + 1); |
659 | if (ts != tx) { | 660 | if (ts != tx) { |
660 | if (0xDEADBEEFA55A5AA5ULL == caught_convert(eventData + 4 + 1)) { | 661 | if (0xDEADBEEFA55A5AA5ULL == caught_convert(eventData + 4 + 1)) { |
661 | iters = i; | 662 | state.SkipWithError("signal"); |
662 | break; | 663 | break; |
663 | } | 664 | } |
664 | continue; | 665 | continue; |
@@ -666,12 +667,8 @@ static void BM_log_latency(int iters) { | |||
666 | 667 | ||
667 | uint64_t start = ts.nsec(); | 668 | uint64_t start = ts.nsec(); |
668 | uint64_t end = log_msg.nsec(); | 669 | uint64_t end = log_msg.nsec(); |
669 | if (end >= start) { | 670 | if (end < start) goto retry; |
670 | StartBenchmarkTiming(start); | 671 | state.SetIterationTime((end - start) / (double)NS_PER_SEC); |
671 | StopBenchmarkTiming(end); | ||
672 | } else { | ||
673 | --i; | ||
674 | } | ||
675 | break; | 672 | break; |
676 | } | 673 | } |
677 | } | 674 | } |
@@ -681,7 +678,9 @@ static void BM_log_latency(int iters) { | |||
681 | 678 | ||
682 | android_logger_list_free(logger_list); | 679 | android_logger_list_free(logger_list); |
683 | } | 680 | } |
684 | BENCHMARK(BM_log_latency); | 681 | // Default gets out of hand for this test, so we set a reasonable number of |
682 | // iterations for a timely result. | ||
683 | BENCHMARK(BM_log_latency)->UseManualTime()->Iterations(200); | ||
685 | 684 | ||
686 | static void caught_delay(int /*signum*/) { | 685 | static void caught_delay(int /*signum*/) { |
687 | unsigned long long v = 0xDEADBEEFA55A5AA6ULL; | 686 | unsigned long long v = 0xDEADBEEFA55A5AA6ULL; |
@@ -693,7 +692,7 @@ static void caught_delay(int /*signum*/) { | |||
693 | * Measure the time it takes for the logd posting call to make it into | 692 | * Measure the time it takes for the logd posting call to make it into |
694 | * the logs. Expect this to be less than double the process wakeup time (2ms). | 693 | * the logs. Expect this to be less than double the process wakeup time (2ms). |
695 | */ | 694 | */ |
696 | static void BM_log_delay(int iters) { | 695 | static void BM_log_delay(benchmark::State& state) { |
697 | pid_t pid = getpid(); | 696 | pid_t pid = getpid(); |
698 | 697 | ||
699 | struct logger_list* logger_list = | 698 | struct logger_list* logger_list = |
@@ -707,9 +706,7 @@ static void BM_log_delay(int iters) { | |||
707 | signal(SIGALRM, caught_delay); | 706 | signal(SIGALRM, caught_delay); |
708 | alarm(alarm_time); | 707 | alarm(alarm_time); |
709 | 708 | ||
710 | StartBenchmarkTiming(); | 709 | while (state.KeepRunning()) { |
711 | |||
712 | for (int i = 0; i < iters; ++i) { | ||
713 | log_time ts(CLOCK_REALTIME); | 710 | log_time ts(CLOCK_REALTIME); |
714 | 711 | ||
715 | LOG_FAILURE_RETRY(android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); | 712 | LOG_FAILURE_RETRY(android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); |
@@ -720,7 +717,7 @@ static void BM_log_delay(int iters) { | |||
720 | alarm(alarm_time); | 717 | alarm(alarm_time); |
721 | 718 | ||
722 | if (ret <= 0) { | 719 | if (ret <= 0) { |
723 | iters = i; | 720 | state.SkipWithError("android_logger_list_read"); |
724 | break; | 721 | break; |
725 | } | 722 | } |
726 | if ((log_msg.entry.len != (4 + 1 + 8)) || | 723 | if ((log_msg.entry.len != (4 + 1 + 8)) || |
@@ -736,7 +733,7 @@ static void BM_log_delay(int iters) { | |||
736 | log_time tx(eventData + 4 + 1); | 733 | log_time tx(eventData + 4 + 1); |
737 | if (ts != tx) { | 734 | if (ts != tx) { |
738 | if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) { | 735 | if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) { |
739 | iters = i; | 736 | state.SkipWithError("signal"); |
740 | break; | 737 | break; |
741 | } | 738 | } |
742 | continue; | 739 | continue; |
@@ -745,12 +742,11 @@ static void BM_log_delay(int iters) { | |||
745 | break; | 742 | break; |
746 | } | 743 | } |
747 | } | 744 | } |
745 | state.PauseTiming(); | ||
748 | 746 | ||
749 | signal(SIGALRM, SIG_DFL); | 747 | signal(SIGALRM, SIG_DFL); |
750 | alarm(0); | 748 | alarm(0); |
751 | 749 | ||
752 | StopBenchmarkTiming(); | ||
753 | |||
754 | android_logger_list_free(logger_list); | 750 | android_logger_list_free(logger_list); |
755 | } | 751 | } |
756 | BENCHMARK(BM_log_delay); | 752 | BENCHMARK(BM_log_delay); |
@@ -758,45 +754,33 @@ BENCHMARK(BM_log_delay); | |||
758 | /* | 754 | /* |
759 | * Measure the time it takes for __android_log_is_loggable. | 755 | * Measure the time it takes for __android_log_is_loggable. |
760 | */ | 756 | */ |
761 | static void BM_is_loggable(int iters) { | 757 | static void BM_is_loggable(benchmark::State& state) { |
762 | static const char logd[] = "logd"; | 758 | static const char logd[] = "logd"; |
763 | 759 | ||
764 | StartBenchmarkTiming(); | 760 | while (state.KeepRunning()) { |
765 | |||
766 | for (int i = 0; i < iters; ++i) { | ||
767 | __android_log_is_loggable_len(ANDROID_LOG_WARN, logd, strlen(logd), | 761 | __android_log_is_loggable_len(ANDROID_LOG_WARN, logd, strlen(logd), |
768 | ANDROID_LOG_VERBOSE); | 762 | ANDROID_LOG_VERBOSE); |
769 | } | 763 | } |
770 | |||
771 | StopBenchmarkTiming(); | ||
772 | } | 764 | } |
773 | BENCHMARK(BM_is_loggable); | 765 | BENCHMARK(BM_is_loggable); |
774 | 766 | ||
775 | /* | 767 | /* |
776 | * Measure the time it takes for android_log_clockid. | 768 | * Measure the time it takes for android_log_clockid. |
777 | */ | 769 | */ |
778 | static void BM_clockid(int iters) { | 770 | static void BM_clockid(benchmark::State& state) { |
779 | StartBenchmarkTiming(); | 771 | while (state.KeepRunning()) { |
780 | |||
781 | for (int i = 0; i < iters; ++i) { | ||
782 | android_log_clockid(); | 772 | android_log_clockid(); |
783 | } | 773 | } |
784 | |||
785 | StopBenchmarkTiming(); | ||
786 | } | 774 | } |
787 | BENCHMARK(BM_clockid); | 775 | BENCHMARK(BM_clockid); |
788 | 776 | ||
789 | /* | 777 | /* |
790 | * Measure the time it takes for __android_log_security. | 778 | * Measure the time it takes for __android_log_security. |
791 | */ | 779 | */ |
792 | static void BM_security(int iters) { | 780 | static void BM_security(benchmark::State& state) { |
793 | StartBenchmarkTiming(); | 781 | while (state.KeepRunning()) { |
794 | |||
795 | for (int i = 0; i < iters; ++i) { | ||
796 | __android_log_security(); | 782 | __android_log_security(); |
797 | } | 783 | } |
798 | |||
799 | StopBenchmarkTiming(); | ||
800 | } | 784 | } |
801 | BENCHMARK(BM_security); | 785 | BENCHMARK(BM_security); |
802 | 786 | ||
@@ -824,21 +808,17 @@ static bool prechargeEventMap() { | |||
824 | /* | 808 | /* |
825 | * Measure the time it takes for android_lookupEventTag_len | 809 | * Measure the time it takes for android_lookupEventTag_len |
826 | */ | 810 | */ |
827 | static void BM_lookupEventTag(int iters) { | 811 | static void BM_lookupEventTag(benchmark::State& state) { |
828 | prechargeEventMap(); | 812 | prechargeEventMap(); |
829 | 813 | ||
830 | std::unordered_set<uint32_t>::const_iterator it = set.begin(); | 814 | std::unordered_set<uint32_t>::const_iterator it = set.begin(); |
831 | 815 | ||
832 | StartBenchmarkTiming(); | 816 | while (state.KeepRunning()) { |
833 | |||
834 | for (int i = 0; i < iters; ++i) { | ||
835 | size_t len; | 817 | size_t len; |
836 | android_lookupEventTag_len(map, &len, (*it)); | 818 | android_lookupEventTag_len(map, &len, (*it)); |
837 | ++it; | 819 | ++it; |
838 | if (it == set.end()) it = set.begin(); | 820 | if (it == set.end()) it = set.begin(); |
839 | } | 821 | } |
840 | |||
841 | StopBenchmarkTiming(); | ||
842 | } | 822 | } |
843 | BENCHMARK(BM_lookupEventTag); | 823 | BENCHMARK(BM_lookupEventTag); |
844 | 824 | ||
@@ -847,7 +827,7 @@ BENCHMARK(BM_lookupEventTag); | |||
847 | */ | 827 | */ |
848 | static uint32_t notTag = 1; | 828 | static uint32_t notTag = 1; |
849 | 829 | ||
850 | static void BM_lookupEventTag_NOT(int iters) { | 830 | static void BM_lookupEventTag_NOT(benchmark::State& state) { |
851 | prechargeEventMap(); | 831 | prechargeEventMap(); |
852 | 832 | ||
853 | while (set.find(notTag) != set.end()) { | 833 | while (set.find(notTag) != set.end()) { |
@@ -855,15 +835,11 @@ static void BM_lookupEventTag_NOT(int iters) { | |||
855 | if (notTag >= USHRT_MAX) notTag = 1; | 835 | if (notTag >= USHRT_MAX) notTag = 1; |
856 | } | 836 | } |
857 | 837 | ||
858 | StartBenchmarkTiming(); | 838 | while (state.KeepRunning()) { |
859 | |||
860 | for (int i = 0; i < iters; ++i) { | ||
861 | size_t len; | 839 | size_t len; |
862 | android_lookupEventTag_len(map, &len, notTag); | 840 | android_lookupEventTag_len(map, &len, notTag); |
863 | } | 841 | } |
864 | 842 | ||
865 | StopBenchmarkTiming(); | ||
866 | |||
867 | ++notTag; | 843 | ++notTag; |
868 | if (notTag >= USHRT_MAX) notTag = 1; | 844 | if (notTag >= USHRT_MAX) notTag = 1; |
869 | } | 845 | } |
@@ -872,42 +848,38 @@ BENCHMARK(BM_lookupEventTag_NOT); | |||
872 | /* | 848 | /* |
873 | * Measure the time it takes for android_lookupEventFormat_len | 849 | * Measure the time it takes for android_lookupEventFormat_len |
874 | */ | 850 | */ |
875 | static void BM_lookupEventFormat(int iters) { | 851 | static void BM_lookupEventFormat(benchmark::State& state) { |
876 | prechargeEventMap(); | 852 | prechargeEventMap(); |
877 | 853 | ||
878 | std::unordered_set<uint32_t>::const_iterator it = set.begin(); | 854 | std::unordered_set<uint32_t>::const_iterator it = set.begin(); |
879 | 855 | ||
880 | StartBenchmarkTiming(); | 856 | while (state.KeepRunning()) { |
881 | |||
882 | for (int i = 0; i < iters; ++i) { | ||
883 | size_t len; | 857 | size_t len; |
884 | android_lookupEventFormat_len(map, &len, (*it)); | 858 | android_lookupEventFormat_len(map, &len, (*it)); |
885 | ++it; | 859 | ++it; |
886 | if (it == set.end()) it = set.begin(); | 860 | if (it == set.end()) it = set.begin(); |
887 | } | 861 | } |
888 | |||
889 | StopBenchmarkTiming(); | ||
890 | } | 862 | } |
891 | BENCHMARK(BM_lookupEventFormat); | 863 | BENCHMARK(BM_lookupEventFormat); |
892 | 864 | ||
893 | /* | 865 | /* |
894 | * Measure the time it takes for android_lookupEventTagNum plus above | 866 | * Measure the time it takes for android_lookupEventTagNum plus above |
895 | */ | 867 | */ |
896 | static void BM_lookupEventTagNum(int iters) { | 868 | static void BM_lookupEventTagNum(benchmark::State& state) { |
897 | prechargeEventMap(); | 869 | prechargeEventMap(); |
898 | 870 | ||
899 | std::unordered_set<uint32_t>::const_iterator it = set.begin(); | 871 | std::unordered_set<uint32_t>::const_iterator it = set.begin(); |
900 | 872 | ||
901 | for (int i = 0; i < iters; ++i) { | 873 | while (state.KeepRunning()) { |
902 | size_t len; | 874 | size_t len; |
903 | const char* name = android_lookupEventTag_len(map, &len, (*it)); | 875 | const char* name = android_lookupEventTag_len(map, &len, (*it)); |
904 | std::string Name(name, len); | 876 | std::string Name(name, len); |
905 | const char* format = android_lookupEventFormat_len(map, &len, (*it)); | 877 | const char* format = android_lookupEventFormat_len(map, &len, (*it)); |
906 | std::string Format(format, len); | 878 | std::string Format(format, len); |
907 | StartBenchmarkTiming(); | 879 | state.ResumeTiming(); |
908 | android_lookupEventTagNum(map, Name.c_str(), Format.c_str(), | 880 | android_lookupEventTagNum(map, Name.c_str(), Format.c_str(), |
909 | ANDROID_LOG_UNKNOWN); | 881 | ANDROID_LOG_UNKNOWN); |
910 | StopBenchmarkTiming(); | 882 | state.PauseTiming(); |
911 | ++it; | 883 | ++it; |
912 | if (it == set.end()) it = set.begin(); | 884 | if (it == set.end()) it = set.begin(); |
913 | } | 885 | } |
@@ -943,7 +915,7 @@ static void send_to_control(char* buf, size_t len) { | |||
943 | close(sock); | 915 | close(sock); |
944 | } | 916 | } |
945 | 917 | ||
946 | static void BM_lookupEventTagNum_logd_new(int iters) { | 918 | static void BM_lookupEventTagNum_logd_new(benchmark::State& state) { |
947 | fprintf(stderr, | 919 | fprintf(stderr, |
948 | "WARNING: " | 920 | "WARNING: " |
949 | "This test can cause logd to grow in size and hit DOS limiter\n"); | 921 | "This test can cause logd to grow in size and hit DOS limiter\n"); |
@@ -965,7 +937,7 @@ static void BM_lookupEventTagNum_logd_new(int iters) { | |||
965 | data_event_log_tags = empty_event_log_tags; | 937 | data_event_log_tags = empty_event_log_tags; |
966 | } | 938 | } |
967 | 939 | ||
968 | for (int i = 0; i < iters; ++i) { | 940 | while (state.KeepRunning()) { |
969 | char buffer[256]; | 941 | char buffer[256]; |
970 | memset(buffer, 0, sizeof(buffer)); | 942 | memset(buffer, 0, sizeof(buffer)); |
971 | log_time now(CLOCK_MONOTONIC); | 943 | log_time now(CLOCK_MONOTONIC); |
@@ -973,9 +945,9 @@ static void BM_lookupEventTagNum_logd_new(int iters) { | |||
973 | snprintf(name, sizeof(name), "a%" PRIu64, now.nsec()); | 945 | snprintf(name, sizeof(name), "a%" PRIu64, now.nsec()); |
974 | snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"(new|1)\"", | 946 | snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"(new|1)\"", |
975 | name); | 947 | name); |
976 | StartBenchmarkTiming(); | 948 | state.ResumeTiming(); |
977 | send_to_control(buffer, sizeof(buffer)); | 949 | send_to_control(buffer, sizeof(buffer)); |
978 | StopBenchmarkTiming(); | 950 | state.PauseTiming(); |
979 | } | 951 | } |
980 | 952 | ||
981 | // Restore copies (logd still know about them, until crash or reboot) | 953 | // Restore copies (logd still know about them, until crash or reboot) |
@@ -1002,12 +974,12 @@ static void BM_lookupEventTagNum_logd_new(int iters) { | |||
1002 | } | 974 | } |
1003 | BENCHMARK(BM_lookupEventTagNum_logd_new); | 975 | BENCHMARK(BM_lookupEventTagNum_logd_new); |
1004 | 976 | ||
1005 | static void BM_lookupEventTagNum_logd_existing(int iters) { | 977 | static void BM_lookupEventTagNum_logd_existing(benchmark::State& state) { |
1006 | prechargeEventMap(); | 978 | prechargeEventMap(); |
1007 | 979 | ||
1008 | std::unordered_set<uint32_t>::const_iterator it = set.begin(); | 980 | std::unordered_set<uint32_t>::const_iterator it = set.begin(); |
1009 | 981 | ||
1010 | for (int i = 0; i < iters; ++i) { | 982 | while (state.KeepRunning()) { |
1011 | size_t len; | 983 | size_t len; |
1012 | const char* name = android_lookupEventTag_len(map, &len, (*it)); | 984 | const char* name = android_lookupEventTag_len(map, &len, (*it)); |
1013 | std::string Name(name, len); | 985 | std::string Name(name, len); |
@@ -1018,9 +990,9 @@ static void BM_lookupEventTagNum_logd_existing(int iters) { | |||
1018 | snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"%s\"", | 990 | snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"%s\"", |
1019 | Name.c_str(), Format.c_str()); | 991 | Name.c_str(), Format.c_str()); |
1020 | 992 | ||
1021 | StartBenchmarkTiming(); | 993 | state.ResumeTiming(); |
1022 | send_to_control(buffer, sizeof(buffer)); | 994 | send_to_control(buffer, sizeof(buffer)); |
1023 | StopBenchmarkTiming(); | 995 | state.PauseTiming(); |
1024 | ++it; | 996 | ++it; |
1025 | if (it == set.end()) it = set.begin(); | 997 | if (it == set.end()) it = set.begin(); |
1026 | } | 998 | } |