xref: /spdk/lib/trace/trace.c (revision 588dfe314bb83d86effdf67ec42837b11c2620bf)
1 /*   SPDX-License-Identifier: BSD-3-Clause
2  *   Copyright (C) 2016 Intel Corporation.
3  *   All rights reserved.
4  */
5 
6 #include "spdk/stdinc.h"
7 
8 #include "spdk/env.h"
9 #include "spdk/string.h"
10 #include "spdk/trace.h"
11 #include "spdk/util.h"
12 #include "spdk/barrier.h"
13 #include "spdk/log.h"
14 #include "spdk/cpuset.h"
15 #include "spdk/likely.h"
16 
17 static int g_trace_fd = -1;
18 static char g_shm_name[64];
19 
20 struct spdk_trace_histories *g_trace_histories;
21 
22 static inline struct spdk_trace_entry *
23 get_trace_entry(struct spdk_trace_history *history, uint64_t offset)
24 {
25 	return &history->entries[offset & (history->num_entries - 1)];
26 }
27 
28 void
29 _spdk_trace_record(uint64_t tsc, uint16_t tpoint_id, uint16_t poller_id, uint32_t size,
30 		   uint64_t object_id, int num_args, ...)
31 {
32 	struct spdk_trace_history *lcore_history;
33 	struct spdk_trace_entry *next_entry;
34 	struct spdk_trace_entry_buffer *buffer;
35 	struct spdk_trace_tpoint *tpoint;
36 	struct spdk_trace_argument *argument;
37 	unsigned lcore, i, offset, num_entries, arglen, argoff, curlen;
38 	uint64_t intval;
39 	void *argval;
40 	va_list vl;
41 
42 	lcore = spdk_env_get_current_core();
43 	if (spdk_unlikely(lcore >= SPDK_TRACE_MAX_LCORE)) {
44 		return;
45 	}
46 
47 	lcore_history = spdk_get_per_lcore_history(g_trace_histories, lcore);
48 
49 	if (tsc == 0) {
50 		tsc = spdk_get_ticks();
51 	}
52 
53 	lcore_history->tpoint_count[tpoint_id]++;
54 
55 	tpoint = &g_trace_flags->tpoint[tpoint_id];
56 	/* Make sure that the number of arguments passed matches tracepoint definition */
57 	if (spdk_unlikely(tpoint->num_args != num_args)) {
58 		assert(0 && "Unexpected number of tracepoint arguments");
59 		return;
60 	}
61 
62 	/* Get next entry index in the circular buffer */
63 	next_entry = get_trace_entry(lcore_history, lcore_history->next_entry);
64 	next_entry->tsc = tsc;
65 	next_entry->tpoint_id = tpoint_id;
66 	next_entry->poller_id = poller_id;
67 	next_entry->size = size;
68 	next_entry->object_id = object_id;
69 
70 	num_entries = 1;
71 	buffer = (struct spdk_trace_entry_buffer *)next_entry;
72 	/* The initial offset needs to be adjusted by the fields present in the first entry
73 	 * (poller_id, size, etc.).
74 	 */
75 	offset = offsetof(struct spdk_trace_entry, args) -
76 		 offsetof(struct spdk_trace_entry_buffer, data);
77 
78 	va_start(vl, num_args);
79 	for (i = 0; i < tpoint->num_args; ++i) {
80 		argument = &tpoint->args[i];
81 		switch (argument->type) {
82 		case SPDK_TRACE_ARG_TYPE_STR:
83 			argval = va_arg(vl, void *);
84 			arglen = strnlen((const char *)argval, argument->size - 1) + 1;
85 			break;
86 		case SPDK_TRACE_ARG_TYPE_INT:
87 		case SPDK_TRACE_ARG_TYPE_PTR:
88 			if (argument->size == 8) {
89 				intval = va_arg(vl, uint64_t);
90 			} else {
91 				intval = va_arg(vl, uint32_t);
92 			}
93 			argval = &intval;
94 			arglen = argument->size;
95 			break;
96 		default:
97 			assert(0 && "Invalid trace argument type");
98 			return;
99 		}
100 
101 		/* Copy argument's data. For some argument types (strings) user is allowed to pass a
102 		 * value that is either larger or smaller than what's defined in the tracepoint's
103 		 * description. If the value is larger, we'll truncate it, while if it's smaller,
104 		 * we'll only fill portion of the buffer, without touching the rest. For instance,
105 		 * if the definition marks an argument as 40B and user passes 12B string, we'll only
106 		 * copy 13B (accounting for the NULL terminator).
107 		 */
108 		argoff = 0;
109 		while (argoff < argument->size) {
110 			/* Current buffer is full, we need to acquire another one */
111 			if (spdk_unlikely(offset == sizeof(buffer->data))) {
112 				buffer = (struct spdk_trace_entry_buffer *) get_trace_entry(
113 						 lcore_history,
114 						 lcore_history->next_entry + num_entries);
115 				buffer->tpoint_id = SPDK_TRACE_MAX_TPOINT_ID;
116 				buffer->tsc = tsc;
117 				num_entries++;
118 				offset = 0;
119 			}
120 
121 			curlen = spdk_min(sizeof(buffer->data) - offset, argument->size - argoff);
122 			if (spdk_likely(argoff < arglen)) {
123 				assert(argval != NULL);
124 				memcpy(&buffer->data[offset], (uint8_t *)argval + argoff,
125 				       spdk_min(curlen, arglen - argoff));
126 			}
127 
128 			offset += curlen;
129 			argoff += curlen;
130 		}
131 
132 		/* Make sure that truncated strings are NULL-terminated */
133 		if (spdk_unlikely(argument->type == SPDK_TRACE_ARG_TYPE_STR)) {
134 			assert(offset > 0);
135 			buffer->data[offset - 1] = '\0';
136 		}
137 	}
138 	va_end(vl);
139 
140 	/* Ensure all elements of the trace entry are visible to outside trace tools */
141 	spdk_smp_wmb();
142 	lcore_history->next_entry += num_entries;
143 }
144 
145 int
146 spdk_trace_init(const char *shm_name, uint64_t num_entries)
147 {
148 	uint32_t i = 0;
149 	int histories_size;
150 	uint64_t lcore_offsets[SPDK_TRACE_MAX_LCORE + 1] = { 0 };
151 	struct spdk_cpuset cpuset = {};
152 
153 	/* 0 entries requested - skip trace initialization */
154 	if (num_entries == 0) {
155 		return 0;
156 	}
157 
158 	spdk_cpuset_zero(&cpuset);
159 	histories_size = sizeof(struct spdk_trace_flags);
160 	SPDK_ENV_FOREACH_CORE(i) {
161 		spdk_cpuset_set_cpu(&cpuset, i, true);
162 		lcore_offsets[i] = histories_size;
163 		histories_size += spdk_get_trace_history_size(num_entries);
164 	}
165 	lcore_offsets[SPDK_TRACE_MAX_LCORE] = histories_size;
166 
167 	snprintf(g_shm_name, sizeof(g_shm_name), "%s", shm_name);
168 
169 	g_trace_fd = shm_open(shm_name, O_RDWR | O_CREAT, 0600);
170 	if (g_trace_fd == -1) {
171 		SPDK_ERRLOG("could not shm_open spdk_trace\n");
172 		SPDK_ERRLOG("errno=%d %s\n", errno, spdk_strerror(errno));
173 		return 1;
174 	}
175 
176 	if (ftruncate(g_trace_fd, histories_size) != 0) {
177 		SPDK_ERRLOG("could not truncate shm\n");
178 		goto trace_init_err;
179 	}
180 
181 	g_trace_histories = mmap(NULL, histories_size, PROT_READ | PROT_WRITE,
182 				 MAP_SHARED, g_trace_fd, 0);
183 	if (g_trace_histories == MAP_FAILED) {
184 		SPDK_ERRLOG("could not mmap shm\n");
185 		goto trace_init_err;
186 	}
187 
188 	/* TODO: On FreeBSD, mlock on shm_open'd memory doesn't seem to work.  Docs say that kern.ipc.shm_use_phys=1
189 	 * should allow it, but forcing that doesn't seem to work either.  So for now just skip mlock on FreeBSD
190 	 * altogether.
191 	 */
192 #if defined(__linux__)
193 	if (mlock(g_trace_histories, histories_size) != 0) {
194 		SPDK_ERRLOG("Could not mlock shm for tracing - %s.\n", spdk_strerror(errno));
195 		if (errno == ENOMEM) {
196 			SPDK_ERRLOG("Check /dev/shm for old tracing files that can be deleted.\n");
197 		}
198 		goto trace_init_err;
199 	}
200 #endif
201 
202 	memset(g_trace_histories, 0, histories_size);
203 
204 	g_trace_flags = &g_trace_histories->flags;
205 
206 	g_trace_flags->tsc_rate = spdk_get_ticks_hz();
207 
208 	for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
209 		struct spdk_trace_history *lcore_history;
210 
211 		g_trace_flags->lcore_history_offsets[i] = lcore_offsets[i];
212 		if (lcore_offsets[i] == 0) {
213 			continue;
214 		}
215 		assert(spdk_cpuset_get_cpu(&cpuset, i));
216 		lcore_history = spdk_get_per_lcore_history(g_trace_histories, i);
217 		lcore_history->lcore = i;
218 		lcore_history->num_entries = num_entries;
219 	}
220 	g_trace_flags->lcore_history_offsets[SPDK_TRACE_MAX_LCORE] = lcore_offsets[SPDK_TRACE_MAX_LCORE];
221 
222 	spdk_trace_flags_init();
223 
224 	return 0;
225 
226 trace_init_err:
227 	if (g_trace_histories != MAP_FAILED) {
228 		munmap(g_trace_histories, histories_size);
229 	}
230 	close(g_trace_fd);
231 	g_trace_fd = -1;
232 	shm_unlink(shm_name);
233 	g_trace_histories = NULL;
234 
235 	return 1;
236 
237 }
238 
239 void
240 spdk_trace_cleanup(void)
241 {
242 	bool unlink = true;
243 	int i;
244 	struct spdk_trace_history *lcore_history;
245 
246 	if (g_trace_histories == NULL) {
247 		return;
248 	}
249 
250 	/*
251 	 * Only unlink the shm if there were no trace_entry recorded. This ensures the file
252 	 * can be used after this process exits/crashes for debugging.
253 	 * Note that we have to calculate this value before g_trace_histories gets unmapped.
254 	 */
255 	for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
256 		lcore_history = spdk_get_per_lcore_history(g_trace_histories, i);
257 		if (lcore_history == NULL) {
258 			continue;
259 		}
260 		unlink = lcore_history->entries[0].tsc == 0;
261 		if (!unlink) {
262 			break;
263 		}
264 	}
265 
266 	munmap(g_trace_histories, sizeof(struct spdk_trace_histories));
267 	g_trace_histories = NULL;
268 	close(g_trace_fd);
269 
270 	if (unlink) {
271 		shm_unlink(g_shm_name);
272 	}
273 }
274