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 #include "spdk/util.h" 41 } 42 43 static struct spdk_trace_histories *g_histories; 44 45 static void usage(void); 46 47 struct entry_key { 48 entry_key(uint16_t _lcore, uint64_t _tsc) : lcore(_lcore), tsc(_tsc) {} 49 uint16_t lcore; 50 uint64_t tsc; 51 }; 52 53 class compare_entry_key 54 { 55 public: 56 bool operator()(const entry_key &first, const entry_key &second) const 57 { 58 if (first.tsc == second.tsc) { 59 return first.lcore < second.lcore; 60 } else { 61 return first.tsc < second.tsc; 62 } 63 } 64 }; 65 66 typedef std::map<entry_key, spdk_trace_entry *, compare_entry_key> entry_map; 67 68 entry_map g_entry_map; 69 70 struct object_stats { 71 72 std::map<uint64_t, uint64_t> start; 73 std::map<uint64_t, uint64_t> index; 74 std::map<uint64_t, uint64_t> size; 75 std::map<uint64_t, uint64_t> tpoint_id; 76 uint64_t counter; 77 78 object_stats() : start(), index(), size(), tpoint_id(), counter(0) {} 79 }; 80 81 struct object_stats g_stats[SPDK_TRACE_MAX_OBJECT]; 82 83 static char *g_exe_name; 84 static int g_verbose = 1; 85 86 static uint64_t g_tsc_rate; 87 static uint64_t g_first_tsc = 0x0; 88 89 static float 90 get_us_from_tsc(uint64_t tsc, uint64_t tsc_rate) 91 { 92 return ((float)tsc) * 1000 * 1000 / tsc_rate; 93 } 94 95 static void 96 print_ptr(const char *arg_string, uint64_t arg) 97 { 98 printf("%-7.7s0x%-14jx ", arg_string, arg); 99 } 100 101 static void 102 print_uint64(const char *arg_string, uint64_t arg) 103 { 104 /* 105 * Print arg as signed, since -1 is a common value especially 106 * for FLUSH WRITEBUF when writev() returns -1 due to full 107 * socket buffer. 108 */ 109 printf("%-7.7s%-16jd ", arg_string, arg); 110 } 111 112 static void 113 print_string(const char *arg_string, uint64_t arg) 114 { 115 char *str = (char *)&arg; 116 printf("%-7.7s%.8s ", arg_string, str); 117 } 118 119 static void 120 print_size(uint32_t size) 121 { 122 if (size > 0) { 123 printf("size: %6u ", size); 124 } else { 125 printf("%13s", " "); 126 } 127 } 128 129 static void 130 print_object_id(uint8_t type, uint64_t id) 131 { 132 printf("id: %c%-15jd ", g_histories->flags.object[type].id_prefix, id); 133 } 134 135 static void 136 print_float(const char *arg_string, float arg) 137 { 138 printf("%-7s%-16.3f ", arg_string, arg); 139 } 140 141 static void 142 print_arg(uint8_t arg_type, const char *arg_string, uint64_t arg) 143 { 144 if (arg_string[0] == 0) { 145 printf("%24s", ""); 146 return; 147 } 148 149 switch (arg_type) { 150 case SPDK_TRACE_ARG_TYPE_PTR: 151 print_ptr(arg_string, arg); 152 break; 153 case SPDK_TRACE_ARG_TYPE_INT: 154 print_uint64(arg_string, arg); 155 break; 156 case SPDK_TRACE_ARG_TYPE_STR: 157 print_string(arg_string, arg); 158 break; 159 } 160 } 161 162 static void 163 print_event(struct spdk_trace_entry *e, uint64_t tsc_rate, 164 uint64_t tsc_offset, uint16_t lcore) 165 { 166 struct spdk_trace_tpoint *d; 167 struct object_stats *stats; 168 float us; 169 170 d = &g_histories->flags.tpoint[e->tpoint_id]; 171 stats = &g_stats[d->object_type]; 172 173 if (d->new_object) { 174 stats->index[e->object_id] = stats->counter++; 175 stats->tpoint_id[e->object_id] = e->tpoint_id; 176 stats->start[e->object_id] = e->tsc; 177 stats->size[e->object_id] = e->size; 178 } 179 180 us = get_us_from_tsc(e->tsc - tsc_offset, tsc_rate); 181 182 printf("%2d: %10.3f (%9ju) ", lcore, us, e->tsc - tsc_offset); 183 if (g_histories->flags.owner[d->owner_type].id_prefix) { 184 printf("%c%02d ", g_histories->flags.owner[d->owner_type].id_prefix, e->poller_id); 185 } else { 186 printf("%4s", " "); 187 } 188 189 printf("%-*s ", (int)sizeof(d->name), d->name); 190 print_size(e->size); 191 192 print_arg(d->arg1_type, d->arg1_name, e->arg1); 193 if (d->new_object) { 194 print_object_id(d->object_type, stats->index[e->object_id]); 195 } else if (d->object_type != OBJECT_NONE) { 196 if (stats->start.find(e->object_id) != stats->start.end()) { 197 struct spdk_trace_tpoint *start_description; 198 199 us = get_us_from_tsc(e->tsc - stats->start[e->object_id], 200 tsc_rate); 201 print_object_id(d->object_type, stats->index[e->object_id]); 202 print_float("time:", us); 203 start_description = &g_histories->flags.tpoint[stats->tpoint_id[e->object_id]]; 204 if (start_description->short_name[0] != 0) { 205 printf(" (%.4s)", start_description->short_name); 206 } 207 } else { 208 printf("id: N/A"); 209 } 210 } else if (e->object_id != 0) { 211 print_arg(SPDK_TRACE_ARG_TYPE_PTR, "object: ", e->object_id); 212 } 213 printf("\n"); 214 } 215 216 static void 217 process_event(struct spdk_trace_entry *e, uint64_t tsc_rate, 218 uint64_t tsc_offset, uint16_t lcore) 219 { 220 if (g_verbose) { 221 print_event(e, tsc_rate, tsc_offset, lcore); 222 } 223 } 224 225 static int 226 populate_events(struct spdk_trace_history *history, int num_entries) 227 { 228 int i, num_entries_filled; 229 struct spdk_trace_entry *e; 230 int first, last, lcore; 231 232 lcore = history->lcore; 233 234 e = history->entries; 235 236 num_entries_filled = num_entries; 237 while (e[num_entries_filled - 1].tsc == 0) { 238 num_entries_filled--; 239 } 240 241 if (num_entries == num_entries_filled) { 242 first = last = 0; 243 for (i = 1; i < num_entries; i++) { 244 if (e[i].tsc < e[first].tsc) { 245 first = i; 246 } 247 if (e[i].tsc > e[last].tsc) { 248 last = i; 249 } 250 } 251 } else { 252 first = 0; 253 last = num_entries_filled - 1; 254 } 255 256 /* 257 * We keep track of the highest first TSC out of all reactors. 258 * We will ignore any events that occured before this TSC on any 259 * other reactors. This will ensure we only print data for the 260 * subset of time where we have data across all reactors. 261 */ 262 if (e[first].tsc > g_first_tsc) { 263 g_first_tsc = e[first].tsc; 264 } 265 266 i = first; 267 while (1) { 268 g_entry_map[entry_key(lcore, e[i].tsc)] = &e[i]; 269 if (i == last) { 270 break; 271 } 272 i++; 273 if (i == num_entries_filled) { 274 i = 0; 275 } 276 } 277 278 return (0); 279 } 280 281 static void usage(void) 282 { 283 fprintf(stderr, "usage:\n"); 284 fprintf(stderr, " %s <option> <lcore#>\n", g_exe_name); 285 fprintf(stderr, " option = '-q' to disable verbose mode\n"); 286 fprintf(stderr, " '-c' to display single lcore history\n"); 287 fprintf(stderr, " '-s' to specify spdk_trace shm name for a\n"); 288 fprintf(stderr, " currently running process\n"); 289 fprintf(stderr, " '-i' to specify the shared memory ID\n"); 290 fprintf(stderr, " '-p' to specify the trace PID\n"); 291 fprintf(stderr, " (If -s is specified, then one of\n"); 292 fprintf(stderr, " -i or -p must be specified)\n"); 293 fprintf(stderr, " '-f' to specify a tracepoint file name\n"); 294 fprintf(stderr, " (-s and -f are mutually exclusive)\n"); 295 } 296 297 int main(int argc, char **argv) 298 { 299 void *history_ptr; 300 struct spdk_trace_history *history; 301 int fd, i, rc; 302 int lcore = SPDK_TRACE_MAX_LCORE; 303 uint64_t tsc_offset; 304 const char *app_name = NULL; 305 const char *file_name = NULL; 306 int op; 307 char shm_name[64]; 308 int shm_id = -1, shm_pid = -1; 309 uint64_t trace_histories_size; 310 struct stat _stat; 311 312 g_exe_name = argv[0]; 313 while ((op = getopt(argc, argv, "c:f:i:p:qs:")) != -1) { 314 switch (op) { 315 case 'c': 316 lcore = atoi(optarg); 317 if (lcore > SPDK_TRACE_MAX_LCORE) { 318 fprintf(stderr, "Selected lcore: %d " 319 "exceeds maximum %d\n", lcore, 320 SPDK_TRACE_MAX_LCORE); 321 exit(1); 322 } 323 break; 324 case 'i': 325 shm_id = atoi(optarg); 326 break; 327 case 'p': 328 shm_pid = atoi(optarg); 329 break; 330 case 'q': 331 g_verbose = 0; 332 break; 333 case 's': 334 app_name = optarg; 335 break; 336 case 'f': 337 file_name = optarg; 338 break; 339 default: 340 usage(); 341 exit(1); 342 } 343 } 344 345 if (file_name != NULL && app_name != NULL) { 346 fprintf(stderr, "-f and -s are mutually exclusive\n"); 347 usage(); 348 exit(1); 349 } 350 351 if (file_name == NULL && app_name == NULL) { 352 fprintf(stderr, "One of -f and -s must be specified\n"); 353 usage(); 354 exit(1); 355 } 356 357 if (file_name) { 358 fd = open(file_name, O_RDONLY); 359 } else { 360 if (shm_id >= 0) { 361 snprintf(shm_name, sizeof(shm_name), "/%s_trace.%d", app_name, shm_id); 362 } else { 363 snprintf(shm_name, sizeof(shm_name), "/%s_trace.pid%d", app_name, shm_pid); 364 } 365 fd = shm_open(shm_name, O_RDONLY, 0600); 366 file_name = shm_name; 367 } 368 if (fd < 0) { 369 fprintf(stderr, "Could not open %s.\n", file_name); 370 usage(); 371 exit(-1); 372 } 373 374 rc = fstat(fd, &_stat); 375 if (rc < 0) { 376 fprintf(stderr, "Could not get size of %s.\n", file_name); 377 usage(); 378 exit(-1); 379 } 380 if ((size_t)_stat.st_size < sizeof(*g_histories)) { 381 fprintf(stderr, "%s is not a valid trace file\n", file_name); 382 usage(); 383 exit(-1); 384 } 385 386 /* Map the header of trace file */ 387 history_ptr = mmap(NULL, sizeof(*g_histories), PROT_READ, MAP_SHARED, fd, 0); 388 if (history_ptr == MAP_FAILED) { 389 fprintf(stderr, "Could not mmap %s.\n", file_name); 390 usage(); 391 exit(-1); 392 } 393 394 g_histories = (struct spdk_trace_histories *)history_ptr; 395 396 g_tsc_rate = g_histories->flags.tsc_rate; 397 if (g_tsc_rate == 0) { 398 fprintf(stderr, "Invalid tsc_rate %ju\n", g_tsc_rate); 399 usage(); 400 exit(-1); 401 } 402 403 if (g_verbose) { 404 printf("TSC Rate: %ju\n", g_tsc_rate); 405 } 406 407 /* Remap the entire trace file */ 408 trace_histories_size = spdk_get_trace_histories_size(g_histories); 409 munmap(history_ptr, sizeof(*g_histories)); 410 if ((size_t)_stat.st_size < trace_histories_size) { 411 fprintf(stderr, "%s is not a valid trace file\n", file_name); 412 usage(); 413 exit(-1); 414 } 415 history_ptr = mmap(NULL, trace_histories_size, PROT_READ, MAP_SHARED, fd, 0); 416 if (history_ptr == MAP_FAILED) { 417 fprintf(stderr, "Could not mmap %s.\n", file_name); 418 usage(); 419 exit(-1); 420 } 421 422 g_histories = (struct spdk_trace_histories *)history_ptr; 423 424 if (lcore == SPDK_TRACE_MAX_LCORE) { 425 for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) { 426 history = spdk_get_per_lcore_history(g_histories, i); 427 if (history->num_entries == 0 || history->entries[0].tsc == 0) { 428 continue; 429 } 430 431 if (g_verbose && history->num_entries) { 432 printf("Trace Size of lcore (%d): %ju\n", i, history->num_entries); 433 } 434 435 populate_events(history, history->num_entries); 436 } 437 } else { 438 history = spdk_get_per_lcore_history(g_histories, lcore); 439 if (history->num_entries > 0 && history->entries[0].tsc != 0) { 440 if (g_verbose && history->num_entries) { 441 printf("Trace Size of lcore (%d): %ju\n", lcore, history->num_entries); 442 } 443 444 populate_events(history, history->num_entries); 445 } 446 } 447 448 tsc_offset = g_first_tsc; 449 for (entry_map::iterator it = g_entry_map.begin(); it != g_entry_map.end(); it++) { 450 if (it->first.tsc < g_first_tsc) { 451 continue; 452 } 453 process_event(it->second, g_tsc_rate, tsc_offset, it->first.lcore); 454 } 455 456 munmap(history_ptr, trace_histories_size); 457 close(fd); 458 459 return (0); 460 } 461