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 | |
| 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 | */ |
| 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 | */ |
| 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 | */ |
| 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 | */ |
| 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 | |
Mark Salyzyn | a04464a | 2014-04-30 08:50:53 -0700 | [diff] [blame] | 102 | static void caught_latency(int /*signum*/) |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 103 | { |
| 104 | unsigned long long v = 0xDEADBEEFA55A5AA5ULL; |
| 105 | |
| 106 | LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); |
| 107 | } |
| 108 | |
| 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 | */ |
| 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(( |
Mark Salyzyn | 7e2f83c | 2014-03-05 07:41:49 -0800 | [diff] [blame] | 146 | ts = log_time(CLOCK_REALTIME), |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 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 | |
Mark Salyzyn | a04464a | 2014-04-30 08:50:53 -0700 | [diff] [blame] | 196 | static void caught_delay(int /*signum*/) |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 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 | */ |
| 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); |