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