1 /*
2  * Copyright (c) 2018 Google, Inc.
3  *
4  * SPDX-License-Identifier: GPL-2.0-or-later
5  */
6 
7 #define _GNU_SOURCE
8 #include <fcntl.h>
9 #include <sys/types.h>
10 #include <sys/stat.h>
11 #include <unistd.h>
12 #include <errno.h>
13 #include <stdlib.h>
14 #include <stdio.h>
15 #include <string.h>
16 
17 #include "tst_res_flags.h"
18 #include "tst_safe_file_ops.h"
19 #include "tst_safe_macros.h"
20 
21 #include "trace_parse.h"
22 
23 #define TRACEFS_MAX_PATH_LEN 512
24 
25 int num_trace_records = 0;
26 struct trace_record *trace = NULL;
27 
28 static int trace_fd = -1;
29 static char *trace_buffer = NULL;
30 
31 const char *tracefs_root = "/sys/kernel/tracing/";
32 const char *debugfs_tracefs_root = "/sys/kernel/debug/tracing/";
33 char *ftrace_root_dir;
34 
parse_event_type(char * event_name)35 static int parse_event_type(char *event_name)
36 {
37 	if (!strcmp(event_name, "sched_process_exit"))
38 		return TRACE_RECORD_SCHED_PROCESS_EXIT;
39 	if (!strcmp(event_name, "sched_process_fork"))
40 		return TRACE_RECORD_SCHED_PROCESS_FORK;
41 	if (!strcmp(event_name, "sched_switch"))
42 		return TRACE_RECORD_SCHED_SWITCH;
43 	if (!strcmp(event_name, "sched_wakeup"))
44 		return TRACE_RECORD_SCHED_WAKEUP;
45 	if (!strcmp(event_name, "sugov_util_update"))
46 		return TRACE_RECORD_SUGOV_UTIL_UPDATE;
47 	if (!strcmp(event_name, "sugov_next_freq"))
48 		return TRACE_RECORD_SUGOV_NEXT_FREQ;
49 	if (!strcmp(event_name, "cpu_frequency"))
50 		return TRACE_RECORD_CPU_FREQUENCY;
51 	if (!strcmp(event_name, "tracing_mark_write"))
52 		return TRACE_RECORD_TRACING_MARK_WRITE;
53 	return -1;
54 }
55 
print_trace_record(struct trace_record * tr)56 void print_trace_record(struct trace_record *tr)
57 {
58 	printf("task: %s pid %d cpu %d flags %d irq_context %c preempt_depth %d timestamp %d.%.6d event_type %d ",
59 	       tr->task, tr->pid, tr->cpu, tr->flags, tr->irq_context,
60 	       tr->preempt_depth, tr->ts.sec, tr->ts.usec,
61 	       tr->event_type);
62 	if (tr->event_type == TRACE_RECORD_SCHED_PROCESS_EXIT)
63 		printf("(sched_process_exit)\n");
64 	else if (tr->event_type == TRACE_RECORD_SCHED_PROCESS_FORK)
65 		printf("(sched_process_fork)\n");
66 	else if (tr->event_type == TRACE_RECORD_SCHED_SWITCH) {
67 		struct trace_sched_switch *t = tr->event_data;
68 		printf("(sched_switch) %s pid=%d prio=%d state=%c => "
69 		       "%s pid=%d prio=%d\n", t->prev_comm, t->prev_pid,
70 		       t->prev_prio, t->prev_state, t->next_comm, t->next_pid,
71 		       t->next_prio);
72 	} else if (tr->event_type == TRACE_RECORD_SCHED_WAKEUP) {
73 		struct trace_sched_wakeup *t = tr->event_data;
74 		printf("(sched_wakeup) %s pid=%d prio=%d cpu=%d\n",
75 		       t->comm, t->pid, t->prio, t->cpu);
76 	} else if (tr->event_type == TRACE_RECORD_SUGOV_UTIL_UPDATE) {
77 		struct trace_sugov_util_update *t = tr->event_data;
78 		printf("(sugov_util_update) cpu=%d util=%d avg_cap=%d "
79 		       "max_cap=%d\n", t->cpu, t->util, t->avg_cap,
80 		       t->max_cap);
81 	} else if (tr->event_type == TRACE_RECORD_SUGOV_NEXT_FREQ) {
82 		struct trace_sugov_next_freq *t = tr->event_data;
83 		printf("(sugov_next_freq) cpu=%d util=%d max=%d freq=%d\n",
84 		       t->cpu, t->util, t->max, t->freq);
85 	} else if (tr->event_type == TRACE_RECORD_CPU_FREQUENCY) {
86 		struct trace_cpu_frequency *t = tr->event_data;
87 		printf("(cpu_frequency) state=%d cpu=%d\n",
88 		       t->state, t->cpu);
89 	} else if (tr->event_type == TRACE_RECORD_TRACING_MARK_WRITE)
90 		printf("(tracing_mark_write)\n");
91 	else
92 		printf("(other)\n");
93 }
94 
trace_setup(void)95 void trace_setup(void)
96 {
97 	struct stat buf;
98 
99 	if (stat("/sys/kernel/tracing/trace", &buf) == 0)
100 		ftrace_root_dir = tracefs_root;
101 	else
102 		ftrace_root_dir = debugfs_tracefs_root;
103 
104 }
105 
tracefs_write(const char * file_name,const char * value)106 void tracefs_write(const char *file_name, const char *value)
107 {
108 	char buf[TRACEFS_MAX_PATH_LEN];
109 
110 	snprintf(buf, sizeof(buf), "%s%s", ftrace_root_dir, file_name);
111 	SAFE_FILE_PRINTF(buf, value);
112 }
113 
trace_cleanup(void)114 void trace_cleanup(void)
115 {
116 	tracefs_write("tracing_on", "0");
117 
118 }
119 
parse_event_data(unsigned int event_type,char * data)120 static void *parse_event_data(unsigned int event_type, char *data)
121 {
122 	if (event_type == TRACE_RECORD_TRACING_MARK_WRITE) {
123 		char *buf = SAFE_MALLOC(strlen(data) + 1);
124 		strcpy(buf, data);
125 		return buf;
126 	}
127 	if (event_type == TRACE_RECORD_CPU_FREQUENCY) {
128 		struct trace_cpu_frequency *t;
129 		t = SAFE_MALLOC(sizeof(struct trace_cpu_frequency));
130 		if (sscanf(data, "state=%d cpu_id=%hd", &t->state, &t->cpu)
131 		    != 2) {
132 			printf("Error parsing cpu_frequency event:\n%s\n",
133 			       data);
134 			free(t);
135 			return NULL;
136 		}
137 		return t;
138 	}
139 	if (event_type == TRACE_RECORD_SUGOV_UTIL_UPDATE) {
140 		struct trace_sugov_util_update *t;
141 		t = SAFE_MALLOC(sizeof(struct trace_sugov_util_update));
142 		if (sscanf(data, "cpu=%d util=%d avg_cap=%d max_cap=%d",
143 			   &t->cpu, &t->util, &t->avg_cap, &t->max_cap) != 4) {
144 			printf("Error parsing sugov_util_update event:\n%s\n",
145 			       data);
146 			free(t);
147 			return NULL;
148 		}
149 		return t;
150 	}
151 	if (event_type == TRACE_RECORD_SUGOV_NEXT_FREQ) {
152 		struct trace_sugov_next_freq *t;
153 		t = SAFE_MALLOC(sizeof(struct trace_sugov_next_freq));
154 		if (sscanf(data, "cpu=%d util=%d max=%d freq=%d",
155 			   &t->cpu, &t->util, &t->max, &t->freq) != 4) {
156 			printf("Error parsing sugov_next_freq event:\n%s\n",
157 			       data);
158 			free(t);
159 			return NULL;
160 		}
161 		return t;
162 	}
163 	if (event_type == TRACE_RECORD_SCHED_SWITCH) {
164 		struct trace_sched_switch *t;
165 		char *tmp, *tmp2;
166 		t = SAFE_MALLOC(sizeof(struct trace_sched_switch));
167 		/*
168 		 * The prev_comm could have spaces in it. Find start of
169 		 * "prev_pid=" as that is just after end of prev_comm.
170 		 */
171 		if (strstr(data, "prev_comm=") != data) {
172 			printf("Malformatted sched_switch event:\n%s\n",
173 			       data);
174 			free(t);
175 			return NULL;
176 		}
177 		tmp = strstr(data, " prev_pid=");
178 		if (!tmp) {
179 			printf("Malformatted sched_switch event, "
180 			       "no prev_pid:\n%s\n", data);
181 			free(t);
182 			return NULL;
183 		}
184 		*tmp = 0;
185 		snprintf(t->prev_comm, sizeof(t->prev_comm), "%s", data + 10);
186 		*tmp = ' ';
187 		tmp++;
188 		if (sscanf(tmp, "prev_pid=%hd prev_prio=%hd "
189 			   "prev_state=%c ==>\n",
190 			   &t->prev_pid, &t->prev_prio, &t->prev_state) != 3) {
191 			printf("Malformatted sched_switch event:\n%s\n",
192 			       data);
193 			free(t);
194 			return NULL;
195 		}
196 		tmp = strstr(tmp, "==> next_comm=");
197 		if (!tmp) {
198 			printf("Malformatted sched_switch event:\n%s\n",
199 			       data);
200 			free(t);
201 			return NULL;
202 		}
203 		tmp += 14;
204 		tmp2 = strstr(tmp, " next_pid=");
205 		if (!tmp2) {
206 			printf("Malformatted sched_switch event:\n%s\n",
207 			       data);
208 			free(t);
209 			return NULL;
210 		}
211 		*tmp2 = 0;
212 		if (strlen(tmp) > 16) {
213 			printf("next_comm %s is greater than 16!\n",
214 			       tmp);
215 			t->next_comm[0] = 0;
216 		}
217 		snprintf(t->next_comm, sizeof(t->next_comm), "%s", tmp);
218 		*tmp2 = ' ';
219 		tmp2++;
220 		if (sscanf(tmp2, "next_pid=%hd next_prio=%hd", &t->next_pid,
221 			   &t->next_prio) != 2) {
222 			printf("Malformatted sched_switch event:\n%s\n",
223 			       data);
224 			free(t);
225 			return NULL;
226 		}
227 		return t;
228 	}
229 	if (event_type == TRACE_RECORD_SCHED_WAKEUP) {
230 		struct trace_sched_wakeup *t;
231 		char *tmp;
232 		t = SAFE_MALLOC(sizeof(struct trace_sched_wakeup));
233 		tmp = strstr(data, " pid=");
234 		if (!tmp) {
235 			printf("Malformatted sched_wakeup event:\n%s\n", data);
236 			free(t);
237 			return NULL;
238 		}
239 		*tmp = 0;
240 		snprintf(t->comm, sizeof(t->comm), "%s", data + 5);
241 		*tmp = ' ';
242 		if (sscanf(tmp, " pid=%hd prio=%hd target_cpu=%hd", &t->pid,
243 			   &t->prio, &t->cpu) != 3) {
244 			printf("Malformatted sched_wakeup event:\n%s\n", data);
245 			free(t);
246 			return NULL;
247 		}
248 		return t;
249 	}
250 	return NULL;
251 }
252 
253 /*
254  * Given a line of text from a trace containing a trace record, parse the trace
255  * record into a struct trace_record.
256  * First 16 chars are the currently running thread name. Drop leading spaces.
257  * Next char is a dash
258  * Next 5 chars are PID. Drop trailing spaces.
259  * Next is some number of spaces.
260  * Next five chars are the CPU, i.e. [001].
261  * Next is some number of spaces.
262  * Next letter is whether IRQs are off.
263  * Next letter is if NEED_RESCHED is set.
264  * Next letter is if this is in hard or soft IRQ context.
265  * Next letter is the preempt disable depth.
266  * Next is some number of spaces.
267  * Next twelve letters are the timestamp.
268  * Next char is colon.
269  * Next char is space.
270  * Next twelve letters are the event name.
271  * Next char is colon.
272  * Rest of line is string specific to event.
273  */
parse_trace_record(struct trace_record * tr,char * line)274 static int parse_trace_record(struct trace_record *tr, char *line) {
275 	unsigned int field_start, idx = 0;
276 	char *found;
277 
278 	/* Skip leading spaces in the task name. */
279 	while (idx < 16 && line[idx] == ' ')
280 		idx++;
281 	if (idx == 16) {
282 		printf("Malformatted trace record, no task name:\n");
283 		printf("%s", line);
284 		return -1;
285 	}
286 	memcpy(tr->task, &line[idx], 16-idx);
287 	if (line[16] != '-') {
288 		printf("Malformatted trace record, no dash after task "
289 		       "name:\n");
290 		printf("%s", line);
291 		return -1;
292 	}
293 	idx = 17;
294 	while(line[idx] && line[idx] != '[') idx++;
295 	if (!line[idx]) {
296 		printf("Malformatted trace record, no open bracket for"
297 		       "CPU after pid:\n");
298 		printf("%s", line);
299 		return -1;
300 	}
301 	line[idx-1] = 0;
302 	if (sscanf(&line[17], "%hd", &tr->pid) != 1) {
303 		printf("Malformatted trace record, error parsing"
304 		       "pid:\n");
305 		printf("%s", line);
306 		return -1;
307 	}
308 	field_start = idx;
309 	while(line[idx] && line[idx] != ']') idx++;
310 	if (!line[idx]) {
311 		printf("Malformatted trace record, no closing bracket for"
312 		       "CPU:\n");
313 		printf("%s", line);
314 		return -1;
315 	}
316 	idx++;
317 	if (line[idx] != ' ') {
318 		printf("Malformatted trace record, no space following CPU:\n");
319 		printf("%s", line);
320 		return -1;
321 	}
322 	line[idx] = 0;
323 	idx++;
324 	if (sscanf(&line[field_start], "[%hd]", &tr->cpu) != 1) {
325 		printf("Malformatted trace record, error parsing CPU:\n");
326 		printf("%s", line);
327 		return -1;
328 	}
329 
330 	if (line[idx] == 'd') {
331 		tr->flags |= TRACE_RECORD_IRQS_OFF;
332 	} else if (line[idx] != '.') {
333 		printf("Malformatted trace record, error parsing irqs-off:\n");
334 		printf("%s", line);
335 		return -1;
336 	}
337 	idx++;
338 	if (line[idx] == 'N') {
339 		tr->flags |= TRACE_RECORD_TIF_NEED_RESCHED;
340 		tr->flags |= TRACE_RECORD_PREEMPT_NEED_RESCHED;
341 	} else if (line[idx] == 'n') {
342 		tr->flags |= TRACE_RECORD_TIF_NEED_RESCHED;
343 	} else if (line[idx] == 'p') {
344 		tr->flags |= TRACE_RECORD_PREEMPT_NEED_RESCHED;
345 	} else if (line[idx] != '.') {
346 		printf("Malformatted trace record, error parsing "
347 		       "need-resched:\n");
348 		printf("%s", line);
349 		return -1;
350 	}
351 	idx++;
352 
353 	if (line[idx] != IRQ_CONTEXT_NORMAL && line[idx] != IRQ_CONTEXT_SOFT &&
354 	    line[idx] != IRQ_CONTEXT_HARD &&
355 	    line[idx] != IRQ_CONTEXT_HARD_IN_SOFT &&
356 	    line[idx] != IRQ_CONTEXT_NMI && line[idx] != IRQ_CONTEXT_NMI_IN_HARD) {
357 		printf("Malformatted trace record, error parsing irq "
358 		       "context:\n");
359 		printf("%s", line);
360 		return -1;
361 	}
362 	tr->irq_context = line[idx];
363 	idx++;
364 
365 	if (line[idx+1] != ' ') {
366 		printf("Malformatted trace record, no space between"
367 		       "flags and timestamp:\n");
368 		printf("%s", line);
369 		return -1;
370 	}
371 	line[idx+1] = 0;
372 	if (line[idx] == '.') {
373 		tr->preempt_depth = 0;
374 	} else if (sscanf(&line[idx], "%hx", &tr->preempt_depth) != 1) {
375 		printf("Malformatted trace record, error parsing "
376 		       "preempt-depth:\n");
377 		printf("%s", line);
378 		return -1;
379 	}
380 	idx += 2;
381 
382 	while (line[idx] && line[idx] == ' ') idx++;
383 	if (!line[idx]) {
384 		printf("Malformatted trace record, missing timestamp:\n");
385 		printf("%s", line);
386 		return -1;
387 	}
388 	if (sscanf(&line[idx], "%d.%d: ", &tr->ts.sec,
389 		   &tr->ts.usec) != 2) {
390 		printf("Malformatted trace record, error parsing "
391 		       "timestamp:\n");
392 		printf("%s", line);
393 		return -1;
394 	}
395 	/* we know a space appears in the string because sscanf parsed it */
396 	found = strchr(&line[idx], ' ');
397 	idx = (found - line + 1);
398 	found = strchr(&line[idx], ':');
399 	if (!found) {
400 		printf("Malformatted trace record, error parsing "
401 		       "event name:\n");
402 		printf("%s", line);
403 		return -1;
404 	}
405 	*found = 0;
406 	tr->event_type = parse_event_type(&line[idx]);
407 
408 	/*
409 	 * there is a space between the ':' after the event name and the event
410 	 * data
411 	 */
412 	if (tr->event_type > 0)
413 		tr->event_data = parse_event_data(tr->event_type, found + 2);
414 
415 	return 0;
416 }
417 
418 #define TRACE_BUFFER_SIZE 8192
refill_buffer(char * buffer,char * idx)419 static int refill_buffer(char *buffer, char *idx)
420 {
421 	int bytes_in_buffer;
422 	int bytes_to_read;
423 	int bytes_read = 0;
424 	int rv;
425 	char buf[256];
426 
427 	bytes_in_buffer = TRACE_BUFFER_SIZE - (idx - buffer) - 1;
428 	bytes_to_read = TRACE_BUFFER_SIZE - bytes_in_buffer - 1;
429 
430 	if (trace_fd == -1) {
431 		snprintf(buf, sizeof(buf), "%strace", ftrace_root_dir);
432 
433 		trace_fd = open(buf, O_RDONLY);
434 		if (trace_fd == -1) {
435 			printf("Could not open trace file!\n");
436 			return 0;
437 		}
438 	}
439 
440 	/* Shift existing bytes in buffer to front. */
441 	memmove(buffer, idx, bytes_in_buffer);
442 	idx = buffer + bytes_in_buffer;
443 
444 	while(bytes_to_read) {
445 		rv = read(trace_fd, idx, bytes_to_read);
446 		if (rv == -1) {
447 			printf("Could not read trace file! (%d)\n", errno);
448 			return -1;
449 		}
450 		if (rv == 0)
451 			break;
452 		idx += rv;
453 		bytes_read += rv;
454 		bytes_to_read -= rv;
455 	}
456 
457 	return bytes_read;
458 }
459 
460 /*
461  * Returns a pointer to a null (not newline) terminated line
462  * of the trace.
463  */
read_trace_line(void)464 static char *read_trace_line(void)
465 {
466 	static char *idx;
467 	char *line, *newline;
468 	int rv;
469 
470 	if (!trace_buffer) {
471 		trace_buffer = SAFE_MALLOC(TRACE_BUFFER_SIZE);
472 		idx = trace_buffer + TRACE_BUFFER_SIZE - 1;
473 		*idx = 0;
474 	}
475 
476 	line = idx;
477 	newline = strchr(idx, '\n');
478 	if (!newline) {
479 		rv = refill_buffer(trace_buffer, idx);
480 		if (rv == -1 || rv == 0)
481 				return NULL;
482 		idx = trace_buffer;
483 		line = idx;
484 		newline = strchr(idx, '\n');
485 	}
486 	if (newline) {
487 		*newline = 0;
488 		idx = newline + 1;
489 		return line;
490 	}
491 	return NULL;
492 }
493 
load_trace(void)494 struct trace_record *load_trace(void)
495 {
496 	int buflines, unused;
497 	int tmp_num_trace_records = 0;
498 	char *line;
499 	enum parse_state_type {
500 		PARSE_STATE_SEEK_NUM_ENTRIES = 0,
501 		PARSE_STATE_REMAINING_COMMENTS,
502 		PARSE_STATE_TRACE_ENTRIES,
503 	};
504 	int parse_state = PARSE_STATE_SEEK_NUM_ENTRIES;
505 
506 	num_trace_records = 0;
507 
508 #ifdef PRINT_PARSING_UPDATES
509 	printf("\n");
510 #endif
511 	while((line = read_trace_line())) {
512 		if (line[0] == '#') {
513 			if (parse_state == PARSE_STATE_TRACE_ENTRIES) {
514 				printf("Malformatted trace output, comment"
515 				       "after start of trace entries.\n");
516 				if (trace)
517 					free(trace);
518 				return NULL;
519 			}
520 			if (parse_state == PARSE_STATE_REMAINING_COMMENTS)
521 				continue;
522 			if (sscanf(line,
523 				   "# entries-in-buffer/entries-written: "
524 				   "%d/%d",
525 				   &buflines, &unused) != 2) {
526 				continue;
527 			}
528 
529 			trace = SAFE_MALLOC(sizeof(struct trace_record) *
530 					    buflines);
531 			parse_state = PARSE_STATE_REMAINING_COMMENTS;
532 		} else {
533 			if (parse_state == PARSE_STATE_SEEK_NUM_ENTRIES) {
534 				printf("Malformatted trace output, non-comment "
535 				       "before number of entries.\n");
536 				if (trace)
537 					free(trace);
538 				return NULL;
539 			}
540 
541 			if (parse_state == PARSE_STATE_REMAINING_COMMENTS)
542 				parse_state = PARSE_STATE_TRACE_ENTRIES;
543 
544 			if (parse_trace_record(&trace[tmp_num_trace_records++],
545 					       line)) {
546 				printf("Malformatted trace record entry:\n");
547 				printf("%s\n", line);
548 				if (trace)
549 					free(trace);
550 				return NULL;
551 			}
552 #ifdef PRINT_PARSING_UPDATES
553 			if (tmp_num_trace_records%1000 == 0) {
554 				printf("\r%d/%d records processed",
555 				       tmp_num_trace_records, buflines);
556 				fflush(stdout);
557 			}
558 #endif
559 		}
560 	}
561 #ifdef PRINT_PARSING_UPDATES
562 	printf("\n");
563 #endif
564 	num_trace_records = tmp_num_trace_records;
565 	if (trace_fd >= 0) {
566 		close(trace_fd);
567 		trace_fd = -1;
568 	}
569 	if (trace_buffer) {
570 		free(trace_buffer);
571 		trace_buffer = NULL;
572 	}
573 	return trace;
574 }
575