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