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 *
spdk_realloc(void * buf,size_t size,size_t align)36 spdk_realloc(void *buf, size_t size, size_t align)
37 {
38 assert(false);
39
40 return NULL;
41 }
42
43 void
spdk_free(void * buf)44 spdk_free(void *buf)
45 {
46 assert(false);
47 }
48
49 uint64_t
spdk_get_ticks(void)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
get_us_from_tsc(uint64_t tsc,uint64_t tsc_rate)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 *
format_argname(const char * name)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
print_ptr(const char * arg_string,uint64_t arg)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
print_uint64(const char * arg_string,uint64_t arg)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
print_string(const char * arg_string,const char * arg)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
print_size(uint32_t size)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
print_object_id(const struct spdk_trace_tpoint * d,struct spdk_trace_parser_entry * entry)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
print_float(const char * arg_string,float arg)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
print_event(struct spdk_trace_parser_entry * entry,uint64_t tsc_rate,uint64_t tsc_offset)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
print_event_json(struct spdk_trace_parser_entry * entry,uint64_t tsc_rate,uint64_t tsc_offset)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
print_tpoint_definitions(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
print_json(void * cb_ctx,const void * data,size_t size)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
trace_print(int lcore)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
trace_print_json(void)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
usage(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
get_newest(const char * path,const struct stat * sb,int tflag,struct FTW * ftw)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
main(int argc,char ** argv)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