1 /*- 2 * BSD LICENSE 3 * 4 * Copyright (c) Intel Corporation. 5 * All rights reserved. 6 * 7 * Redistribution and use in source and binary forms, with or without 8 * modification, are permitted provided that the following conditions 9 * are met: 10 * 11 * * Redistributions of source code must retain the above copyright 12 * notice, this list of conditions and the following disclaimer. 13 * * Redistributions in binary form must reproduce the above copyright 14 * notice, this list of conditions and the following disclaimer in 15 * the documentation and/or other materials provided with the 16 * distribution. 17 * * Neither the name of Intel Corporation nor the names of its 18 * contributors may be used to endorse or promote products derived 19 * from this software without specific prior written permission. 20 * 21 * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS 22 * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT 23 * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR 24 * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT 25 * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, 26 * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT 27 * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, 28 * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY 29 * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT 30 * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE 31 * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. 32 */ 33 34 #include "spdk/stdinc.h" 35 36 #include <map> 37 38 extern "C" { 39 #include "spdk/trace.h" 40 } 41 42 static struct spdk_trace_histories *g_histories; 43 44 static void usage(void); 45 46 struct entry_key { 47 entry_key(uint16_t _lcore, uint64_t _tsc) : lcore(_lcore), tsc(_tsc) {} 48 uint16_t lcore; 49 uint64_t tsc; 50 }; 51 52 class compare_entry_key 53 { 54 public: 55 bool operator()(const entry_key &first, const entry_key &second) const 56 { 57 if (first.tsc == second.tsc) { 58 return first.lcore < second.lcore; 59 } else { 60 return first.tsc < second.tsc; 61 } 62 } 63 }; 64 65 typedef std::map<entry_key, spdk_trace_entry *, compare_entry_key> entry_map; 66 67 entry_map g_entry_map; 68 69 struct object_stats { 70 71 std::map<uint64_t, uint64_t> start; 72 std::map<uint64_t, uint64_t> index; 73 std::map<uint64_t, uint64_t> size; 74 std::map<uint64_t, uint64_t> tpoint_id; 75 uint64_t counter; 76 77 object_stats() : start(), index(), size(), tpoint_id(), counter(0) {} 78 }; 79 80 struct object_stats g_stats[SPDK_TRACE_MAX_OBJECT]; 81 82 static char *exe_name; 83 static int verbose = 1; 84 static int g_fudge_factor = 20; 85 86 static uint64_t tsc_rate; 87 static uint64_t first_tsc = 0x0; 88 static uint64_t last_tsc = -1ULL; 89 90 static float 91 get_us_from_tsc(uint64_t tsc, uint64_t tsc_rate) 92 { 93 return ((float)tsc) * 1000 * 1000 / tsc_rate; 94 } 95 96 static void 97 print_ptr(const char *arg_string, uint64_t arg) 98 { 99 printf("%-7.7s0x%-14jx ", arg_string, arg); 100 } 101 102 static void 103 print_uint64(const char *arg_string, uint64_t arg) 104 { 105 /* 106 * Print arg as signed, since -1 is a common value especially 107 * for FLUSH WRITEBUF when writev() returns -1 due to full 108 * socket buffer. 109 */ 110 printf("%-7.7s%-16jd ", arg_string, arg); 111 } 112 113 static void 114 print_size(uint32_t size) 115 { 116 if (size > 0) { 117 printf("size: %6u ", size); 118 } else { 119 printf("%13s", " "); 120 } 121 } 122 123 static void 124 print_object_id(uint8_t type, uint64_t id) 125 { 126 printf("id: %c%-15jd ", g_histories->flags.object[type].id_prefix, id); 127 } 128 129 static void 130 print_float(const char *arg_string, float arg) 131 { 132 printf("%-7s%-16.3f ", arg_string, arg); 133 } 134 135 static void 136 print_arg(bool arg_is_ptr, const char *arg_string, uint64_t arg) 137 { 138 if (arg_string[0] == 0) { 139 return; 140 } 141 142 if (arg_is_ptr) { 143 print_ptr(arg_string, arg); 144 } else { 145 print_uint64(arg_string, arg); 146 } 147 } 148 149 static void 150 print_event(struct spdk_trace_entry *e, uint64_t tsc_rate, 151 uint64_t tsc_offset, uint16_t lcore) 152 { 153 struct spdk_trace_tpoint *d; 154 struct object_stats *stats; 155 float us; 156 157 d = &g_histories->flags.tpoint[e->tpoint_id]; 158 stats = &g_stats[d->object_type]; 159 160 if (d->new_object) { 161 stats->index[e->object_id] = stats->counter++; 162 stats->tpoint_id[e->object_id] = e->tpoint_id; 163 stats->start[e->object_id] = e->tsc; 164 stats->size[e->object_id] = e->size; 165 } 166 167 if (d->arg1_is_alias) { 168 stats->index[e->arg1] = stats->index[e->object_id]; 169 stats->start[e->arg1] = stats->start[e->object_id]; 170 stats->size[e->arg1] = stats->size[e->object_id]; 171 } 172 173 us = get_us_from_tsc(e->tsc - tsc_offset, tsc_rate); 174 175 printf("%2d: %10.3f (%9ju) ", lcore, us, e->tsc - tsc_offset); 176 if (g_histories->flags.owner[d->owner_type].id_prefix) { 177 printf("%c%02d ", g_histories->flags.owner[d->owner_type].id_prefix, e->poller_id); 178 } else { 179 printf("%4s", " "); 180 } 181 182 printf("%-*s ", (int)sizeof(d->name), d->name); 183 print_size(e->size); 184 185 if (d->new_object) { 186 print_arg(d->arg1_is_ptr, d->arg1_name, e->arg1); 187 print_object_id(d->object_type, stats->index[e->object_id]); 188 } else if (d->object_type != OBJECT_NONE) { 189 if (stats->start.find(e->object_id) != stats->start.end()) { 190 struct spdk_trace_tpoint *start_description; 191 192 us = get_us_from_tsc(e->tsc - stats->start[e->object_id], 193 tsc_rate); 194 print_object_id(d->object_type, stats->index[e->object_id]); 195 print_float("time:", us); 196 start_description = &g_histories->flags.tpoint[stats->tpoint_id[e->object_id]]; 197 if (start_description->short_name[0] != 0) { 198 printf(" (%.4s)", start_description->short_name); 199 } 200 } else { 201 printf("id: N/A"); 202 } 203 } else { 204 print_arg(d->arg1_is_ptr, d->arg1_name, e->arg1); 205 } 206 printf("\n"); 207 } 208 209 static void 210 process_event(struct spdk_trace_entry *e, uint64_t tsc_rate, 211 uint64_t tsc_offset, uint16_t lcore) 212 { 213 if (verbose) { 214 print_event(e, tsc_rate, tsc_offset, lcore); 215 } 216 } 217 218 static int 219 populate_events(struct spdk_trace_history *history) 220 { 221 int i, entry_size, history_size, num_entries, num_entries_filled; 222 struct spdk_trace_entry *e; 223 int first, last, lcore; 224 225 lcore = history->lcore; 226 227 entry_size = sizeof(history->entries[0]); 228 history_size = sizeof(history->entries); 229 num_entries = history_size / entry_size; 230 231 e = history->entries; 232 233 num_entries_filled = num_entries; 234 while (e[num_entries_filled - 1].tsc == 0) { 235 num_entries_filled--; 236 } 237 238 if (num_entries == num_entries_filled) { 239 first = last = 0; 240 for (i = 1; i < num_entries; i++) { 241 if (e[i].tsc < e[first].tsc) { 242 first = i; 243 } 244 if (e[i].tsc > e[last].tsc) { 245 last = i; 246 } 247 } 248 249 first += g_fudge_factor; 250 if (first >= num_entries) { 251 first -= num_entries; 252 } 253 254 last -= g_fudge_factor; 255 if (last < 0) { 256 last += num_entries; 257 } 258 } else { 259 first = 0; 260 last = num_entries_filled - 1; 261 } 262 263 /* 264 * We keep track of the highest first TSC out of all reactors and 265 * the lowest last TSC out of all reactors. We will ignore any 266 * events outside the range of these two TSC values. This will 267 * ensure we only print data for the subset of time where we have 268 * data across all reactors. 269 */ 270 if (e[first].tsc > first_tsc) { 271 first_tsc = e[first].tsc; 272 } 273 if (e[last].tsc < last_tsc) { 274 last_tsc = e[last].tsc; 275 } 276 277 i = first; 278 while (1) { 279 g_entry_map[entry_key(lcore, e[i].tsc)] = &e[i]; 280 if (i == last) { 281 break; 282 } 283 i++; 284 if (i == num_entries_filled) { 285 i = 0; 286 } 287 } 288 289 return (0); 290 } 291 292 static void usage(void) 293 { 294 fprintf(stderr, "usage:\n"); 295 fprintf(stderr, " %s <option> <lcore#>\n", exe_name); 296 fprintf(stderr, " option = '-q' to disable verbose mode\n"); 297 fprintf(stderr, " '-s' to specify spdk_trace shm name\n"); 298 fprintf(stderr, " '-c' to display single lcore history\n"); 299 fprintf(stderr, " '-f' to specify number of events to ignore at\n"); 300 fprintf(stderr, " beginning and end of trace (default: 20)\n"); 301 fprintf(stderr, " '-i' to specify the shared memory ID\n"); 302 fprintf(stderr, " '-p' to specify the trace PID\n"); 303 fprintf(stderr, " (One of -i or -p must be specified)\n"); 304 } 305 306 int main(int argc, char **argv) 307 { 308 void *history_ptr; 309 struct spdk_trace_history *history_entries, *history; 310 int fd, i; 311 int lcore = SPDK_TRACE_MAX_LCORE; 312 uint64_t tsc_offset; 313 const char *app_name = "spdk"; 314 int op; 315 char shm_name[64]; 316 int shm_id = -1, shm_pid = -1; 317 318 exe_name = argv[0]; 319 while ((op = getopt(argc, argv, "c:f:i:p:qs:")) != -1) { 320 switch (op) { 321 case 'c': 322 lcore = atoi(optarg); 323 if (lcore > SPDK_TRACE_MAX_LCORE) { 324 fprintf(stderr, "Selected lcore: %d " 325 "exceeds maximum %d\n", lcore, 326 SPDK_TRACE_MAX_LCORE); 327 exit(1); 328 } 329 break; 330 case 'f': 331 g_fudge_factor = atoi(optarg); 332 break; 333 case 'i': 334 shm_id = atoi(optarg); 335 break; 336 case 'p': 337 shm_pid = atoi(optarg); 338 break; 339 case 'q': 340 verbose = 0; 341 break; 342 case 's': 343 app_name = optarg; 344 break; 345 default: 346 usage(); 347 exit(1); 348 } 349 } 350 351 if (shm_id >= 0) { 352 snprintf(shm_name, sizeof(shm_name), "/%s_trace.%d", app_name, shm_id); 353 } else { 354 snprintf(shm_name, sizeof(shm_name), "/%s_trace.pid%d", app_name, shm_pid); 355 } 356 357 fd = shm_open(shm_name, O_RDONLY, 0600); 358 if (fd < 0) { 359 fprintf(stderr, "Could not open shm %s.\n", shm_name); 360 usage(); 361 exit(-1); 362 } 363 364 history_ptr = mmap(NULL, sizeof(*g_histories), PROT_READ, MAP_SHARED, fd, 0); 365 if (history_ptr == MAP_FAILED) { 366 fprintf(stderr, "Could not mmap shm %s.\n", shm_name); 367 usage(); 368 exit(-1); 369 } 370 371 g_histories = (struct spdk_trace_histories *)history_ptr; 372 373 tsc_rate = g_histories->flags.tsc_rate; 374 if (tsc_rate == 0) { 375 fprintf(stderr, "Invalid tsc_rate %ju\n", tsc_rate); 376 usage(); 377 exit(-1); 378 } 379 380 if (verbose) { 381 printf("TSC Rate: %ju\n", tsc_rate); 382 } 383 384 history_entries = (struct spdk_trace_history *)malloc(sizeof(g_histories->per_lcore_history)); 385 if (history_entries == NULL) { 386 goto cleanup; 387 } 388 memcpy(history_entries, g_histories->per_lcore_history, 389 sizeof(g_histories->per_lcore_history)); 390 391 if (lcore == SPDK_TRACE_MAX_LCORE) { 392 for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) { 393 history = &history_entries[i]; 394 if (history->entries[0].tsc == 0) { 395 continue; 396 } 397 populate_events(history); 398 } 399 } else { 400 history = &history_entries[lcore]; 401 if (history->entries[0].tsc != 0) { 402 populate_events(history); 403 } 404 } 405 406 tsc_offset = first_tsc; 407 for (entry_map::iterator it = g_entry_map.begin(); it != g_entry_map.end(); it++) { 408 if (it->first.tsc < first_tsc || it->first.tsc > last_tsc) { 409 continue; 410 } 411 process_event(it->second, tsc_rate, tsc_offset, it->first.lcore); 412 } 413 414 free(history_entries); 415 416 cleanup: 417 munmap(history_ptr, sizeof(*g_histories)); 418 close(fd); 419 420 return (0); 421 } 422