xref: /spdk/lib/trace/trace.c (revision 21d0c3ad63007d3539fd55907f89fc96b92f69ca)
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 "spdk/bit_array.h"
17 #include "trace_internal.h"
18 
19 static int g_trace_fd = -1;
20 static char g_shm_name[64];
21 
22 static __thread uint32_t t_ut_array_index;
23 static __thread struct spdk_trace_history *t_ut_lcore_history;
24 
25 static uint32_t g_user_thread_index_start;
26 struct spdk_trace_file *g_trace_file;
27 static struct spdk_bit_array *g_ut_array;
28 static pthread_mutex_t g_ut_array_mutex;
29 
30 #define TRACE_NUM_OWNERS (16 * 1024)
31 #define TRACE_OWNER_DESCRIPTION_SIZE (119)
32 SPDK_STATIC_ASSERT(sizeof(struct spdk_trace_owner) == 9, "incorrect size");
33 SPDK_STATIC_ASSERT(sizeof(struct spdk_trace_owner) + TRACE_OWNER_DESCRIPTION_SIZE == 128,
34 		   "incorrect size");
35 
36 static inline struct spdk_trace_entry *
37 get_trace_entry(struct spdk_trace_history *history, uint64_t offset)
38 {
39 	return &history->entries[offset & (history->num_entries - 1)];
40 }
41 
42 void
43 _spdk_trace_record(uint64_t tsc, uint16_t tpoint_id, uint16_t owner_id, uint32_t size,
44 		   uint64_t object_id, int num_args, ...)
45 {
46 	struct spdk_trace_history *lcore_history;
47 	struct spdk_trace_entry *next_entry;
48 	struct spdk_trace_entry_buffer *buffer;
49 	struct spdk_trace_tpoint *tpoint;
50 	struct spdk_trace_argument *argument;
51 	unsigned lcore, i, offset, num_entries, arglen, argoff, curlen;
52 	uint64_t intval;
53 	void *argval;
54 	va_list vl;
55 
56 	lcore = spdk_env_get_current_core();
57 	if (spdk_likely(lcore != SPDK_ENV_LCORE_ID_ANY)) {
58 		lcore_history = spdk_get_per_lcore_history(g_trace_file, lcore);
59 	} else if (t_ut_lcore_history != NULL) {
60 		lcore_history = t_ut_lcore_history;
61 	} else {
62 		return;
63 	}
64 
65 	if (tsc == 0) {
66 		tsc = spdk_get_ticks();
67 	}
68 
69 	lcore_history->tpoint_count[tpoint_id]++;
70 
71 	tpoint = &g_trace_file->tpoint[tpoint_id];
72 	/* Make sure that the number of arguments passed matches tracepoint definition */
73 	if (spdk_unlikely(tpoint->num_args != num_args)) {
74 		assert(0 && "Unexpected number of tracepoint arguments");
75 		return;
76 	}
77 
78 	/* Get next entry index in the circular buffer */
79 	next_entry = get_trace_entry(lcore_history, lcore_history->next_entry);
80 	next_entry->tsc = tsc;
81 	next_entry->tpoint_id = tpoint_id;
82 	next_entry->owner_id = owner_id;
83 	next_entry->size = size;
84 	next_entry->object_id = object_id;
85 
86 	num_entries = 1;
87 	buffer = (struct spdk_trace_entry_buffer *)next_entry;
88 	/* The initial offset needs to be adjusted by the fields present in the first entry
89 	 * (owner_id, size, etc.).
90 	 */
91 	offset = offsetof(struct spdk_trace_entry, args) -
92 		 offsetof(struct spdk_trace_entry_buffer, data);
93 
94 	va_start(vl, num_args);
95 	for (i = 0; i < tpoint->num_args; ++i) {
96 		argument = &tpoint->args[i];
97 		switch (argument->type) {
98 		case SPDK_TRACE_ARG_TYPE_STR:
99 			argval = va_arg(vl, void *);
100 			arglen = strnlen((const char *)argval, argument->size - 1) + 1;
101 			break;
102 		case SPDK_TRACE_ARG_TYPE_INT:
103 		case SPDK_TRACE_ARG_TYPE_PTR:
104 			if (argument->size == 8) {
105 				intval = va_arg(vl, uint64_t);
106 			} else {
107 				intval = va_arg(vl, uint32_t);
108 			}
109 			argval = &intval;
110 			arglen = argument->size;
111 			break;
112 		default:
113 			assert(0 && "Invalid trace argument type");
114 			return;
115 		}
116 
117 		/* Copy argument's data. For some argument types (strings) user is allowed to pass a
118 		 * value that is either larger or smaller than what's defined in the tracepoint's
119 		 * description. If the value is larger, we'll truncate it, while if it's smaller,
120 		 * we'll only fill portion of the buffer, without touching the rest. For instance,
121 		 * if the definition marks an argument as 40B and user passes 12B string, we'll only
122 		 * copy 13B (accounting for the NULL terminator).
123 		 */
124 		argoff = 0;
125 		while (argoff < argument->size) {
126 			/* Current buffer is full, we need to acquire another one */
127 			if (spdk_unlikely(offset == sizeof(buffer->data))) {
128 				buffer = (struct spdk_trace_entry_buffer *) get_trace_entry(
129 						 lcore_history,
130 						 lcore_history->next_entry + num_entries);
131 				buffer->tpoint_id = SPDK_TRACE_MAX_TPOINT_ID;
132 				buffer->tsc = tsc;
133 				num_entries++;
134 				offset = 0;
135 			}
136 
137 			curlen = spdk_min(sizeof(buffer->data) - offset, argument->size - argoff);
138 			if (spdk_likely(argoff < arglen)) {
139 				assert(argval != NULL);
140 				memcpy(&buffer->data[offset], (uint8_t *)argval + argoff,
141 				       spdk_min(curlen, arglen - argoff));
142 			}
143 
144 			offset += curlen;
145 			argoff += curlen;
146 		}
147 
148 		/* Make sure that truncated strings are NULL-terminated */
149 		if (spdk_unlikely(argument->type == SPDK_TRACE_ARG_TYPE_STR)) {
150 			assert(offset > 0);
151 			buffer->data[offset - 1] = '\0';
152 		}
153 	}
154 	va_end(vl);
155 
156 	/* Ensure all elements of the trace entry are visible to outside trace tools */
157 	spdk_smp_wmb();
158 	lcore_history->next_entry += num_entries;
159 }
160 
161 int
162 spdk_trace_register_user_thread(void)
163 {
164 	int ret;
165 	uint32_t ut_index;
166 	pthread_t tid;
167 
168 	if (!g_ut_array) {
169 		SPDK_ERRLOG("user thread array not created\n");
170 		return -ENOMEM;
171 	}
172 
173 	if (spdk_env_get_current_core() != SPDK_ENV_LCORE_ID_ANY) {
174 		SPDK_ERRLOG("cannot register an user thread from a dedicated cpu %d\n",
175 			    spdk_env_get_current_core());
176 		return -EINVAL;
177 	}
178 
179 	pthread_mutex_lock(&g_ut_array_mutex);
180 
181 	t_ut_array_index = spdk_bit_array_find_first_clear(g_ut_array, 0);
182 	if (t_ut_array_index == UINT32_MAX) {
183 		SPDK_ERRLOG("could not find an entry in the user thread array\n");
184 		pthread_mutex_unlock(&g_ut_array_mutex);
185 		return -ENOENT;
186 	}
187 
188 	ut_index = t_ut_array_index + g_user_thread_index_start;
189 
190 	t_ut_lcore_history = spdk_get_per_lcore_history(g_trace_file, ut_index);
191 
192 	assert(t_ut_lcore_history != NULL);
193 
194 	memset(g_trace_file->tname[ut_index], 0, SPDK_TRACE_THREAD_NAME_LEN);
195 
196 	tid = pthread_self();
197 	ret = pthread_getname_np(tid, g_trace_file->tname[ut_index], SPDK_TRACE_THREAD_NAME_LEN);
198 	if (ret) {
199 		SPDK_ERRLOG("cannot get thread name\n");
200 		pthread_mutex_unlock(&g_ut_array_mutex);
201 		return ret;
202 	}
203 
204 	spdk_bit_array_set(g_ut_array, t_ut_array_index);
205 
206 	pthread_mutex_unlock(&g_ut_array_mutex);
207 
208 	return 0;
209 }
210 
211 int
212 spdk_trace_unregister_user_thread(void)
213 {
214 	if (!g_ut_array) {
215 		SPDK_ERRLOG("user thread array not created\n");
216 		return -ENOMEM;
217 	}
218 
219 	if (spdk_env_get_current_core() != SPDK_ENV_LCORE_ID_ANY) {
220 		SPDK_ERRLOG("cannot unregister an user thread from a dedicated cpu %d\n",
221 			    spdk_env_get_current_core());
222 		return -EINVAL;
223 	}
224 
225 	pthread_mutex_lock(&g_ut_array_mutex);
226 
227 	spdk_bit_array_clear(g_ut_array, t_ut_array_index);
228 
229 	pthread_mutex_unlock(&g_ut_array_mutex);
230 
231 	return 0;
232 }
233 
234 int
235 spdk_trace_init(const char *shm_name, uint64_t num_entries, uint32_t num_threads)
236 {
237 	uint32_t i = 0, max_dedicated_cpu = 0;
238 	uint64_t file_size;
239 	uint64_t lcore_offsets[SPDK_TRACE_MAX_LCORE] = { 0 };
240 	uint64_t owner_offset;
241 	struct spdk_cpuset cpuset = {};
242 
243 	/* 0 entries requested - skip trace initialization */
244 	if (num_entries == 0) {
245 		return 0;
246 	}
247 
248 	if (num_threads >= SPDK_TRACE_MAX_LCORE) {
249 		SPDK_ERRLOG("cannot alloc trace entries for %d user threads\n", num_threads);
250 		SPDK_ERRLOG("supported maximum %d threads\n", SPDK_TRACE_MAX_LCORE - 1);
251 		return 1;
252 	}
253 
254 	spdk_cpuset_zero(&cpuset);
255 	file_size = sizeof(struct spdk_trace_file);
256 	SPDK_ENV_FOREACH_CORE(i) {
257 		spdk_cpuset_set_cpu(&cpuset, i, true);
258 		lcore_offsets[i] = file_size;
259 		file_size += spdk_get_trace_history_size(num_entries);
260 		max_dedicated_cpu = i;
261 	}
262 
263 	g_user_thread_index_start = max_dedicated_cpu + 1;
264 
265 	if (g_user_thread_index_start + num_threads > SPDK_TRACE_MAX_LCORE) {
266 		SPDK_ERRLOG("user threads overlap with the threads on dedicated cpus\n");
267 		return 1;
268 	}
269 
270 	g_ut_array = spdk_bit_array_create(num_threads);
271 	if (!g_ut_array) {
272 		SPDK_ERRLOG("could not create bit array for threads\n");
273 		return 1;
274 	}
275 
276 	for (i = g_user_thread_index_start; i < g_user_thread_index_start + num_threads; i++) {
277 		lcore_offsets[i] = file_size;
278 		file_size += spdk_get_trace_history_size(num_entries);
279 	}
280 	owner_offset = file_size;
281 	file_size += TRACE_NUM_OWNERS *
282 		     (sizeof(struct spdk_trace_owner) + TRACE_OWNER_DESCRIPTION_SIZE);
283 
284 	snprintf(g_shm_name, sizeof(g_shm_name), "%s", shm_name);
285 
286 	g_trace_fd = shm_open(shm_name, O_RDWR | O_CREAT, 0600);
287 	if (g_trace_fd == -1) {
288 		SPDK_ERRLOG("could not shm_open spdk_trace\n");
289 		SPDK_ERRLOG("errno=%d %s\n", errno, spdk_strerror(errno));
290 		spdk_bit_array_free(&g_ut_array);
291 		return 1;
292 	}
293 
294 	if (ftruncate(g_trace_fd, file_size) != 0) {
295 		SPDK_ERRLOG("could not truncate shm\n");
296 		goto trace_init_err;
297 	}
298 
299 	g_trace_file = mmap(NULL, file_size, PROT_READ | PROT_WRITE,
300 			    MAP_SHARED, g_trace_fd, 0);
301 	if (g_trace_file == MAP_FAILED) {
302 		SPDK_ERRLOG("could not mmap shm\n");
303 		goto trace_init_err;
304 	}
305 
306 	/* TODO: On FreeBSD, mlock on shm_open'd memory doesn't seem to work.  Docs say that kern.ipc.shm_use_phys=1
307 	 * should allow it, but forcing that doesn't seem to work either.  So for now just skip mlock on FreeBSD
308 	 * altogether.
309 	 */
310 #if defined(__linux__)
311 	if (mlock(g_trace_file, file_size) != 0) {
312 		SPDK_ERRLOG("Could not mlock shm for tracing - %s.\n", spdk_strerror(errno));
313 		if (errno == ENOMEM) {
314 			SPDK_ERRLOG("Check /dev/shm for old tracing files that can be deleted.\n");
315 		}
316 		goto trace_init_err;
317 	}
318 #endif
319 
320 	memset(g_trace_file, 0, file_size);
321 
322 	g_trace_file->tsc_rate = spdk_get_ticks_hz();
323 
324 	for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
325 		struct spdk_trace_history *lcore_history;
326 
327 		g_trace_file->lcore_history_offsets[i] = lcore_offsets[i];
328 		if (lcore_offsets[i] == 0) {
329 			continue;
330 		}
331 
332 		if (i <= max_dedicated_cpu) {
333 			assert(spdk_cpuset_get_cpu(&cpuset, i));
334 		}
335 
336 		lcore_history = spdk_get_per_lcore_history(g_trace_file, i);
337 		lcore_history->lcore = i;
338 		lcore_history->num_entries = num_entries;
339 	}
340 	g_trace_file->file_size = file_size;
341 	g_trace_file->num_owners = TRACE_NUM_OWNERS;
342 	g_trace_file->owner_description_size = TRACE_OWNER_DESCRIPTION_SIZE;
343 	g_trace_file->owner_offset = owner_offset;
344 
345 	if (trace_flags_init()) {
346 		goto trace_init_err;
347 	}
348 
349 	return 0;
350 
351 trace_init_err:
352 	if (g_trace_file != MAP_FAILED) {
353 		munmap(g_trace_file, file_size);
354 	}
355 	close(g_trace_fd);
356 	g_trace_fd = -1;
357 	shm_unlink(shm_name);
358 	spdk_bit_array_free(&g_ut_array);
359 	g_trace_file = NULL;
360 
361 	return 1;
362 
363 }
364 
365 void
366 spdk_trace_cleanup(void)
367 {
368 	bool unlink = true;
369 	int i;
370 	struct spdk_trace_history *lcore_history;
371 
372 	if (g_trace_file == NULL) {
373 		return;
374 	}
375 
376 	trace_flags_fini();
377 
378 	/*
379 	 * Only unlink the shm if there were no trace_entry recorded. This ensures the file
380 	 * can be used after this process exits/crashes for debugging.
381 	 * Note that we have to calculate this value before g_trace_file gets unmapped.
382 	 */
383 	for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
384 		lcore_history = spdk_get_per_lcore_history(g_trace_file, i);
385 		if (lcore_history == NULL) {
386 			continue;
387 		}
388 		unlink = lcore_history->entries[0].tsc == 0;
389 		if (!unlink) {
390 			break;
391 		}
392 	}
393 
394 	munmap(g_trace_file, sizeof(struct spdk_trace_file));
395 	g_trace_file = NULL;
396 	close(g_trace_fd);
397 	spdk_bit_array_free(&g_ut_array);
398 
399 	if (unlink) {
400 		shm_unlink(g_shm_name);
401 	}
402 }
403 
404 const char *
405 trace_get_shm_name(void)
406 {
407 	return g_shm_name;
408 }
409