xref: /spdk/app/trace/trace.cpp (revision 20f59ee12e141cbf47f64ff7cd072a1e9363e0c8)
1 /*-
2  *   BSD LICENSE
3  *
4  *   Copyright (c) Intel Corporation.
5  *   All rights reserved.
6  *
7  *   Redistribution and use in source and binary forms, with or without
8  *   modification, are permitted provided that the following conditions
9  *   are met:
10  *
11  *     * Redistributions of source code must retain the above copyright
12  *       notice, this list of conditions and the following disclaimer.
13  *     * Redistributions in binary form must reproduce the above copyright
14  *       notice, this list of conditions and the following disclaimer in
15  *       the documentation and/or other materials provided with the
16  *       distribution.
17  *     * Neither the name of Intel Corporation nor the names of its
18  *       contributors may be used to endorse or promote products derived
19  *       from this software without specific prior written permission.
20  *
21  *   THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
22  *   "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
23  *   LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
24  *   A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
25  *   OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
26  *   SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
27  *   LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
28  *   DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
29  *   THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
30  *   (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
31  *   OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
32  */
33 
34 #include <sys/types.h>
35 #include <sys/uio.h>
36 #include <sys/mman.h>
37 #include <sys/stat.h>
38 #include <fcntl.h>
39 #include <inttypes.h>
40 #include <stdio.h>
41 #include <stdlib.h>
42 #include <stdint.h>
43 #include <string.h>
44 #include <errno.h>
45 #include <unistd.h>
46 #include <signal.h>
47 #include <fcntl.h>
48 
49 #include <map>
50 
51 extern "C" {
52 #include "spdk/trace.h"
53 }
54 
55 static struct spdk_trace_histories *g_histories;
56 
57 static void usage(void);
58 
59 struct entry_key {
60 	entry_key(uint16_t _lcore, uint64_t _tsc) : lcore(_lcore), tsc(_tsc) {}
61 	uint16_t lcore;
62 	uint64_t tsc;
63 };
64 
65 class compare_entry_key
66 {
67 public:
68 	bool operator()(const entry_key &first, const entry_key &second) const
69 	{
70 		if (first.tsc == second.tsc) {
71 			return first.lcore < second.lcore;
72 		} else {
73 			return first.tsc < second.tsc;
74 		}
75 	}
76 };
77 
78 typedef std::map<entry_key, spdk_trace_entry *, compare_entry_key> entry_map;
79 
80 entry_map g_entry_map;
81 
82 struct object_stats {
83 
84 	std::map<uint64_t, uint64_t> start;
85 	std::map<uint64_t, uint64_t> index;
86 	std::map<uint64_t, uint64_t> size;
87 	std::map<uint64_t, uint64_t> tpoint_id;
88 	uint64_t counter;
89 
90 	object_stats() : start(), index(), size(), tpoint_id(), counter(0) {}
91 };
92 
93 struct object_stats g_stats[SPDK_TRACE_MAX_OBJECT];
94 
95 static char *exe_name;
96 static int verbose = 1;
97 static int g_instance_id = 0;
98 static int g_fudge_factor = 20;
99 
100 static uint64_t tsc_rate;
101 static uint64_t first_tsc = 0x0;
102 static uint64_t last_tsc = -1ULL;
103 
104 static float
105 get_us_from_tsc(uint64_t tsc, uint64_t tsc_rate)
106 {
107 	return ((float)tsc) * 1000 * 1000 / tsc_rate;
108 }
109 
110 static void
111 print_ptr(const char *arg_string, uint64_t arg)
112 {
113 	printf("%-7.7s0x%-14jx ", arg_string, arg);
114 }
115 
116 static void
117 print_uint64(const char *arg_string, uint64_t arg)
118 {
119 	/*
120 	 * Print arg as signed, since -1 is a common value especially
121 	 *  for FLUSH WRITEBUF when writev() returns -1 due to full
122 	 *  socket buffer.
123 	 */
124 	printf("%-7.7s%-16jd ", arg_string, arg);
125 }
126 
127 static void
128 print_size(uint32_t size)
129 {
130 	if (size > 0) {
131 		printf("size: %6u ", size);
132 	} else {
133 		printf("%13s", " ");
134 	}
135 }
136 
137 static void
138 print_object_id(uint8_t type, uint64_t id)
139 {
140 	printf("id:    %c%-15jd ", g_histories->object[type].id_prefix, id);
141 }
142 
143 static void
144 print_float(const char *arg_string, float arg)
145 {
146 	printf("%-7s%-16.3f ", arg_string, arg);
147 }
148 
149 static void
150 print_arg(bool arg_is_ptr, const char *arg_string, uint64_t arg)
151 {
152 	if (arg_string[0] == 0)
153 		return;
154 
155 	if (arg_is_ptr)
156 		print_ptr(arg_string, arg);
157 	else
158 		print_uint64(arg_string, arg);
159 }
160 
161 static void
162 print_event(struct spdk_trace_entry *e, uint64_t tsc_rate,
163 	    uint64_t tsc_offset, uint16_t lcore)
164 {
165 	struct spdk_trace_tpoint	*d;
166 	struct object_stats		*stats;
167 	float				us;
168 
169 	d = &g_histories->tpoint[e->tpoint_id];
170 	stats = &g_stats[d->object_type];
171 
172 	if (d->new_object) {
173 		stats->index[e->object_id] = stats->counter++;
174 		stats->tpoint_id[e->object_id] = e->tpoint_id;
175 		stats->start[e->object_id] = e->tsc;
176 		stats->size[e->object_id] = e->size;
177 	}
178 
179 	if (d->arg1_is_alias) {
180 		stats->index[e->arg1] = stats->index[e->object_id];
181 		stats->start[e->arg1] = stats->start[e->object_id];
182 		stats->size[e->arg1] = stats->size[e->object_id];
183 	}
184 
185 	us = get_us_from_tsc(e->tsc - tsc_offset, tsc_rate);
186 
187 	printf("%2d: %10.3f (%9ju) ", lcore, us, e->tsc - tsc_offset);
188 	if (g_histories->owner[d->owner_type].id_prefix) {
189 		printf("%c%02d ", g_histories->owner[d->owner_type].id_prefix, e->poller_id);
190 	} else {
191 		printf("%4s", " ");
192 	}
193 
194 	printf("%-*s ", (int)sizeof(d->name), d->name);
195 	print_size(e->size);
196 
197 	if (d->new_object) {
198 		print_arg(d->arg1_is_ptr, d->arg1_name, e->arg1);
199 		print_object_id(d->object_type, stats->index[e->object_id]);
200 	} else if (d->object_type != OBJECT_NONE) {
201 		if (stats->start.find(e->object_id) != stats->start.end()) {
202 			struct spdk_trace_tpoint *start_description;
203 
204 			us = get_us_from_tsc(e->tsc - stats->start[e->object_id],
205 					     tsc_rate);
206 			print_object_id(d->object_type, stats->index[e->object_id]);
207 			print_float("time:", us);
208 			start_description = &g_histories->tpoint[stats->tpoint_id[e->object_id]];
209 			if (start_description->short_name[0] != 0) {
210 				printf(" (%.4s)", start_description->short_name);
211 			}
212 		} else {
213 			printf("id:    N/A");
214 		}
215 	} else {
216 		print_arg(d->arg1_is_ptr, d->arg1_name, e->arg1);
217 	}
218 	printf("\n");
219 }
220 
221 static void
222 process_event(struct spdk_trace_entry *e, uint64_t tsc_rate,
223 	      uint64_t tsc_offset, uint16_t lcore)
224 {
225 	if (verbose) {
226 		print_event(e, tsc_rate, tsc_offset, lcore);
227 	}
228 }
229 
230 static int
231 populate_events(struct spdk_trace_history *history)
232 {
233 	int i, entry_size, history_size, num_entries, num_entries_filled;
234 	struct spdk_trace_entry *e;
235 	int first, last, lcore;
236 
237 	lcore = history->lcore;
238 
239 	entry_size = sizeof(history->entries[0]);
240 	history_size = sizeof(history->entries);
241 	num_entries = history_size / entry_size;
242 
243 	e = history->entries;
244 
245 	num_entries_filled = num_entries;
246 	while (e[num_entries_filled - 1].tsc == 0) {
247 		num_entries_filled--;
248 	}
249 
250 	if (num_entries == num_entries_filled) {
251 		first = last = 0;
252 		for (i = 1; i < num_entries; i++) {
253 			if (e[i].tsc < e[first].tsc)
254 				first = i;
255 			if (e[i].tsc > e[last].tsc)
256 				last = i;
257 		}
258 
259 		first += g_fudge_factor;
260 		if (first >= num_entries)
261 			first -= num_entries;
262 
263 		last -= g_fudge_factor;
264 		if (last < 0)
265 			last += num_entries;
266 	} else {
267 		first = 0;
268 		last = num_entries_filled - 1;
269 	}
270 
271 	/*
272 	 * We keep track of the highest first TSC out of all reactors and
273 	 *  the lowest last TSC out of all reactors.  We will ignore any
274 	 *  events outside the range of these two TSC values.  This will
275 	 *  ensure we only print data for the subset of time where we have
276 	 *  data across all reactors.
277 	 */
278 	if (e[first].tsc > first_tsc) {
279 		first_tsc = e[first].tsc;
280 	}
281 	if (e[last].tsc < last_tsc) {
282 		last_tsc = e[last].tsc;
283 	}
284 
285 	i = first;
286 	while (1) {
287 		g_entry_map[entry_key(lcore, e[i].tsc)] = &e[i];
288 		if (i == last) {
289 			break;
290 		}
291 		i++;
292 		if (i == num_entries_filled) {
293 			i = 0;
294 		}
295 	}
296 
297 	return (0);
298 }
299 
300 static void usage(void)
301 {
302 	fprintf(stderr, "usage:\n");
303 	fprintf(stderr, "   %s <option> <lcore#>\n", exe_name);
304 	fprintf(stderr, "        option = '-q' to disable verbose mode\n");
305 	fprintf(stderr, "                 '-s' to specify spdk_trace shm name\n");
306 	fprintf(stderr, "                 '-c' to display single lcore history\n");
307 	fprintf(stderr, "                 '-f' to specify number of events to ignore at\n");
308 	fprintf(stderr, "                      beginning and end of trace (default: 20)\n");
309 	fprintf(stderr, "                 '-i' to specify the instance ID, (default: 0)\n");
310 }
311 
312 int main(int argc, char **argv)
313 {
314 	void			*history_ptr;
315 	struct spdk_trace_history *history_entries, *history;
316 	int			fd, i;
317 	int			lcore = RTE_MAX_LCORE;
318 	uint64_t		tsc_offset;
319 	const char		*app_name = "ids";
320 	int			op;
321 	char			shm_name[64];
322 
323 	exe_name = argv[0];
324 	while ((op = getopt(argc, argv, "c:f:i:qs:")) != -1) {
325 		switch (op) {
326 		case 'c':
327 			lcore = atoi(optarg);
328 			if (lcore > RTE_MAX_LCORE) {
329 				fprintf(stderr, "Selected lcore: %d "
330 					"exceeds maximum %d\n", lcore,
331 					RTE_MAX_LCORE);
332 				exit(1);
333 			}
334 			break;
335 		case 'f':
336 			g_fudge_factor = atoi(optarg);
337 			break;
338 		case 'i':
339 			g_instance_id = atoi(optarg);
340 			break;
341 		case 'q':
342 			verbose = 0;
343 			break;
344 		case 's':
345 			app_name = optarg;
346 			break;
347 		default:
348 			usage();
349 			exit(1);
350 		}
351 	}
352 
353 	snprintf(shm_name, sizeof(shm_name), "%s_trace.%d", app_name, g_instance_id);
354 	fd = shm_open(shm_name, O_RDONLY, 0600);
355 	if (fd < 0) {
356 		fprintf(stderr, "Could not open shm %s.\n", shm_name);
357 		usage();
358 		exit(-1);
359 	}
360 	history_ptr = mmap(NULL, sizeof(*g_histories), PROT_READ, MAP_SHARED, fd, 0);
361 	g_histories = (struct spdk_trace_histories *)history_ptr;
362 
363 	tsc_rate = g_histories->tsc_rate;
364 
365 	if (verbose) {
366 		printf("TSC Rate: %ju\n", tsc_rate);
367 	}
368 
369 	history_entries = (struct spdk_trace_history *)malloc(sizeof(g_histories->per_lcore_history));
370 	if (history_entries == NULL) {
371 		goto cleanup;
372 	}
373 	memcpy(history_entries, g_histories->per_lcore_history,
374 	       sizeof(g_histories->per_lcore_history));
375 
376 	if (lcore == RTE_MAX_LCORE) {
377 		for (i = 0; i < RTE_MAX_LCORE; i++) {
378 			history = &history_entries[i];
379 			if (history->entries[0].tsc == 0) {
380 				continue;
381 			}
382 			populate_events(history);
383 		}
384 	} else {
385 		history = &history_entries[lcore];
386 		if (history->entries[0].tsc != 0) {
387 			populate_events(history);
388 		}
389 	}
390 
391 	tsc_offset = first_tsc;
392 	for (entry_map::iterator it = g_entry_map.begin(); it != g_entry_map.end(); it++) {
393 		if (it->first.tsc < first_tsc || it->first.tsc > last_tsc) {
394 			continue;
395 		}
396 		process_event(it->second, tsc_rate, tsc_offset, it->first.lcore);
397 	}
398 
399 	free(history_entries);
400 
401 cleanup:
402 	munmap(history_ptr, sizeof(*g_histories));
403 	close(fd);
404 
405 	return (0);
406 }
407