/*- * BSD LICENSE * * Copyright (c) Intel Corporation. * All rights reserved. * * Redistribution and use in source and binary forms, with or without * modification, are permitted provided that the following conditions * are met: * * * Redistributions of source code must retain the above copyright * notice, this list of conditions and the following disclaimer. * * Redistributions in binary form must reproduce the above copyright * notice, this list of conditions and the following disclaimer in * the documentation and/or other materials provided with the * distribution. * * Neither the name of Intel Corporation nor the names of its * contributors may be used to endorse or promote products derived * from this software without specific prior written permission. * * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. */ #include "spdk/stdinc.h" #include "spdk/env.h" #include "spdk/json.h" #include "spdk/likely.h" #include "spdk/string.h" #include "spdk/util.h" #include extern "C" { #include "spdk/trace.h" #include "spdk/util.h" } static struct spdk_trace_histories *g_histories; static struct spdk_json_write_ctx *g_json; static bool g_print_tsc = false; /* This is a bit ugly, but we don't want to include env_dpdk in the app, while spdk_util, which we * do need, uses some of the functions implemented there. We're not actually using the functions * that depend on those, so just define them as no-ops to allow the app to link. */ extern "C" { void * spdk_realloc(void *buf, size_t size, size_t align) { assert(false); return NULL; } void spdk_free(void *buf) { assert(false); } } /* 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) { return ((float)tsc) * 1000 * 1000 / tsc_rate; } static const char * format_argname(const char *name) { static char namebuf[16]; snprintf(namebuf, sizeof(namebuf), "%s: ", name); return namebuf; } static void print_ptr(const char *arg_string, uint64_t arg) { printf("%-7.7s0x%-14jx ", format_argname(arg_string), arg); } static void print_uint64(const char *arg_string, uint64_t arg) { /* * Print arg as signed, since -1 is a common value especially * for FLUSH WRITEBUF when writev() returns -1 due to full * socket buffer. */ printf("%-7.7s%-16jd ", format_argname(arg_string), arg); } static void print_string(const char *arg_string, const char *arg) { printf("%-7.7s%-16.16s ", format_argname(arg_string), arg); } static void print_size(uint32_t size) { if (size > 0) { printf("size: %6u ", size); } else { printf("%13s", " "); } } static void print_object_id(uint8_t type, uint64_t id) { printf("id: %c%-15jd ", g_histories->flags.object[type].id_prefix, id); } static void 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); 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) { struct spdk_trace_tpoint *d; struct object_stats *stats; float us; size_t i; d = &g_histories->flags.tpoint[e->tpoint_id]; stats = &g_stats[d->object_type]; us = get_us_from_tsc(e->tsc - tsc_offset, tsc_rate); printf("%2d: %10.3f ", 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); } else { printf("%4s", " "); } printf("%-*s ", (int)sizeof(d->name), d->name); print_size(e->size); if (d->new_object) { print_object_id(d->object_type, stats->index[e->object_id]); } 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]); print_float("time", us); } else { printf("id: N/A"); } } else if (e->object_id != 0) { 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]); } printf("\n"); } static void print_event_json(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; size_t i; d = &g_histories->flags.tpoint[e->tpoint_id]; stats = &g_stats[d->object_type]; spdk_json_write_object_begin(g_json); spdk_json_write_named_uint64(g_json, "lcore", 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) { spdk_json_write_named_string_fmt(g_json, "poller", "%c%02d", g_histories->flags.owner[d->owner_type].id_prefix, e->poller_id); } if (e->size != 0) { spdk_json_write_named_uint32(g_json, "size", e->size); } if (d->new_object || d->object_type != OBJECT_NONE || e->object_id != 0) { char object_type; spdk_json_write_named_object_begin(g_json, "object"); if (d->new_object) { object_type = g_histories->flags.object[d->object_type].id_prefix; spdk_json_write_named_string_fmt(g_json, "id", "%c%lu", object_type, stats->index[e->object_id]); } 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()) { spdk_json_write_named_string_fmt(g_json, "id", "%c%lu", object_type, stats->index[e->object_id]); spdk_json_write_named_uint64(g_json, "time", e->tsc - stats->start[e->object_id]); } } 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]); } spdk_json_write_array_end(g_json); } spdk_json_write_object_end(g_json); } static void process_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; 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; } } } 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; size_t i, j; /* We only care about these when printing JSON */ if (!g_json) { return; } spdk_json_write_named_uint64(g_json, "tsc_rate", g_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]; if (tpoint->tpoint_id == 0) { continue; } spdk_json_write_object_begin(g_json); spdk_json_write_named_string(g_json, "name", tpoint->name); spdk_json_write_named_uint32(g_json, "id", tpoint->tpoint_id); spdk_json_write_named_bool(g_json, "new_object", tpoint->new_object); spdk_json_write_named_array_begin(g_json, "args"); for (j = 0; j < tpoint->num_args; ++j) { spdk_json_write_object_begin(g_json); spdk_json_write_named_string(g_json, "name", tpoint->args[j].name); spdk_json_write_named_uint32(g_json, "type", tpoint->args[j].type); spdk_json_write_named_uint32(g_json, "size", tpoint->args[j].size); spdk_json_write_object_end(g_json); } spdk_json_write_array_end(g_json); spdk_json_write_object_end(g_json); } spdk_json_write_array_end(g_json); } static int print_json(void *cb_ctx, const void *data, size_t size) { ssize_t rc; while (size > 0) { rc = write(STDOUT_FILENO, data, size); if (rc < 0) { fprintf(stderr, "%s: %s\n", g_exe_name, spdk_strerror(errno)); abort(); } size -= rc; } return 0; } static void usage(void) { fprintf(stderr, "usage:\n"); fprintf(stderr, " %s