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 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 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 89 void trace_cleanup(void) 90 { 91 SAFE_FILE_PRINTF(TRACING_DIR "tracing_on", "0"); 92 93 } 94 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 */ 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 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 */ 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 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
