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