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