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