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 <sys/socket.h>
18 #include <cutils/sockets.h>
19 #include <log/log.h>
20 #include <log/logger.h>
21 #include <log/log_read.h>
22
23 #include "benchmark.h"
24
25 // enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and
26 // non-syscall libs. Since we are benchmarking, or using this in the emergency
27 // signal to stuff a terminating code, we do NOT want to introduce
28 // a syscall or usleep on EAGAIN retry.
29 #define LOG_FAILURE_RETRY(exp) ({ \
30 typeof (exp) _rc; \
31 do { \
32 _rc = (exp); \
33 } while (((_rc == -1) \
34 && ((errno == EINTR) \
35 || (errno == EAGAIN))) \
36 || (_rc == -EINTR) \
37 || (_rc == -EAGAIN)); \
38 _rc; })
39
40 /*
41 * Measure the fastest rate we can reliabley stuff print messages into
42 * the log at high pressure. Expect this to be less than double the process
43 * wakeup time (2ms?)
44 */
BM_log_maximum_retry(int iters)45 static void BM_log_maximum_retry(int iters) {
46 StartBenchmarkTiming();
47
48 for (int i = 0; i < iters; ++i) {
49 LOG_FAILURE_RETRY(
50 __android_log_print(ANDROID_LOG_INFO,
51 "BM_log_maximum_retry", "%d", i));
52 }
53
54 StopBenchmarkTiming();
55 }
56 BENCHMARK(BM_log_maximum_retry);
57
58 /*
59 * Measure the fastest rate we can stuff print messages into the log
60 * at high pressure. Expect this to be less than double the process wakeup
61 * time (2ms?)
62 */
BM_log_maximum(int iters)63 static void BM_log_maximum(int iters) {
64 StartBenchmarkTiming();
65
66 for (int i = 0; i < iters; ++i) {
67 __android_log_print(ANDROID_LOG_INFO, "BM_log_maximum", "%d", i);
68 }
69
70 StopBenchmarkTiming();
71 }
72 BENCHMARK(BM_log_maximum);
73
74 /*
75 * Measure the time it takes to submit the android logging call using
76 * discrete acquisition under light load. Expect this to be a pair of
77 * syscall periods (2us).
78 */
BM_clock_overhead(int iters)79 static void BM_clock_overhead(int iters) {
80 for (int i = 0; i < iters; ++i) {
81 StartBenchmarkTiming();
82 StopBenchmarkTiming();
83 }
84 }
85 BENCHMARK(BM_clock_overhead);
86
87 /*
88 * Measure the time it takes to submit the android logging call using
89 * discrete acquisition under light load. Expect this to be a dozen or so
90 * syscall periods (40us).
91 */
BM_log_overhead(int iters)92 static void BM_log_overhead(int iters) {
93 for (int i = 0; i < iters; ++i) {
94 StartBenchmarkTiming();
95 __android_log_print(ANDROID_LOG_INFO, "BM_log_overhead", "%d", i);
96 StopBenchmarkTiming();
97 usleep(1000);
98 }
99 }
100 BENCHMARK(BM_log_overhead);
101
caught_latency(int)102 static void caught_latency(int /*signum*/)
103 {
104 unsigned long long v = 0xDEADBEEFA55A5AA5ULL;
105
106 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
107 }
108
caught_convert(char * cp)109 static unsigned long long caught_convert(char *cp)
110 {
111 unsigned long long l = cp[0] & 0xFF;
112 l |= (unsigned long long) (cp[1] & 0xFF) << 8;
113 l |= (unsigned long long) (cp[2] & 0xFF) << 16;
114 l |= (unsigned long long) (cp[3] & 0xFF) << 24;
115 l |= (unsigned long long) (cp[4] & 0xFF) << 32;
116 l |= (unsigned long long) (cp[5] & 0xFF) << 40;
117 l |= (unsigned long long) (cp[6] & 0xFF) << 48;
118 l |= (unsigned long long) (cp[7] & 0xFF) << 56;
119 return l;
120 }
121
122 static const int alarm_time = 3;
123
124 /*
125 * Measure the time it takes for the logd posting call to acquire the
126 * timestamp to place into the internal record. Expect this to be less than
127 * 4 syscalls (3us).
128 */
BM_log_latency(int iters)129 static void BM_log_latency(int iters) {
130 pid_t pid = getpid();
131
132 struct logger_list * logger_list = android_logger_list_open(LOG_ID_EVENTS,
133 O_RDONLY, 0, pid);
134
135 if (!logger_list) {
136 fprintf(stderr, "Unable to open events log: %s\n", strerror(errno));
137 exit(EXIT_FAILURE);
138 }
139
140 signal(SIGALRM, caught_latency);
141 alarm(alarm_time);
142
143 for (int j = 0, i = 0; i < iters && j < 10*iters; ++i, ++j) {
144 log_time ts;
145 LOG_FAILURE_RETRY((
146 ts = log_time(CLOCK_REALTIME),
147 android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))));
148
149 for (;;) {
150 log_msg log_msg;
151 int ret = android_logger_list_read(logger_list, &log_msg);
152 alarm(alarm_time);
153
154 if (ret <= 0) {
155 iters = i;
156 break;
157 }
158 if ((log_msg.entry.len != (4 + 1 + 8))
159 || (log_msg.id() != LOG_ID_EVENTS)) {
160 continue;
161 }
162
163 char* eventData = log_msg.msg();
164
165 if (eventData[4] != EVENT_TYPE_LONG) {
166 continue;
167 }
168 log_time tx(eventData + 4 + 1);
169 if (ts != tx) {
170 if (0xDEADBEEFA55A5AA5ULL == caught_convert(eventData + 4 + 1)) {
171 iters = i;
172 break;
173 }
174 continue;
175 }
176
177 uint64_t start = ts.nsec();
178 uint64_t end = log_msg.nsec();
179 if (end >= start) {
180 StartBenchmarkTiming(start);
181 StopBenchmarkTiming(end);
182 } else {
183 --i;
184 }
185 break;
186 }
187 }
188
189 signal(SIGALRM, SIG_DFL);
190 alarm(0);
191
192 android_logger_list_free(logger_list);
193 }
194 BENCHMARK(BM_log_latency);
195
caught_delay(int)196 static void caught_delay(int /*signum*/)
197 {
198 unsigned long long v = 0xDEADBEEFA55A5AA6ULL;
199
200 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
201 }
202
203 /*
204 * Measure the time it takes for the logd posting call to make it into
205 * the logs. Expect this to be less than double the process wakeup time (2ms).
206 */
BM_log_delay(int iters)207 static void BM_log_delay(int iters) {
208 pid_t pid = getpid();
209
210 struct logger_list * logger_list = android_logger_list_open(LOG_ID_EVENTS,
211 O_RDONLY, 0, pid);
212
213 if (!logger_list) {
214 fprintf(stderr, "Unable to open events log: %s\n", strerror(errno));
215 exit(EXIT_FAILURE);
216 }
217
218 signal(SIGALRM, caught_delay);
219 alarm(alarm_time);
220
221 StartBenchmarkTiming();
222
223 for (int i = 0; i < iters; ++i) {
224 log_time ts(CLOCK_REALTIME);
225
226 LOG_FAILURE_RETRY(
227 android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
228
229 for (;;) {
230 log_msg log_msg;
231 int ret = android_logger_list_read(logger_list, &log_msg);
232 alarm(alarm_time);
233
234 if (ret <= 0) {
235 iters = i;
236 break;
237 }
238 if ((log_msg.entry.len != (4 + 1 + 8))
239 || (log_msg.id() != LOG_ID_EVENTS)) {
240 continue;
241 }
242
243 char* eventData = log_msg.msg();
244
245 if (eventData[4] != EVENT_TYPE_LONG) {
246 continue;
247 }
248 log_time tx(eventData + 4 + 1);
249 if (ts != tx) {
250 if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) {
251 iters = i;
252 break;
253 }
254 continue;
255 }
256
257 break;
258 }
259 }
260
261 signal(SIGALRM, SIG_DFL);
262 alarm(0);
263
264 StopBenchmarkTiming();
265
266 android_logger_list_free(logger_list);
267 }
268 BENCHMARK(BM_log_delay);
269