summaryrefslogtreecommitdiffstats
path: root/liblog
diff options
context:
space:
mode:
authorMark Salyzyn2018-01-11 13:20:24 -0600
committerMark Salyzyn2018-01-16 10:11:26 -0600
commit1520bd43b0ce6511cd086eaf495692c4bc2f6d6b (patch)
tree626659ce4c63d3ddbec910a74054f449358916f7 /liblog
parent3b44d2846eac9c198c95b7cff293b9b8507c2534 (diff)
downloadplatform-system-core-1520bd43b0ce6511cd086eaf495692c4bc2f6d6b.tar.gz
platform-system-core-1520bd43b0ce6511cd086eaf495692c4bc2f6d6b.tar.xz
platform-system-core-1520bd43b0ce6511cd086eaf495692c4bc2f6d6b.zip
liblog: benchmarks use google-benchmark library
Remove our circa 2014 snapshot of the google benchmarking library, and use the now very stable google-benchmark suite. Some porting effort, and deal with some benchmarking saddle points that take too long to sort out. Focus on minimal API changes, _odd_ new behaviors, and style. Test: liblog_benchmarks, ensure results in about the same range Bug: 69423514 Change-Id: I2add1df9cb664333bcf983b57121ae151b26935b
Diffstat (limited to 'liblog')
-rw-r--r--liblog/tests/Android.mk7
-rw-r--r--liblog/tests/benchmark.h147
-rw-r--r--liblog/tests/benchmark_main.cpp247
-rw-r--r--liblog/tests/liblog_benchmark.cpp288
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-
24test_tags := tests 24test_tags := tests
25 25
26benchmark_c_flags := \ 26benchmark_c_flags := \
27 -Ibionic/tests \ 27 -Wall \
28 -Wall -Wextra \ 28 -Wextra \
29 -Werror \ 29 -Werror \
30 -fno-builtin \ 30 -fno-builtin \
31 31
32benchmark_src_files := \ 32benchmark_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)
41LOCAL_CFLAGS += $(benchmark_c_flags) 40LOCAL_CFLAGS += $(benchmark_c_flags)
42LOCAL_SHARED_LIBRARIES += liblog libm libbase 41LOCAL_SHARED_LIBRARIES += liblog libm libbase
43LOCAL_SRC_FILES := $(benchmark_src_files) 42LOCAL_SRC_FILES := $(benchmark_src_files)
44include $(BUILD_NATIVE_TEST) 43include $(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
27namespace testing {
28
29class Benchmark;
30template <typename T> class BenchmarkWantsArg;
31template <typename T> class BenchmarkWithArg;
32
33void BenchmarkRegister(Benchmark* bm);
34int PrettyPrintInt(char* str, int len, unsigned int arg);
35
36class 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
58template <typename T>
59class 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
75template <typename T>
76class 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
97template <typename T>
98class BenchmarkWantsArg : public BenchmarkWantsArgBase<T> {
99 public:
100 BenchmarkWantsArg<T>(const char* name, void (*fn)(int, T)) :
101 BenchmarkWantsArgBase<T>(name, fn) { }
102};
103
104template <>
105class 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
118static inline Benchmark* BenchmarkFactory(const char* name, void (*fn)(int)) {
119 return new Benchmark(name, fn);
120}
121
122template <typename T>
123static inline BenchmarkWantsArg<T>* BenchmarkFactory(const char* name, void (*fn)(int, T)) {
124 return new BenchmarkWantsArg<T>(name, fn);
125}
126
127} // namespace testing
128
129template <typename T>
130static 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
136void SetBenchmarkBytesProcessed(uint64_t);
137void ResetBenchmarkTiming(void);
138void StopBenchmarkTiming(void);
139void StartBenchmarkTiming(void);
140void StartBenchmarkTiming(uint64_t);
141void 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
29static uint64_t gBytesProcessed;
30static uint64_t gBenchmarkTotalTimeNs;
31static uint64_t gBenchmarkTotalTimeNsSquared;
32static uint64_t gBenchmarkNum;
33static uint64_t gBenchmarkStartTimeNs;
34
35typedef std::vector< ::testing::Benchmark*> BenchmarkList;
36static BenchmarkList* gBenchmarks;
37
38static 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
52static 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
59namespace testing {
60
61int 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
79bool 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
101void BenchmarkRegister(Benchmark* b) {
102 if (gBenchmarks == NULL) {
103 gBenchmarks = new BenchmarkList;
104 }
105 gBenchmarks->push_back(b);
106}
107
108void 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
120void 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
174void SetBenchmarkBytesProcessed(uint64_t x) {
175 gBytesProcessed = x;
176}
177
178void ResetBenchmarkTiming() {
179 gBenchmarkStartTimeNs = 0;
180 gBenchmarkTotalTimeNs = 0;
181 gBenchmarkTotalTimeNsSquared = 0;
182 gBenchmarkNum = 0;
183}
184
185void 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
195void StartBenchmarkTiming(void) {
196 if (gBenchmarkStartTimeNs == 0) {
197 gBenchmarkStartTimeNs = NanoTime();
198 }
199}
200
201void 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
213void StartBenchmarkTiming(uint64_t NanoTime) {
214 if (gBenchmarkStartTimeNs == 0) {
215 gBenchmarkStartTimeNs = NanoTime;
216 }
217}
218
219int 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" 34BENCHMARK_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 */
54static void BM_log_maximum_retry(int iters) { 55static 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}
64BENCHMARK(BM_log_maximum_retry); 61BENCHMARK(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 */
71static void BM_log_maximum(int iters) { 68static 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}
80BENCHMARK(BM_log_maximum); 74BENCHMARK(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
90static void BM_log_maximum_null(int iters) { 84static 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}
95BENCHMARK(BM_log_maximum_null); 89BENCHMARK(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 */
106static void BM_clock_overhead(int iters) { 102static 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}
112BENCHMARK(BM_clock_overhead); 108BENCHMARK(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 */
117static void BM_pmsg_short(int iters) { 113static 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}
187BENCHMARK(BM_pmsg_short); 183BENCHMARK(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 */
193static void BM_pmsg_short_aligned(int iters) { 189static 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}
261BENCHMARK(BM_pmsg_short_aligned); 258BENCHMARK(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 */
267static void BM_pmsg_short_unaligned1(int iters) { 264static 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}
335BENCHMARK(BM_pmsg_short_unaligned1); 333BENCHMARK(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 */
341static void BM_pmsg_long_aligned(int iters) { 339static 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}
407BENCHMARK(BM_pmsg_long_aligned); 406BENCHMARK(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 */
413static void BM_pmsg_long_unaligned1(int iters) { 412static 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}
479BENCHMARK(BM_pmsg_long_unaligned1); 479BENCHMARK(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 */
488static void test_print(const char* fmt, ...) { 487static 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 */
501static void BM_sprintf_overhead(int iters) { 500static 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}
509BENCHMARK(BM_sprintf_overhead); 508BENCHMARK(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 */
517static void BM_log_print_overhead(int iters) { 515static 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}
525BENCHMARK(BM_log_print_overhead); 524BENCHMARK(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 */
533static void BM_log_event_overhead(int iters) { 531static 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}
542BENCHMARK(BM_log_event_overhead); 540BENCHMARK(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 */
550static void BM_log_event_overhead_42(int iters) { 547static 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}
564BENCHMARK(BM_log_event_overhead_42); 561BENCHMARK(BM_log_event_overhead_42);
565 562
566static void BM_log_event_overhead_null(int iters) { 563static 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}
571BENCHMARK(BM_log_event_overhead_null); 568BENCHMARK(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 */
578static void BM_log_light_overhead(int iters) { 574static 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}
586BENCHMARK(BM_log_light_overhead); 582BENCHMARK(BM_log_light_overhead);
587 583
588static void BM_log_light_overhead_null(int iters) { 584static 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}
593BENCHMARK(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.
591BENCHMARK(BM_log_light_overhead_null)->Iterations(500);
594 592
595static void caught_latency(int /*signum*/) { 593static 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 */
620static void BM_log_latency(int iters) { 620static 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}
684BENCHMARK(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.
683BENCHMARK(BM_log_latency)->UseManualTime()->Iterations(200);
685 684
686static void caught_delay(int /*signum*/) { 685static 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 */
696static void BM_log_delay(int iters) { 695static 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}
756BENCHMARK(BM_log_delay); 752BENCHMARK(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 */
761static void BM_is_loggable(int iters) { 757static 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}
773BENCHMARK(BM_is_loggable); 765BENCHMARK(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 */
778static void BM_clockid(int iters) { 770static 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}
787BENCHMARK(BM_clockid); 775BENCHMARK(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 */
792static void BM_security(int iters) { 780static 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}
801BENCHMARK(BM_security); 785BENCHMARK(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 */
827static void BM_lookupEventTag(int iters) { 811static 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}
843BENCHMARK(BM_lookupEventTag); 823BENCHMARK(BM_lookupEventTag);
844 824
@@ -847,7 +827,7 @@ BENCHMARK(BM_lookupEventTag);
847 */ 827 */
848static uint32_t notTag = 1; 828static uint32_t notTag = 1;
849 829
850static void BM_lookupEventTag_NOT(int iters) { 830static 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 */
875static void BM_lookupEventFormat(int iters) { 851static 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}
891BENCHMARK(BM_lookupEventFormat); 863BENCHMARK(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 */
896static void BM_lookupEventTagNum(int iters) { 868static 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
946static void BM_lookupEventTagNum_logd_new(int iters) { 918static 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}
1003BENCHMARK(BM_lookupEventTagNum_logd_new); 975BENCHMARK(BM_lookupEventTagNum_logd_new);
1004 976
1005static void BM_lookupEventTagNum_logd_existing(int iters) { 977static 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 }