Spdk/lib/trace/trace.c

/*   SPDX-License-Identifier: BSD-3-Clause
 *   Copyright (C) 2016 Intel Corporation.
 *   All rights reserved.
 */

#include "spdk/stdinc.h"

#include "spdk/env.h"
#include "spdk/string.h"
#include "spdk/trace.h"
#include "spdk/util.h"
#include "spdk/barrier.h"
#include "spdk/log.h"
#include "spdk/cpuset.h"
#include "spdk/likely.h"

static int g_trace_fd = -1;
static char g_shm_name[64];

struct spdk_trace_histories *g_trace_histories;

static inline struct spdk_trace_entry *
get_trace_entry(struct spdk_trace_history *history, uint64_t offset)
{
	return &history->entries[offset & (history->num_entries - 1)];
}

void
_spdk_trace_record(uint64_t tsc, uint16_t tpoint_id, uint16_t poller_id, uint32_t size,
		   uint64_t object_id, int num_args, ...)
{
	struct spdk_trace_history *lcore_history;
	struct spdk_trace_entry *next_entry;
	struct spdk_trace_entry_buffer *buffer;
	struct spdk_trace_tpoint *tpoint;
	struct spdk_trace_argument *argument;
	unsigned lcore, i, offset, num_entries, arglen, argoff, curlen;
	uint64_t intval;
	void *argval;
	va_list vl;

	lcore = spdk_env_get_current_core();
	if (spdk_unlikely(lcore >= SPDK_TRACE_MAX_LCORE)) {
		return;
	}

	lcore_history = spdk_get_per_lcore_history(g_trace_histories, lcore);

	if (tsc == 0) {
		tsc = spdk_get_ticks();
	}

	lcore_history->tpoint_count[tpoint_id]++;

	tpoint = &g_trace_flags->tpoint[tpoint_id];
	/* Make sure that the number of arguments passed matches tracepoint definition */
	if (spdk_unlikely(tpoint->num_args != num_args)) {
		assert(0 && "Unexpected number of tracepoint arguments");
		return;
	}

	/* Get next entry index in the circular buffer */
	next_entry = get_trace_entry(lcore_history, lcore_history->next_entry);
	next_entry->tsc = tsc;
	next_entry->tpoint_id = tpoint_id;
	next_entry->poller_id = poller_id;
	next_entry->size = size;
	next_entry->object_id = object_id;

	num_entries = 1;
	buffer = (struct spdk_trace_entry_buffer *)next_entry;
	/* The initial offset needs to be adjusted by the fields present in the first entry
	 * (poller_id, size, etc.).
	 */
	offset = offsetof(struct spdk_trace_entry, args) -
		 offsetof(struct spdk_trace_entry_buffer, data);

	va_start(vl, num_args);
	for (i = 0; i < tpoint->num_args; ++i) {
		argument = &tpoint->args[i];
		switch (argument->type) {
		case SPDK_TRACE_ARG_TYPE_STR:
			argval = va_arg(vl, void *);
			arglen = strnlen((const char *)argval, argument->size - 1) + 1;
			break;
		case SPDK_TRACE_ARG_TYPE_INT:
		case SPDK_TRACE_ARG_TYPE_PTR:
			if (argument->size == 8) {
				intval = va_arg(vl, uint64_t);
			} else {
				intval = va_arg(vl, uint32_t);
			}
			argval = &intval;
			arglen = argument->size;
			break;
		default:
			assert(0 && "Invalid trace argument type");
			return;
		}

		/* Copy argument's data. For some argument types (strings) user is allowed to pass a
		 * value that is either larger or smaller than what's defined in the tracepoint's
		 * description. If the value is larger, we'll truncate it, while if it's smaller,
		 * we'll only fill portion of the buffer, without touching the rest. For instance,
		 * if the definition marks an argument as 40B and user passes 12B string, we'll only
		 * copy 13B (accounting for the NULL terminator).
		 */
		argoff = 0;
		while (argoff < argument->size) {
			/* Current buffer is full, we need to acquire another one */
			if (spdk_unlikely(offset == sizeof(buffer->data))) {
				buffer = (struct spdk_trace_entry_buffer *) get_trace_entry(
						 lcore_history,
						 lcore_history->next_entry + num_entries);
				buffer->tpoint_id = SPDK_TRACE_MAX_TPOINT_ID;
				buffer->tsc = tsc;
				num_entries++;
				offset = 0;
			}

			curlen = spdk_min(sizeof(buffer->data) - offset, argument->size - argoff);
			if (spdk_likely(argoff < arglen)) {
				assert(argval != NULL);
				memcpy(&buffer->data[offset], (uint8_t *)argval + argoff,
				       spdk_min(curlen, arglen - argoff));
			}

			offset += curlen;
			argoff += curlen;
		}

		/* Make sure that truncated strings are NULL-terminated */
		if (spdk_unlikely(argument->type == SPDK_TRACE_ARG_TYPE_STR)) {
			assert(offset > 0);
			buffer->data[offset - 1] = '\0';
		}
	}
	va_end(vl);

	/* Ensure all elements of the trace entry are visible to outside trace tools */
	spdk_smp_wmb();
	lcore_history->next_entry += num_entries;
}

int
spdk_trace_init(const char *shm_name, uint64_t num_entries)
{
	uint32_t i = 0;
	int histories_size;
	uint64_t lcore_offsets[SPDK_TRACE_MAX_LCORE + 1] = { 0 };
	struct spdk_cpuset cpuset = {};

	/* 0 entries requested - skip trace initialization */
	if (num_entries == 0) {
		return 0;
	}

	spdk_cpuset_zero(&cpuset);
	histories_size = sizeof(struct spdk_trace_flags);
	SPDK_ENV_FOREACH_CORE(i) {
		spdk_cpuset_set_cpu(&cpuset, i, true);
		lcore_offsets[i] = histories_size;
		histories_size += spdk_get_trace_history_size(num_entries);
	}
	lcore_offsets[SPDK_TRACE_MAX_LCORE] = histories_size;

	snprintf(g_shm_name, sizeof(g_shm_name), "%s", shm_name);

	g_trace_fd = shm_open(shm_name, O_RDWR | O_CREAT, 0600);
	if (g_trace_fd == -1) {
		SPDK_ERRLOG("could not shm_open spdk_trace\n");
		SPDK_ERRLOG("errno=%d %s\n", errno, spdk_strerror(errno));
		return 1;
	}

	if (ftruncate(g_trace_fd, histories_size) != 0) {
		SPDK_ERRLOG("could not truncate shm\n");
		goto trace_init_err;
	}

	g_trace_histories = mmap(NULL, histories_size, PROT_READ | PROT_WRITE,
				 MAP_SHARED, g_trace_fd, 0);
	if (g_trace_histories == MAP_FAILED) {
		SPDK_ERRLOG("could not mmap shm\n");
		goto trace_init_err;
	}

	/* TODO: On FreeBSD, mlock on shm_open'd memory doesn't seem to work.  Docs say that kern.ipc.shm_use_phys=1
	 * should allow it, but forcing that doesn't seem to work either.  So for now just skip mlock on FreeBSD
	 * altogether.
	 */
#if defined(__linux__)
	if (mlock(g_trace_histories, histories_size) != 0) {
		SPDK_ERRLOG("Could not mlock shm for tracing - %s.\n", spdk_strerror(errno));
		if (errno == ENOMEM) {
			SPDK_ERRLOG("Check /dev/shm for old tracing files that can be deleted.\n");
		}
		goto trace_init_err;
	}
#endif

	memset(g_trace_histories, 0, histories_size);

	g_trace_flags = &g_trace_histories->flags;

	g_trace_flags->tsc_rate = spdk_get_ticks_hz();

	for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
		struct spdk_trace_history *lcore_history;

		g_trace_flags->lcore_history_offsets[i] = lcore_offsets[i];
		if (lcore_offsets[i] == 0) {
			continue;
		}
		assert(spdk_cpuset_get_cpu(&cpuset, i));
		lcore_history = spdk_get_per_lcore_history(g_trace_histories, i);
		lcore_history->lcore = i;
		lcore_history->num_entries = num_entries;
	}
	g_trace_flags->lcore_history_offsets[SPDK_TRACE_MAX_LCORE] = lcore_offsets[SPDK_TRACE_MAX_LCORE];

	spdk_trace_flags_init();

	return 0;

trace_init_err:
	if (g_trace_histories != MAP_FAILED) {
		munmap(g_trace_histories, histories_size);
	}
	close(g_trace_fd);
	g_trace_fd = -1;
	shm_unlink(shm_name);
	g_trace_histories = NULL;

	return 1;

}

void
spdk_trace_cleanup(void)
{
	bool unlink = true;
	int i;
	struct spdk_trace_history *lcore_history;

	if (g_trace_histories == NULL) {
		return;
	}

	/*
	 * Only unlink the shm if there were no trace_entry recorded. This ensures the file
	 * can be used after this process exits/crashes for debugging.
	 * Note that we have to calculate this value before g_trace_histories gets unmapped.
	 */
	for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
		lcore_history = spdk_get_per_lcore_history(g_trace_histories, i);
		if (lcore_history == NULL) {
			continue;
		}
		unlink = lcore_history->entries[0].tsc == 0;
		if (!unlink) {
			break;
		}
	}

	munmap(g_trace_histories, sizeof(struct spdk_trace_histories));
	g_trace_histories = NULL;
	close(g_trace_fd);

	if (unlink) {
		shm_unlink(g_shm_name);
	}
}