Mark Salyzyn | 819c58a | 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 | 163ebdc | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 17 | #include <fcntl.h> |
| 18 | #include <sys/endian.h> |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 19 | #include <sys/socket.h> |
Mark Salyzyn | 163ebdc | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 20 | #include <sys/types.h> |
| 21 | #include <unistd.h> |
| 22 | |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 23 | #include <cutils/sockets.h> |
| 24 | #include <log/log.h> |
| 25 | #include <log/logger.h> |
Mark Salyzyn | 163ebdc | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 26 | #include <private/android_logger.h> |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 27 | |
| 28 | #include "benchmark.h" |
| 29 | |
| 30 | // enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and |
| 31 | // non-syscall libs. Since we are benchmarking, or using this in the emergency |
| 32 | // signal to stuff a terminating code, we do NOT want to introduce |
| 33 | // a syscall or usleep on EAGAIN retry. |
| 34 | #define LOG_FAILURE_RETRY(exp) ({ \ |
| 35 | typeof (exp) _rc; \ |
| 36 | do { \ |
| 37 | _rc = (exp); \ |
| 38 | } while (((_rc == -1) \ |
| 39 | && ((errno == EINTR) \ |
| 40 | || (errno == EAGAIN))) \ |
| 41 | || (_rc == -EINTR) \ |
| 42 | || (_rc == -EAGAIN)); \ |
| 43 | _rc; }) |
| 44 | |
| 45 | /* |
| 46 | * Measure the fastest rate we can reliabley stuff print messages into |
| 47 | * the log at high pressure. Expect this to be less than double the process |
| 48 | * wakeup time (2ms?) |
| 49 | */ |
| 50 | static void BM_log_maximum_retry(int iters) { |
| 51 | StartBenchmarkTiming(); |
| 52 | |
| 53 | for (int i = 0; i < iters; ++i) { |
| 54 | LOG_FAILURE_RETRY( |
| 55 | __android_log_print(ANDROID_LOG_INFO, |
| 56 | "BM_log_maximum_retry", "%d", i)); |
| 57 | } |
| 58 | |
| 59 | StopBenchmarkTiming(); |
| 60 | } |
| 61 | BENCHMARK(BM_log_maximum_retry); |
| 62 | |
| 63 | /* |
| 64 | * Measure the fastest rate we can stuff print messages into the log |
| 65 | * at high pressure. Expect this to be less than double the process wakeup |
| 66 | * time (2ms?) |
| 67 | */ |
| 68 | static void BM_log_maximum(int iters) { |
| 69 | StartBenchmarkTiming(); |
| 70 | |
| 71 | for (int i = 0; i < iters; ++i) { |
| 72 | __android_log_print(ANDROID_LOG_INFO, "BM_log_maximum", "%d", i); |
| 73 | } |
| 74 | |
| 75 | StopBenchmarkTiming(); |
| 76 | } |
| 77 | BENCHMARK(BM_log_maximum); |
| 78 | |
| 79 | /* |
| 80 | * Measure the time it takes to submit the android logging call using |
| 81 | * discrete acquisition under light load. Expect this to be a pair of |
| 82 | * syscall periods (2us). |
| 83 | */ |
| 84 | static void BM_clock_overhead(int iters) { |
| 85 | for (int i = 0; i < iters; ++i) { |
| 86 | StartBenchmarkTiming(); |
| 87 | StopBenchmarkTiming(); |
| 88 | } |
| 89 | } |
| 90 | BENCHMARK(BM_clock_overhead); |
| 91 | |
| 92 | /* |
Mark Salyzyn | 163ebdc | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 93 | * Measure the time it takes to submit the android logging data to pstore |
| 94 | */ |
| 95 | static void BM_pmsg_short(int iters) { |
| 96 | |
| 97 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); |
| 98 | if (pstore_fd < 0) { |
| 99 | return; |
| 100 | } |
| 101 | |
| 102 | /* |
| 103 | * struct { |
| 104 | * // what we provide to pstore |
| 105 | * android_pmsg_log_header_t pmsg_header; |
| 106 | * // what we provide to socket |
| 107 | * android_log_header_t header; |
| 108 | * // caller provides |
| 109 | * union { |
| 110 | * struct { |
| 111 | * char prio; |
| 112 | * char payload[]; |
| 113 | * } string; |
| 114 | * struct { |
| 115 | * uint32_t tag |
| 116 | * char payload[]; |
| 117 | * } binary; |
| 118 | * }; |
| 119 | * }; |
| 120 | */ |
| 121 | |
| 122 | struct timespec ts; |
| 123 | clock_gettime(android_log_clockid(), &ts); |
| 124 | |
| 125 | android_pmsg_log_header_t pmsg_header; |
| 126 | pmsg_header.magic = LOGGER_MAGIC; |
| 127 | pmsg_header.len = sizeof(android_pmsg_log_header_t) |
| 128 | + sizeof(android_log_header_t); |
| 129 | pmsg_header.uid = getuid(); |
| 130 | pmsg_header.pid = getpid(); |
| 131 | |
| 132 | android_log_header_t header; |
| 133 | header.tid = gettid(); |
| 134 | header.realtime.tv_sec = ts.tv_sec; |
| 135 | header.realtime.tv_nsec = ts.tv_nsec; |
| 136 | |
| 137 | static const unsigned nr = 1; |
| 138 | static const unsigned header_length = 2; |
| 139 | struct iovec newVec[nr + header_length]; |
| 140 | |
| 141 | newVec[0].iov_base = (unsigned char *) &pmsg_header; |
| 142 | newVec[0].iov_len = sizeof(pmsg_header); |
| 143 | newVec[1].iov_base = (unsigned char *) &header; |
| 144 | newVec[1].iov_len = sizeof(header); |
| 145 | |
| 146 | android_log_event_int_t buffer; |
| 147 | |
| 148 | header.id = LOG_ID_EVENTS; |
| 149 | buffer.header.tag = 0; |
| 150 | buffer.payload.type = EVENT_TYPE_INT; |
| 151 | uint32_t snapshot = 0; |
| 152 | buffer.payload.data = htole32(snapshot); |
| 153 | |
| 154 | newVec[2].iov_base = &buffer; |
| 155 | newVec[2].iov_len = sizeof(buffer); |
| 156 | |
| 157 | StartBenchmarkTiming(); |
| 158 | for (int i = 0; i < iters; ++i) { |
| 159 | ++snapshot; |
| 160 | buffer.payload.data = htole32(snapshot); |
| 161 | writev(pstore_fd, newVec, nr); |
| 162 | } |
| 163 | StopBenchmarkTiming(); |
| 164 | close(pstore_fd); |
| 165 | } |
| 166 | BENCHMARK(BM_pmsg_short); |
| 167 | |
| 168 | /* |
| 169 | * Measure the time it takes to submit the android logging data to pstore |
| 170 | * best case aligned single block. |
| 171 | */ |
| 172 | static void BM_pmsg_short_aligned(int iters) { |
| 173 | |
| 174 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); |
| 175 | if (pstore_fd < 0) { |
| 176 | return; |
| 177 | } |
| 178 | |
| 179 | /* |
| 180 | * struct { |
| 181 | * // what we provide to pstore |
| 182 | * android_pmsg_log_header_t pmsg_header; |
| 183 | * // what we provide to socket |
| 184 | * android_log_header_t header; |
| 185 | * // caller provides |
| 186 | * union { |
| 187 | * struct { |
| 188 | * char prio; |
| 189 | * char payload[]; |
| 190 | * } string; |
| 191 | * struct { |
| 192 | * uint32_t tag |
| 193 | * char payload[]; |
| 194 | * } binary; |
| 195 | * }; |
| 196 | * }; |
| 197 | */ |
| 198 | |
| 199 | struct timespec ts; |
| 200 | clock_gettime(android_log_clockid(), &ts); |
| 201 | |
| 202 | struct packet { |
| 203 | android_pmsg_log_header_t pmsg_header; |
| 204 | android_log_header_t header; |
| 205 | android_log_event_int_t payload; |
| 206 | }; |
Elliott Hughes | 5f4a946 | 2016-06-06 19:56:24 -0700 | [diff] [blame] | 207 | alignas(8) char buf[sizeof(struct packet) + 8]; |
Mark Salyzyn | 163ebdc | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 208 | memset(buf, 0, sizeof(buf)); |
| 209 | struct packet *buffer = (struct packet*)(((uintptr_t)buf + 7) & ~7); |
| 210 | if (((uintptr_t)&buffer->pmsg_header) & 7) { |
| 211 | fprintf (stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters); |
| 212 | } |
| 213 | |
| 214 | buffer->pmsg_header.magic = LOGGER_MAGIC; |
| 215 | buffer->pmsg_header.len = sizeof(android_pmsg_log_header_t) |
| 216 | + sizeof(android_log_header_t); |
| 217 | buffer->pmsg_header.uid = getuid(); |
| 218 | buffer->pmsg_header.pid = getpid(); |
| 219 | |
| 220 | buffer->header.tid = gettid(); |
| 221 | buffer->header.realtime.tv_sec = ts.tv_sec; |
| 222 | buffer->header.realtime.tv_nsec = ts.tv_nsec; |
| 223 | |
| 224 | buffer->header.id = LOG_ID_EVENTS; |
| 225 | buffer->payload.header.tag = 0; |
| 226 | buffer->payload.payload.type = EVENT_TYPE_INT; |
| 227 | uint32_t snapshot = 0; |
| 228 | buffer->payload.payload.data = htole32(snapshot); |
| 229 | |
| 230 | StartBenchmarkTiming(); |
| 231 | for (int i = 0; i < iters; ++i) { |
| 232 | ++snapshot; |
| 233 | buffer->payload.payload.data = htole32(snapshot); |
| 234 | write(pstore_fd, &buffer->pmsg_header, |
| 235 | sizeof(android_pmsg_log_header_t) + |
| 236 | sizeof(android_log_header_t) + |
| 237 | sizeof(android_log_event_int_t)); |
| 238 | } |
| 239 | StopBenchmarkTiming(); |
| 240 | close(pstore_fd); |
| 241 | } |
| 242 | BENCHMARK(BM_pmsg_short_aligned); |
| 243 | |
| 244 | /* |
| 245 | * Measure the time it takes to submit the android logging data to pstore |
| 246 | * best case aligned single block. |
| 247 | */ |
| 248 | static void BM_pmsg_short_unaligned1(int iters) { |
| 249 | |
| 250 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); |
| 251 | if (pstore_fd < 0) { |
| 252 | return; |
| 253 | } |
| 254 | |
| 255 | /* |
| 256 | * struct { |
| 257 | * // what we provide to pstore |
| 258 | * android_pmsg_log_header_t pmsg_header; |
| 259 | * // what we provide to socket |
| 260 | * android_log_header_t header; |
| 261 | * // caller provides |
| 262 | * union { |
| 263 | * struct { |
| 264 | * char prio; |
| 265 | * char payload[]; |
| 266 | * } string; |
| 267 | * struct { |
| 268 | * uint32_t tag |
| 269 | * char payload[]; |
| 270 | * } binary; |
| 271 | * }; |
| 272 | * }; |
| 273 | */ |
| 274 | |
| 275 | struct timespec ts; |
| 276 | clock_gettime(android_log_clockid(), &ts); |
| 277 | |
| 278 | struct packet { |
| 279 | android_pmsg_log_header_t pmsg_header; |
| 280 | android_log_header_t header; |
| 281 | android_log_event_int_t payload; |
| 282 | }; |
Elliott Hughes | 5f4a946 | 2016-06-06 19:56:24 -0700 | [diff] [blame] | 283 | alignas(8) char buf[sizeof(struct packet) + 8]; |
Mark Salyzyn | 163ebdc | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 284 | memset(buf, 0, sizeof(buf)); |
| 285 | struct packet *buffer = (struct packet*)((((uintptr_t)buf + 7) & ~7) + 1); |
| 286 | if ((((uintptr_t)&buffer->pmsg_header) & 7) != 1) { |
| 287 | fprintf (stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters); |
| 288 | } |
| 289 | |
| 290 | buffer->pmsg_header.magic = LOGGER_MAGIC; |
| 291 | buffer->pmsg_header.len = sizeof(android_pmsg_log_header_t) |
| 292 | + sizeof(android_log_header_t); |
| 293 | buffer->pmsg_header.uid = getuid(); |
| 294 | buffer->pmsg_header.pid = getpid(); |
| 295 | |
| 296 | buffer->header.tid = gettid(); |
| 297 | buffer->header.realtime.tv_sec = ts.tv_sec; |
| 298 | buffer->header.realtime.tv_nsec = ts.tv_nsec; |
| 299 | |
| 300 | buffer->header.id = LOG_ID_EVENTS; |
| 301 | buffer->payload.header.tag = 0; |
| 302 | buffer->payload.payload.type = EVENT_TYPE_INT; |
| 303 | uint32_t snapshot = 0; |
| 304 | buffer->payload.payload.data = htole32(snapshot); |
| 305 | |
| 306 | StartBenchmarkTiming(); |
| 307 | for (int i = 0; i < iters; ++i) { |
| 308 | ++snapshot; |
| 309 | buffer->payload.payload.data = htole32(snapshot); |
| 310 | write(pstore_fd, &buffer->pmsg_header, |
| 311 | sizeof(android_pmsg_log_header_t) + |
| 312 | sizeof(android_log_header_t) + |
| 313 | sizeof(android_log_event_int_t)); |
| 314 | } |
| 315 | StopBenchmarkTiming(); |
| 316 | close(pstore_fd); |
| 317 | } |
| 318 | BENCHMARK(BM_pmsg_short_unaligned1); |
| 319 | |
| 320 | /* |
| 321 | * Measure the time it takes to submit the android logging data to pstore |
| 322 | * best case aligned single block. |
| 323 | */ |
| 324 | static void BM_pmsg_long_aligned(int iters) { |
| 325 | |
| 326 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); |
| 327 | if (pstore_fd < 0) { |
| 328 | return; |
| 329 | } |
| 330 | |
| 331 | /* |
| 332 | * struct { |
| 333 | * // what we provide to pstore |
| 334 | * android_pmsg_log_header_t pmsg_header; |
| 335 | * // what we provide to socket |
| 336 | * android_log_header_t header; |
| 337 | * // caller provides |
| 338 | * union { |
| 339 | * struct { |
| 340 | * char prio; |
| 341 | * char payload[]; |
| 342 | * } string; |
| 343 | * struct { |
| 344 | * uint32_t tag |
| 345 | * char payload[]; |
| 346 | * } binary; |
| 347 | * }; |
| 348 | * }; |
| 349 | */ |
| 350 | |
| 351 | struct timespec ts; |
| 352 | clock_gettime(android_log_clockid(), &ts); |
| 353 | |
| 354 | struct packet { |
| 355 | android_pmsg_log_header_t pmsg_header; |
| 356 | android_log_header_t header; |
| 357 | android_log_event_int_t payload; |
| 358 | }; |
Elliott Hughes | 5f4a946 | 2016-06-06 19:56:24 -0700 | [diff] [blame] | 359 | alignas(8) char buf[sizeof(struct packet) + 8 + LOGGER_ENTRY_MAX_PAYLOAD]; |
Mark Salyzyn | 163ebdc | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 360 | memset(buf, 0, sizeof(buf)); |
| 361 | struct packet *buffer = (struct packet*)(((uintptr_t)buf + 7) & ~7); |
| 362 | if (((uintptr_t)&buffer->pmsg_header) & 7) { |
| 363 | fprintf (stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters); |
| 364 | } |
| 365 | |
| 366 | buffer->pmsg_header.magic = LOGGER_MAGIC; |
| 367 | buffer->pmsg_header.len = sizeof(android_pmsg_log_header_t) |
| 368 | + sizeof(android_log_header_t); |
| 369 | buffer->pmsg_header.uid = getuid(); |
| 370 | buffer->pmsg_header.pid = getpid(); |
| 371 | |
| 372 | buffer->header.tid = gettid(); |
| 373 | buffer->header.realtime.tv_sec = ts.tv_sec; |
| 374 | buffer->header.realtime.tv_nsec = ts.tv_nsec; |
| 375 | |
| 376 | buffer->header.id = LOG_ID_EVENTS; |
| 377 | buffer->payload.header.tag = 0; |
| 378 | buffer->payload.payload.type = EVENT_TYPE_INT; |
| 379 | uint32_t snapshot = 0; |
| 380 | buffer->payload.payload.data = htole32(snapshot); |
| 381 | |
| 382 | StartBenchmarkTiming(); |
| 383 | for (int i = 0; i < iters; ++i) { |
| 384 | ++snapshot; |
| 385 | buffer->payload.payload.data = htole32(snapshot); |
| 386 | write(pstore_fd, &buffer->pmsg_header, LOGGER_ENTRY_MAX_PAYLOAD); |
| 387 | } |
| 388 | StopBenchmarkTiming(); |
| 389 | close(pstore_fd); |
| 390 | } |
| 391 | BENCHMARK(BM_pmsg_long_aligned); |
| 392 | |
| 393 | /* |
| 394 | * Measure the time it takes to submit the android logging data to pstore |
| 395 | * best case aligned single block. |
| 396 | */ |
| 397 | static void BM_pmsg_long_unaligned1(int iters) { |
| 398 | |
| 399 | int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); |
| 400 | if (pstore_fd < 0) { |
| 401 | return; |
| 402 | } |
| 403 | |
| 404 | /* |
| 405 | * struct { |
| 406 | * // what we provide to pstore |
| 407 | * android_pmsg_log_header_t pmsg_header; |
| 408 | * // what we provide to socket |
| 409 | * android_log_header_t header; |
| 410 | * // caller provides |
| 411 | * union { |
| 412 | * struct { |
| 413 | * char prio; |
| 414 | * char payload[]; |
| 415 | * } string; |
| 416 | * struct { |
| 417 | * uint32_t tag |
| 418 | * char payload[]; |
| 419 | * } binary; |
| 420 | * }; |
| 421 | * }; |
| 422 | */ |
| 423 | |
| 424 | struct timespec ts; |
| 425 | clock_gettime(android_log_clockid(), &ts); |
| 426 | |
| 427 | struct packet { |
| 428 | android_pmsg_log_header_t pmsg_header; |
| 429 | android_log_header_t header; |
| 430 | android_log_event_int_t payload; |
| 431 | }; |
Elliott Hughes | 5f4a946 | 2016-06-06 19:56:24 -0700 | [diff] [blame] | 432 | alignas(8) char buf[sizeof(struct packet) + 8 + LOGGER_ENTRY_MAX_PAYLOAD]; |
Mark Salyzyn | 163ebdc | 2015-12-16 13:11:36 -0800 | [diff] [blame] | 433 | memset(buf, 0, sizeof(buf)); |
| 434 | struct packet *buffer = (struct packet*)((((uintptr_t)buf + 7) & ~7) + 1); |
| 435 | if ((((uintptr_t)&buffer->pmsg_header) & 7) != 1) { |
| 436 | fprintf (stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters); |
| 437 | } |
| 438 | |
| 439 | buffer->pmsg_header.magic = LOGGER_MAGIC; |
| 440 | buffer->pmsg_header.len = sizeof(android_pmsg_log_header_t) |
| 441 | + sizeof(android_log_header_t); |
| 442 | buffer->pmsg_header.uid = getuid(); |
| 443 | buffer->pmsg_header.pid = getpid(); |
| 444 | |
| 445 | buffer->header.tid = gettid(); |
| 446 | buffer->header.realtime.tv_sec = ts.tv_sec; |
| 447 | buffer->header.realtime.tv_nsec = ts.tv_nsec; |
| 448 | |
| 449 | buffer->header.id = LOG_ID_EVENTS; |
| 450 | buffer->payload.header.tag = 0; |
| 451 | buffer->payload.payload.type = EVENT_TYPE_INT; |
| 452 | uint32_t snapshot = 0; |
| 453 | buffer->payload.payload.data = htole32(snapshot); |
| 454 | |
| 455 | StartBenchmarkTiming(); |
| 456 | for (int i = 0; i < iters; ++i) { |
| 457 | ++snapshot; |
| 458 | buffer->payload.payload.data = htole32(snapshot); |
| 459 | write(pstore_fd, &buffer->pmsg_header, LOGGER_ENTRY_MAX_PAYLOAD); |
| 460 | } |
| 461 | StopBenchmarkTiming(); |
| 462 | close(pstore_fd); |
| 463 | } |
| 464 | BENCHMARK(BM_pmsg_long_unaligned1); |
| 465 | |
| 466 | /* |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 467 | * Measure the time it takes to submit the android logging call using |
| 468 | * discrete acquisition under light load. Expect this to be a dozen or so |
| 469 | * syscall periods (40us). |
| 470 | */ |
| 471 | static void BM_log_overhead(int iters) { |
| 472 | for (int i = 0; i < iters; ++i) { |
| 473 | StartBenchmarkTiming(); |
| 474 | __android_log_print(ANDROID_LOG_INFO, "BM_log_overhead", "%d", i); |
| 475 | StopBenchmarkTiming(); |
| 476 | usleep(1000); |
| 477 | } |
| 478 | } |
| 479 | BENCHMARK(BM_log_overhead); |
| 480 | |
Mark Salyzyn | a04464a | 2014-04-30 08:50:53 -0700 | [diff] [blame] | 481 | static void caught_latency(int /*signum*/) |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 482 | { |
| 483 | unsigned long long v = 0xDEADBEEFA55A5AA5ULL; |
| 484 | |
| 485 | LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); |
| 486 | } |
| 487 | |
| 488 | static unsigned long long caught_convert(char *cp) |
| 489 | { |
| 490 | unsigned long long l = cp[0] & 0xFF; |
| 491 | l |= (unsigned long long) (cp[1] & 0xFF) << 8; |
| 492 | l |= (unsigned long long) (cp[2] & 0xFF) << 16; |
| 493 | l |= (unsigned long long) (cp[3] & 0xFF) << 24; |
| 494 | l |= (unsigned long long) (cp[4] & 0xFF) << 32; |
| 495 | l |= (unsigned long long) (cp[5] & 0xFF) << 40; |
| 496 | l |= (unsigned long long) (cp[6] & 0xFF) << 48; |
| 497 | l |= (unsigned long long) (cp[7] & 0xFF) << 56; |
| 498 | return l; |
| 499 | } |
| 500 | |
| 501 | static const int alarm_time = 3; |
| 502 | |
| 503 | /* |
| 504 | * Measure the time it takes for the logd posting call to acquire the |
| 505 | * timestamp to place into the internal record. Expect this to be less than |
| 506 | * 4 syscalls (3us). |
| 507 | */ |
| 508 | static void BM_log_latency(int iters) { |
| 509 | pid_t pid = getpid(); |
| 510 | |
| 511 | struct logger_list * logger_list = android_logger_list_open(LOG_ID_EVENTS, |
Mark Salyzyn | 2d3f38a | 2015-01-26 10:46:44 -0800 | [diff] [blame] | 512 | ANDROID_LOG_RDONLY, 0, pid); |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 513 | |
| 514 | if (!logger_list) { |
| 515 | fprintf(stderr, "Unable to open events log: %s\n", strerror(errno)); |
| 516 | exit(EXIT_FAILURE); |
| 517 | } |
| 518 | |
| 519 | signal(SIGALRM, caught_latency); |
| 520 | alarm(alarm_time); |
| 521 | |
| 522 | for (int j = 0, i = 0; i < iters && j < 10*iters; ++i, ++j) { |
| 523 | log_time ts; |
| 524 | LOG_FAILURE_RETRY(( |
Mark Salyzyn | 7e2f83c | 2014-03-05 07:41:49 -0800 | [diff] [blame] | 525 | ts = log_time(CLOCK_REALTIME), |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 526 | android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)))); |
| 527 | |
| 528 | for (;;) { |
| 529 | log_msg log_msg; |
| 530 | int ret = android_logger_list_read(logger_list, &log_msg); |
| 531 | alarm(alarm_time); |
| 532 | |
| 533 | if (ret <= 0) { |
| 534 | iters = i; |
| 535 | break; |
| 536 | } |
| 537 | if ((log_msg.entry.len != (4 + 1 + 8)) |
| 538 | || (log_msg.id() != LOG_ID_EVENTS)) { |
| 539 | continue; |
| 540 | } |
| 541 | |
| 542 | char* eventData = log_msg.msg(); |
| 543 | |
Mark Salyzyn | 305374c | 2016-08-18 14:59:41 -0700 | [diff] [blame] | 544 | if (!eventData || (eventData[4] != EVENT_TYPE_LONG)) { |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 545 | continue; |
| 546 | } |
| 547 | log_time tx(eventData + 4 + 1); |
| 548 | if (ts != tx) { |
| 549 | if (0xDEADBEEFA55A5AA5ULL == caught_convert(eventData + 4 + 1)) { |
| 550 | iters = i; |
| 551 | break; |
| 552 | } |
| 553 | continue; |
| 554 | } |
| 555 | |
| 556 | uint64_t start = ts.nsec(); |
| 557 | uint64_t end = log_msg.nsec(); |
| 558 | if (end >= start) { |
| 559 | StartBenchmarkTiming(start); |
| 560 | StopBenchmarkTiming(end); |
| 561 | } else { |
| 562 | --i; |
| 563 | } |
| 564 | break; |
| 565 | } |
| 566 | } |
| 567 | |
| 568 | signal(SIGALRM, SIG_DFL); |
| 569 | alarm(0); |
| 570 | |
| 571 | android_logger_list_free(logger_list); |
| 572 | } |
| 573 | BENCHMARK(BM_log_latency); |
| 574 | |
Mark Salyzyn | a04464a | 2014-04-30 08:50:53 -0700 | [diff] [blame] | 575 | static void caught_delay(int /*signum*/) |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 576 | { |
| 577 | unsigned long long v = 0xDEADBEEFA55A5AA6ULL; |
| 578 | |
| 579 | LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); |
| 580 | } |
| 581 | |
| 582 | /* |
| 583 | * Measure the time it takes for the logd posting call to make it into |
| 584 | * the logs. Expect this to be less than double the process wakeup time (2ms). |
| 585 | */ |
| 586 | static void BM_log_delay(int iters) { |
| 587 | pid_t pid = getpid(); |
| 588 | |
| 589 | struct logger_list * logger_list = android_logger_list_open(LOG_ID_EVENTS, |
Mark Salyzyn | 2d3f38a | 2015-01-26 10:46:44 -0800 | [diff] [blame] | 590 | ANDROID_LOG_RDONLY, 0, pid); |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 591 | |
| 592 | if (!logger_list) { |
| 593 | fprintf(stderr, "Unable to open events log: %s\n", strerror(errno)); |
| 594 | exit(EXIT_FAILURE); |
| 595 | } |
| 596 | |
| 597 | signal(SIGALRM, caught_delay); |
| 598 | alarm(alarm_time); |
| 599 | |
| 600 | StartBenchmarkTiming(); |
| 601 | |
| 602 | for (int i = 0; i < iters; ++i) { |
| 603 | log_time ts(CLOCK_REALTIME); |
| 604 | |
| 605 | LOG_FAILURE_RETRY( |
| 606 | android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); |
| 607 | |
| 608 | for (;;) { |
| 609 | log_msg log_msg; |
| 610 | int ret = android_logger_list_read(logger_list, &log_msg); |
| 611 | alarm(alarm_time); |
| 612 | |
| 613 | if (ret <= 0) { |
| 614 | iters = i; |
| 615 | break; |
| 616 | } |
| 617 | if ((log_msg.entry.len != (4 + 1 + 8)) |
| 618 | || (log_msg.id() != LOG_ID_EVENTS)) { |
| 619 | continue; |
| 620 | } |
| 621 | |
| 622 | char* eventData = log_msg.msg(); |
| 623 | |
Mark Salyzyn | 305374c | 2016-08-18 14:59:41 -0700 | [diff] [blame] | 624 | if (!eventData || (eventData[4] != EVENT_TYPE_LONG)) { |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 625 | continue; |
| 626 | } |
| 627 | log_time tx(eventData + 4 + 1); |
| 628 | if (ts != tx) { |
| 629 | if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) { |
| 630 | iters = i; |
| 631 | break; |
| 632 | } |
| 633 | continue; |
| 634 | } |
| 635 | |
| 636 | break; |
| 637 | } |
| 638 | } |
| 639 | |
| 640 | signal(SIGALRM, SIG_DFL); |
| 641 | alarm(0); |
| 642 | |
| 643 | StopBenchmarkTiming(); |
| 644 | |
| 645 | android_logger_list_free(logger_list); |
| 646 | } |
| 647 | BENCHMARK(BM_log_delay); |
Mark Salyzyn | 1ac79cb | 2015-04-23 15:08:11 -0700 | [diff] [blame] | 648 | |
| 649 | /* |
| 650 | * Measure the time it takes for __android_log_is_loggable. |
| 651 | */ |
| 652 | static void BM_is_loggable(int iters) { |
| 653 | StartBenchmarkTiming(); |
| 654 | |
| 655 | for (int i = 0; i < iters; ++i) { |
| 656 | __android_log_is_loggable(ANDROID_LOG_WARN, "logd", ANDROID_LOG_VERBOSE); |
| 657 | } |
| 658 | |
| 659 | StopBenchmarkTiming(); |
| 660 | } |
| 661 | BENCHMARK(BM_is_loggable); |
Mark Salyzyn | a67d8a5 | 2015-12-21 12:32:48 -0800 | [diff] [blame] | 662 | |
| 663 | /* |
| 664 | * Measure the time it takes for android_log_clockid. |
| 665 | */ |
| 666 | static void BM_clockid(int iters) { |
| 667 | StartBenchmarkTiming(); |
| 668 | |
| 669 | for (int i = 0; i < iters; ++i) { |
| 670 | android_log_clockid(); |
| 671 | } |
| 672 | |
| 673 | StopBenchmarkTiming(); |
| 674 | } |
| 675 | BENCHMARK(BM_clockid); |
| 676 | |
| 677 | /* |
| 678 | * Measure the time it takes for __android_log_security. |
| 679 | */ |
| 680 | static void BM_security(int iters) { |
| 681 | StartBenchmarkTiming(); |
| 682 | |
| 683 | for (int i = 0; i < iters; ++i) { |
| 684 | __android_log_security(); |
| 685 | } |
| 686 | |
| 687 | StopBenchmarkTiming(); |
| 688 | } |
| 689 | BENCHMARK(BM_security); |