d/numam-spdk
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

lib/trace: add trace_record tool

Browse Source 
trace_record is used to poll the spdk trace shm file
and store new entries from it to another specified trace file.
This could help retain the trace_entires from the overlay of
trace circular buffer

Note:
* trace_record reads the input tracefile into a process-local
memory and writes trace entries to the output file only at shutdown.
* trace_record can be shut down on SIGINT or SIGTERM signal.

A usage sample is:
./spdk_trace_record -s bdev_svc -p <spdk app pid> -f trace.tmp -q

Change-Id: If073a05022ec9c1b45923c38ba407a873be8741b
Signed-off-by: Liu Xiaodong <xiaodong.liu@intel.com>
Reviewed-on: https://review.gerrithub.io/c/433385
Tested-by: SPDK CI Jenkins <sys_sgci@intel.com>
Reviewed-by: Jim Harris <james.r.harris@intel.com>
Reviewed-by: Shuhei Matsumoto <shuhei.matsumoto.xt@hitachi.com>
Reviewed-by: Changpeng Liu <changpeng.liu@intel.com>
This commit is contained in:
Liu Xiaodong 2018-11-14 22:01:51 -05:00 committed by Changpeng Liu
parent abc156458f
commit a206234d09
10 changed files with 919 additions and 8 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
app/Makefile
View File

@ -35,6 +35,7 @@ SPDK_ROOT_DIR := $(abspath $(CURDIR)/..)
include $(SPDK_ROOT_DIR)/mk/spdk.common.mk
DIRS-y += trace
DIRS-y += trace_record
DIRS-y += nvmf_tgt
DIRS-y += iscsi_top
DIRS-y += iscsi_tgt

1
app/trace_record/.gitignore vendored Normal file
View File

@ -0,0 +1 @@
spdk_trace_record

43
app/trace_record/Makefile Normal file
View File

@ -0,0 +1,43 @@
#
# 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.
#
SPDK_ROOT_DIR := $(abspath $(CURDIR)/../..)
include $(SPDK_ROOT_DIR)/mk/spdk.common.mk
SPDK_LIB_LIST = util log
APP = spdk_trace_record
C_SRCS := trace_record.c
include $(SPDK_ROOT_DIR)/mk/spdk.app.mk

704
app/trace_record/trace_record.c Normal file
View File

@ -0,0 +1,704 @@
/*-
* 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/string.h"
#include "spdk/trace.h"
#include "spdk/util.h"
#include "spdk/barrier.h"
#define TRACE_FILE_COPY_SIZE (32 * 1024)
#define TRACE_PATH_MAX 2048
static char *g_exe_name;
static int g_verbose = 1;
static uint64_t g_tsc_rate;
static uint64_t g_utsc_rate;
static bool g_shutdown = false;
static uint64_t g_histories_size;
struct lcore_trace_record_ctx {
char lcore_file[TRACE_PATH_MAX];
int fd;
struct spdk_trace_history *in_history;
struct spdk_trace_history *out_history;
/* Recorded next entry index in record */
uint64_t rec_next_entry;
/* Record tsc for report */
uint64_t first_entry_tsc;
uint64_t last_entry_tsc;
/* Total number of entries in lcore trace file */
uint64_t num_entries;
};
struct aggr_trace_record_ctx {
const char *out_file;
int out_fd;
int shm_fd;
struct lcore_trace_record_ctx lcore_ports[SPDK_TRACE_MAX_LCORE];
struct spdk_trace_histories *trace_histories;
};
static int
input_trace_file_mmap(struct aggr_trace_record_ctx *ctx, const char *shm_name)
{
void *history_ptr;
int i;
ctx->shm_fd = shm_open(shm_name, O_RDONLY, 0);
if (ctx->shm_fd < 0) {
fprintf(stderr, "Could not open %s.\n", shm_name);
return -1;
}
/* Map the header of trace file */
history_ptr = mmap(NULL, sizeof(struct spdk_trace_histories), PROT_READ, MAP_SHARED, ctx->shm_fd,
0);
if (history_ptr == MAP_FAILED) {
fprintf(stderr, "Could not mmap shm %s.\n", shm_name);
close(ctx->shm_fd);
return -1;
}
ctx->trace_histories = (struct spdk_trace_histories *)history_ptr;
g_tsc_rate = ctx->trace_histories->flags.tsc_rate;
g_utsc_rate = g_tsc_rate / 1000;
if (g_tsc_rate == 0) {
fprintf(stderr, "Invalid tsc_rate %ju\n", g_tsc_rate);
munmap(history_ptr, sizeof(struct spdk_trace_histories));
close(ctx->shm_fd);
return -1;
}
if (g_verbose) {
printf("TSC Rate: %ju\n", g_tsc_rate);
}
/* Remap the entire trace file */
g_histories_size = spdk_get_trace_histories_size(ctx->trace_histories);
munmap(history_ptr, sizeof(struct spdk_trace_histories));
history_ptr = mmap(NULL, g_histories_size, PROT_READ, MAP_SHARED, ctx->shm_fd, 0);
if (history_ptr == MAP_FAILED) {
fprintf(stderr, "Could not remmap shm %s.\n", shm_name);
close(ctx->shm_fd);
return -1;
}
ctx->trace_histories = (struct spdk_trace_histories *)history_ptr;
for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
ctx->lcore_ports[i].in_history = spdk_get_per_lcore_history(ctx->trace_histories, i);
if (g_verbose) {
printf("Number of trace entries for lcore (%d): %ju\n", i,
ctx->lcore_ports[i].in_history->num_entries);
}
}
return 0;
}
static int
output_trace_files_prepare(struct aggr_trace_record_ctx *ctx, const char *aggr_path)
{
int flags = O_CREAT | O_EXCL | O_RDWR;
struct lcore_trace_record_ctx *port_ctx;
int name_len;
int i, rc;
/* Assign file names for related trace files */
ctx->out_file = aggr_path;
for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
port_ctx = &ctx->lcore_ports[i];
/* Get the length of trace file name for each lcore with format "%s-%d" */
name_len = snprintf(port_ctx->lcore_file, TRACE_PATH_MAX, "%s-%d", ctx->out_file, i);
if (name_len >= TRACE_PATH_MAX) {
fprintf(stderr, "Length of file path (%s) exceeds limitation for lcore file.\n",
aggr_path);
goto err;
}
}
/* If output trace file already exists, try to unlink it together with its temporary files */
if (access(ctx->out_file, F_OK) == 0) {
rc = unlink(ctx->out_file);
if (rc) {
goto err;
}
for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
port_ctx = &ctx->lcore_ports[i];
if (access(port_ctx->lcore_file, F_OK) == 0) {
rc = unlink(port_ctx->lcore_file);
if (rc) {
goto err;
}
}
}
}
for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
port_ctx = &ctx->lcore_ports[i];
port_ctx->fd = open(port_ctx->lcore_file, flags, 0600);
if (port_ctx->fd < 0) {
fprintf(stderr, "Could not open lcore file %s.\n", port_ctx->lcore_file);
goto err;
}
if (g_verbose) {
printf("Create tmp lcore trace file %s for lcore %d\n", port_ctx->lcore_file, i);
}
port_ctx->out_history = calloc(1, sizeof(struct spdk_trace_history));
if (port_ctx->out_history == NULL) {
fprintf(stderr, "Failed to allocate memory for out_history.\n");
goto err;
}
}
return 0;
err:
for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
port_ctx = &ctx->lcore_ports[i];
free(port_ctx->out_history);
if (port_ctx->fd > 0) {
close(port_ctx->fd);
}
}
return -1;
}
static void
output_trace_files_finish(struct aggr_trace_record_ctx *ctx)
{
struct lcore_trace_record_ctx *port_ctx;
int i;
for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
port_ctx = &ctx->lcore_ports[i];
free(port_ctx->out_history);
close(port_ctx->fd);
unlink(port_ctx->lcore_file);
if (g_verbose) {
printf("Remove tmp lcore trace file %s for lcore %d\n", port_ctx->lcore_file, i);
}
}
}
static int
cont_write(int fildes, const void *buf, size_t nbyte)
{
int rc;
int _nbyte = nbyte;
while (_nbyte) {
rc = write(fildes, buf, _nbyte);
if (rc < 0) {
if (errno != EINTR) {
return -1;
}
continue;
}
_nbyte -= rc;
}
return nbyte;
}
static int
cont_read(int fildes, void *buf, size_t nbyte)
{
int rc;
int _nbyte = nbyte;
while (_nbyte) {
rc = read(fildes, buf, _nbyte);
if (rc == 0) {
return nbyte - _nbyte;
} else if (rc < 0) {
if (errno != EINTR) {
return -1;
}
continue;
}
_nbyte -= rc;
}
return nbyte;
}
static int
lcore_trace_last_entry_idx(struct spdk_trace_history *in_history, int cir_next_idx)
{
int last_idx;
if (cir_next_idx == 0) {
last_idx = in_history->num_entries - 1;
} else {
last_idx = cir_next_idx - 1;
}
return last_idx;
}
static int
circular_buffer_padding_backward(int fd, struct spdk_trace_history *in_history,
int cir_start, int cir_end)
{
int rc;
if (cir_end <= cir_start) {
fprintf(stderr, "Wrong using of circular_buffer_padding_back\n");
return -1;
}
rc = cont_write(fd, &in_history->entries[cir_start],
sizeof(struct spdk_trace_entry) * (cir_end - cir_start));
if (rc < 0) {
fprintf(stderr, "Failed to append entries into lcore file\n");
return rc;
}
return 0;
}
static int
circular_buffer_padding_across(int fd, struct spdk_trace_history *in_history,
int cir_start, int cir_end)
{
int rc;
int num_entries = in_history->num_entries;
if (cir_end > cir_start) {
fprintf(stderr, "Wrong using of circular_buffer_padding_across\n");
return -1;
}
rc = cont_write(fd, &in_history->entries[cir_start],
sizeof(struct spdk_trace_entry) * (num_entries - cir_start));
if (rc < 0) {
fprintf(stderr, "Failed to append entries into lcore file backward\n");
return rc;
}
if (cir_end == 0) {
return 0;
}
rc = cont_write(fd, &in_history->entries[0], sizeof(struct spdk_trace_entry) * cir_end);
if (rc < 0) {
fprintf(stderr, "Failed to append entries into lcore file forward\n");
return rc;
}
return 0;
}
static int
circular_buffer_padding_all(int fd, struct spdk_trace_history *in_history,
int cir_end)
{
return circular_buffer_padding_across(fd, in_history, cir_end, cir_end);
}
static int
lcore_trace_record(struct lcore_trace_record_ctx *lcore_port)
{
struct spdk_trace_history *in_history = lcore_port->in_history;
uint64_t rec_next_entry = lcore_port->rec_next_entry;
uint64_t rec_num_entries = lcore_port->num_entries;
int fd = lcore_port->fd;
uint64_t shm_next_entry;
uint64_t num_cir_entries;
uint64_t shm_cir_next;
uint64_t rec_cir_next;
int rc;
int last_idx;
shm_next_entry = in_history->next_entry;
/* Ensure all entries of spdk_trace_history are latest to next_entry */
spdk_smp_rmb();
if (shm_next_entry == rec_next_entry) {
/* There is no update */
return 0;
} else if (shm_next_entry < rec_next_entry) {
/* Error branch */
fprintf(stderr, "Trace porting error in lcore %d, trace rollback occurs.\n", in_history->lcore);
fprintf(stderr, "shm_next_entry is %ju, record_next_entry is %ju.\n", shm_next_entry,
rec_next_entry);
return -1;
}
num_cir_entries = in_history->num_entries;
shm_cir_next = shm_next_entry & (num_cir_entries - 1);
/* Record first entry's tsc and corresponding entries when recording first time. */
if (lcore_port->first_entry_tsc == 0) {
if (shm_next_entry < num_cir_entries) {
/* Updates haven't been across circular buffer yet.
* The first entry in shared memory is the eldest one.
*/
lcore_port->first_entry_tsc = in_history->entries[0].tsc;
lcore_port->num_entries += shm_cir_next;
rc = circular_buffer_padding_backward(fd, in_history, 0, shm_cir_next);
} else {
/* Updates have already been across circular buffer.
* The eldest entry in shared memory is pointed by shm_cir_next.
*/
lcore_port->first_entry_tsc = in_history->entries[shm_cir_next].tsc;
lcore_port->num_entries += num_cir_entries;
rc = circular_buffer_padding_all(fd, in_history, shm_cir_next);
}
goto out;
}
if (shm_next_entry - rec_next_entry > num_cir_entries) {
/* There must be missed updates */
fprintf(stderr, "Trace-record missed %ju trace entries\n",
shm_next_entry - rec_next_entry - num_cir_entries);
lcore_port->num_entries += num_cir_entries;
rc = circular_buffer_padding_all(fd, in_history, shm_cir_next);
} else if (shm_next_entry - rec_next_entry == num_cir_entries) {
/* All circular buffer is updated */
lcore_port->num_entries += num_cir_entries;
rc = circular_buffer_padding_all(fd, in_history, shm_cir_next);
} else {
/* Part of circular buffer is updated */
rec_cir_next = rec_next_entry & (num_cir_entries - 1);
if (shm_cir_next > rec_cir_next) {
/* Updates are not across circular buffer */
lcore_port->num_entries += shm_cir_next - rec_cir_next;
rc = circular_buffer_padding_backward(fd, in_history, rec_cir_next, shm_cir_next);
} else {
/* Updates are across circular buffer */
lcore_port->num_entries += num_cir_entries - rec_cir_next + shm_cir_next;
rc = circular_buffer_padding_across(fd, in_history, rec_cir_next, shm_cir_next);
}
}
out:
if (rc) {
return rc;
}
if (g_verbose) {
printf("Append %ju trace_entry for lcore %d\n", lcore_port->num_entries - rec_num_entries,
in_history->lcore);
}
/* Update tpoint_count info */
memcpy(lcore_port->out_history, lcore_port->in_history, sizeof(struct spdk_trace_history));
/* Update last_entry_tsc to align with appended entries */
last_idx = lcore_trace_last_entry_idx(in_history, shm_cir_next);
lcore_port->last_entry_tsc = in_history->entries[last_idx].tsc;
lcore_port->rec_next_entry = shm_next_entry;
return rc;
}
static int
trace_files_aggregate(struct aggr_trace_record_ctx *ctx)
{
int flags = O_CREAT | O_EXCL | O_RDWR;
struct lcore_trace_record_ctx *lcore_port;
char copy_buff[TRACE_FILE_COPY_SIZE];
uint64_t lcore_offsets[SPDK_TRACE_MAX_LCORE + 1];
int rc, i;
ssize_t len = 0;
uint64_t len_sum;
ctx->out_fd = open(ctx->out_file, flags, 0600);
if (ctx->out_fd < 0) {
fprintf(stderr, "Could not open aggregation file %s.\n", ctx->out_file);
return -1;
}
if (g_verbose) {
printf("Create trace file %s for output\n", ctx->out_file);
}
/* Write flags of histories into head of converged trace file, except num_entriess */
rc = cont_write(ctx->out_fd, ctx->trace_histories,
sizeof(struct spdk_trace_histories) - sizeof(lcore_offsets));
if (rc < 0) {
fprintf(stderr, "Failed to write trace header into trace file\n");
goto out;
}
/* Update and append lcore offsets converged trace file */
lcore_offsets[0] = sizeof(struct spdk_trace_flags);
for (i = 1; i < (int)SPDK_COUNTOF(lcore_offsets); i++) {
lcore_offsets[i] = spdk_get_trace_history_size(ctx->lcore_ports[i - 1].num_entries) +
lcore_offsets[i - 1];
}
rc = cont_write(ctx->out_fd, lcore_offsets, sizeof(lcore_offsets));
if (rc < 0) {
fprintf(stderr, "Failed to write lcore offsets into trace file\n");
goto out;
}
/* Append each lcore trace file into converged trace file */
for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
lcore_port = &ctx->lcore_ports[i];
lcore_port->out_history->num_entries = lcore_port->num_entries;
rc = cont_write(ctx->out_fd, lcore_port->out_history, sizeof(struct spdk_trace_history));
if (rc < 0) {
fprintf(stderr, "Failed to write lcore trace header into trace file\n");
goto out;
}
/* Move file offset to the start of trace_entries */
rc = lseek(lcore_port->fd, 0, SEEK_SET);
if (rc != 0) {
fprintf(stderr, "Failed to lseek lcore trace file\n");
goto out;
}
len_sum = 0;
while ((len = cont_read(lcore_port->fd, copy_buff, TRACE_FILE_COPY_SIZE)) > 0) {
len_sum += len;
rc = cont_write(ctx->out_fd, copy_buff, len);
if (rc != len) {
fprintf(stderr, "Failed to write lcore trace entries into trace file\n");
goto out;
}
}
if (len_sum != lcore_port->num_entries * sizeof(struct spdk_trace_entry)) {
fprintf(stderr, "Len of lcore trace file doesn't match number of entries for lcore\n");
}
}
printf("All lcores trace entries are aggregated into trace file %s\n", ctx->out_file);
out:
close(ctx->out_fd);
return rc;
}
static void
__shutdown_signal(int signo)
{
g_shutdown = true;
}
static int
setup_exit_signal_handler(void)
{
struct sigaction sigact;
int rc;
memset(&sigact, 0, sizeof(sigact));
sigemptyset(&sigact.sa_mask);
/* Install the same handler for SIGINT and SIGTERM */
sigact.sa_handler = __shutdown_signal;
rc = sigaction(SIGINT, &sigact, NULL);
if (rc < 0) {
fprintf(stderr, "sigaction(SIGINT) failed\n");
return rc;
}
rc = sigaction(SIGTERM, &sigact, NULL);
if (rc < 0) {
fprintf(stderr, "sigaction(SIGTERM) failed\n");
}
return rc;
}
static void usage(void)
{
printf("\n%s is used to record all SPDK generated trace entries\n", g_exe_name);
printf("from SPDK trace shared-memory to specified file.\n\n");
printf("usage:\n");
printf(" %s <option>\n", g_exe_name);
printf(" option = '-q' to disable verbose mode\n");
printf(" '-s' to specify spdk_trace shm name for a\n");
printf(" currently running process\n");
printf(" '-i' to specify the shared memory ID\n");
printf(" '-p' to specify the trace PID\n");
printf(" (one of -i or -p must be specified)\n");
printf(" '-f' to specify output trace file name\n");
printf(" '-h' to print usage information\n");
}
int main(int argc, char **argv)
{
const char *app_name = NULL;
const char *file_name = NULL;
int op;
char shm_name[64];
int shm_id = -1, shm_pid = -1;
int rc = 0;
int i;
struct aggr_trace_record_ctx ctx = {};
struct lcore_trace_record_ctx *lcore_port;
g_exe_name = argv[0];
while ((op = getopt(argc, argv, "f:i:p:qs:h")) != -1) {
switch (op) {
case 'i':
shm_id = spdk_strtol(optarg, 10);
break;
case 'p':
shm_pid = spdk_strtol(optarg, 10);
break;
case 'q':
g_verbose = 0;
break;
case 's':
app_name = optarg;
break;
case 'f':
file_name = optarg;
break;
case 'h':
default:
usage();
exit(1);
}
}
if (file_name == NULL) {
fprintf(stderr, "-f must be specified\n");
usage();
exit(1);
}
if (app_name == NULL) {
fprintf(stderr, "-s must be specified\n");
usage();
exit(1);
}
if (shm_id == -1 && shm_pid == -1) {
fprintf(stderr, "-i or -p must be specified\n");
usage();
exit(1);
}
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);
}
rc = setup_exit_signal_handler();
if (rc) {
exit(1);
}
rc = input_trace_file_mmap(&ctx, shm_name);
if (rc) {
exit(1);
}
rc = output_trace_files_prepare(&ctx, file_name);
if (rc) {
exit(1);
}
printf("Start to poll trace shm file %s\n", shm_name);
while (!g_shutdown && rc == 0) {
for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
lcore_port = &ctx.lcore_ports[i];
rc = lcore_trace_record(lcore_port);
if (rc) {
break;
}
}
}
if (rc) {
exit(1);
}
printf("Start to aggregate lcore trace files\n");
rc = trace_files_aggregate(&ctx);
if (rc) {
exit(1);
}
/* Summary report */
printf("TSC Rate: %ju\n", g_tsc_rate);
for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
lcore_port = &ctx.lcore_ports[i];
if (lcore_port->num_entries == 0) {
continue;
}
printf("Port %ju trace entries for lcore (%d) in %ju usec\n",
lcore_port->num_entries, i,
(lcore_port->last_entry_tsc - lcore_port->first_entry_tsc) / g_utsc_rate);
}
munmap(ctx.trace_histories, g_histories_size);
close(ctx.shm_fd);
output_trace_files_finish(&ctx);
return 0;
}

26
doc/nvmf_tracing.md
View File

@ -124,6 +124,32 @@ the same I/O.
28: 6033.056 ( 12669500) RDMA_REQ_COMPLETED id: r3564 time: 100.211
~~~
# Capturing sufficient trace events {#capture_trace_events}
Since the tracepoint file generated directly by SPDK application is a circular buffer in shared memory,
the trace events captured by it may be insufficient for further analysis.
The spdk_trace_record program can be found in the app/trace_record directory.
spdk_trace_record is used to poll the spdk tracepoint shared memory, record new entries from it,
and store all entries into specified output file at its shutdown on SIGINT or SIGTERM.
After SPDK nvmf target is launched, simply execute the command line shown in the log:
~~~{.sh}
app/trace_record/spdk_trace_record -q -s nvmf -p 24147 -f /tmp/spdk_nvmf_record.trace
~~~
Also send I/Os to the SPDK target application to generate events by previous perf example for 10 minutes.
~~~{.sh}
./perf -q 128 -s 4096 -w randread -t 600 -r 'trtype:RDMA adrfam:IPv4 traddr:192.168.100.2 trsvcid:4420'
~~~
After the completion of perf exmaple, shut down spdk_trace_record by signal SIGINT (Ctrl + C).
To analyze the tracepoints output file from spdk_trace_record, simply run spdk_trace program by:
~~~{.sh}
app/trace/spdk_trace -f /tmp/spdk_nvmf_record.trace
~~~
# Adding New Tracepoints {#add_tracepoints}
SPDK applications and libraries provide several trace points. You can add new

4
include/spdk/trace.h
View File

@ -102,8 +102,8 @@ struct spdk_trace_history {
*/
uint64_t tpoint_count[SPDK_TRACE_MAX_TPOINT_ID];
/** Index to next spdk_trace_entry to fill in the circular buffer. */
uint32_t next_entry;
/** Index to next spdk_trace_entry to fill. */
uint64_t next_entry;
/**
* Circular buffer of spdk_trace_entry structures for tracing

9
lib/event/app.c
View File

@ -763,7 +763,7 @@ usage(void (*app_usage)(void))
printf(" -W, --pci-whitelist <bdf>\n");
printf(" pci addr to whitelist (-B and -W cannot be used at the same time)\n");
printf(" --huge-dir <path> use a specific hugetlbfs mount to reserve memory from\n");
printf(" --num-trace-entries <num> number of trace entries for each core (default %d)\n",
printf(" --num-trace-entries <num> number of trace entries for each core, must be power of 2. (default %d)\n",
SPDK_APP_DEFAULT_NUM_TRACE_ENTRIES);
spdk_log_usage(stdout, "-L");
spdk_trace_mask_usage(stdout, "-e");
@ -976,11 +976,16 @@ spdk_app_parse_args(int argc, char **argv, struct spdk_app_opts *opts,
case NUM_TRACE_ENTRIES_OPT_IDX:
tmp = spdk_strtoll(optarg, 0);
if (tmp <= 0) {
fprintf(stderr, "Invalid num_entries %s\n", optarg);
fprintf(stderr, "Invalid num-trace-entries %s\n", optarg);
usage(app_usage);
goto out;
}
opts->num_entries = (uint64_t)tmp;
if (opts->num_entries & (opts->num_entries - 1)) {
fprintf(stderr, "num-trace-entries must be power of 2\n");
usage(app_usage);
goto out;
}
break;
case MAX_REACTOR_DELAY_OPT_IDX:
tmp = spdk_strtol(optarg, 10);

11
lib/trace/trace.c
View File

@ -37,6 +37,7 @@
#include "spdk/string.h"
#include "spdk/trace.h"
#include "spdk/util.h"
#include "spdk/barrier.h"
static int g_trace_fd = -1;
static char g_shm_name[64];
@ -50,6 +51,7 @@ _spdk_trace_record(uint64_t tsc, uint16_t tpoint_id, uint16_t poller_id, uint32_
struct spdk_trace_history *lcore_history;
struct spdk_trace_entry *next_entry;
unsigned lcore;
uint64_t next_circular_entry;
lcore = spdk_env_get_current_core();
if (lcore >= SPDK_TRACE_MAX_LCORE) {
@ -63,7 +65,9 @@ _spdk_trace_record(uint64_t tsc, uint16_t tpoint_id, uint16_t poller_id, uint32_
lcore_history->tpoint_count[tpoint_id]++;
next_entry = &lcore_history->entries[lcore_history->next_entry];
/* Get next entry index in the circular buffer */
next_circular_entry = lcore_history->next_entry & (lcore_history->num_entries - 1);
next_entry = &lcore_history->entries[next_circular_entry];
next_entry->tsc = tsc;
next_entry->tpoint_id = tpoint_id;
next_entry->poller_id = poller_id;
@ -71,10 +75,9 @@ _spdk_trace_record(uint64_t tsc, uint16_t tpoint_id, uint16_t poller_id, uint32_
next_entry->object_id = object_id;
next_entry->arg1 = arg1;
/* Ensure all elements of the trace entry are visible to outside trace tools */
spdk_smp_wmb();
lcore_history->next_entry++;
if (lcore_history->next_entry == lcore_history->num_entries) {
lcore_history->next_entry = 0;
}
}
int

1
test/iscsi_tgt/iscsi_tgt.sh
View File

@ -33,6 +33,7 @@ run_test suite ./test/iscsi_tgt/lvol/iscsi_lvol.sh
run_test suite ./test/iscsi_tgt/fio/fio.sh
run_test suite ./test/iscsi_tgt/qos/qos.sh
run_test suite ./test/iscsi_tgt/ip_migration/ip_migration.sh
run_test suite ./test/iscsi_tgt/trace_record/trace_record.sh
if [ $RUN_NIGHTLY -eq 1 ]; then
if [ $SPDK_TEST_PMDK -eq 1 ]; then

127
test/iscsi_tgt/trace_record/trace_record.sh Executable file
View File

@ -0,0 +1,127 @@
#!/usr/bin/env bash
testdir=$(readlink -f $(dirname $0))
rootdir=$(readlink -f $testdir/../../..)
source $rootdir/test/common/autotest_common.sh
source $rootdir/test/iscsi_tgt/common.sh
TRACE_TMP_FOLDER=./tmp-trace
TRACE_RECORD_OUTPUT=${TRACE_TMP_FOLDER}/record.trace
TRACE_RECORD_NOTICE_LOG=${TRACE_TMP_FOLDER}/record.notice
TRACE_TOOL_LOG=${TRACE_TMP_FOLDER}/trace.log
delete_tmp_files() {
rm -rf $TRACE_TMP_FOLDER
}
if [ -z "$TARGET_IP" ]; then
echo "TARGET_IP not defined in environment"
exit 1
fi
if [ -z "$INITIATOR_IP" ]; then
echo "INITIATOR_IP not defined in environment"
exit 1
fi
timing_enter trace_record
NUM_TRACE_ENTRIES=4096
MALLOC_BDEV_SIZE=64
MALLOC_BLOCK_SIZE=4096
rpc_py="$rootdir/scripts/rpc.py"
fio_py="$rootdir/scripts/fio.py"
timing_enter start_iscsi_tgt
echo "start iscsi_tgt with trace enabled"
$ISCSI_APP -m 0xf --num-trace-entries $NUM_TRACE_ENTRIES --tpoint-group-mask 0xf &
iscsi_pid=$!
echo "Process pid: $iscsi_pid"
trap "killprocess $iscsi_pid; exit 1" SIGINT SIGTERM EXIT
waitforlisten $iscsi_pid
echo "iscsi_tgt is listening. Running tests..."
timing_exit start_iscsi_tgt
$rpc_py add_portal_group $PORTAL_TAG $TARGET_IP:$ISCSI_PORT
$rpc_py add_initiator_group $INITIATOR_TAG $INITIATOR_NAME $NETMASK
echo "Create bdevs and target nodes"
CONNECTION_NUMBER=15
for i in $(seq 0 $CONNECTION_NUMBER); do
malloc_bdev="$($rpc_py construct_malloc_bdev $MALLOC_BDEV_SIZE $MALLOC_BLOCK_SIZE)"
$rpc_py construct_target_node Target$i Target${i}_alias "${malloc_bdev}:0" $PORTAL_TAG:$INITIATOR_TAG 256 -d
done
sleep 1
iscsiadm -m discovery -t sendtargets -p $TARGET_IP:$ISCSI_PORT
iscsiadm -m node --login -p $TARGET_IP:$ISCSI_PORT
mkdir -p ${TRACE_TMP_FOLDER}
./app/trace_record/spdk_trace_record -s iscsi -p ${iscsi_pid} -f ${TRACE_RECORD_OUTPUT} -q 1>${TRACE_RECORD_NOTICE_LOG} &
record_pid=$!
echo "Trace record pid: $record_pid"
trap "iscsicleanup; killprocess $iscsi_pid; killprocess $record_pid; delete_tmp_files; exit 1" SIGINT SIGTERM EXIT
echo "Running FIO"
$fio_py 131072 32 randrw 1
iscsicleanup
# Delete Malloc blockdevs and targets
for i in $(seq 0 $CONNECTION_NUMBER); do
$rpc_py delete_target_node iqn.2016-06.io.spdk:Target${i}
$rpc_py delete_malloc_bdev Malloc${i}
done
trap "delete_tmp_files; exit 1" SIGINT SIGTERM EXIT
killprocess $iscsi_pid
killprocess $record_pid
./app/trace/spdk_trace -f ${TRACE_RECORD_OUTPUT} > ${TRACE_TOOL_LOG}
#verify trace record and trace tool
#trace entries str in trace-record, like "Trace Size of lcore (0): 4136"
record_num="$(grep "trace entries for lcore" ${TRACE_RECORD_NOTICE_LOG} | cut -d ' ' -f 2)"
#trace entries str in trace-tool, like "Port 4096 trace entries for lcore (0) in 441871 msec"
trace_tool_num="$(grep "Trace Size of lcore" ${TRACE_TOOL_LOG} | cut -d ' ' -f 6)"
delete_tmp_files
echo "entries numbers from trace record are:" $record_num
echo "entries numbers from trace tool are:" $trace_tool_num
arr_record_num=($record_num)
arr_trace_tool_num=($trace_tool_num)
len_arr_record_num=${#arr_record_num[@]}
len_arr_trace_tool_num=${#arr_trace_tool_num[@]}
#lcore num check
if [ $len_arr_record_num -ne $len_arr_trace_tool_num ]; then
echo "trace record test on iscsi: failure on lcore number check"
set -e
exit 1
fi
#trace entries num check
for i in $(seq 0 $((len_arr_record_num - 1))); do
if [ ${arr_record_num[$i]} -le ${NUM_TRACE_ENTRIES} ]; then
echo "trace record test on iscsi: failure on inefficient entries number check"
set -e
exit 1
fi
if [ ${arr_record_num[$i]} -ne ${arr_trace_tool_num[$i]} ]; then
echo "trace record test on iscsi: failure on entries number check"
set -e
exit 1
fi
done
trap - SIGINT SIGTERM EXIT
timing_exit trace_record