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