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 struct spdk_trace_owner *owner; 137 const struct spdk_trace_tpoint *d; 138 float us; 139 size_t i; 140 141 d = &g_file->tpoint[e->tpoint_id]; 142 us = get_us_from_tsc(e->tsc - tsc_offset, tsc_rate); 143 144 printf("%-*s ", (int)sizeof(g_file->tname[entry->lcore]), g_file->tname[entry->lcore]); 145 printf("%2d: %10.3f ", entry->lcore, us); 146 if (g_print_tsc) { 147 printf("(%9ju) ", e->tsc - tsc_offset); 148 } 149 owner = spdk_get_trace_owner(g_file, e->owner_id); 150 /* For now, only try to print first 64 bytes of description. */ 151 if (e->owner_id > 0 && owner->tsc < e->tsc) { 152 printf("%-*s ", 64, owner->description); 153 } else { 154 printf("%-*s ", 64, ""); 155 } 156 157 printf("%-*s ", (int)sizeof(d->name), d->name); 158 print_size(e->size); 159 160 if (d->new_object) { 161 print_object_id(d, entry); 162 } else if (d->object_type != OBJECT_NONE) { 163 if (entry->object_index != UINT64_MAX) { 164 us = get_us_from_tsc(e->tsc - entry->object_start, tsc_rate); 165 print_object_id(d, entry); 166 print_float("time", us); 167 } else { 168 printf("id: %-17s", "N/A"); 169 } 170 } else if (e->object_id != 0) { 171 print_ptr("object", e->object_id); 172 } 173 174 for (i = 0; i < d->num_args; ++i) { 175 if (entry->args[i].is_related) { 176 /* This argument was already implicitly shown by its 177 * associated related object ID. 178 */ 179 continue; 180 } 181 switch (d->args[i].type) { 182 case SPDK_TRACE_ARG_TYPE_PTR: 183 print_ptr(d->args[i].name, (uint64_t)entry->args[i].u.pointer); 184 break; 185 case SPDK_TRACE_ARG_TYPE_INT: 186 print_uint64(d->args[i].name, entry->args[i].u.integer); 187 break; 188 case SPDK_TRACE_ARG_TYPE_STR: 189 print_string(d->args[i].name, entry->args[i].u.string); 190 break; 191 } 192 } 193 printf("\n"); 194 } 195 196 static void 197 print_event_json(struct spdk_trace_parser_entry *entry, uint64_t tsc_rate, uint64_t tsc_offset) 198 { 199 struct spdk_trace_entry *e = entry->entry; 200 const struct spdk_trace_tpoint *d; 201 size_t i; 202 203 d = &g_file->tpoint[e->tpoint_id]; 204 205 spdk_json_write_object_begin(g_json); 206 spdk_json_write_named_uint64(g_json, "lcore", entry->lcore); 207 spdk_json_write_named_uint64(g_json, "tpoint", e->tpoint_id); 208 spdk_json_write_named_uint64(g_json, "tsc", e->tsc); 209 210 if (g_file->owner_type[d->owner_type].id_prefix) { 211 spdk_json_write_named_string_fmt(g_json, "poller", "%c%02d", 212 g_file->owner_type[d->owner_type].id_prefix, 213 e->owner_id); 214 } 215 if (e->size != 0) { 216 spdk_json_write_named_uint32(g_json, "size", e->size); 217 } 218 if (d->new_object || d->object_type != OBJECT_NONE || e->object_id != 0) { 219 char object_type; 220 221 spdk_json_write_named_object_begin(g_json, "object"); 222 if (d->new_object) { 223 object_type = g_file->object[d->object_type].id_prefix; 224 spdk_json_write_named_string_fmt(g_json, "id", "%c%" PRIu64, object_type, 225 entry->object_index); 226 } else if (d->object_type != OBJECT_NONE) { 227 object_type = g_file->object[d->object_type].id_prefix; 228 if (entry->object_index != UINT64_MAX) { 229 spdk_json_write_named_string_fmt(g_json, "id", "%c%" PRIu64, 230 object_type, 231 entry->object_index); 232 spdk_json_write_named_uint64(g_json, "time", 233 e->tsc - entry->object_start); 234 } 235 } 236 spdk_json_write_named_uint64(g_json, "value", e->object_id); 237 spdk_json_write_object_end(g_json); 238 } 239 240 /* Print related objects array */ 241 if (entry->related_index != UINT64_MAX) { 242 spdk_json_write_named_string_fmt(g_json, "related", "%c%" PRIu64, 243 g_file->object[entry->related_type].id_prefix, 244 entry->related_index); 245 } 246 247 if (d->num_args > 0) { 248 spdk_json_write_named_array_begin(g_json, "args"); 249 for (i = 0; i < d->num_args; ++i) { 250 switch (d->args[i].type) { 251 case SPDK_TRACE_ARG_TYPE_PTR: 252 spdk_json_write_uint64(g_json, (uint64_t)entry->args[i].u.pointer); 253 break; 254 case SPDK_TRACE_ARG_TYPE_INT: 255 spdk_json_write_uint64(g_json, entry->args[i].u.integer); 256 break; 257 case SPDK_TRACE_ARG_TYPE_STR: 258 spdk_json_write_string(g_json, entry->args[i].u.string); 259 break; 260 } 261 } 262 spdk_json_write_array_end(g_json); 263 } 264 265 spdk_json_write_object_end(g_json); 266 } 267 268 static void 269 print_tpoint_definitions(void) 270 { 271 const struct spdk_trace_tpoint *tpoint; 272 size_t i, j; 273 274 /* We only care about these when printing JSON */ 275 if (!g_json) { 276 return; 277 } 278 279 spdk_json_write_named_uint64(g_json, "tsc_rate", g_file->tsc_rate); 280 spdk_json_write_named_array_begin(g_json, "tpoints"); 281 282 for (i = 0; i < SPDK_COUNTOF(g_file->tpoint); ++i) { 283 tpoint = &g_file->tpoint[i]; 284 if (tpoint->tpoint_id == 0) { 285 continue; 286 } 287 288 spdk_json_write_object_begin(g_json); 289 spdk_json_write_named_string(g_json, "name", tpoint->name); 290 spdk_json_write_named_uint32(g_json, "id", tpoint->tpoint_id); 291 spdk_json_write_named_bool(g_json, "new_object", tpoint->new_object); 292 293 spdk_json_write_named_array_begin(g_json, "args"); 294 for (j = 0; j < tpoint->num_args; ++j) { 295 spdk_json_write_object_begin(g_json); 296 spdk_json_write_named_string(g_json, "name", tpoint->args[j].name); 297 spdk_json_write_named_uint32(g_json, "type", tpoint->args[j].type); 298 spdk_json_write_named_uint32(g_json, "size", tpoint->args[j].size); 299 spdk_json_write_object_end(g_json); 300 } 301 spdk_json_write_array_end(g_json); 302 spdk_json_write_object_end(g_json); 303 } 304 305 spdk_json_write_array_end(g_json); 306 } 307 308 static int 309 print_json(void *cb_ctx, const void *data, size_t size) 310 { 311 ssize_t rc; 312 313 while (size > 0) { 314 rc = write(STDOUT_FILENO, data, size); 315 if (rc < 0) { 316 fprintf(stderr, "%s: %s\n", g_exe_name, spdk_strerror(errno)); 317 abort(); 318 } 319 320 size -= rc; 321 } 322 323 return 0; 324 } 325 326 static int 327 trace_print(int lcore) 328 { 329 struct spdk_trace_parser_entry entry; 330 int i; 331 uint64_t tsc_offset, entry_count; 332 uint64_t tsc_rate = g_file->tsc_rate; 333 334 printf("TSC Rate: %ju\n", tsc_rate); 335 for (i = 0; i < SPDK_TRACE_MAX_LCORE; ++i) { 336 if (lcore == SPDK_TRACE_MAX_LCORE || i == lcore) { 337 entry_count = spdk_trace_parser_get_entry_count(g_parser, i); 338 if (entry_count > 0) { 339 printf("Trace Size of lcore (%d): %ju\n", i, entry_count); 340 } 341 } 342 } 343 344 tsc_offset = spdk_trace_parser_get_tsc_offset(g_parser); 345 while (spdk_trace_parser_next_entry(g_parser, &entry)) { 346 if (entry.entry->tsc < tsc_offset) { 347 continue; 348 } 349 print_event(&entry, tsc_rate, tsc_offset); 350 } 351 352 return 0; 353 } 354 355 static int 356 trace_print_json(void) 357 { 358 struct spdk_trace_parser_entry entry; 359 uint64_t tsc_offset; 360 uint64_t tsc_rate = g_file->tsc_rate; 361 362 g_json = spdk_json_write_begin(print_json, NULL, 0); 363 if (g_json == NULL) { 364 fprintf(stderr, "Failed to allocate JSON write context\n"); 365 return -1; 366 } 367 368 spdk_json_write_object_begin(g_json); 369 print_tpoint_definitions(); 370 spdk_json_write_named_array_begin(g_json, "entries"); 371 372 tsc_offset = spdk_trace_parser_get_tsc_offset(g_parser); 373 while (spdk_trace_parser_next_entry(g_parser, &entry)) { 374 if (entry.entry->tsc < tsc_offset) { 375 continue; 376 } 377 print_event_json(&entry, tsc_rate, tsc_offset); 378 } 379 380 spdk_json_write_array_end(g_json); 381 spdk_json_write_object_end(g_json); 382 spdk_json_write_end(g_json); 383 384 return 0; 385 } 386 387 static void 388 usage(void) 389 { 390 fprintf(stderr, "usage:\n"); 391 fprintf(stderr, " %s <option> <lcore#>\n", g_exe_name); 392 fprintf(stderr, " '-c' to display single lcore history\n"); 393 fprintf(stderr, " '-t' to display TSC offset for each event\n"); 394 fprintf(stderr, " '-s' to specify spdk_trace shm name for a\n"); 395 fprintf(stderr, " currently running process\n"); 396 fprintf(stderr, " '-i' to specify the shared memory ID\n"); 397 fprintf(stderr, " '-p' to specify the trace PID\n"); 398 fprintf(stderr, " (If -s is specified, then one of\n"); 399 fprintf(stderr, " -i or -p must be specified)\n"); 400 fprintf(stderr, " '-f' to specify a tracepoint file name\n"); 401 fprintf(stderr, " (-s and -f are mutually exclusive)\n"); 402 #if defined(__linux__) 403 fprintf(stderr, " Without -s or -f, %s will look for\n", g_exe_name); 404 fprintf(stderr, " newest trace file in /dev/shm\n"); 405 #endif 406 fprintf(stderr, " '-j' to use JSON to format the output\n"); 407 } 408 409 #if defined(__linux__) 410 static time_t g_mtime = 0; 411 static char g_newest_file[PATH_MAX] = {}; 412 413 static int 414 get_newest(const char *path, const struct stat *sb, int tflag, struct FTW *ftw) 415 { 416 if (tflag == FTW_F && sb->st_mtime > g_mtime && 417 strstr(path, SPDK_TRACE_SHM_NAME_BASE) != NULL) { 418 g_mtime = sb->st_mtime; 419 strncpy(g_newest_file, path, PATH_MAX - 1); 420 } 421 return 0; 422 } 423 #endif 424 425 int 426 main(int argc, char **argv) 427 { 428 struct spdk_trace_parser_opts opts; 429 enum print_format_type print_format = PRINT_FMT_DEFAULT; 430 int lcore = SPDK_TRACE_MAX_LCORE; 431 const char *app_name = NULL; 432 const char *file_name = NULL; 433 int op; 434 int rc = 0; 435 char shm_name[64]; 436 int shm_id = -1, shm_pid = -1; 437 438 g_exe_name = argv[0]; 439 while ((op = getopt(argc, argv, "c:f:i:jp:s:t")) != -1) { 440 switch (op) { 441 case 'c': 442 lcore = atoi(optarg); 443 if (lcore > SPDK_TRACE_MAX_LCORE) { 444 fprintf(stderr, "Selected lcore: %d " 445 "exceeds maximum %d\n", lcore, 446 SPDK_TRACE_MAX_LCORE); 447 exit(1); 448 } 449 break; 450 case 'i': 451 shm_id = atoi(optarg); 452 break; 453 case 'p': 454 shm_pid = atoi(optarg); 455 break; 456 case 's': 457 app_name = optarg; 458 break; 459 case 'f': 460 file_name = optarg; 461 break; 462 case 't': 463 g_print_tsc = true; 464 break; 465 case 'j': 466 print_format = PRINT_FMT_JSON; 467 break; 468 default: 469 usage(); 470 exit(1); 471 } 472 } 473 474 if (file_name != NULL && app_name != NULL) { 475 fprintf(stderr, "-f and -s are mutually exclusive\n"); 476 usage(); 477 exit(1); 478 } 479 480 if (file_name == NULL && app_name == NULL) { 481 #if defined(__linux__) 482 nftw("/dev/shm", get_newest, 1, 0); 483 if (strlen(g_newest_file) > 0) { 484 file_name = g_newest_file; 485 printf("Using newest trace file found: %s\n", file_name); 486 } else { 487 fprintf(stderr, "No shm file found and -f not specified\n"); 488 usage(); 489 exit(1); 490 } 491 #else 492 fprintf(stderr, "One of -f and -s must be specified\n"); 493 usage(); 494 exit(1); 495 #endif 496 } 497 498 if (!file_name) { 499 if (shm_id >= 0) { 500 snprintf(shm_name, sizeof(shm_name), "/%s_trace.%d", app_name, shm_id); 501 } else { 502 snprintf(shm_name, sizeof(shm_name), "/%s_trace.pid%d", app_name, shm_pid); 503 } 504 file_name = shm_name; 505 } 506 507 opts.filename = file_name; 508 opts.lcore = lcore; 509 opts.mode = app_name == NULL ? SPDK_TRACE_PARSER_MODE_FILE : SPDK_TRACE_PARSER_MODE_SHM; 510 g_parser = spdk_trace_parser_init(&opts); 511 if (g_parser == NULL) { 512 fprintf(stderr, "Failed to initialize trace parser\n"); 513 exit(1); 514 } 515 516 g_file = spdk_trace_parser_get_file(g_parser); 517 switch (print_format) { 518 case PRINT_FMT_JSON: 519 rc = trace_print_json(); 520 break; 521 case PRINT_FMT_DEFAULT: 522 default: 523 rc = trace_print(lcore); 524 break; 525 } 526 527 spdk_trace_parser_cleanup(g_parser); 528 529 return rc; 530 } 531