From 69390766a4178dd74e9c71b9d500fdc465766f3b Mon Sep 17 00:00:00 2001 From: Konrad Sztyber Date: Fri, 3 Sep 2021 12:01:06 +0200 Subject: [PATCH] app/trace: use trace_parse library to process traces Removed code that was copied to the trace_parse library and replaced with calls to that library. This significantly reduces the size of the application (LOC), as it's only responsible for formatting the traces and pretty-printing them. Signed-off-by: Konrad Sztyber Change-Id: Ib9f4e65f9f0072fb00bfa60cece1ce0627f109a0 Reviewed-on: https://review.spdk.io/gerrit/c/spdk/spdk/+/9436 Community-CI: Broadcom CI Reviewed-by: Jim Harris Reviewed-by: Krzysztof Karas Reviewed-by: Aleksey Marchuk Reviewed-by: Tomasz Zawadzki Tested-by: SPDK CI Jenkins --- app/trace/Makefile | 2 +- app/trace/trace.cpp | 467 +++++++++----------------------------------- 2 files changed, 93 insertions(+), 376 deletions(-) diff --git a/app/trace/Makefile b/app/trace/Makefile index d222496a9a..6c07363192 100644 --- a/app/trace/Makefile +++ b/app/trace/Makefile @@ -38,7 +38,7 @@ include $(SPDK_ROOT_DIR)/mk/spdk.modules.mk APP = spdk_trace SPDK_NO_LINK_ENV = 1 -SPDK_LIB_LIST += json +SPDK_LIB_LIST += json trace_parser CXX_SRCS := trace.cpp diff --git a/app/trace/trace.cpp b/app/trace/trace.cpp index 7d378273ce..0fa2f71281 100644 --- a/app/trace/trace.cpp +++ b/app/trace/trace.cpp @@ -41,11 +41,12 @@ #include extern "C" { -#include "spdk/trace.h" +#include "spdk/trace_parser.h" #include "spdk/util.h" } -static struct spdk_trace_histories *g_histories; +static struct spdk_trace_parser *g_parser; +static const struct spdk_trace_flags *g_flags; static struct spdk_json_write_ctx *g_json; static bool g_print_tsc = false; @@ -71,66 +72,8 @@ extern "C" { static void usage(void); -struct entry_key { - entry_key(uint16_t _lcore, uint64_t _tsc) : lcore(_lcore), tsc(_tsc) {} - uint16_t lcore; - uint64_t tsc; -}; - -class compare_entry_key -{ -public: - bool operator()(const entry_key &first, const entry_key &second) const - { - if (first.tsc == second.tsc) { - return first.lcore < second.lcore; - } else { - return first.tsc < second.tsc; - } - } -}; - -typedef std::map entry_map; - -entry_map g_entry_map; - -struct object_stats { - - std::map start; - std::map index; - std::map size; - std::map tpoint_id; - uint64_t counter; - - object_stats() : start(), index(), size(), tpoint_id(), counter(0) {} -}; - -struct argument_context { - struct spdk_trace_entry *entry; - struct spdk_trace_entry_buffer *buffer; - uint16_t lcore; - size_t offset; - - argument_context(struct spdk_trace_entry *entry, - uint16_t lcore) : entry(entry), lcore(lcore) - { - buffer = (struct spdk_trace_entry_buffer *)entry; - - /* The first argument resides within the spdk_trace_entry structure, so the initial - * offset needs to be adjusted to the start of the spdk_trace_entry.args array - */ - offset = offsetof(struct spdk_trace_entry, args) - - offsetof(struct spdk_trace_entry_buffer, data); - } -}; - -struct object_stats g_stats[SPDK_TRACE_MAX_OBJECT]; - static char *g_exe_name; -static uint64_t g_tsc_rate; -static uint64_t g_first_tsc = 0x0; - static float get_us_from_tsc(uint64_t tsc, uint64_t tsc_rate) { @@ -182,7 +125,7 @@ print_size(uint32_t size) static void print_object_id(uint8_t type, uint64_t id) { - printf("id: %c%-15jd ", g_histories->flags.object[type].id_prefix, id); + printf("id: %c%-15jd ", g_flags->object[type].id_prefix, id); } static void @@ -191,126 +134,23 @@ print_float(const char *arg_string, float arg) printf("%-7s%-16.3f ", format_argname(arg_string), arg); } -static struct spdk_trace_entry_buffer * -get_next_buffer(struct spdk_trace_entry_buffer *buf, uint16_t lcore) -{ - struct spdk_trace_history *history; - - history = spdk_get_per_lcore_history(g_histories, lcore); - assert(history); - - if (spdk_unlikely((void *)buf == &history->entries[history->num_entries - 1])) { - return (struct spdk_trace_entry_buffer *)&history->entries[0]; - } else { - return buf + 1; - } -} - -static bool -build_arg(struct argument_context *argctx, const struct spdk_trace_argument *arg, - void *buf, size_t bufsize) -{ - struct spdk_trace_entry *entry = argctx->entry; - struct spdk_trace_entry_buffer *buffer = argctx->buffer; - size_t curlen, argoff; - - argoff = 0; - while (argoff < arg->size) { - if (argctx->offset == sizeof(buffer->data)) { - buffer = get_next_buffer(buffer, argctx->lcore); - if (spdk_unlikely(buffer->tpoint_id != SPDK_TRACE_MAX_TPOINT_ID || - buffer->tsc != entry->tsc)) { - return false; - } - - argctx->offset = 0; - argctx->buffer = buffer; - } - - curlen = spdk_min(sizeof(buffer->data) - argctx->offset, arg->size - argoff); - if (argoff < bufsize) { - memcpy((uint8_t *)buf + argoff, &buffer->data[argctx->offset], - spdk_min(curlen, bufsize - argoff)); - } - - argctx->offset += curlen; - argoff += curlen; - } - - return true; -} - static void -print_arg(struct argument_context *argctx, const struct spdk_trace_argument *arg) +print_event(struct spdk_trace_parser_entry *entry, uint64_t tsc_rate, uint64_t tsc_offset) { - uint64_t value = 0; - char strbuf[256]; - - switch (arg->type) { - case SPDK_TRACE_ARG_TYPE_PTR: - if (build_arg(argctx, arg, &value, sizeof(value))) { - print_ptr(arg->name, value); - } - break; - case SPDK_TRACE_ARG_TYPE_INT: - if (build_arg(argctx, arg, &value, sizeof(value))) { - print_uint64(arg->name, value); - } - break; - case SPDK_TRACE_ARG_TYPE_STR: - assert((size_t)arg->size <= sizeof(strbuf)); - if (build_arg(argctx, arg, strbuf, sizeof(strbuf))) { - print_string(arg->name, strbuf); - } - break; - } -} - -static void -print_arg_json(struct argument_context *argctx, const struct spdk_trace_argument *arg) -{ - uint64_t value = 0; - char strbuf[256]; - - switch (arg->type) { - case SPDK_TRACE_ARG_TYPE_PTR: - case SPDK_TRACE_ARG_TYPE_INT: - if (build_arg(argctx, arg, &value, sizeof(value))) { - spdk_json_write_uint64(g_json, value); - } else { - spdk_json_write_null(g_json); - } - break; - case SPDK_TRACE_ARG_TYPE_STR: - assert((size_t)arg->size <= sizeof(strbuf)); - if (build_arg(argctx, arg, strbuf, sizeof(strbuf))) { - spdk_json_write_string(g_json, strbuf); - } else { - spdk_json_write_null(g_json); - } - break; - } -} - -static void -print_event(struct spdk_trace_entry *e, uint64_t tsc_rate, - uint64_t tsc_offset, uint16_t lcore) -{ - struct spdk_trace_tpoint *d; - struct object_stats *stats; + struct spdk_trace_entry *e = entry->entry; + const struct spdk_trace_tpoint *d; float us; size_t i; - d = &g_histories->flags.tpoint[e->tpoint_id]; - stats = &g_stats[d->object_type]; + d = &g_flags->tpoint[e->tpoint_id]; us = get_us_from_tsc(e->tsc - tsc_offset, tsc_rate); - printf("%2d: %10.3f ", lcore, us); + printf("%2d: %10.3f ", entry->lcore, us); if (g_print_tsc) { printf("(%9ju) ", e->tsc - tsc_offset); } - if (g_histories->flags.owner[d->owner_type].id_prefix) { - printf("%c%02d ", g_histories->flags.owner[d->owner_type].id_prefix, e->poller_id); + if (g_flags->owner[d->owner_type].id_prefix) { + printf("%c%02d ", g_flags->owner[d->owner_type].id_prefix, e->poller_id); } else { printf("%4s", " "); } @@ -319,12 +159,11 @@ print_event(struct spdk_trace_entry *e, uint64_t tsc_rate, print_size(e->size); if (d->new_object) { - print_object_id(d->object_type, stats->index[e->object_id]); + print_object_id(d->object_type, entry->object_index); } else if (d->object_type != OBJECT_NONE) { - if (stats->start.find(e->object_id) != stats->start.end()) { - us = get_us_from_tsc(e->tsc - stats->start[e->object_id], - tsc_rate); - print_object_id(d->object_type, stats->index[e->object_id]); + if (entry->object_index != UINT64_MAX) { + us = get_us_from_tsc(e->tsc - entry->object_start, tsc_rate); + print_object_id(d->object_type, entry->object_index); print_float("time", us); } else { printf("id: N/A"); @@ -333,32 +172,39 @@ print_event(struct spdk_trace_entry *e, uint64_t tsc_rate, print_ptr("object", e->object_id); } - struct argument_context argctx(e, lcore); for (i = 0; i < d->num_args; ++i) { - print_arg(&argctx, &d->args[i]); + switch (d->args[i].type) { + case SPDK_TRACE_ARG_TYPE_PTR: + print_ptr(d->args[i].name, (uint64_t)entry->args[i].pointer); + break; + case SPDK_TRACE_ARG_TYPE_INT: + print_uint64(d->args[i].name, entry->args[i].integer); + break; + case SPDK_TRACE_ARG_TYPE_STR: + print_string(d->args[i].name, entry->args[i].string); + break; + } } printf("\n"); } static void -print_event_json(struct spdk_trace_entry *e, uint64_t tsc_rate, - uint64_t tsc_offset, uint16_t lcore) +print_event_json(struct spdk_trace_parser_entry *entry, uint64_t tsc_rate, uint64_t tsc_offset) { - struct spdk_trace_tpoint *d; - struct object_stats *stats; + struct spdk_trace_entry *e = entry->entry; + const struct spdk_trace_tpoint *d; size_t i; - d = &g_histories->flags.tpoint[e->tpoint_id]; - stats = &g_stats[d->object_type]; + d = &g_flags->tpoint[e->tpoint_id]; spdk_json_write_object_begin(g_json); - spdk_json_write_named_uint64(g_json, "lcore", lcore); + spdk_json_write_named_uint64(g_json, "lcore", entry->lcore); spdk_json_write_named_uint64(g_json, "tpoint", e->tpoint_id); spdk_json_write_named_uint64(g_json, "tsc", e->tsc); - if (g_histories->flags.owner[d->owner_type].id_prefix) { + if (g_flags->owner[d->owner_type].id_prefix) { spdk_json_write_named_string_fmt(g_json, "poller", "%c%02d", - g_histories->flags.owner[d->owner_type].id_prefix, + g_flags->owner[d->owner_type].id_prefix, e->poller_id); } if (e->size != 0) { @@ -369,28 +215,36 @@ print_event_json(struct spdk_trace_entry *e, uint64_t tsc_rate, spdk_json_write_named_object_begin(g_json, "object"); if (d->new_object) { - object_type = g_histories->flags.object[d->object_type].id_prefix; + object_type = g_flags->object[d->object_type].id_prefix; spdk_json_write_named_string_fmt(g_json, "id", "%c%" PRIu64, object_type, - stats->index[e->object_id]); + entry->object_index); } else if (d->object_type != OBJECT_NONE) { - object_type = g_histories->flags.object[d->object_type].id_prefix; - if (stats->start.find(e->object_id) != stats->start.end()) { + object_type = g_flags->object[d->object_type].id_prefix; + if (entry->object_index != UINT64_MAX) { spdk_json_write_named_string_fmt(g_json, "id", "%c%" PRIu64, object_type, - stats->index[e->object_id]); + entry->object_index); spdk_json_write_named_uint64(g_json, "time", - e->tsc - stats->start[e->object_id]); + e->tsc - entry->object_start); } } spdk_json_write_named_uint64(g_json, "value", e->object_id); spdk_json_write_object_end(g_json); } if (d->num_args > 0) { - struct argument_context argctx(e, lcore); - spdk_json_write_named_array_begin(g_json, "args"); for (i = 0; i < d->num_args; ++i) { - print_arg_json(&argctx, &d->args[i]); + switch (d->args[i].type) { + case SPDK_TRACE_ARG_TYPE_PTR: + spdk_json_write_uint64(g_json, (uint64_t)entry->args[i].pointer); + break; + case SPDK_TRACE_ARG_TYPE_INT: + spdk_json_write_uint64(g_json, entry->args[i].integer); + break; + case SPDK_TRACE_ARG_TYPE_STR: + spdk_json_write_string(g_json, entry->args[i].string); + break; + } } spdk_json_write_array_end(g_json); } @@ -399,91 +253,19 @@ print_event_json(struct spdk_trace_entry *e, uint64_t tsc_rate, } static void -process_event(struct spdk_trace_entry *e, uint64_t tsc_rate, - uint64_t tsc_offset, uint16_t lcore) +process_event(struct spdk_trace_parser_entry *e, uint64_t tsc_rate, uint64_t tsc_offset) { - struct spdk_trace_tpoint *d; - struct object_stats *stats; - - d = &g_histories->flags.tpoint[e->tpoint_id]; - stats = &g_stats[d->object_type]; - - if (d->new_object) { - stats->index[e->object_id] = stats->counter++; - stats->tpoint_id[e->object_id] = e->tpoint_id; - stats->start[e->object_id] = e->tsc; - stats->size[e->object_id] = e->size; - } - if (g_json == NULL) { - print_event(e, tsc_rate, tsc_offset, lcore); + print_event(e, tsc_rate, tsc_offset); } else { - print_event_json(e, tsc_rate, tsc_offset, lcore); + print_event_json(e, tsc_rate, tsc_offset); } } -static int -populate_events(struct spdk_trace_history *history, int num_entries) -{ - int i, num_entries_filled; - struct spdk_trace_entry *e; - int first, last, lcore; - - lcore = history->lcore; - - e = history->entries; - - num_entries_filled = num_entries; - while (e[num_entries_filled - 1].tsc == 0) { - num_entries_filled--; - } - - if (num_entries == num_entries_filled) { - first = last = 0; - for (i = 1; i < num_entries; i++) { - if (e[i].tsc < e[first].tsc) { - first = i; - } - if (e[i].tsc > e[last].tsc) { - last = i; - } - } - } else { - first = 0; - last = num_entries_filled - 1; - } - - /* - * We keep track of the highest first TSC out of all reactors. - * We will ignore any events that occured before this TSC on any - * other reactors. This will ensure we only print data for the - * subset of time where we have data across all reactors. - */ - if (e[first].tsc > g_first_tsc) { - g_first_tsc = e[first].tsc; - } - - i = first; - while (1) { - if (e[i].tpoint_id != SPDK_TRACE_MAX_TPOINT_ID) { - g_entry_map[entry_key(lcore, e[i].tsc)] = &e[i]; - } - if (i == last) { - break; - } - i++; - if (i == num_entries_filled) { - i = 0; - } - } - - return (0); -} - static void print_tpoint_definitions(void) { - struct spdk_trace_tpoint *tpoint; + const struct spdk_trace_tpoint *tpoint; size_t i, j; /* We only care about these when printing JSON */ @@ -491,11 +273,11 @@ print_tpoint_definitions(void) return; } - spdk_json_write_named_uint64(g_json, "tsc_rate", g_tsc_rate); + spdk_json_write_named_uint64(g_json, "tsc_rate", g_flags->tsc_rate); spdk_json_write_named_array_begin(g_json, "tpoints"); - for (i = 0; i < SPDK_COUNTOF(g_histories->flags.tpoint); ++i) { - tpoint = &g_histories->flags.tpoint[i]; + for (i = 0; i < SPDK_COUNTOF(g_flags->tpoint); ++i) { + tpoint = &g_flags->tpoint[i]; if (tpoint->tpoint_id == 0) { continue; } @@ -557,19 +339,16 @@ static void usage(void) int main(int argc, char **argv) { - void *history_ptr; - struct spdk_trace_history *history; - int fd, i, rc; - int lcore = SPDK_TRACE_MAX_LCORE; - uint64_t tsc_offset; - const char *app_name = NULL; - const char *file_name = NULL; - int op; - char shm_name[64]; - int shm_id = -1, shm_pid = -1; - uint64_t trace_histories_size; - struct stat _stat; - bool json = false; + struct spdk_trace_parser_opts opts; + struct spdk_trace_parser_entry entry; + int lcore = SPDK_TRACE_MAX_LCORE; + uint64_t tsc_offset, entry_count; + const char *app_name = NULL; + const char *file_name = NULL; + int op, i; + char shm_name[64]; + int shm_id = -1, shm_pid = -1; + bool json = false; g_exe_name = argv[0]; while ((op = getopt(argc, argv, "c:f:i:jp:s:t")) != -1) { @@ -627,109 +406,48 @@ int main(int argc, char **argv) } } - if (file_name) { - fd = open(file_name, O_RDONLY); - } else { + if (!file_name) { if (shm_id >= 0) { snprintf(shm_name, sizeof(shm_name), "/%s_trace.%d", app_name, shm_id); } else { snprintf(shm_name, sizeof(shm_name), "/%s_trace.pid%d", app_name, shm_pid); } - fd = shm_open(shm_name, O_RDONLY, 0600); file_name = shm_name; } - if (fd < 0) { - fprintf(stderr, "Could not open %s.\n", file_name); - usage(); - exit(-1); - } - - rc = fstat(fd, &_stat); - if (rc < 0) { - fprintf(stderr, "Could not get size of %s.\n", file_name); - usage(); - exit(-1); - } - if ((size_t)_stat.st_size < sizeof(*g_histories)) { - fprintf(stderr, "%s is not a valid trace file\n", file_name); - usage(); - exit(-1); - } - - /* Map the header of trace file */ - history_ptr = mmap(NULL, sizeof(*g_histories), PROT_READ, MAP_SHARED, fd, 0); - if (history_ptr == MAP_FAILED) { - fprintf(stderr, "Could not mmap %s.\n", file_name); - usage(); - exit(-1); - } - - g_histories = (struct spdk_trace_histories *)history_ptr; - - g_tsc_rate = g_histories->flags.tsc_rate; - if (g_tsc_rate == 0) { - fprintf(stderr, "Invalid tsc_rate %ju\n", g_tsc_rate); - usage(); - exit(-1); + + opts.filename = file_name; + opts.lcore = lcore; + opts.mode = app_name == NULL ? SPDK_TRACE_PARSER_MODE_FILE : SPDK_TRACE_PARSER_MODE_SHM; + g_parser = spdk_trace_parser_init(&opts); + if (g_parser == NULL) { + fprintf(stderr, "Failed to initialize trace parser\n"); + exit(1); } + g_flags = spdk_trace_parser_get_flags(g_parser); if (!g_json) { - printf("TSC Rate: %ju\n", g_tsc_rate); - } - - /* Remap the entire trace file */ - trace_histories_size = spdk_get_trace_histories_size(g_histories); - munmap(history_ptr, sizeof(*g_histories)); - if ((size_t)_stat.st_size < trace_histories_size) { - fprintf(stderr, "%s is not a valid trace file\n", file_name); - usage(); - exit(-1); - } - history_ptr = mmap(NULL, trace_histories_size, PROT_READ, MAP_SHARED, fd, 0); - if (history_ptr == MAP_FAILED) { - fprintf(stderr, "Could not mmap %s.\n", file_name); - usage(); - exit(-1); - } - - g_histories = (struct spdk_trace_histories *)history_ptr; - - if (lcore == SPDK_TRACE_MAX_LCORE) { - for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) { - history = spdk_get_per_lcore_history(g_histories, i); - if (history->num_entries == 0 || history->entries[0].tsc == 0) { - continue; - } - - if (!g_json && history->num_entries) { - printf("Trace Size of lcore (%d): %ju\n", i, history->num_entries); - } - - populate_events(history, history->num_entries); - } + printf("TSC Rate: %ju\n", g_flags->tsc_rate); } else { - history = spdk_get_per_lcore_history(g_histories, lcore); - if (history->num_entries > 0 && history->entries[0].tsc != 0) { - if (!g_json && history->num_entries) { - printf("Trace Size of lcore (%d): %ju\n", lcore, history->num_entries); - } - - populate_events(history, history->num_entries); - } - } - - if (g_json != NULL) { spdk_json_write_object_begin(g_json); print_tpoint_definitions(); spdk_json_write_named_array_begin(g_json, "entries"); } - tsc_offset = g_first_tsc; - for (entry_map::iterator it = g_entry_map.begin(); it != g_entry_map.end(); it++) { - if (it->first.tsc < g_first_tsc) { + for (i = 0; i < SPDK_TRACE_MAX_LCORE; ++i) { + if (lcore == SPDK_TRACE_MAX_LCORE || i == lcore) { + entry_count = spdk_trace_parser_get_entry_count(g_parser, i); + if (entry_count > 0) { + printf("Trace Size of lcore (%d): %ju\n", i, entry_count); + } + } + } + + tsc_offset = spdk_trace_parser_get_tsc_offset(g_parser); + while (spdk_trace_parser_next_entry(g_parser, &entry)) { + if (entry.entry->tsc < tsc_offset) { continue; } - process_event(it->second, g_tsc_rate, tsc_offset, it->first.lcore); + process_event(&entry, g_flags->tsc_rate, tsc_offset); } if (g_json != NULL) { @@ -738,8 +456,7 @@ int main(int argc, char **argv) spdk_json_write_end(g_json); } - munmap(history_ptr, trace_histories_size); - close(fd); + spdk_trace_parser_cleanup(g_parser); return (0); }