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