Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 1 | /* |
| 2 | * Copyright (C) 2013-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 | |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 17 | #include <fcntl.h> |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 18 | #include <inttypes.h> |
| 19 | #include <poll.h> |
Tom Cherry | ec2dea7 | 2019-10-14 15:28:35 -0700 | [diff] [blame] | 20 | #include <sched.h> |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 21 | #include <sys/socket.h> |
Mark Salyzyn | 952a58b | 2017-09-11 13:29:59 -0700 | [diff] [blame] | 22 | #include <sys/syscall.h> |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 23 | #include <sys/types.h> |
Tom Cherry | ebebf69 | 2019-01-16 14:17:08 -0800 | [diff] [blame] | 24 | #include <sys/uio.h> |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 25 | #include <unistd.h> |
| 26 | |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 27 | #include <unordered_set> |
| 28 | |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 29 | #include <android-base/file.h> |
Tom Cherry | 71054b2 | 2020-02-21 15:08:40 -0800 | [diff] [blame] | 30 | #include <android-base/properties.h> |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 31 | #include <benchmark/benchmark.h> |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 32 | #include <cutils/sockets.h> |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 33 | #include <log/event_tag_map.h> |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 34 | #include <private/android_logger.h> |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 35 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 36 | BENCHMARK_MAIN(); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 37 | |
| 38 | // enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and |
| 39 | // non-syscall libs. Since we are benchmarking, or using this in the emergency |
| 40 | // signal to stuff a terminating code, we do NOT want to introduce |
| 41 | // a syscall or usleep on EAGAIN retry. |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 42 | #define LOG_FAILURE_RETRY(exp) \ |
| 43 | ({ \ |
| 44 | typeof(exp) _rc; \ |
| 45 | do { \ |
| 46 | _rc = (exp); \ |
| 47 | } while (((_rc == -1) && ((errno == EINTR) || (errno == EAGAIN))) || \ |
| 48 | (_rc == -EINTR) || (_rc == -EAGAIN)); \ |
| 49 | _rc; \ |
| 50 | }) |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 51 | |
| 52 | /* |
| 53 | * Measure the fastest rate we can reliabley stuff print messages into |
| 54 | * the log at high pressure. Expect this to be less than double the process |
| 55 | * wakeup time (2ms?) |
| 56 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 57 | static void BM_log_maximum_retry(benchmark::State& state) { |
| 58 | while (state.KeepRunning()) { |
Haibo Huang | 629b22b | 2019-06-06 21:27:48 -0700 | [diff] [blame] | 59 | LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_INFO, "BM_log_maximum_retry", "%" PRIu64, |
| 60 | state.iterations())); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 61 | } |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 62 | } |
| 63 | BENCHMARK(BM_log_maximum_retry); |
| 64 | |
| 65 | /* |
| 66 | * Measure the fastest rate we can stuff print messages into the log |
| 67 | * at high pressure. Expect this to be less than double the process wakeup |
| 68 | * time (2ms?) |
| 69 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 70 | static void BM_log_maximum(benchmark::State& state) { |
| 71 | while (state.KeepRunning()) { |
Haibo Huang | 629b22b | 2019-06-06 21:27:48 -0700 | [diff] [blame] | 72 | __android_log_print(ANDROID_LOG_INFO, "BM_log_maximum", "%" PRIu64, state.iterations()); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 73 | } |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 74 | } |
| 75 | BENCHMARK(BM_log_maximum); |
| 76 | |
| 77 | /* |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 78 | * Measure the time it takes to collect the time using |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 79 | * discrete acquisition (state.PauseTiming() to state.ResumeTiming()) |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 80 | * under light load. Expect this to be a syscall period (2us) or |
| 81 | * data read time if zero-syscall. |
| 82 | * |
| 83 | * vdso support in the kernel and the library can allow |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 84 | * clock_gettime to be zero-syscall, but there there does remain some |
| 85 | * benchmarking overhead to pause and resume; assumptions are both are |
| 86 | * covered. |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 87 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 88 | static void BM_clock_overhead(benchmark::State& state) { |
| 89 | while (state.KeepRunning()) { |
| 90 | state.PauseTiming(); |
| 91 | state.ResumeTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 92 | } |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 93 | } |
| 94 | BENCHMARK(BM_clock_overhead); |
| 95 | |
Mark Salyzyn | 952a58b | 2017-09-11 13:29:59 -0700 | [diff] [blame] | 96 | static void do_clock_overhead(benchmark::State& state, clockid_t clk_id) { |
| 97 | timespec t; |
| 98 | while (state.KeepRunning()) { |
| 99 | clock_gettime(clk_id, &t); |
| 100 | } |
| 101 | } |
| 102 | |
| 103 | static void BM_time_clock_gettime_REALTIME(benchmark::State& state) { |
| 104 | do_clock_overhead(state, CLOCK_REALTIME); |
| 105 | } |
| 106 | BENCHMARK(BM_time_clock_gettime_REALTIME); |
| 107 | |
| 108 | static void BM_time_clock_gettime_MONOTONIC(benchmark::State& state) { |
| 109 | do_clock_overhead(state, CLOCK_MONOTONIC); |
| 110 | } |
| 111 | BENCHMARK(BM_time_clock_gettime_MONOTONIC); |
| 112 | |
| 113 | static void BM_time_clock_gettime_MONOTONIC_syscall(benchmark::State& state) { |
| 114 | timespec t; |
| 115 | while (state.KeepRunning()) { |
| 116 | syscall(__NR_clock_gettime, CLOCK_MONOTONIC, &t); |
| 117 | } |
| 118 | } |
| 119 | BENCHMARK(BM_time_clock_gettime_MONOTONIC_syscall); |
| 120 | |
| 121 | static void BM_time_clock_gettime_MONOTONIC_RAW(benchmark::State& state) { |
| 122 | do_clock_overhead(state, CLOCK_MONOTONIC_RAW); |
| 123 | } |
| 124 | BENCHMARK(BM_time_clock_gettime_MONOTONIC_RAW); |
| 125 | |
| 126 | static void BM_time_clock_gettime_BOOTTIME(benchmark::State& state) { |
| 127 | do_clock_overhead(state, CLOCK_BOOTTIME); |
| 128 | } |
| 129 | BENCHMARK(BM_time_clock_gettime_BOOTTIME); |
| 130 | |
| 131 | static void BM_time_clock_getres_MONOTONIC(benchmark::State& state) { |
| 132 | timespec t; |
| 133 | while (state.KeepRunning()) { |
| 134 | clock_getres(CLOCK_MONOTONIC, &t); |
| 135 | } |
| 136 | } |
| 137 | BENCHMARK(BM_time_clock_getres_MONOTONIC); |
| 138 | |
| 139 | static void BM_time_clock_getres_MONOTONIC_syscall(benchmark::State& state) { |
| 140 | timespec t; |
| 141 | while (state.KeepRunning()) { |
| 142 | syscall(__NR_clock_getres, CLOCK_MONOTONIC, &t); |
| 143 | } |
| 144 | } |
| 145 | BENCHMARK(BM_time_clock_getres_MONOTONIC_syscall); |
| 146 | |
| 147 | static void BM_time_time(benchmark::State& state) { |
| 148 | while (state.KeepRunning()) { |
| 149 | time_t now; |
| 150 | now = time(&now); |
| 151 | } |
| 152 | } |
| 153 | BENCHMARK(BM_time_time); |
| 154 | |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 155 | /* |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 156 | * Measure the time it takes to submit the android logging data to pstore |
| 157 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 158 | static void BM_pmsg_short(benchmark::State& state) { |
Tom Cherry | 96e06ea | 2019-02-12 11:26:23 -0800 | [diff] [blame] | 159 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY | O_CLOEXEC)); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 160 | if (pstore_fd < 0) { |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 161 | state.SkipWithError("/dev/pmsg0"); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 162 | return; |
| 163 | } |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 164 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 165 | /* |
| 166 | * struct { |
| 167 | * // what we provide to pstore |
| 168 | * android_pmsg_log_header_t pmsg_header; |
| 169 | * // what we provide to socket |
| 170 | * android_log_header_t header; |
| 171 | * // caller provides |
| 172 | * union { |
| 173 | * struct { |
| 174 | * char prio; |
| 175 | * char payload[]; |
| 176 | * } string; |
| 177 | * struct { |
| 178 | * uint32_t tag |
| 179 | * char payload[]; |
| 180 | * } binary; |
| 181 | * }; |
| 182 | * }; |
| 183 | */ |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 184 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 185 | struct timespec ts; |
| 186 | clock_gettime(android_log_clockid(), &ts); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 187 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 188 | android_pmsg_log_header_t pmsg_header; |
| 189 | pmsg_header.magic = LOGGER_MAGIC; |
| 190 | pmsg_header.len = |
| 191 | sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t); |
| 192 | pmsg_header.uid = getuid(); |
| 193 | pmsg_header.pid = getpid(); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 194 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 195 | android_log_header_t header; |
| 196 | header.tid = gettid(); |
| 197 | header.realtime.tv_sec = ts.tv_sec; |
| 198 | header.realtime.tv_nsec = ts.tv_nsec; |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 199 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 200 | static const unsigned nr = 1; |
| 201 | static const unsigned header_length = 2; |
| 202 | struct iovec newVec[nr + header_length]; |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 203 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 204 | newVec[0].iov_base = (unsigned char*)&pmsg_header; |
| 205 | newVec[0].iov_len = sizeof(pmsg_header); |
| 206 | newVec[1].iov_base = (unsigned char*)&header; |
| 207 | newVec[1].iov_len = sizeof(header); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 208 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 209 | android_log_event_int_t buffer; |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 210 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 211 | header.id = LOG_ID_EVENTS; |
| 212 | buffer.header.tag = 0; |
| 213 | buffer.payload.type = EVENT_TYPE_INT; |
| 214 | uint32_t snapshot = 0; |
Tom Cherry | abcdd12 | 2019-09-30 14:33:46 -0700 | [diff] [blame] | 215 | buffer.payload.data = snapshot; |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 216 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 217 | newVec[2].iov_base = &buffer; |
| 218 | newVec[2].iov_len = sizeof(buffer); |
| 219 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 220 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 221 | ++snapshot; |
Tom Cherry | abcdd12 | 2019-09-30 14:33:46 -0700 | [diff] [blame] | 222 | buffer.payload.data = snapshot; |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 223 | writev(pstore_fd, newVec, nr); |
| 224 | } |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 225 | state.PauseTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 226 | close(pstore_fd); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 227 | } |
| 228 | BENCHMARK(BM_pmsg_short); |
| 229 | |
| 230 | /* |
| 231 | * Measure the time it takes to submit the android logging data to pstore |
| 232 | * best case aligned single block. |
| 233 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 234 | static void BM_pmsg_short_aligned(benchmark::State& state) { |
Tom Cherry | 96e06ea | 2019-02-12 11:26:23 -0800 | [diff] [blame] | 235 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY | O_CLOEXEC)); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 236 | if (pstore_fd < 0) { |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 237 | state.SkipWithError("/dev/pmsg0"); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 238 | return; |
| 239 | } |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 240 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 241 | /* |
| 242 | * struct { |
| 243 | * // what we provide to pstore |
| 244 | * android_pmsg_log_header_t pmsg_header; |
| 245 | * // what we provide to socket |
| 246 | * android_log_header_t header; |
| 247 | * // caller provides |
| 248 | * union { |
| 249 | * struct { |
| 250 | * char prio; |
| 251 | * char payload[]; |
| 252 | * } string; |
| 253 | * struct { |
| 254 | * uint32_t tag |
| 255 | * char payload[]; |
| 256 | * } binary; |
| 257 | * }; |
| 258 | * }; |
| 259 | */ |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 260 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 261 | struct timespec ts; |
| 262 | clock_gettime(android_log_clockid(), &ts); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 263 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 264 | struct packet { |
| 265 | android_pmsg_log_header_t pmsg_header; |
| 266 | android_log_header_t header; |
| 267 | android_log_event_int_t payload; |
| 268 | }; |
| 269 | alignas(8) char buf[sizeof(struct packet) + 8]; |
| 270 | memset(buf, 0, sizeof(buf)); |
| 271 | struct packet* buffer = (struct packet*)(((uintptr_t)buf + 7) & ~7); |
| 272 | if (((uintptr_t)&buffer->pmsg_header) & 7) { |
Haibo Huang | 629b22b | 2019-06-06 21:27:48 -0700 | [diff] [blame] | 273 | fprintf(stderr, "&buffer=0x%p iterations=%" PRIu64 "\n", &buffer->pmsg_header, |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 274 | state.iterations()); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 275 | } |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 276 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 277 | buffer->pmsg_header.magic = LOGGER_MAGIC; |
| 278 | buffer->pmsg_header.len = |
| 279 | sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t); |
| 280 | buffer->pmsg_header.uid = getuid(); |
| 281 | buffer->pmsg_header.pid = getpid(); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 282 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 283 | buffer->header.tid = gettid(); |
| 284 | buffer->header.realtime.tv_sec = ts.tv_sec; |
| 285 | buffer->header.realtime.tv_nsec = ts.tv_nsec; |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 286 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 287 | buffer->header.id = LOG_ID_EVENTS; |
| 288 | buffer->payload.header.tag = 0; |
| 289 | buffer->payload.payload.type = EVENT_TYPE_INT; |
| 290 | uint32_t snapshot = 0; |
Tom Cherry | abcdd12 | 2019-09-30 14:33:46 -0700 | [diff] [blame] | 291 | buffer->payload.payload.data = snapshot; |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 292 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 293 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 294 | ++snapshot; |
Tom Cherry | abcdd12 | 2019-09-30 14:33:46 -0700 | [diff] [blame] | 295 | buffer->payload.payload.data = snapshot; |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 296 | write(pstore_fd, &buffer->pmsg_header, |
| 297 | sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t) + |
| 298 | sizeof(android_log_event_int_t)); |
| 299 | } |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 300 | state.PauseTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 301 | close(pstore_fd); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 302 | } |
| 303 | BENCHMARK(BM_pmsg_short_aligned); |
| 304 | |
| 305 | /* |
| 306 | * Measure the time it takes to submit the android logging data to pstore |
| 307 | * best case aligned single block. |
| 308 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 309 | static void BM_pmsg_short_unaligned1(benchmark::State& state) { |
Tom Cherry | 96e06ea | 2019-02-12 11:26:23 -0800 | [diff] [blame] | 310 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY | O_CLOEXEC)); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 311 | if (pstore_fd < 0) { |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 312 | state.SkipWithError("/dev/pmsg0"); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 313 | return; |
| 314 | } |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 315 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 316 | /* |
| 317 | * struct { |
| 318 | * // what we provide to pstore |
| 319 | * android_pmsg_log_header_t pmsg_header; |
| 320 | * // what we provide to socket |
| 321 | * android_log_header_t header; |
| 322 | * // caller provides |
| 323 | * union { |
| 324 | * struct { |
| 325 | * char prio; |
| 326 | * char payload[]; |
| 327 | * } string; |
| 328 | * struct { |
| 329 | * uint32_t tag |
| 330 | * char payload[]; |
| 331 | * } binary; |
| 332 | * }; |
| 333 | * }; |
| 334 | */ |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 335 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 336 | struct timespec ts; |
| 337 | clock_gettime(android_log_clockid(), &ts); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 338 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 339 | struct packet { |
| 340 | android_pmsg_log_header_t pmsg_header; |
| 341 | android_log_header_t header; |
| 342 | android_log_event_int_t payload; |
| 343 | }; |
| 344 | alignas(8) char buf[sizeof(struct packet) + 8]; |
| 345 | memset(buf, 0, sizeof(buf)); |
| 346 | struct packet* buffer = (struct packet*)((((uintptr_t)buf + 7) & ~7) + 1); |
| 347 | if ((((uintptr_t)&buffer->pmsg_header) & 7) != 1) { |
Haibo Huang | 629b22b | 2019-06-06 21:27:48 -0700 | [diff] [blame] | 348 | fprintf(stderr, "&buffer=0x%p iterations=%" PRIu64 "\n", &buffer->pmsg_header, |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 349 | state.iterations()); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 350 | } |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 351 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 352 | buffer->pmsg_header.magic = LOGGER_MAGIC; |
| 353 | buffer->pmsg_header.len = |
| 354 | sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t); |
| 355 | buffer->pmsg_header.uid = getuid(); |
| 356 | buffer->pmsg_header.pid = getpid(); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 357 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 358 | buffer->header.tid = gettid(); |
| 359 | buffer->header.realtime.tv_sec = ts.tv_sec; |
| 360 | buffer->header.realtime.tv_nsec = ts.tv_nsec; |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 361 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 362 | buffer->header.id = LOG_ID_EVENTS; |
| 363 | buffer->payload.header.tag = 0; |
| 364 | buffer->payload.payload.type = EVENT_TYPE_INT; |
| 365 | uint32_t snapshot = 0; |
Tom Cherry | abcdd12 | 2019-09-30 14:33:46 -0700 | [diff] [blame] | 366 | buffer->payload.payload.data = snapshot; |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 367 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 368 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 369 | ++snapshot; |
Tom Cherry | abcdd12 | 2019-09-30 14:33:46 -0700 | [diff] [blame] | 370 | buffer->payload.payload.data = snapshot; |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 371 | write(pstore_fd, &buffer->pmsg_header, |
| 372 | sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t) + |
| 373 | sizeof(android_log_event_int_t)); |
| 374 | } |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 375 | state.PauseTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 376 | close(pstore_fd); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 377 | } |
| 378 | BENCHMARK(BM_pmsg_short_unaligned1); |
| 379 | |
| 380 | /* |
| 381 | * Measure the time it takes to submit the android logging data to pstore |
| 382 | * best case aligned single block. |
| 383 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 384 | static void BM_pmsg_long_aligned(benchmark::State& state) { |
Tom Cherry | 96e06ea | 2019-02-12 11:26:23 -0800 | [diff] [blame] | 385 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY | O_CLOEXEC)); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 386 | if (pstore_fd < 0) { |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 387 | state.SkipWithError("/dev/pmsg0"); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 388 | return; |
| 389 | } |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 390 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 391 | /* |
| 392 | * struct { |
| 393 | * // what we provide to pstore |
| 394 | * android_pmsg_log_header_t pmsg_header; |
| 395 | * // what we provide to socket |
| 396 | * android_log_header_t header; |
| 397 | * // caller provides |
| 398 | * union { |
| 399 | * struct { |
| 400 | * char prio; |
| 401 | * char payload[]; |
| 402 | * } string; |
| 403 | * struct { |
| 404 | * uint32_t tag |
| 405 | * char payload[]; |
| 406 | * } binary; |
| 407 | * }; |
| 408 | * }; |
| 409 | */ |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 410 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 411 | struct timespec ts; |
| 412 | clock_gettime(android_log_clockid(), &ts); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 413 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 414 | struct packet { |
| 415 | android_pmsg_log_header_t pmsg_header; |
| 416 | android_log_header_t header; |
| 417 | android_log_event_int_t payload; |
| 418 | }; |
| 419 | alignas(8) char buf[sizeof(struct packet) + 8 + LOGGER_ENTRY_MAX_PAYLOAD]; |
| 420 | memset(buf, 0, sizeof(buf)); |
| 421 | struct packet* buffer = (struct packet*)(((uintptr_t)buf + 7) & ~7); |
| 422 | if (((uintptr_t)&buffer->pmsg_header) & 7) { |
Haibo Huang | 629b22b | 2019-06-06 21:27:48 -0700 | [diff] [blame] | 423 | fprintf(stderr, "&buffer=0x%p iterations=%" PRIu64 "\n", &buffer->pmsg_header, |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 424 | state.iterations()); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 425 | } |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 426 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 427 | buffer->pmsg_header.magic = LOGGER_MAGIC; |
| 428 | buffer->pmsg_header.len = |
| 429 | sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t); |
| 430 | buffer->pmsg_header.uid = getuid(); |
| 431 | buffer->pmsg_header.pid = getpid(); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 432 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 433 | buffer->header.tid = gettid(); |
| 434 | buffer->header.realtime.tv_sec = ts.tv_sec; |
| 435 | buffer->header.realtime.tv_nsec = ts.tv_nsec; |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 436 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 437 | buffer->header.id = LOG_ID_EVENTS; |
| 438 | buffer->payload.header.tag = 0; |
| 439 | buffer->payload.payload.type = EVENT_TYPE_INT; |
| 440 | uint32_t snapshot = 0; |
Tom Cherry | abcdd12 | 2019-09-30 14:33:46 -0700 | [diff] [blame] | 441 | buffer->payload.payload.data = snapshot; |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 442 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 443 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 444 | ++snapshot; |
Tom Cherry | abcdd12 | 2019-09-30 14:33:46 -0700 | [diff] [blame] | 445 | buffer->payload.payload.data = snapshot; |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 446 | write(pstore_fd, &buffer->pmsg_header, LOGGER_ENTRY_MAX_PAYLOAD); |
| 447 | } |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 448 | state.PauseTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 449 | close(pstore_fd); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 450 | } |
| 451 | BENCHMARK(BM_pmsg_long_aligned); |
| 452 | |
| 453 | /* |
| 454 | * Measure the time it takes to submit the android logging data to pstore |
| 455 | * best case aligned single block. |
| 456 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 457 | static void BM_pmsg_long_unaligned1(benchmark::State& state) { |
Tom Cherry | 96e06ea | 2019-02-12 11:26:23 -0800 | [diff] [blame] | 458 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY | O_CLOEXEC)); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 459 | if (pstore_fd < 0) { |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 460 | state.SkipWithError("/dev/pmsg0"); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 461 | return; |
| 462 | } |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 463 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 464 | /* |
| 465 | * struct { |
| 466 | * // what we provide to pstore |
| 467 | * android_pmsg_log_header_t pmsg_header; |
| 468 | * // what we provide to socket |
| 469 | * android_log_header_t header; |
| 470 | * // caller provides |
| 471 | * union { |
| 472 | * struct { |
| 473 | * char prio; |
| 474 | * char payload[]; |
| 475 | * } string; |
| 476 | * struct { |
| 477 | * uint32_t tag |
| 478 | * char payload[]; |
| 479 | * } binary; |
| 480 | * }; |
| 481 | * }; |
| 482 | */ |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 483 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 484 | struct timespec ts; |
| 485 | clock_gettime(android_log_clockid(), &ts); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 486 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 487 | struct packet { |
| 488 | android_pmsg_log_header_t pmsg_header; |
| 489 | android_log_header_t header; |
| 490 | android_log_event_int_t payload; |
| 491 | }; |
| 492 | alignas(8) char buf[sizeof(struct packet) + 8 + LOGGER_ENTRY_MAX_PAYLOAD]; |
| 493 | memset(buf, 0, sizeof(buf)); |
| 494 | struct packet* buffer = (struct packet*)((((uintptr_t)buf + 7) & ~7) + 1); |
| 495 | if ((((uintptr_t)&buffer->pmsg_header) & 7) != 1) { |
Haibo Huang | 629b22b | 2019-06-06 21:27:48 -0700 | [diff] [blame] | 496 | fprintf(stderr, "&buffer=0x%p iterations=%" PRIu64 "\n", &buffer->pmsg_header, |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 497 | state.iterations()); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 498 | } |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 499 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 500 | buffer->pmsg_header.magic = LOGGER_MAGIC; |
| 501 | buffer->pmsg_header.len = |
| 502 | sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t); |
| 503 | buffer->pmsg_header.uid = getuid(); |
| 504 | buffer->pmsg_header.pid = getpid(); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 505 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 506 | buffer->header.tid = gettid(); |
| 507 | buffer->header.realtime.tv_sec = ts.tv_sec; |
| 508 | buffer->header.realtime.tv_nsec = ts.tv_nsec; |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 509 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 510 | buffer->header.id = LOG_ID_EVENTS; |
| 511 | buffer->payload.header.tag = 0; |
| 512 | buffer->payload.payload.type = EVENT_TYPE_INT; |
| 513 | uint32_t snapshot = 0; |
Tom Cherry | abcdd12 | 2019-09-30 14:33:46 -0700 | [diff] [blame] | 514 | buffer->payload.payload.data = snapshot; |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 515 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 516 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 517 | ++snapshot; |
Tom Cherry | abcdd12 | 2019-09-30 14:33:46 -0700 | [diff] [blame] | 518 | buffer->payload.payload.data = snapshot; |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 519 | write(pstore_fd, &buffer->pmsg_header, LOGGER_ENTRY_MAX_PAYLOAD); |
| 520 | } |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 521 | state.PauseTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 522 | close(pstore_fd); |
Mark Salyzyn | 4fa06c4 | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 523 | } |
| 524 | BENCHMARK(BM_pmsg_long_unaligned1); |
| 525 | |
| 526 | /* |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 527 | * Measure the time it takes to form sprintf plus time using |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 528 | * discrete acquisition under light load. Expect this to be a syscall period |
| 529 | * (2us) or sprintf time if zero-syscall time. |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 530 | */ |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 531 | /* helper function */ |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 532 | static void test_print(const char* fmt, ...) { |
| 533 | va_list ap; |
| 534 | char buf[1024]; |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 535 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 536 | va_start(ap, fmt); |
| 537 | vsnprintf(buf, sizeof(buf), fmt, ap); |
| 538 | va_end(ap); |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 539 | } |
| 540 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 541 | #define logd_yield() sched_yield() // allow logd to catch up |
| 542 | #define logd_sleep() usleep(50) // really allow logd to catch up |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 543 | |
| 544 | /* performance test */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 545 | static void BM_sprintf_overhead(benchmark::State& state) { |
| 546 | while (state.KeepRunning()) { |
Haibo Huang | 629b22b | 2019-06-06 21:27:48 -0700 | [diff] [blame] | 547 | test_print("BM_sprintf_overhead:%" PRIu64, state.iterations()); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 548 | state.PauseTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 549 | logd_yield(); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 550 | state.ResumeTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 551 | } |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 552 | } |
| 553 | BENCHMARK(BM_sprintf_overhead); |
| 554 | |
| 555 | /* |
| 556 | * Measure the time it takes to submit the android printing logging call |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 557 | * using discrete acquisition discrete acquisition under light load. Expect |
| 558 | * this to be a dozen or so syscall periods (40us) plus time to run *printf |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 559 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 560 | static void BM_log_print_overhead(benchmark::State& state) { |
| 561 | while (state.KeepRunning()) { |
Haibo Huang | 629b22b | 2019-06-06 21:27:48 -0700 | [diff] [blame] | 562 | __android_log_print(ANDROID_LOG_INFO, "BM_log_overhead", "%" PRIu64, state.iterations()); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 563 | state.PauseTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 564 | logd_yield(); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 565 | state.ResumeTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 566 | } |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 567 | } |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 568 | BENCHMARK(BM_log_print_overhead); |
| 569 | |
| 570 | /* |
| 571 | * Measure the time it takes to submit the android event logging call |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 572 | * using discrete acquisition under light load. Expect this to be a long path |
| 573 | * to logger to convert the unknown tag (0) into a tagname (less than 200us). |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 574 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 575 | static void BM_log_event_overhead(benchmark::State& state) { |
| 576 | for (int64_t i = 0; state.KeepRunning(); ++i) { |
Mark Salyzyn | cffa4c6 | 2017-03-28 11:40:55 -0700 | [diff] [blame] | 577 | // log tag number 0 is not known, nor shall it ever be known |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 578 | __android_log_btwrite(0, EVENT_TYPE_LONG, &i, sizeof(i)); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 579 | state.PauseTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 580 | logd_yield(); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 581 | state.ResumeTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 582 | } |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 583 | } |
| 584 | BENCHMARK(BM_log_event_overhead); |
| 585 | |
Mark Salyzyn | cffa4c6 | 2017-03-28 11:40:55 -0700 | [diff] [blame] | 586 | /* |
| 587 | * Measure the time it takes to submit the android event logging call |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 588 | * using discrete acquisition under light load with a known logtag. Expect |
| 589 | * this to be a dozen or so syscall periods (less than 40us) |
Mark Salyzyn | cffa4c6 | 2017-03-28 11:40:55 -0700 | [diff] [blame] | 590 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 591 | static void BM_log_event_overhead_42(benchmark::State& state) { |
| 592 | for (int64_t i = 0; state.KeepRunning(); ++i) { |
Mark Salyzyn | cffa4c6 | 2017-03-28 11:40:55 -0700 | [diff] [blame] | 593 | // In system/core/logcat/event.logtags: |
| 594 | // # These are used for testing, do not modify without updating |
| 595 | // # tests/framework-tests/src/android/util/EventLogFunctionalTest.java. |
| 596 | // # system/core/liblog/tests/liblog_benchmark.cpp |
| 597 | // # system/core/liblog/tests/liblog_test.cpp |
| 598 | // 42 answer (to life the universe etc|3) |
| 599 | __android_log_btwrite(42, EVENT_TYPE_LONG, &i, sizeof(i)); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 600 | state.PauseTiming(); |
Mark Salyzyn | cffa4c6 | 2017-03-28 11:40:55 -0700 | [diff] [blame] | 601 | logd_yield(); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 602 | state.ResumeTiming(); |
Mark Salyzyn | cffa4c6 | 2017-03-28 11:40:55 -0700 | [diff] [blame] | 603 | } |
| 604 | } |
| 605 | BENCHMARK(BM_log_event_overhead_42); |
| 606 | |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 607 | /* |
| 608 | * Measure the time it takes to submit the android event logging call |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 609 | * using discrete acquisition under very-light load (<1% CPU utilization). |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 610 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 611 | static void BM_log_light_overhead(benchmark::State& state) { |
| 612 | for (int64_t i = 0; state.KeepRunning(); ++i) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 613 | __android_log_btwrite(0, EVENT_TYPE_LONG, &i, sizeof(i)); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 614 | state.PauseTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 615 | usleep(10000); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 616 | state.ResumeTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 617 | } |
Mark Salyzyn | 4189ccc | 2015-02-04 12:40:55 -0800 | [diff] [blame] | 618 | } |
| 619 | BENCHMARK(BM_log_light_overhead); |
| 620 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 621 | static void caught_latency(int /*signum*/) { |
| 622 | unsigned long long v = 0xDEADBEEFA55A5AA5ULL; |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 623 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 624 | LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 625 | } |
| 626 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 627 | static unsigned long long caught_convert(char* cp) { |
| 628 | unsigned long long l = cp[0] & 0xFF; |
| 629 | l |= (unsigned long long)(cp[1] & 0xFF) << 8; |
| 630 | l |= (unsigned long long)(cp[2] & 0xFF) << 16; |
| 631 | l |= (unsigned long long)(cp[3] & 0xFF) << 24; |
| 632 | l |= (unsigned long long)(cp[4] & 0xFF) << 32; |
| 633 | l |= (unsigned long long)(cp[5] & 0xFF) << 40; |
| 634 | l |= (unsigned long long)(cp[6] & 0xFF) << 48; |
| 635 | l |= (unsigned long long)(cp[7] & 0xFF) << 56; |
| 636 | return l; |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 637 | } |
| 638 | |
| 639 | static const int alarm_time = 3; |
| 640 | |
| 641 | /* |
| 642 | * Measure the time it takes for the logd posting call to acquire the |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 643 | * timestamp to place into the internal record. Expect this to be less than |
| 644 | * 4 syscalls (3us). This test uses manual injection of timing because it is |
| 645 | * comparing the timestamp at send, and then picking up the corresponding log |
| 646 | * end-to-end long path from logd to see what actual timestamp was submitted. |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 647 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 648 | static void BM_log_latency(benchmark::State& state) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 649 | pid_t pid = getpid(); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 650 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 651 | struct logger_list* logger_list = |
| 652 | android_logger_list_open(LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 0, pid); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 653 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 654 | if (!logger_list) { |
| 655 | fprintf(stderr, "Unable to open events log: %s\n", strerror(errno)); |
| 656 | exit(EXIT_FAILURE); |
| 657 | } |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 658 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 659 | signal(SIGALRM, caught_latency); |
| 660 | alarm(alarm_time); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 661 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 662 | for (size_t j = 0; state.KeepRunning() && j < 10 * state.iterations(); ++j) { |
| 663 | retry: // We allow transitory errors (logd overloaded) to be retried. |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 664 | log_time ts; |
| 665 | LOG_FAILURE_RETRY((ts = log_time(CLOCK_REALTIME), |
| 666 | android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)))); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 667 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 668 | for (;;) { |
| 669 | log_msg log_msg; |
| 670 | int ret = android_logger_list_read(logger_list, &log_msg); |
| 671 | alarm(alarm_time); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 672 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 673 | if (ret <= 0) { |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 674 | state.SkipWithError("android_logger_list_read"); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 675 | break; |
| 676 | } |
| 677 | if ((log_msg.entry.len != (4 + 1 + 8)) || |
| 678 | (log_msg.id() != LOG_ID_EVENTS)) { |
| 679 | continue; |
| 680 | } |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 681 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 682 | char* eventData = log_msg.msg(); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 683 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 684 | if (!eventData || (eventData[4] != EVENT_TYPE_LONG)) { |
| 685 | continue; |
| 686 | } |
| 687 | log_time tx(eventData + 4 + 1); |
| 688 | if (ts != tx) { |
| 689 | if (0xDEADBEEFA55A5AA5ULL == caught_convert(eventData + 4 + 1)) { |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 690 | state.SkipWithError("signal"); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 691 | break; |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 692 | } |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 693 | continue; |
| 694 | } |
| 695 | |
| 696 | uint64_t start = ts.nsec(); |
| 697 | uint64_t end = log_msg.nsec(); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 698 | if (end < start) goto retry; |
| 699 | state.SetIterationTime((end - start) / (double)NS_PER_SEC); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 700 | break; |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 701 | } |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 702 | } |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 703 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 704 | signal(SIGALRM, SIG_DFL); |
| 705 | alarm(0); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 706 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 707 | android_logger_list_free(logger_list); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 708 | } |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 709 | // Default gets out of hand for this test, so we set a reasonable number of |
| 710 | // iterations for a timely result. |
| 711 | BENCHMARK(BM_log_latency)->UseManualTime()->Iterations(200); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 712 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 713 | static void caught_delay(int /*signum*/) { |
| 714 | unsigned long long v = 0xDEADBEEFA55A5AA6ULL; |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 715 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 716 | LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 717 | } |
| 718 | |
| 719 | /* |
| 720 | * Measure the time it takes for the logd posting call to make it into |
| 721 | * the logs. Expect this to be less than double the process wakeup time (2ms). |
| 722 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 723 | static void BM_log_delay(benchmark::State& state) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 724 | pid_t pid = getpid(); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 725 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 726 | struct logger_list* logger_list = |
| 727 | android_logger_list_open(LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 0, pid); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 728 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 729 | if (!logger_list) { |
| 730 | fprintf(stderr, "Unable to open events log: %s\n", strerror(errno)); |
| 731 | exit(EXIT_FAILURE); |
| 732 | } |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 733 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 734 | signal(SIGALRM, caught_delay); |
| 735 | alarm(alarm_time); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 736 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 737 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 738 | log_time ts(CLOCK_REALTIME); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 739 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 740 | LOG_FAILURE_RETRY(android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 741 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 742 | for (;;) { |
| 743 | log_msg log_msg; |
| 744 | int ret = android_logger_list_read(logger_list, &log_msg); |
| 745 | alarm(alarm_time); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 746 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 747 | if (ret <= 0) { |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 748 | state.SkipWithError("android_logger_list_read"); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 749 | break; |
| 750 | } |
| 751 | if ((log_msg.entry.len != (4 + 1 + 8)) || |
| 752 | (log_msg.id() != LOG_ID_EVENTS)) { |
| 753 | continue; |
| 754 | } |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 755 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 756 | char* eventData = log_msg.msg(); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 757 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 758 | if (!eventData || (eventData[4] != EVENT_TYPE_LONG)) { |
| 759 | continue; |
| 760 | } |
| 761 | log_time tx(eventData + 4 + 1); |
| 762 | if (ts != tx) { |
| 763 | if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) { |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 764 | state.SkipWithError("signal"); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 765 | break; |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 766 | } |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 767 | continue; |
| 768 | } |
| 769 | |
| 770 | break; |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 771 | } |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 772 | } |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 773 | state.PauseTiming(); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 774 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 775 | signal(SIGALRM, SIG_DFL); |
| 776 | alarm(0); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 777 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 778 | android_logger_list_free(logger_list); |
Mark Salyzyn | fb2a5da | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 779 | } |
| 780 | BENCHMARK(BM_log_delay); |
Mark Salyzyn | 4f808ef | 2015-04-23 15:08:11 -0700 | [diff] [blame] | 781 | |
| 782 | /* |
| 783 | * Measure the time it takes for __android_log_is_loggable. |
| 784 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 785 | static void BM_is_loggable(benchmark::State& state) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 786 | static const char logd[] = "logd"; |
Mark Salyzyn | 29d0b83 | 2016-09-22 09:56:51 -0700 | [diff] [blame] | 787 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 788 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 789 | __android_log_is_loggable_len(ANDROID_LOG_WARN, logd, strlen(logd), |
| 790 | ANDROID_LOG_VERBOSE); |
| 791 | } |
Mark Salyzyn | 4f808ef | 2015-04-23 15:08:11 -0700 | [diff] [blame] | 792 | } |
| 793 | BENCHMARK(BM_is_loggable); |
Mark Salyzyn | d486019 | 2015-12-21 12:32:48 -0800 | [diff] [blame] | 794 | |
| 795 | /* |
| 796 | * Measure the time it takes for android_log_clockid. |
| 797 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 798 | static void BM_clockid(benchmark::State& state) { |
| 799 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 800 | android_log_clockid(); |
| 801 | } |
Mark Salyzyn | d486019 | 2015-12-21 12:32:48 -0800 | [diff] [blame] | 802 | } |
| 803 | BENCHMARK(BM_clockid); |
| 804 | |
| 805 | /* |
| 806 | * Measure the time it takes for __android_log_security. |
| 807 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 808 | static void BM_security(benchmark::State& state) { |
| 809 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 810 | __android_log_security(); |
| 811 | } |
Mark Salyzyn | d486019 | 2015-12-21 12:32:48 -0800 | [diff] [blame] | 812 | } |
| 813 | BENCHMARK(BM_security); |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 814 | |
| 815 | // Keep maps around for multiple iterations |
| 816 | static std::unordered_set<uint32_t> set; |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 817 | static EventTagMap* map; |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 818 | |
| 819 | static bool prechargeEventMap() { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 820 | if (map) return true; |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 821 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 822 | fprintf(stderr, "Precharge: start\n"); |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 823 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 824 | map = android_openEventTagMap(NULL); |
| 825 | for (uint32_t tag = 1; tag < USHRT_MAX; ++tag) { |
| 826 | size_t len; |
| 827 | if (android_lookupEventTag_len(map, &len, tag) == NULL) continue; |
| 828 | set.insert(tag); |
| 829 | } |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 830 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 831 | fprintf(stderr, "Precharge: stop %zu\n", set.size()); |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 832 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 833 | return true; |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 834 | } |
| 835 | |
| 836 | /* |
| 837 | * Measure the time it takes for android_lookupEventTag_len |
| 838 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 839 | static void BM_lookupEventTag(benchmark::State& state) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 840 | prechargeEventMap(); |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 841 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 842 | std::unordered_set<uint32_t>::const_iterator it = set.begin(); |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 843 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 844 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 845 | size_t len; |
| 846 | android_lookupEventTag_len(map, &len, (*it)); |
| 847 | ++it; |
| 848 | if (it == set.end()) it = set.begin(); |
| 849 | } |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 850 | } |
| 851 | BENCHMARK(BM_lookupEventTag); |
| 852 | |
| 853 | /* |
| 854 | * Measure the time it takes for android_lookupEventTag_len |
| 855 | */ |
| 856 | static uint32_t notTag = 1; |
| 857 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 858 | static void BM_lookupEventTag_NOT(benchmark::State& state) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 859 | prechargeEventMap(); |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 860 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 861 | while (set.find(notTag) != set.end()) { |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 862 | ++notTag; |
| 863 | if (notTag >= USHRT_MAX) notTag = 1; |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 864 | } |
| 865 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 866 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 867 | size_t len; |
| 868 | android_lookupEventTag_len(map, &len, notTag); |
| 869 | } |
| 870 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 871 | ++notTag; |
| 872 | if (notTag >= USHRT_MAX) notTag = 1; |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 873 | } |
| 874 | BENCHMARK(BM_lookupEventTag_NOT); |
| 875 | |
| 876 | /* |
| 877 | * Measure the time it takes for android_lookupEventFormat_len |
| 878 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 879 | static void BM_lookupEventFormat(benchmark::State& state) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 880 | prechargeEventMap(); |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 881 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 882 | std::unordered_set<uint32_t>::const_iterator it = set.begin(); |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 883 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 884 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 885 | size_t len; |
| 886 | android_lookupEventFormat_len(map, &len, (*it)); |
| 887 | ++it; |
| 888 | if (it == set.end()) it = set.begin(); |
| 889 | } |
Mark Salyzyn | a2b5b56 | 2016-11-22 13:08:59 -0800 | [diff] [blame] | 890 | } |
| 891 | BENCHMARK(BM_lookupEventFormat); |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 892 | |
| 893 | /* |
| 894 | * Measure the time it takes for android_lookupEventTagNum plus above |
| 895 | */ |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 896 | static void BM_lookupEventTagNum(benchmark::State& state) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 897 | prechargeEventMap(); |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 898 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 899 | std::unordered_set<uint32_t>::const_iterator it = set.begin(); |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 900 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 901 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 902 | size_t len; |
| 903 | const char* name = android_lookupEventTag_len(map, &len, (*it)); |
| 904 | std::string Name(name, len); |
| 905 | const char* format = android_lookupEventFormat_len(map, &len, (*it)); |
| 906 | std::string Format(format, len); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 907 | state.ResumeTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 908 | android_lookupEventTagNum(map, Name.c_str(), Format.c_str(), |
| 909 | ANDROID_LOG_UNKNOWN); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 910 | state.PauseTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 911 | ++it; |
| 912 | if (it == set.end()) it = set.begin(); |
| 913 | } |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 914 | } |
| 915 | BENCHMARK(BM_lookupEventTagNum); |
| 916 | |
Tom Cherry | f459c58 | 2019-11-14 08:56:39 -0800 | [diff] [blame] | 917 | // Must be functionally identical to liblog internal SendLogdControlMessage() |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 918 | static void send_to_control(char* buf, size_t len) { |
Tom Cherry | 96e06ea | 2019-02-12 11:26:23 -0800 | [diff] [blame] | 919 | int sock = |
| 920 | socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_STREAM | SOCK_CLOEXEC); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 921 | if (sock < 0) return; |
| 922 | size_t writeLen = strlen(buf) + 1; |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 923 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 924 | ssize_t ret = TEMP_FAILURE_RETRY(write(sock, buf, writeLen)); |
| 925 | if (ret <= 0) { |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 926 | close(sock); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 927 | return; |
| 928 | } |
| 929 | while ((ret = read(sock, buf, len)) > 0) { |
| 930 | if (((size_t)ret == len) || (len < PAGE_SIZE)) { |
| 931 | break; |
| 932 | } |
| 933 | len -= ret; |
| 934 | buf += ret; |
| 935 | |
| 936 | struct pollfd p = {.fd = sock, .events = POLLIN, .revents = 0 }; |
| 937 | |
| 938 | ret = poll(&p, 1, 20); |
| 939 | if ((ret <= 0) || !(p.revents & POLLIN)) { |
| 940 | break; |
| 941 | } |
| 942 | } |
| 943 | close(sock); |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 944 | } |
| 945 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 946 | static void BM_lookupEventTagNum_logd_new(benchmark::State& state) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 947 | fprintf(stderr, |
| 948 | "WARNING: " |
| 949 | "This test can cause logd to grow in size and hit DOS limiter\n"); |
| 950 | // Make copies |
| 951 | static const char empty_event_log_tags[] = "# content owned by logd\n"; |
| 952 | static const char dev_event_log_tags_path[] = "/dev/event-log-tags"; |
| 953 | std::string dev_event_log_tags; |
| 954 | if (android::base::ReadFileToString(dev_event_log_tags_path, |
| 955 | &dev_event_log_tags) && |
| 956 | (dev_event_log_tags.length() == 0)) { |
| 957 | dev_event_log_tags = empty_event_log_tags; |
| 958 | } |
| 959 | static const char data_event_log_tags_path[] = |
| 960 | "/data/misc/logd/event-log-tags"; |
| 961 | std::string data_event_log_tags; |
| 962 | if (android::base::ReadFileToString(data_event_log_tags_path, |
| 963 | &data_event_log_tags) && |
| 964 | (data_event_log_tags.length() == 0)) { |
| 965 | data_event_log_tags = empty_event_log_tags; |
| 966 | } |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 967 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 968 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 969 | char buffer[256]; |
| 970 | memset(buffer, 0, sizeof(buffer)); |
| 971 | log_time now(CLOCK_MONOTONIC); |
| 972 | char name[64]; |
| 973 | snprintf(name, sizeof(name), "a%" PRIu64, now.nsec()); |
| 974 | snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"(new|1)\"", |
| 975 | name); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 976 | state.ResumeTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 977 | send_to_control(buffer, sizeof(buffer)); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 978 | state.PauseTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 979 | } |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 980 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 981 | // Restore copies (logd still know about them, until crash or reboot) |
| 982 | if (dev_event_log_tags.length() && |
| 983 | !android::base::WriteStringToFile(dev_event_log_tags, |
| 984 | dev_event_log_tags_path)) { |
| 985 | fprintf(stderr, |
| 986 | "WARNING: " |
| 987 | "failed to restore %s\n", |
| 988 | dev_event_log_tags_path); |
| 989 | } |
| 990 | if (data_event_log_tags.length() && |
| 991 | !android::base::WriteStringToFile(data_event_log_tags, |
| 992 | data_event_log_tags_path)) { |
| 993 | fprintf(stderr, |
| 994 | "WARNING: " |
| 995 | "failed to restore %s\n", |
| 996 | data_event_log_tags_path); |
| 997 | } |
| 998 | fprintf(stderr, |
| 999 | "WARNING: " |
| 1000 | "Restarting logd to make it forget what we just did\n"); |
| 1001 | system("stop logd ; start logd"); |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 1002 | } |
| 1003 | BENCHMARK(BM_lookupEventTagNum_logd_new); |
| 1004 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 1005 | static void BM_lookupEventTagNum_logd_existing(benchmark::State& state) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 1006 | prechargeEventMap(); |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 1007 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 1008 | std::unordered_set<uint32_t>::const_iterator it = set.begin(); |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 1009 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 1010 | while (state.KeepRunning()) { |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 1011 | size_t len; |
| 1012 | const char* name = android_lookupEventTag_len(map, &len, (*it)); |
| 1013 | std::string Name(name, len); |
| 1014 | const char* format = android_lookupEventFormat_len(map, &len, (*it)); |
| 1015 | std::string Format(format, len); |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 1016 | |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 1017 | char buffer[256]; |
| 1018 | snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"%s\"", |
| 1019 | Name.c_str(), Format.c_str()); |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 1020 | |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 1021 | state.ResumeTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 1022 | send_to_control(buffer, sizeof(buffer)); |
Mark Salyzyn | cecd60d | 2018-01-11 11:20:24 -0800 | [diff] [blame] | 1023 | state.PauseTiming(); |
Mark Salyzyn | 6e31568 | 2017-03-09 08:09:43 -0800 | [diff] [blame] | 1024 | ++it; |
| 1025 | if (it == set.end()) it = set.begin(); |
| 1026 | } |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 1027 | } |
| 1028 | BENCHMARK(BM_lookupEventTagNum_logd_existing); |
Tom Cherry | 71054b2 | 2020-02-21 15:08:40 -0800 | [diff] [blame] | 1029 | |
| 1030 | static void BM_log_verbose_overhead(benchmark::State& state) { |
| 1031 | std::string test_log_tag = "liblog_verbose_tag"; |
| 1032 | android::base::SetProperty("log.tag." + test_log_tag, "I"); |
| 1033 | for (auto _ : state) { |
| 1034 | __android_log_print(ANDROID_LOG_VERBOSE, test_log_tag.c_str(), "%s test log message %d %d", |
| 1035 | "test test", 123, 456); |
| 1036 | } |
| 1037 | android::base::SetProperty("log.tag." + test_log_tag, ""); |
| 1038 | } |
| 1039 | BENCHMARK(BM_log_verbose_overhead); |