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 letter is the migrate disable.
267 * Next is some number of spaces.
268 * Next twelve letters are the timestamp.
269 * Next char is colon.
270 * Next char is space.
271 * Next twelve letters are the event name.
272 * Next char is colon.
273 * Rest of line is string specific to event.
274 */
parse_trace_record(struct trace_record * tr,char * line)275 static int parse_trace_record(struct trace_record *tr, char *line) {
276 unsigned int field_start, idx = 0;
277 char *found;
278
279 /* Skip leading spaces in the task name. */
280 while (idx < 16 && line[idx] == ' ')
281 idx++;
282 if (idx == 16) {
283 printf("Malformatted trace record, no task name:\n");
284 printf("%s", line);
285 return -1;
286 }
287 memcpy(tr->task, &line[idx], 16-idx);
288 if (line[16] != '-') {
289 printf("Malformatted trace record, no dash after task "
290 "name:\n");
291 printf("%s", line);
292 return -1;
293 }
294 idx = 17;
295 while(line[idx] && line[idx] != '[') idx++;
296 if (!line[idx]) {
297 printf("Malformatted trace record, no open bracket for"
298 "CPU after pid:\n");
299 printf("%s", line);
300 return -1;
301 }
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 idx++;
323 if (sscanf(&line[field_start], "[%hd]", &tr->cpu) != 1) {
324 printf("Malformatted trace record, error parsing CPU:\n");
325 printf("%s", line);
326 return -1;
327 }
328
329 if (line[idx] == 'd') {
330 tr->flags |= TRACE_RECORD_IRQS_OFF;
331 } else if (line[idx] != '.') {
332 printf("Malformatted trace record, error parsing irqs-off:\n");
333 printf("%s", line);
334 return -1;
335 }
336 idx++;
337 if (line[idx] == 'N') {
338 tr->flags |= TRACE_RECORD_TIF_NEED_RESCHED;
339 tr->flags |= TRACE_RECORD_PREEMPT_NEED_RESCHED;
340 } else if (line[idx] == 'n') {
341 tr->flags |= TRACE_RECORD_TIF_NEED_RESCHED;
342 } else if (line[idx] == 'p') {
343 tr->flags |= TRACE_RECORD_PREEMPT_NEED_RESCHED;
344 } else if (line[idx] != '.') {
345 printf("Malformatted trace record, error parsing "
346 "need-resched:\n");
347 printf("%s", line);
348 return -1;
349 }
350 idx++;
351
352 if (line[idx] != IRQ_CONTEXT_NORMAL && line[idx] != IRQ_CONTEXT_SOFT &&
353 line[idx] != IRQ_CONTEXT_HARD &&
354 line[idx] != IRQ_CONTEXT_HARD_IN_SOFT &&
355 line[idx] != IRQ_CONTEXT_NMI && line[idx] != IRQ_CONTEXT_NMI_IN_HARD) {
356 printf("Malformatted trace record, error parsing irq "
357 "context:\n");
358 printf("%s", line);
359 return -1;
360 }
361 tr->irq_context = line[idx];
362 idx++;
363
364 if (line[idx] == '.') {
365 tr->preempt_depth = 0;
366 } else if (sscanf(&line[idx], "%hx", &tr->preempt_depth) != 1) {
367 printf("Malformatted trace record, error parsing "
368 "preempt-depth:\n");
369 printf("%s", line);
370 return -1;
371 }
372 idx++;
373
374 /* migrate_disable may not always exist */
375 if (line[idx] != ' ') {
376 if (line[idx] == '.')
377 tr->migrate_disable = 0;
378 else if (sscanf(&line[idx], "%d", &tr->migrate_disable) != 1) {
379 printf("Malformatted trace record, error parsing migrate_disable:\n");
380 printf("%s", line);
381 return -1;
382 }
383 idx++;
384 }
385
386 if (line[idx] != ' ') {
387 printf("Malformatted trace record, no space between:"
388 "flags and timestamp:\n");
389 printf("%s", line);
390 return -1;
391 }
392 idx++;
393
394 while (line[idx] && line[idx] == ' ') idx++;
395 if (!line[idx]) {
396 printf("Malformatted trace record, missing timestamp:\n");
397 printf("%s", line);
398 return -1;
399 }
400 if (sscanf(&line[idx], "%d.%d: ", &tr->ts.sec,
401 &tr->ts.usec) != 2) {
402 printf("Malformatted trace record, error parsing "
403 "timestamp:\n");
404 printf("%s", line);
405 return -1;
406 }
407 /* we know a space appears in the string because sscanf parsed it */
408 found = strchr(&line[idx], ' ');
409 idx = (found - line + 1);
410 found = strchr(&line[idx], ':');
411 if (!found) {
412 printf("Malformatted trace record, error parsing "
413 "event name:\n");
414 printf("%s", line);
415 return -1;
416 }
417 *found = 0;
418 tr->event_type = parse_event_type(&line[idx]);
419
420 /*
421 * there is a space between the ':' after the event name and the event
422 * data
423 */
424 if (tr->event_type > 0)
425 tr->event_data = parse_event_data(tr->event_type, found + 2);
426
427 return 0;
428 }
429
430 #define TRACE_BUFFER_SIZE 8192
refill_buffer(char * buffer,char * idx)431 static int refill_buffer(char *buffer, char *idx)
432 {
433 int bytes_in_buffer;
434 int bytes_to_read;
435 int bytes_read = 0;
436 int rv;
437 char buf[256];
438
439 bytes_in_buffer = TRACE_BUFFER_SIZE - (idx - buffer) - 1;
440 bytes_to_read = TRACE_BUFFER_SIZE - bytes_in_buffer - 1;
441
442 if (trace_fd == -1) {
443 snprintf(buf, sizeof(buf), "%strace", ftrace_root_dir);
444
445 trace_fd = open(buf, O_RDONLY);
446 if (trace_fd == -1) {
447 printf("Could not open trace file!\n");
448 return 0;
449 }
450 }
451
452 /* Shift existing bytes in buffer to front. */
453 memmove(buffer, idx, bytes_in_buffer);
454 idx = buffer + bytes_in_buffer;
455
456 while(bytes_to_read) {
457 rv = read(trace_fd, idx, bytes_to_read);
458 if (rv == -1) {
459 printf("Could not read trace file! (%d)\n", errno);
460 return -1;
461 }
462 if (rv == 0)
463 break;
464 idx += rv;
465 bytes_read += rv;
466 bytes_to_read -= rv;
467 }
468
469 return bytes_read;
470 }
471
472 /*
473 * Returns a pointer to a null (not newline) terminated line
474 * of the trace.
475 */
read_trace_line(void)476 static char *read_trace_line(void)
477 {
478 static char *idx;
479 char *line, *newline;
480 int rv;
481
482 if (!trace_buffer) {
483 trace_buffer = SAFE_MALLOC(TRACE_BUFFER_SIZE);
484 idx = trace_buffer + TRACE_BUFFER_SIZE - 1;
485 *idx = 0;
486 }
487
488 line = idx;
489 newline = strchr(idx, '\n');
490 if (!newline) {
491 rv = refill_buffer(trace_buffer, idx);
492 if (rv == -1 || rv == 0)
493 return NULL;
494 idx = trace_buffer;
495 line = idx;
496 newline = strchr(idx, '\n');
497 }
498 if (newline) {
499 *newline = 0;
500 idx = newline + 1;
501 return line;
502 }
503 return NULL;
504 }
505
load_trace(void)506 struct trace_record *load_trace(void)
507 {
508 int buflines, unused;
509 int tmp_num_trace_records = 0;
510 char *line;
511 enum parse_state_type {
512 PARSE_STATE_SEEK_NUM_ENTRIES = 0,
513 PARSE_STATE_REMAINING_COMMENTS,
514 PARSE_STATE_TRACE_ENTRIES,
515 };
516 int parse_state = PARSE_STATE_SEEK_NUM_ENTRIES;
517
518 num_trace_records = 0;
519
520 #ifdef PRINT_PARSING_UPDATES
521 printf("\n");
522 #endif
523 while((line = read_trace_line())) {
524 if (line[0] == '#') {
525 if (parse_state == PARSE_STATE_TRACE_ENTRIES) {
526 printf("Malformatted trace output, comment"
527 "after start of trace entries.\n");
528 if (trace)
529 free(trace);
530 return NULL;
531 }
532 if (parse_state == PARSE_STATE_REMAINING_COMMENTS)
533 continue;
534 if (sscanf(line,
535 "# entries-in-buffer/entries-written: "
536 "%d/%d",
537 &buflines, &unused) != 2) {
538 continue;
539 }
540
541 trace = SAFE_MALLOC(sizeof(struct trace_record) *
542 buflines);
543 parse_state = PARSE_STATE_REMAINING_COMMENTS;
544 } else {
545 if (parse_state == PARSE_STATE_SEEK_NUM_ENTRIES) {
546 printf("Malformatted trace output, non-comment "
547 "before number of entries.\n");
548 if (trace)
549 free(trace);
550 return NULL;
551 }
552
553 if (parse_state == PARSE_STATE_REMAINING_COMMENTS)
554 parse_state = PARSE_STATE_TRACE_ENTRIES;
555
556 if (parse_trace_record(&trace[tmp_num_trace_records++],
557 line)) {
558 printf("Malformatted trace record entry:\n");
559 printf("%s\n", line);
560 if (trace)
561 free(trace);
562 return NULL;
563 }
564 #ifdef PRINT_PARSING_UPDATES
565 if (tmp_num_trace_records%1000 == 0) {
566 printf("\r%d/%d records processed",
567 tmp_num_trace_records, buflines);
568 fflush(stdout);
569 }
570 #endif
571 }
572 }
573 #ifdef PRINT_PARSING_UPDATES
574 printf("\n");
575 #endif
576 num_trace_records = tmp_num_trace_records;
577 if (trace_fd >= 0) {
578 close(trace_fd);
579 trace_fd = -1;
580 }
581 if (trace_buffer) {
582 free(trace_buffer);
583 trace_buffer = NULL;
584 }
585 return trace;
586 }
587