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 */
BM_log_maximum_retry(int iters)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 */
BM_log_maximum(int iters)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
set_log_null()82 static void set_log_null() {
83 android_set_log_transport(LOGGER_NULL);
84 }
85
set_log_default()86 static void set_log_default() {
87 android_set_log_transport(LOGGER_DEFAULT);
88 }
89
BM_log_maximum_null(int iters)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 */
BM_clock_overhead(int iters)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 */
BM_pmsg_short(int iters)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 */
BM_pmsg_short_aligned(int iters)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 */
BM_pmsg_short_unaligned1(int iters)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 */
BM_pmsg_long_aligned(int iters)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 */
BM_pmsg_long_unaligned1(int iters)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 */
test_print(const char * fmt,...)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 */
BM_sprintf_overhead(int iters)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 */
BM_log_print_overhead(int iters)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 dozen or so syscall periods (40us)
531 */
BM_log_event_overhead(int iters)532 static void BM_log_event_overhead(int iters) {
533 for (unsigned long long i = 0; i < (unsigned)iters; ++i) {
534 StartBenchmarkTiming();
535 __android_log_btwrite(0, EVENT_TYPE_LONG, &i, sizeof(i));
536 StopBenchmarkTiming();
537 logd_yield();
538 }
539 }
540 BENCHMARK(BM_log_event_overhead);
541
BM_log_event_overhead_null(int iters)542 static void BM_log_event_overhead_null(int iters) {
543 set_log_null();
544 BM_log_event_overhead(iters);
545 set_log_default();
546 }
547 BENCHMARK(BM_log_event_overhead_null);
548
549 /*
550 * Measure the time it takes to submit the android event logging call
551 * using discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming())
552 * under very-light load (<1% CPU utilization).
553 */
BM_log_light_overhead(int iters)554 static void BM_log_light_overhead(int iters) {
555 for (unsigned long long i = 0; i < (unsigned)iters; ++i) {
556 StartBenchmarkTiming();
557 __android_log_btwrite(0, EVENT_TYPE_LONG, &i, sizeof(i));
558 StopBenchmarkTiming();
559 usleep(10000);
560 }
561 }
562 BENCHMARK(BM_log_light_overhead);
563
BM_log_light_overhead_null(int iters)564 static void BM_log_light_overhead_null(int iters) {
565 set_log_null();
566 BM_log_light_overhead(iters);
567 set_log_default();
568 }
569 BENCHMARK(BM_log_light_overhead_null);
570
caught_latency(int)571 static void caught_latency(int /*signum*/) {
572 unsigned long long v = 0xDEADBEEFA55A5AA5ULL;
573
574 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
575 }
576
caught_convert(char * cp)577 static unsigned long long caught_convert(char* cp) {
578 unsigned long long l = cp[0] & 0xFF;
579 l |= (unsigned long long)(cp[1] & 0xFF) << 8;
580 l |= (unsigned long long)(cp[2] & 0xFF) << 16;
581 l |= (unsigned long long)(cp[3] & 0xFF) << 24;
582 l |= (unsigned long long)(cp[4] & 0xFF) << 32;
583 l |= (unsigned long long)(cp[5] & 0xFF) << 40;
584 l |= (unsigned long long)(cp[6] & 0xFF) << 48;
585 l |= (unsigned long long)(cp[7] & 0xFF) << 56;
586 return l;
587 }
588
589 static const int alarm_time = 3;
590
591 /*
592 * Measure the time it takes for the logd posting call to acquire the
593 * timestamp to place into the internal record. Expect this to be less than
594 * 4 syscalls (3us).
595 */
BM_log_latency(int iters)596 static void BM_log_latency(int iters) {
597 pid_t pid = getpid();
598
599 struct logger_list* logger_list =
600 android_logger_list_open(LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 0, pid);
601
602 if (!logger_list) {
603 fprintf(stderr, "Unable to open events log: %s\n", strerror(errno));
604 exit(EXIT_FAILURE);
605 }
606
607 signal(SIGALRM, caught_latency);
608 alarm(alarm_time);
609
610 for (int j = 0, i = 0; i < iters && j < 10 * iters; ++i, ++j) {
611 log_time ts;
612 LOG_FAILURE_RETRY((ts = log_time(CLOCK_REALTIME),
613 android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))));
614
615 for (;;) {
616 log_msg log_msg;
617 int ret = android_logger_list_read(logger_list, &log_msg);
618 alarm(alarm_time);
619
620 if (ret <= 0) {
621 iters = i;
622 break;
623 }
624 if ((log_msg.entry.len != (4 + 1 + 8)) ||
625 (log_msg.id() != LOG_ID_EVENTS)) {
626 continue;
627 }
628
629 char* eventData = log_msg.msg();
630
631 if (!eventData || (eventData[4] != EVENT_TYPE_LONG)) {
632 continue;
633 }
634 log_time tx(eventData + 4 + 1);
635 if (ts != tx) {
636 if (0xDEADBEEFA55A5AA5ULL == caught_convert(eventData + 4 + 1)) {
637 iters = i;
638 break;
639 }
640 continue;
641 }
642
643 uint64_t start = ts.nsec();
644 uint64_t end = log_msg.nsec();
645 if (end >= start) {
646 StartBenchmarkTiming(start);
647 StopBenchmarkTiming(end);
648 } else {
649 --i;
650 }
651 break;
652 }
653 }
654
655 signal(SIGALRM, SIG_DFL);
656 alarm(0);
657
658 android_logger_list_free(logger_list);
659 }
660 BENCHMARK(BM_log_latency);
661
caught_delay(int)662 static void caught_delay(int /*signum*/) {
663 unsigned long long v = 0xDEADBEEFA55A5AA6ULL;
664
665 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
666 }
667
668 /*
669 * Measure the time it takes for the logd posting call to make it into
670 * the logs. Expect this to be less than double the process wakeup time (2ms).
671 */
BM_log_delay(int iters)672 static void BM_log_delay(int iters) {
673 pid_t pid = getpid();
674
675 struct logger_list* logger_list =
676 android_logger_list_open(LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 0, pid);
677
678 if (!logger_list) {
679 fprintf(stderr, "Unable to open events log: %s\n", strerror(errno));
680 exit(EXIT_FAILURE);
681 }
682
683 signal(SIGALRM, caught_delay);
684 alarm(alarm_time);
685
686 StartBenchmarkTiming();
687
688 for (int i = 0; i < iters; ++i) {
689 log_time ts(CLOCK_REALTIME);
690
691 LOG_FAILURE_RETRY(android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
692
693 for (;;) {
694 log_msg log_msg;
695 int ret = android_logger_list_read(logger_list, &log_msg);
696 alarm(alarm_time);
697
698 if (ret <= 0) {
699 iters = i;
700 break;
701 }
702 if ((log_msg.entry.len != (4 + 1 + 8)) ||
703 (log_msg.id() != LOG_ID_EVENTS)) {
704 continue;
705 }
706
707 char* eventData = log_msg.msg();
708
709 if (!eventData || (eventData[4] != EVENT_TYPE_LONG)) {
710 continue;
711 }
712 log_time tx(eventData + 4 + 1);
713 if (ts != tx) {
714 if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) {
715 iters = i;
716 break;
717 }
718 continue;
719 }
720
721 break;
722 }
723 }
724
725 signal(SIGALRM, SIG_DFL);
726 alarm(0);
727
728 StopBenchmarkTiming();
729
730 android_logger_list_free(logger_list);
731 }
732 BENCHMARK(BM_log_delay);
733
734 /*
735 * Measure the time it takes for __android_log_is_loggable.
736 */
BM_is_loggable(int iters)737 static void BM_is_loggable(int iters) {
738 static const char logd[] = "logd";
739
740 StartBenchmarkTiming();
741
742 for (int i = 0; i < iters; ++i) {
743 __android_log_is_loggable_len(ANDROID_LOG_WARN, logd, strlen(logd),
744 ANDROID_LOG_VERBOSE);
745 }
746
747 StopBenchmarkTiming();
748 }
749 BENCHMARK(BM_is_loggable);
750
751 /*
752 * Measure the time it takes for android_log_clockid.
753 */
BM_clockid(int iters)754 static void BM_clockid(int iters) {
755 StartBenchmarkTiming();
756
757 for (int i = 0; i < iters; ++i) {
758 android_log_clockid();
759 }
760
761 StopBenchmarkTiming();
762 }
763 BENCHMARK(BM_clockid);
764
765 /*
766 * Measure the time it takes for __android_log_security.
767 */
BM_security(int iters)768 static void BM_security(int iters) {
769 StartBenchmarkTiming();
770
771 for (int i = 0; i < iters; ++i) {
772 __android_log_security();
773 }
774
775 StopBenchmarkTiming();
776 }
777 BENCHMARK(BM_security);
778
779 // Keep maps around for multiple iterations
780 static std::unordered_set<uint32_t> set;
781 static EventTagMap* map;
782
prechargeEventMap()783 static bool prechargeEventMap() {
784 if (map) return true;
785
786 fprintf(stderr, "Precharge: start\n");
787
788 map = android_openEventTagMap(NULL);
789 for (uint32_t tag = 1; tag < USHRT_MAX; ++tag) {
790 size_t len;
791 if (android_lookupEventTag_len(map, &len, tag) == NULL) continue;
792 set.insert(tag);
793 }
794
795 fprintf(stderr, "Precharge: stop %zu\n", set.size());
796
797 return true;
798 }
799
800 /*
801 * Measure the time it takes for android_lookupEventTag_len
802 */
BM_lookupEventTag(int iters)803 static void BM_lookupEventTag(int iters) {
804 prechargeEventMap();
805
806 std::unordered_set<uint32_t>::const_iterator it = set.begin();
807
808 StartBenchmarkTiming();
809
810 for (int i = 0; i < iters; ++i) {
811 size_t len;
812 android_lookupEventTag_len(map, &len, (*it));
813 ++it;
814 if (it == set.end()) it = set.begin();
815 }
816
817 StopBenchmarkTiming();
818 }
819 BENCHMARK(BM_lookupEventTag);
820
821 /*
822 * Measure the time it takes for android_lookupEventTag_len
823 */
824 static uint32_t notTag = 1;
825
BM_lookupEventTag_NOT(int iters)826 static void BM_lookupEventTag_NOT(int iters) {
827 prechargeEventMap();
828
829 while (set.find(notTag) != set.end()) {
830 ++notTag;
831 if (notTag >= USHRT_MAX) notTag = 1;
832 }
833
834 StartBenchmarkTiming();
835
836 for (int i = 0; i < iters; ++i) {
837 size_t len;
838 android_lookupEventTag_len(map, &len, notTag);
839 }
840
841 StopBenchmarkTiming();
842
843 ++notTag;
844 if (notTag >= USHRT_MAX) notTag = 1;
845 }
846 BENCHMARK(BM_lookupEventTag_NOT);
847
848 /*
849 * Measure the time it takes for android_lookupEventFormat_len
850 */
BM_lookupEventFormat(int iters)851 static void BM_lookupEventFormat(int iters) {
852 prechargeEventMap();
853
854 std::unordered_set<uint32_t>::const_iterator it = set.begin();
855
856 StartBenchmarkTiming();
857
858 for (int i = 0; i < iters; ++i) {
859 size_t len;
860 android_lookupEventFormat_len(map, &len, (*it));
861 ++it;
862 if (it == set.end()) it = set.begin();
863 }
864
865 StopBenchmarkTiming();
866 }
867 BENCHMARK(BM_lookupEventFormat);
868
869 /*
870 * Measure the time it takes for android_lookupEventTagNum plus above
871 */
BM_lookupEventTagNum(int iters)872 static void BM_lookupEventTagNum(int iters) {
873 prechargeEventMap();
874
875 std::unordered_set<uint32_t>::const_iterator it = set.begin();
876
877 for (int i = 0; i < iters; ++i) {
878 size_t len;
879 const char* name = android_lookupEventTag_len(map, &len, (*it));
880 std::string Name(name, len);
881 const char* format = android_lookupEventFormat_len(map, &len, (*it));
882 std::string Format(format, len);
883 StartBenchmarkTiming();
884 android_lookupEventTagNum(map, Name.c_str(), Format.c_str(),
885 ANDROID_LOG_UNKNOWN);
886 StopBenchmarkTiming();
887 ++it;
888 if (it == set.end()) it = set.begin();
889 }
890 }
891 BENCHMARK(BM_lookupEventTagNum);
892
893 // Must be functionally identical to liblog internal __send_log_msg.
send_to_control(char * buf,size_t len)894 static void send_to_control(char* buf, size_t len) {
895 int sock = socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED,
896 SOCK_STREAM);
897 if (sock < 0) return;
898 size_t writeLen = strlen(buf) + 1;
899
900 ssize_t ret = TEMP_FAILURE_RETRY(write(sock, buf, writeLen));
901 if (ret <= 0) {
902 close(sock);
903 return;
904 }
905 while ((ret = read(sock, buf, len)) > 0) {
906 if (((size_t)ret == len) || (len < PAGE_SIZE)) {
907 break;
908 }
909 len -= ret;
910 buf += ret;
911
912 struct pollfd p = {.fd = sock, .events = POLLIN, .revents = 0 };
913
914 ret = poll(&p, 1, 20);
915 if ((ret <= 0) || !(p.revents & POLLIN)) {
916 break;
917 }
918 }
919 close(sock);
920 }
921
BM_lookupEventTagNum_logd_new(int iters)922 static void BM_lookupEventTagNum_logd_new(int iters) {
923 fprintf(stderr,
924 "WARNING: "
925 "This test can cause logd to grow in size and hit DOS limiter\n");
926 // Make copies
927 static const char empty_event_log_tags[] = "# content owned by logd\n";
928 static const char dev_event_log_tags_path[] = "/dev/event-log-tags";
929 std::string dev_event_log_tags;
930 if (android::base::ReadFileToString(dev_event_log_tags_path,
931 &dev_event_log_tags) &&
932 (dev_event_log_tags.length() == 0)) {
933 dev_event_log_tags = empty_event_log_tags;
934 }
935 static const char data_event_log_tags_path[] =
936 "/data/misc/logd/event-log-tags";
937 std::string data_event_log_tags;
938 if (android::base::ReadFileToString(data_event_log_tags_path,
939 &data_event_log_tags) &&
940 (data_event_log_tags.length() == 0)) {
941 data_event_log_tags = empty_event_log_tags;
942 }
943
944 for (int i = 0; i < iters; ++i) {
945 char buffer[256];
946 memset(buffer, 0, sizeof(buffer));
947 log_time now(CLOCK_MONOTONIC);
948 char name[64];
949 snprintf(name, sizeof(name), "a%" PRIu64, now.nsec());
950 snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"(new|1)\"",
951 name);
952 StartBenchmarkTiming();
953 send_to_control(buffer, sizeof(buffer));
954 StopBenchmarkTiming();
955 }
956
957 // Restore copies (logd still know about them, until crash or reboot)
958 if (dev_event_log_tags.length() &&
959 !android::base::WriteStringToFile(dev_event_log_tags,
960 dev_event_log_tags_path)) {
961 fprintf(stderr,
962 "WARNING: "
963 "failed to restore %s\n",
964 dev_event_log_tags_path);
965 }
966 if (data_event_log_tags.length() &&
967 !android::base::WriteStringToFile(data_event_log_tags,
968 data_event_log_tags_path)) {
969 fprintf(stderr,
970 "WARNING: "
971 "failed to restore %s\n",
972 data_event_log_tags_path);
973 }
974 fprintf(stderr,
975 "WARNING: "
976 "Restarting logd to make it forget what we just did\n");
977 system("stop logd ; start logd");
978 }
979 BENCHMARK(BM_lookupEventTagNum_logd_new);
980
BM_lookupEventTagNum_logd_existing(int iters)981 static void BM_lookupEventTagNum_logd_existing(int iters) {
982 prechargeEventMap();
983
984 std::unordered_set<uint32_t>::const_iterator it = set.begin();
985
986 for (int i = 0; i < iters; ++i) {
987 size_t len;
988 const char* name = android_lookupEventTag_len(map, &len, (*it));
989 std::string Name(name, len);
990 const char* format = android_lookupEventFormat_len(map, &len, (*it));
991 std::string Format(format, len);
992
993 char buffer[256];
994 snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"%s\"",
995 Name.c_str(), Format.c_str());
996
997 StartBenchmarkTiming();
998 send_to_control(buffer, sizeof(buffer));
999 StopBenchmarkTiming();
1000 ++it;
1001 if (it == set.end()) it = set.begin();
1002 }
1003 }
1004 BENCHMARK(BM_lookupEventTagNum_logd_existing);
1005