1 /* SPDX-License-Identifier: BSD-3-Clause 2 * Copyright (C) 2016 Intel Corporation. 3 * All rights reserved. 4 */ 5 6 #include "spdk/stdinc.h" 7 #include "spdk/env.h" 8 #include "spdk/json.h" 9 #include "spdk/likely.h" 10 #include "spdk/string.h" 11 #include "spdk/util.h" 12 13 #include <map> 14 15 extern "C" { 16 #include "spdk/trace_parser.h" 17 #include "spdk/util.h" 18 } 19 20 enum print_format_type { 21 PRINT_FMT_JSON, 22 PRINT_FMT_DEFAULT, 23 }; 24 25 static struct spdk_trace_parser *g_parser; 26 static const struct spdk_trace_file *g_file; 27 static struct spdk_json_write_ctx *g_json; 28 static bool g_print_tsc = false; 29 30 /* This is a bit ugly, but we don't want to include env_dpdk in the app, while spdk_util, which we 31 * do need, uses some of the functions implemented there. We're not actually using the functions 32 * that depend on those, so just define them as no-ops to allow the app to link. 33 */ 34 extern "C" { 35 void * 36 spdk_realloc(void *buf, size_t size, size_t align) 37 { 38 assert(false); 39 40 return NULL; 41 } 42 43 void 44 spdk_free(void *buf) 45 { 46 assert(false); 47 } 48 49 uint64_t 50 spdk_get_ticks(void) 51 { 52 return 0; 53 } 54 } /* extern "C" */ 55 56 static void usage(void); 57 58 static char *g_exe_name; 59 60 static float 61 get_us_from_tsc(uint64_t tsc, uint64_t tsc_rate) 62 { 63 return ((float)tsc) * 1000 * 1000 / tsc_rate; 64 } 65 66 static const char * 67 format_argname(const char *name) 68 { 69 static char namebuf[16]; 70 71 snprintf(namebuf, sizeof(namebuf), "%s: ", name); 72 return namebuf; 73 } 74 75 static void 76 print_ptr(const char *arg_string, uint64_t arg) 77 { 78 printf("%-7.7s0x%-14jx ", format_argname(arg_string), arg); 79 } 80 81 static void 82 print_uint64(const char *arg_string, uint64_t arg) 83 { 84 /* 85 * Print arg as signed, since -1 is a common value especially 86 * for FLUSH WRITEBUF when writev() returns -1 due to full 87 * socket buffer. 88 */ 89 printf("%-7.7s%-16jd ", format_argname(arg_string), arg); 90 } 91 92 static void 93 print_string(const char *arg_string, const char *arg) 94 { 95 printf("%-7.7s%-16.16s ", format_argname(arg_string), arg); 96 } 97 98 static void 99 print_size(uint32_t size) 100 { 101 if (size > 0) { 102 printf("size: %6u ", size); 103 } else { 104 printf("%13s", " "); 105 } 106 } 107 108 static void 109 print_object_id(const struct spdk_trace_tpoint *d, struct spdk_trace_parser_entry *entry) 110 { 111 /* Set size to 128 and 256 bytes to make sure we can fit all the characters we need */ 112 char related_id[128] = {'\0'}; 113 char ids[256] = {'\0'}; 114 115 if (entry->related_type != OBJECT_NONE) { 116 snprintf(related_id, sizeof(related_id), " (%c%jd)", 117 g_file->object[entry->related_type].id_prefix, 118 entry->related_index); 119 } 120 121 snprintf(ids, sizeof(ids), "%c%jd%s", g_file->object[d->object_type].id_prefix, 122 entry->object_index, related_id); 123 printf("id: %-17s", ids); 124 } 125 126 static void 127 print_float(const char *arg_string, float arg) 128 { 129 printf("%-7s%-16.3f ", format_argname(arg_string), arg); 130 } 131 132 static void 133 print_event(struct spdk_trace_parser_entry *entry, uint64_t tsc_rate, uint64_t tsc_offset) 134 { 135 struct spdk_trace_entry *e = entry->entry; 136 const struct spdk_trace_tpoint *d; 137 float us; 138 size_t i; 139 140 d = &g_file->tpoint[e->tpoint_id]; 141 us = get_us_from_tsc(e->tsc - tsc_offset, tsc_rate); 142 143 printf("%-*s ", (int)sizeof(g_file->tname[entry->lcore]), g_file->tname[entry->lcore]); 144 printf("%2d: %10.3f ", entry->lcore, us); 145 if (g_print_tsc) { 146 printf("(%9ju) ", e->tsc - tsc_offset); 147 } 148 if (g_file->owner_type[d->owner_type].id_prefix) { 149 printf("%c%02d ", g_file->owner_type[d->owner_type].id_prefix, e->poller_id); 150 } else { 151 printf("%4s", " "); 152 } 153 154 printf("%-*s ", (int)sizeof(d->name), d->name); 155 print_size(e->size); 156 157 if (d->new_object) { 158 print_object_id(d, entry); 159 } else if (d->object_type != OBJECT_NONE) { 160 if (entry->object_index != UINT64_MAX) { 161 us = get_us_from_tsc(e->tsc - entry->object_start, tsc_rate); 162 print_object_id(d, entry); 163 print_float("time", us); 164 } else { 165 printf("id: %-17s", "N/A"); 166 } 167 } else if (e->object_id != 0) { 168 print_ptr("object", e->object_id); 169 } 170 171 for (i = 0; i < d->num_args; ++i) { 172 if (entry->args[i].is_related) { 173 /* This argument was already implicitly shown by its 174 * associated related object ID. 175 */ 176 continue; 177 } 178 switch (d->args[i].type) { 179 case SPDK_TRACE_ARG_TYPE_PTR: 180 print_ptr(d->args[i].name, (uint64_t)entry->args[i].u.pointer); 181 break; 182 case SPDK_TRACE_ARG_TYPE_INT: 183 print_uint64(d->args[i].name, entry->args[i].u.integer); 184 break; 185 case SPDK_TRACE_ARG_TYPE_STR: 186 print_string(d->args[i].name, entry->args[i].u.string); 187 break; 188 } 189 } 190 printf("\n"); 191 } 192 193 static void 194 print_event_json(struct spdk_trace_parser_entry *entry, uint64_t tsc_rate, uint64_t tsc_offset) 195 { 196 struct spdk_trace_entry *e = entry->entry; 197 const struct spdk_trace_tpoint *d; 198 size_t i; 199 200 d = &g_file->tpoint[e->tpoint_id]; 201 202 spdk_json_write_object_begin(g_json); 203 spdk_json_write_named_uint64(g_json, "lcore", entry->lcore); 204 spdk_json_write_named_uint64(g_json, "tpoint", e->tpoint_id); 205 spdk_json_write_named_uint64(g_json, "tsc", e->tsc); 206 207 if (g_file->owner_type[d->owner_type].id_prefix) { 208 spdk_json_write_named_string_fmt(g_json, "poller", "%c%02d", 209 g_file->owner_type[d->owner_type].id_prefix, 210 e->poller_id); 211 } 212 if (e->size != 0) { 213 spdk_json_write_named_uint32(g_json, "size", e->size); 214 } 215 if (d->new_object || d->object_type != OBJECT_NONE || e->object_id != 0) { 216 char object_type; 217 218 spdk_json_write_named_object_begin(g_json, "object"); 219 if (d->new_object) { 220 object_type = g_file->object[d->object_type].id_prefix; 221 spdk_json_write_named_string_fmt(g_json, "id", "%c%" PRIu64, object_type, 222 entry->object_index); 223 } else if (d->object_type != OBJECT_NONE) { 224 object_type = g_file->object[d->object_type].id_prefix; 225 if (entry->object_index != UINT64_MAX) { 226 spdk_json_write_named_string_fmt(g_json, "id", "%c%" PRIu64, 227 object_type, 228 entry->object_index); 229 spdk_json_write_named_uint64(g_json, "time", 230 e->tsc - entry->object_start); 231 } 232 } 233 spdk_json_write_named_uint64(g_json, "value", e->object_id); 234 spdk_json_write_object_end(g_json); 235 } 236 237 /* Print related objects array */ 238 if (entry->related_index != UINT64_MAX) { 239 spdk_json_write_named_string_fmt(g_json, "related", "%c%" PRIu64, 240 g_file->object[entry->related_type].id_prefix, 241 entry->related_index); 242 } 243 244 if (d->num_args > 0) { 245 spdk_json_write_named_array_begin(g_json, "args"); 246 for (i = 0; i < d->num_args; ++i) { 247 switch (d->args[i].type) { 248 case SPDK_TRACE_ARG_TYPE_PTR: 249 spdk_json_write_uint64(g_json, (uint64_t)entry->args[i].u.pointer); 250 break; 251 case SPDK_TRACE_ARG_TYPE_INT: 252 spdk_json_write_uint64(g_json, entry->args[i].u.integer); 253 break; 254 case SPDK_TRACE_ARG_TYPE_STR: 255 spdk_json_write_string(g_json, entry->args[i].u.string); 256 break; 257 } 258 } 259 spdk_json_write_array_end(g_json); 260 } 261 262 spdk_json_write_object_end(g_json); 263 } 264 265 static void 266 print_tpoint_definitions(void) 267 { 268 const struct spdk_trace_tpoint *tpoint; 269 size_t i, j; 270 271 /* We only care about these when printing JSON */ 272 if (!g_json) { 273 return; 274 } 275 276 spdk_json_write_named_uint64(g_json, "tsc_rate", g_file->tsc_rate); 277 spdk_json_write_named_array_begin(g_json, "tpoints"); 278 279 for (i = 0; i < SPDK_COUNTOF(g_file->tpoint); ++i) { 280 tpoint = &g_file->tpoint[i]; 281 if (tpoint->tpoint_id == 0) { 282 continue; 283 } 284 285 spdk_json_write_object_begin(g_json); 286 spdk_json_write_named_string(g_json, "name", tpoint->name); 287 spdk_json_write_named_uint32(g_json, "id", tpoint->tpoint_id); 288 spdk_json_write_named_bool(g_json, "new_object", tpoint->new_object); 289 290 spdk_json_write_named_array_begin(g_json, "args"); 291 for (j = 0; j < tpoint->num_args; ++j) { 292 spdk_json_write_object_begin(g_json); 293 spdk_json_write_named_string(g_json, "name", tpoint->args[j].name); 294 spdk_json_write_named_uint32(g_json, "type", tpoint->args[j].type); 295 spdk_json_write_named_uint32(g_json, "size", tpoint->args[j].size); 296 spdk_json_write_object_end(g_json); 297 } 298 spdk_json_write_array_end(g_json); 299 spdk_json_write_object_end(g_json); 300 } 301 302 spdk_json_write_array_end(g_json); 303 } 304 305 static int 306 print_json(void *cb_ctx, const void *data, size_t size) 307 { 308 ssize_t rc; 309 310 while (size > 0) { 311 rc = write(STDOUT_FILENO, data, size); 312 if (rc < 0) { 313 fprintf(stderr, "%s: %s\n", g_exe_name, spdk_strerror(errno)); 314 abort(); 315 } 316 317 size -= rc; 318 } 319 320 return 0; 321 } 322 323 static int 324 trace_print(int lcore) 325 { 326 struct spdk_trace_parser_entry entry; 327 int i; 328 uint64_t tsc_offset, entry_count; 329 uint64_t tsc_rate = g_file->tsc_rate; 330 331 printf("TSC Rate: %ju\n", tsc_rate); 332 for (i = 0; i < SPDK_TRACE_MAX_LCORE; ++i) { 333 if (lcore == SPDK_TRACE_MAX_LCORE || i == lcore) { 334 entry_count = spdk_trace_parser_get_entry_count(g_parser, i); 335 if (entry_count > 0) { 336 printf("Trace Size of lcore (%d): %ju\n", i, entry_count); 337 } 338 } 339 } 340 341 tsc_offset = spdk_trace_parser_get_tsc_offset(g_parser); 342 while (spdk_trace_parser_next_entry(g_parser, &entry)) { 343 if (entry.entry->tsc < tsc_offset) { 344 continue; 345 } 346 print_event(&entry, tsc_rate, tsc_offset); 347 } 348 349 return 0; 350 } 351 352 static int 353 trace_print_json(void) 354 { 355 struct spdk_trace_parser_entry entry; 356 uint64_t tsc_offset; 357 uint64_t tsc_rate = g_file->tsc_rate; 358 359 g_json = spdk_json_write_begin(print_json, NULL, 0); 360 if (g_json == NULL) { 361 fprintf(stderr, "Failed to allocate JSON write context\n"); 362 return -1; 363 } 364 365 spdk_json_write_object_begin(g_json); 366 print_tpoint_definitions(); 367 spdk_json_write_named_array_begin(g_json, "entries"); 368 369 tsc_offset = spdk_trace_parser_get_tsc_offset(g_parser); 370 while (spdk_trace_parser_next_entry(g_parser, &entry)) { 371 if (entry.entry->tsc < tsc_offset) { 372 continue; 373 } 374 print_event_json(&entry, tsc_rate, tsc_offset); 375 } 376 377 spdk_json_write_array_end(g_json); 378 spdk_json_write_object_end(g_json); 379 spdk_json_write_end(g_json); 380 381 return 0; 382 } 383 384 static void 385 usage(void) 386 { 387 fprintf(stderr, "usage:\n"); 388 fprintf(stderr, " %s <option> <lcore#>\n", g_exe_name); 389 fprintf(stderr, " '-c' to display single lcore history\n"); 390 fprintf(stderr, " '-t' to display TSC offset for each event\n"); 391 fprintf(stderr, " '-s' to specify spdk_trace shm name for a\n"); 392 fprintf(stderr, " currently running process\n"); 393 fprintf(stderr, " '-i' to specify the shared memory ID\n"); 394 fprintf(stderr, " '-p' to specify the trace PID\n"); 395 fprintf(stderr, " (If -s is specified, then one of\n"); 396 fprintf(stderr, " -i or -p must be specified)\n"); 397 fprintf(stderr, " '-f' to specify a tracepoint file name\n"); 398 fprintf(stderr, " (-s and -f are mutually exclusive)\n"); 399 #if defined(__linux__) 400 fprintf(stderr, " Without -s or -f, %s will look for\n", g_exe_name); 401 fprintf(stderr, " newest trace file in /dev/shm\n"); 402 #endif 403 fprintf(stderr, " '-j' to use JSON to format the output\n"); 404 } 405 406 #if defined(__linux__) 407 static time_t g_mtime = 0; 408 static char g_newest_file[PATH_MAX] = {}; 409 410 static int 411 get_newest(const char *path, const struct stat *sb, int tflag, struct FTW *ftw) 412 { 413 if (tflag == FTW_F && sb->st_mtime > g_mtime && 414 strstr(path, SPDK_TRACE_SHM_NAME_BASE) != NULL) { 415 g_mtime = sb->st_mtime; 416 strncpy(g_newest_file, path, PATH_MAX - 1); 417 } 418 return 0; 419 } 420 #endif 421 422 int 423 main(int argc, char **argv) 424 { 425 struct spdk_trace_parser_opts opts; 426 enum print_format_type print_format = PRINT_FMT_DEFAULT; 427 int lcore = SPDK_TRACE_MAX_LCORE; 428 const char *app_name = NULL; 429 const char *file_name = NULL; 430 int op; 431 int rc = 0; 432 char shm_name[64]; 433 int shm_id = -1, shm_pid = -1; 434 435 g_exe_name = argv[0]; 436 while ((op = getopt(argc, argv, "c:f:i:jp:s:t")) != -1) { 437 switch (op) { 438 case 'c': 439 lcore = atoi(optarg); 440 if (lcore > SPDK_TRACE_MAX_LCORE) { 441 fprintf(stderr, "Selected lcore: %d " 442 "exceeds maximum %d\n", lcore, 443 SPDK_TRACE_MAX_LCORE); 444 exit(1); 445 } 446 break; 447 case 'i': 448 shm_id = atoi(optarg); 449 break; 450 case 'p': 451 shm_pid = atoi(optarg); 452 break; 453 case 's': 454 app_name = optarg; 455 break; 456 case 'f': 457 file_name = optarg; 458 break; 459 case 't': 460 g_print_tsc = true; 461 break; 462 case 'j': 463 print_format = PRINT_FMT_JSON; 464 break; 465 default: 466 usage(); 467 exit(1); 468 } 469 } 470 471 if (file_name != NULL && app_name != NULL) { 472 fprintf(stderr, "-f and -s are mutually exclusive\n"); 473 usage(); 474 exit(1); 475 } 476 477 if (file_name == NULL && app_name == NULL) { 478 #if defined(__linux__) 479 nftw("/dev/shm", get_newest, 1, 0); 480 if (strlen(g_newest_file) > 0) { 481 file_name = g_newest_file; 482 printf("Using newest trace file found: %s\n", file_name); 483 } else { 484 fprintf(stderr, "No shm file found and -f not specified\n"); 485 usage(); 486 exit(1); 487 } 488 #else 489 fprintf(stderr, "One of -f and -s must be specified\n"); 490 usage(); 491 exit(1); 492 #endif 493 } 494 495 if (!file_name) { 496 if (shm_id >= 0) { 497 snprintf(shm_name, sizeof(shm_name), "/%s_trace.%d", app_name, shm_id); 498 } else { 499 snprintf(shm_name, sizeof(shm_name), "/%s_trace.pid%d", app_name, shm_pid); 500 } 501 file_name = shm_name; 502 } 503 504 opts.filename = file_name; 505 opts.lcore = lcore; 506 opts.mode = app_name == NULL ? SPDK_TRACE_PARSER_MODE_FILE : SPDK_TRACE_PARSER_MODE_SHM; 507 g_parser = spdk_trace_parser_init(&opts); 508 if (g_parser == NULL) { 509 fprintf(stderr, "Failed to initialize trace parser\n"); 510 exit(1); 511 } 512 513 g_file = spdk_trace_parser_get_file(g_parser); 514 switch (print_format) { 515 case PRINT_FMT_JSON: 516 rc = trace_print_json(); 517 break; 518 case PRINT_FMT_DEFAULT: 519 default: 520 rc = trace_print(lcore); 521 break; 522 } 523 524 spdk_trace_parser_cleanup(g_parser); 525 526 return rc; 527 } 528