app/trace: use trace_parse library to process traces (69390766) · Commits · Public Repositories / spdk

app/trace/Makefile

+1 −1

Original line number	Diff line number	Diff line
		@@ -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

app/trace/trace.cpp

+91 −374

Original line number	Diff line number	Diff line
		@@ -41,11 +41,12 @@
		#include <map>

		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_key, spdk_trace_entry *, compare_entry_key> entry_map;

		entry_map g_entry_map;

		struct object_stats {

		std::map<uint64_t, uint64_t> start;
		std::map<uint64_t, uint64_t> index;
		std::map<uint64_t, uint64_t> size;
		std::map<uint64_t, uint64_t> 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)
		{
		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)
		print_event(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;
		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);
		} else {
		print_event_json(e, tsc_rate, tsc_offset, lcore);
		}
		}

		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;
		}
		}
		print_event(e, tsc_rate, tsc_offset);
		} else {
		first = 0;
		last = num_entries_filled - 1;
		print_event_json(e, tsc_rate, tsc_offset);
		}

		/*
		* 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,18 +339,15 @@ static void usage(void)

		int main(int argc, char **argv)
		{
		void *history_ptr;
		struct spdk_trace_history *history;
		int fd, i, rc;
		struct spdk_trace_parser_opts opts;
		struct spdk_trace_parser_entry entry;
		int lcore = SPDK_TRACE_MAX_LCORE;
		uint64_t tsc_offset;
		uint64_t tsc_offset, entry_count;
		const char *app_name = NULL;
		const char *file_name = NULL;
		int op;
		int op, i;
		char shm_name[64];
		int shm_id = -1, shm_pid = -1;
		uint64_t trace_histories_size;
		struct stat _stat;
		bool json = false;

		g_exe_name = argv[0];
		@@ -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);
		spdk_json_write_object_begin(g_json);
		print_tpoint_definitions();
		spdk_json_write_named_array_begin(g_json, "entries");
		}

		populate_events(history, history->num_entries);
		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);
		}
		}

		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) {
		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);
		}