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