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