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