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_flags *g_flags; 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_flags->object[entry->related_type].id_prefix, 113 entry->related_index); 114 } 115 116 snprintf(ids, sizeof(ids), "%c%jd%s", g_flags->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_flags->tpoint[e->tpoint_id]; 136 us = get_us_from_tsc(e->tsc - tsc_offset, tsc_rate); 137 138 printf("%2d: %10.3f ", entry->lcore, us); 139 if (g_print_tsc) { 140 printf("(%9ju) ", e->tsc - tsc_offset); 141 } 142 if (g_flags->owner[d->owner_type].id_prefix) { 143 printf("%c%02d ", g_flags->owner[d->owner_type].id_prefix, e->poller_id); 144 } else { 145 printf("%4s", " "); 146 } 147 148 printf("%-*s ", (int)sizeof(d->name), d->name); 149 print_size(e->size); 150 151 if (d->new_object) { 152 print_object_id(d, entry); 153 } else if (d->object_type != OBJECT_NONE) { 154 if (entry->object_index != UINT64_MAX) { 155 us = get_us_from_tsc(e->tsc - entry->object_start, tsc_rate); 156 print_object_id(d, entry); 157 print_float("time", us); 158 } else { 159 printf("id: %-17s", "N/A"); 160 } 161 } else if (e->object_id != 0) { 162 print_ptr("object", e->object_id); 163 } 164 165 for (i = 0; i < d->num_args; ++i) { 166 switch (d->args[i].type) { 167 case SPDK_TRACE_ARG_TYPE_PTR: 168 print_ptr(d->args[i].name, (uint64_t)entry->args[i].pointer); 169 break; 170 case SPDK_TRACE_ARG_TYPE_INT: 171 print_uint64(d->args[i].name, entry->args[i].integer); 172 break; 173 case SPDK_TRACE_ARG_TYPE_STR: 174 print_string(d->args[i].name, entry->args[i].string); 175 break; 176 } 177 } 178 printf("\n"); 179 } 180 181 static void 182 print_event_json(struct spdk_trace_parser_entry *entry, uint64_t tsc_rate, uint64_t tsc_offset) 183 { 184 struct spdk_trace_entry *e = entry->entry; 185 const struct spdk_trace_tpoint *d; 186 size_t i; 187 188 d = &g_flags->tpoint[e->tpoint_id]; 189 190 spdk_json_write_object_begin(g_json); 191 spdk_json_write_named_uint64(g_json, "lcore", entry->lcore); 192 spdk_json_write_named_uint64(g_json, "tpoint", e->tpoint_id); 193 spdk_json_write_named_uint64(g_json, "tsc", e->tsc); 194 195 if (g_flags->owner[d->owner_type].id_prefix) { 196 spdk_json_write_named_string_fmt(g_json, "poller", "%c%02d", 197 g_flags->owner[d->owner_type].id_prefix, 198 e->poller_id); 199 } 200 if (e->size != 0) { 201 spdk_json_write_named_uint32(g_json, "size", e->size); 202 } 203 if (d->new_object || d->object_type != OBJECT_NONE || e->object_id != 0) { 204 char object_type; 205 206 spdk_json_write_named_object_begin(g_json, "object"); 207 if (d->new_object) { 208 object_type = g_flags->object[d->object_type].id_prefix; 209 spdk_json_write_named_string_fmt(g_json, "id", "%c%" PRIu64, object_type, 210 entry->object_index); 211 } else if (d->object_type != OBJECT_NONE) { 212 object_type = g_flags->object[d->object_type].id_prefix; 213 if (entry->object_index != UINT64_MAX) { 214 spdk_json_write_named_string_fmt(g_json, "id", "%c%" PRIu64, 215 object_type, 216 entry->object_index); 217 spdk_json_write_named_uint64(g_json, "time", 218 e->tsc - entry->object_start); 219 } 220 } 221 spdk_json_write_named_uint64(g_json, "value", e->object_id); 222 spdk_json_write_object_end(g_json); 223 } 224 225 /* Print related objects array */ 226 if (entry->related_index != UINT64_MAX) { 227 spdk_json_write_named_string_fmt(g_json, "related", "%c%" PRIu64, 228 g_flags->object[entry->related_type].id_prefix, 229 entry->related_index); 230 } 231 232 if (d->num_args > 0) { 233 spdk_json_write_named_array_begin(g_json, "args"); 234 for (i = 0; i < d->num_args; ++i) { 235 switch (d->args[i].type) { 236 case SPDK_TRACE_ARG_TYPE_PTR: 237 spdk_json_write_uint64(g_json, (uint64_t)entry->args[i].pointer); 238 break; 239 case SPDK_TRACE_ARG_TYPE_INT: 240 spdk_json_write_uint64(g_json, entry->args[i].integer); 241 break; 242 case SPDK_TRACE_ARG_TYPE_STR: 243 spdk_json_write_string(g_json, entry->args[i].string); 244 break; 245 } 246 } 247 spdk_json_write_array_end(g_json); 248 } 249 250 spdk_json_write_object_end(g_json); 251 } 252 253 static void 254 process_event(struct spdk_trace_parser_entry *e, uint64_t tsc_rate, uint64_t tsc_offset) 255 { 256 if (g_json == NULL) { 257 print_event(e, tsc_rate, tsc_offset); 258 } else { 259 print_event_json(e, tsc_rate, tsc_offset); 260 } 261 } 262 263 static void 264 print_tpoint_definitions(void) 265 { 266 const struct spdk_trace_tpoint *tpoint; 267 size_t i, j; 268 269 /* We only care about these when printing JSON */ 270 if (!g_json) { 271 return; 272 } 273 274 spdk_json_write_named_uint64(g_json, "tsc_rate", g_flags->tsc_rate); 275 spdk_json_write_named_array_begin(g_json, "tpoints"); 276 277 for (i = 0; i < SPDK_COUNTOF(g_flags->tpoint); ++i) { 278 tpoint = &g_flags->tpoint[i]; 279 if (tpoint->tpoint_id == 0) { 280 continue; 281 } 282 283 spdk_json_write_object_begin(g_json); 284 spdk_json_write_named_string(g_json, "name", tpoint->name); 285 spdk_json_write_named_uint32(g_json, "id", tpoint->tpoint_id); 286 spdk_json_write_named_bool(g_json, "new_object", tpoint->new_object); 287 288 spdk_json_write_named_array_begin(g_json, "args"); 289 for (j = 0; j < tpoint->num_args; ++j) { 290 spdk_json_write_object_begin(g_json); 291 spdk_json_write_named_string(g_json, "name", tpoint->args[j].name); 292 spdk_json_write_named_uint32(g_json, "type", tpoint->args[j].type); 293 spdk_json_write_named_uint32(g_json, "size", tpoint->args[j].size); 294 spdk_json_write_object_end(g_json); 295 } 296 spdk_json_write_array_end(g_json); 297 spdk_json_write_object_end(g_json); 298 } 299 300 spdk_json_write_array_end(g_json); 301 } 302 303 static int 304 print_json(void *cb_ctx, const void *data, size_t size) 305 { 306 ssize_t rc; 307 308 while (size > 0) { 309 rc = write(STDOUT_FILENO, data, size); 310 if (rc < 0) { 311 fprintf(stderr, "%s: %s\n", g_exe_name, spdk_strerror(errno)); 312 abort(); 313 } 314 315 size -= rc; 316 } 317 318 return 0; 319 } 320 321 static void 322 usage(void) 323 { 324 fprintf(stderr, "usage:\n"); 325 fprintf(stderr, " %s <option> <lcore#>\n", g_exe_name); 326 fprintf(stderr, " '-c' to display single lcore history\n"); 327 fprintf(stderr, " '-t' to display TSC offset for each event\n"); 328 fprintf(stderr, " '-s' to specify spdk_trace shm name for a\n"); 329 fprintf(stderr, " currently running process\n"); 330 fprintf(stderr, " '-i' to specify the shared memory ID\n"); 331 fprintf(stderr, " '-p' to specify the trace PID\n"); 332 fprintf(stderr, " (If -s is specified, then one of\n"); 333 fprintf(stderr, " -i or -p must be specified)\n"); 334 fprintf(stderr, " '-f' to specify a tracepoint file name\n"); 335 fprintf(stderr, " (-s and -f are mutually exclusive)\n"); 336 fprintf(stderr, " '-j' to use JSON to format the output\n"); 337 } 338 339 int 340 main(int argc, char **argv) 341 { 342 struct spdk_trace_parser_opts opts; 343 struct spdk_trace_parser_entry entry; 344 int lcore = SPDK_TRACE_MAX_LCORE; 345 uint64_t tsc_offset, entry_count; 346 const char *app_name = NULL; 347 const char *file_name = NULL; 348 int op, i; 349 char shm_name[64]; 350 int shm_id = -1, shm_pid = -1; 351 bool json = false; 352 353 g_exe_name = argv[0]; 354 while ((op = getopt(argc, argv, "c:f:i:jp:s:t")) != -1) { 355 switch (op) { 356 case 'c': 357 lcore = atoi(optarg); 358 if (lcore > SPDK_TRACE_MAX_LCORE) { 359 fprintf(stderr, "Selected lcore: %d " 360 "exceeds maximum %d\n", lcore, 361 SPDK_TRACE_MAX_LCORE); 362 exit(1); 363 } 364 break; 365 case 'i': 366 shm_id = atoi(optarg); 367 break; 368 case 'p': 369 shm_pid = atoi(optarg); 370 break; 371 case 's': 372 app_name = optarg; 373 break; 374 case 'f': 375 file_name = optarg; 376 break; 377 case 't': 378 g_print_tsc = true; 379 break; 380 case 'j': 381 json = true; 382 break; 383 default: 384 usage(); 385 exit(1); 386 } 387 } 388 389 if (file_name != NULL && app_name != NULL) { 390 fprintf(stderr, "-f and -s are mutually exclusive\n"); 391 usage(); 392 exit(1); 393 } 394 395 if (file_name == NULL && app_name == NULL) { 396 fprintf(stderr, "One of -f and -s must be specified\n"); 397 usage(); 398 exit(1); 399 } 400 401 if (json) { 402 g_json = spdk_json_write_begin(print_json, NULL, 0); 403 if (g_json == NULL) { 404 fprintf(stderr, "Failed to allocate JSON write context\n"); 405 exit(1); 406 } 407 } 408 409 if (!file_name) { 410 if (shm_id >= 0) { 411 snprintf(shm_name, sizeof(shm_name), "/%s_trace.%d", app_name, shm_id); 412 } else { 413 snprintf(shm_name, sizeof(shm_name), "/%s_trace.pid%d", app_name, shm_pid); 414 } 415 file_name = shm_name; 416 } 417 418 opts.filename = file_name; 419 opts.lcore = lcore; 420 opts.mode = app_name == NULL ? SPDK_TRACE_PARSER_MODE_FILE : SPDK_TRACE_PARSER_MODE_SHM; 421 g_parser = spdk_trace_parser_init(&opts); 422 if (g_parser == NULL) { 423 fprintf(stderr, "Failed to initialize trace parser\n"); 424 exit(1); 425 } 426 427 g_flags = spdk_trace_parser_get_flags(g_parser); 428 if (!g_json) { 429 printf("TSC Rate: %ju\n", g_flags->tsc_rate); 430 } else { 431 spdk_json_write_object_begin(g_json); 432 print_tpoint_definitions(); 433 spdk_json_write_named_array_begin(g_json, "entries"); 434 } 435 436 for (i = 0; i < SPDK_TRACE_MAX_LCORE; ++i) { 437 if (lcore == SPDK_TRACE_MAX_LCORE || i == lcore) { 438 entry_count = spdk_trace_parser_get_entry_count(g_parser, i); 439 if (entry_count > 0) { 440 printf("Trace Size of lcore (%d): %ju\n", i, entry_count); 441 } 442 } 443 } 444 445 tsc_offset = spdk_trace_parser_get_tsc_offset(g_parser); 446 while (spdk_trace_parser_next_entry(g_parser, &entry)) { 447 if (entry.entry->tsc < tsc_offset) { 448 continue; 449 } 450 process_event(&entry, g_flags->tsc_rate, tsc_offset); 451 } 452 453 if (g_json != NULL) { 454 spdk_json_write_array_end(g_json); 455 spdk_json_write_object_end(g_json); 456 spdk_json_write_end(g_json); 457 } 458 459 spdk_trace_parser_cleanup(g_parser); 460 461 return (0); 462 } 463