1 // SPDX-License-Identifier: GPL-2.0 2 /* 3 * Copyright (C) 2021 Red Hat Inc, Daniel Bristot de Oliveira <bristot@kernel.org> 4 */ 5 6 #include <getopt.h> 7 #include <stdlib.h> 8 #include <string.h> 9 #include <signal.h> 10 #include <unistd.h> 11 #include <stdio.h> 12 #include <time.h> 13 14 #include "utils.h" 15 #include "osnoise.h" 16 #include "timerlat.h" 17 18 struct timerlat_top_params { 19 char *cpus; 20 char *monitored_cpus; 21 char *trace_output; 22 unsigned long long runtime; 23 long long stop_us; 24 long long stop_total_us; 25 long long timerlat_period_us; 26 long long print_stack; 27 int sleep_time; 28 int output_divisor; 29 int duration; 30 int quiet; 31 int set_sched; 32 int dma_latency; 33 struct sched_attr sched_param; 34 struct trace_events *events; 35 }; 36 37 struct timerlat_top_cpu { 38 int irq_count; 39 int thread_count; 40 41 unsigned long long cur_irq; 42 unsigned long long min_irq; 43 unsigned long long sum_irq; 44 unsigned long long max_irq; 45 46 unsigned long long cur_thread; 47 unsigned long long min_thread; 48 unsigned long long sum_thread; 49 unsigned long long max_thread; 50 }; 51 52 struct timerlat_top_data { 53 struct timerlat_top_cpu *cpu_data; 54 int nr_cpus; 55 }; 56 57 /* 58 * timerlat_free_top - free runtime data 59 */ 60 static void 61 timerlat_free_top(struct timerlat_top_data *data) 62 { 63 free(data->cpu_data); 64 free(data); 65 } 66 67 /* 68 * timerlat_alloc_histogram - alloc runtime data 69 */ 70 static struct timerlat_top_data *timerlat_alloc_top(int nr_cpus) 71 { 72 struct timerlat_top_data *data; 73 int cpu; 74 75 data = calloc(1, sizeof(*data)); 76 if (!data) 77 return NULL; 78 79 data->nr_cpus = nr_cpus; 80 81 /* one set of histograms per CPU */ 82 data->cpu_data = calloc(1, sizeof(*data->cpu_data) * nr_cpus); 83 if (!data->cpu_data) 84 goto cleanup; 85 86 /* set the min to max */ 87 for (cpu = 0; cpu < nr_cpus; cpu++) { 88 data->cpu_data[cpu].min_irq = ~0; 89 data->cpu_data[cpu].min_thread = ~0; 90 } 91 92 return data; 93 94 cleanup: 95 timerlat_free_top(data); 96 return NULL; 97 } 98 99 /* 100 * timerlat_hist_update - record a new timerlat occurent on cpu, updating data 101 */ 102 static void 103 timerlat_top_update(struct osnoise_tool *tool, int cpu, 104 unsigned long long thread, 105 unsigned long long latency) 106 { 107 struct timerlat_top_data *data = tool->data; 108 struct timerlat_top_cpu *cpu_data = &data->cpu_data[cpu]; 109 110 if (!thread) { 111 cpu_data->irq_count++; 112 cpu_data->cur_irq = latency; 113 update_min(&cpu_data->min_irq, &latency); 114 update_sum(&cpu_data->sum_irq, &latency); 115 update_max(&cpu_data->max_irq, &latency); 116 } else { 117 cpu_data->thread_count++; 118 cpu_data->cur_thread = latency; 119 update_min(&cpu_data->min_thread, &latency); 120 update_sum(&cpu_data->sum_thread, &latency); 121 update_max(&cpu_data->max_thread, &latency); 122 } 123 } 124 125 /* 126 * timerlat_top_handler - this is the handler for timerlat tracer events 127 */ 128 static int 129 timerlat_top_handler(struct trace_seq *s, struct tep_record *record, 130 struct tep_event *event, void *context) 131 { 132 struct trace_instance *trace = context; 133 unsigned long long latency, thread; 134 struct osnoise_tool *top; 135 int cpu = record->cpu; 136 137 top = container_of(trace, struct osnoise_tool, trace); 138 139 tep_get_field_val(s, event, "context", record, &thread, 1); 140 tep_get_field_val(s, event, "timer_latency", record, &latency, 1); 141 142 timerlat_top_update(top, cpu, thread, latency); 143 144 return 0; 145 } 146 147 /* 148 * timerlat_top_header - print the header of the tool output 149 */ 150 static void timerlat_top_header(struct osnoise_tool *top) 151 { 152 struct timerlat_top_params *params = top->params; 153 struct trace_seq *s = top->trace.seq; 154 char duration[26]; 155 156 get_duration(top->start_time, duration, sizeof(duration)); 157 158 trace_seq_printf(s, "\033[2;37;40m"); 159 trace_seq_printf(s, " Timer Latency "); 160 trace_seq_printf(s, "\033[0;0;0m"); 161 trace_seq_printf(s, "\n"); 162 163 trace_seq_printf(s, "%-6s | IRQ Timer Latency (%s) | Thread Timer Latency (%s)\n", duration, 164 params->output_divisor == 1 ? "ns" : "us", 165 params->output_divisor == 1 ? "ns" : "us"); 166 167 trace_seq_printf(s, "\033[2;30;47m"); 168 trace_seq_printf(s, "CPU COUNT | cur min avg max | cur min avg max"); 169 trace_seq_printf(s, "\033[0;0;0m"); 170 trace_seq_printf(s, "\n"); 171 } 172 173 /* 174 * timerlat_top_print - prints the output of a given CPU 175 */ 176 static void timerlat_top_print(struct osnoise_tool *top, int cpu) 177 { 178 179 struct timerlat_top_params *params = top->params; 180 struct timerlat_top_data *data = top->data; 181 struct timerlat_top_cpu *cpu_data = &data->cpu_data[cpu]; 182 int divisor = params->output_divisor; 183 struct trace_seq *s = top->trace.seq; 184 185 if (divisor == 0) 186 return; 187 188 /* 189 * Skip if no data is available: is this cpu offline? 190 */ 191 if (!cpu_data->irq_count && !cpu_data->thread_count) 192 return; 193 194 /* 195 * Unless trace is being lost, IRQ counter is always the max. 196 */ 197 trace_seq_printf(s, "%3d #%-9d |", cpu, cpu_data->irq_count); 198 199 if (!cpu_data->irq_count) { 200 trace_seq_printf(s, " - "); 201 trace_seq_printf(s, " - "); 202 trace_seq_printf(s, " - "); 203 trace_seq_printf(s, " - |"); 204 } else { 205 trace_seq_printf(s, "%9llu ", cpu_data->cur_irq / params->output_divisor); 206 trace_seq_printf(s, "%9llu ", cpu_data->min_irq / params->output_divisor); 207 trace_seq_printf(s, "%9llu ", (cpu_data->sum_irq / cpu_data->irq_count) / divisor); 208 trace_seq_printf(s, "%9llu |", cpu_data->max_irq / divisor); 209 } 210 211 if (!cpu_data->thread_count) { 212 trace_seq_printf(s, " - "); 213 trace_seq_printf(s, " - "); 214 trace_seq_printf(s, " - "); 215 trace_seq_printf(s, " -\n"); 216 } else { 217 trace_seq_printf(s, "%9llu ", cpu_data->cur_thread / divisor); 218 trace_seq_printf(s, "%9llu ", cpu_data->min_thread / divisor); 219 trace_seq_printf(s, "%9llu ", 220 (cpu_data->sum_thread / cpu_data->thread_count) / divisor); 221 trace_seq_printf(s, "%9llu\n", cpu_data->max_thread / divisor); 222 } 223 } 224 225 /* 226 * clear_terminal - clears the output terminal 227 */ 228 static void clear_terminal(struct trace_seq *seq) 229 { 230 if (!config_debug) 231 trace_seq_printf(seq, "\033c"); 232 } 233 234 /* 235 * timerlat_print_stats - print data for all cpus 236 */ 237 static void 238 timerlat_print_stats(struct timerlat_top_params *params, struct osnoise_tool *top) 239 { 240 struct trace_instance *trace = &top->trace; 241 static int nr_cpus = -1; 242 int i; 243 244 if (nr_cpus == -1) 245 nr_cpus = sysconf(_SC_NPROCESSORS_CONF); 246 247 if (!params->quiet) 248 clear_terminal(trace->seq); 249 250 timerlat_top_header(top); 251 252 for (i = 0; i < nr_cpus; i++) { 253 if (params->cpus && !params->monitored_cpus[i]) 254 continue; 255 timerlat_top_print(top, i); 256 } 257 258 trace_seq_do_printf(trace->seq); 259 trace_seq_reset(trace->seq); 260 } 261 262 /* 263 * timerlat_top_usage - prints timerlat top usage message 264 */ 265 static void timerlat_top_usage(char *usage) 266 { 267 int i; 268 269 static const char *const msg[] = { 270 "", 271 " usage: rtla timerlat [top] [-h] [-q] [-a us] [-d s] [-D] [-n] [-p us] [-i us] [-T us] [-s us] \\", 272 " [[-t[=file]] [-e sys[:event]] [--filter <filter>] [--trigger <trigger>] [-c cpu-list] \\", 273 " [-P priority] [--dma-latency us]", 274 "", 275 " -h/--help: print this menu", 276 " -a/--auto: set automatic trace mode, stopping the session if argument in us latency is hit", 277 " -p/--period us: timerlat period in us", 278 " -i/--irq us: stop trace if the irq latency is higher than the argument in us", 279 " -T/--thread us: stop trace if the thread latency is higher than the argument in us", 280 " -s/--stack us: save the stack trace at the IRQ if a thread latency is higher than the argument in us", 281 " -c/--cpus cpus: run the tracer only on the given cpus", 282 " -d/--duration time[m|h|d]: duration of the session in seconds", 283 " -D/--debug: print debug info", 284 " -t/--trace[=file]: save the stopped trace to [file|timerlat_trace.txt]", 285 " -e/--event <sys:event>: enable the <sys:event> in the trace instance, multiple -e are allowed", 286 " --filter <command>: enable a trace event filter to the previous -e event", 287 " --trigger <command>: enable a trace event trigger to the previous -e event", 288 " -n/--nano: display data in nanoseconds", 289 " -q/--quiet print only a summary at the end", 290 " --dma-latency us: set /dev/cpu_dma_latency latency <us> to reduce exit from idle latency", 291 " -P/--priority o:prio|r:prio|f:prio|d:runtime:period : set scheduling parameters", 292 " o:prio - use SCHED_OTHER with prio", 293 " r:prio - use SCHED_RR with prio", 294 " f:prio - use SCHED_FIFO with prio", 295 " d:runtime[us|ms|s]:period[us|ms|s] - use SCHED_DEADLINE with runtime and period", 296 " in nanoseconds", 297 NULL, 298 }; 299 300 if (usage) 301 fprintf(stderr, "%s\n", usage); 302 303 fprintf(stderr, "rtla timerlat top: a per-cpu summary of the timer latency (version %s)\n", 304 VERSION); 305 306 for (i = 0; msg[i]; i++) 307 fprintf(stderr, "%s\n", msg[i]); 308 exit(1); 309 } 310 311 /* 312 * timerlat_top_parse_args - allocs, parse and fill the cmd line parameters 313 */ 314 static struct timerlat_top_params 315 *timerlat_top_parse_args(int argc, char **argv) 316 { 317 struct timerlat_top_params *params; 318 struct trace_events *tevent; 319 long long auto_thresh; 320 int retval; 321 int c; 322 323 params = calloc(1, sizeof(*params)); 324 if (!params) 325 exit(1); 326 327 /* disabled by default */ 328 params->dma_latency = -1; 329 330 /* display data in microseconds */ 331 params->output_divisor = 1000; 332 333 while (1) { 334 static struct option long_options[] = { 335 {"auto", required_argument, 0, 'a'}, 336 {"cpus", required_argument, 0, 'c'}, 337 {"debug", no_argument, 0, 'D'}, 338 {"duration", required_argument, 0, 'd'}, 339 {"event", required_argument, 0, 'e'}, 340 {"help", no_argument, 0, 'h'}, 341 {"irq", required_argument, 0, 'i'}, 342 {"nano", no_argument, 0, 'n'}, 343 {"period", required_argument, 0, 'p'}, 344 {"priority", required_argument, 0, 'P'}, 345 {"quiet", no_argument, 0, 'q'}, 346 {"stack", required_argument, 0, 's'}, 347 {"thread", required_argument, 0, 'T'}, 348 {"trace", optional_argument, 0, 't'}, 349 {"trigger", required_argument, 0, '0'}, 350 {"filter", required_argument, 0, '1'}, 351 {"dma-latency", required_argument, 0, '2'}, 352 {0, 0, 0, 0} 353 }; 354 355 /* getopt_long stores the option index here. */ 356 int option_index = 0; 357 358 c = getopt_long(argc, argv, "a:c:d:De:hi:np:P:qs:t::T:0:1:2:", 359 long_options, &option_index); 360 361 /* detect the end of the options. */ 362 if (c == -1) 363 break; 364 365 switch (c) { 366 case 'a': 367 auto_thresh = get_llong_from_str(optarg); 368 369 /* set thread stop to auto_thresh */ 370 params->stop_total_us = auto_thresh; 371 372 /* get stack trace */ 373 params->print_stack = auto_thresh; 374 375 /* set trace */ 376 params->trace_output = "timerlat_trace.txt"; 377 378 break; 379 case 'c': 380 retval = parse_cpu_list(optarg, ¶ms->monitored_cpus); 381 if (retval) 382 timerlat_top_usage("\nInvalid -c cpu list\n"); 383 params->cpus = optarg; 384 break; 385 case 'D': 386 config_debug = 1; 387 break; 388 case 'd': 389 params->duration = parse_seconds_duration(optarg); 390 if (!params->duration) 391 timerlat_top_usage("Invalid -D duration\n"); 392 break; 393 case 'e': 394 tevent = trace_event_alloc(optarg); 395 if (!tevent) { 396 err_msg("Error alloc trace event"); 397 exit(EXIT_FAILURE); 398 } 399 400 if (params->events) 401 tevent->next = params->events; 402 params->events = tevent; 403 break; 404 case 'h': 405 case '?': 406 timerlat_top_usage(NULL); 407 break; 408 case 'i': 409 params->stop_us = get_llong_from_str(optarg); 410 break; 411 case 'n': 412 params->output_divisor = 1; 413 break; 414 case 'p': 415 params->timerlat_period_us = get_llong_from_str(optarg); 416 if (params->timerlat_period_us > 1000000) 417 timerlat_top_usage("Period longer than 1 s\n"); 418 break; 419 case 'P': 420 retval = parse_prio(optarg, ¶ms->sched_param); 421 if (retval == -1) 422 timerlat_top_usage("Invalid -P priority"); 423 params->set_sched = 1; 424 break; 425 case 'q': 426 params->quiet = 1; 427 break; 428 case 's': 429 params->print_stack = get_llong_from_str(optarg); 430 break; 431 case 'T': 432 params->stop_total_us = get_llong_from_str(optarg); 433 break; 434 case 't': 435 if (optarg) 436 /* skip = */ 437 params->trace_output = &optarg[1]; 438 else 439 params->trace_output = "timerlat_trace.txt"; 440 break; 441 case '0': /* trigger */ 442 if (params->events) { 443 retval = trace_event_add_trigger(params->events, optarg); 444 if (retval) { 445 err_msg("Error adding trigger %s\n", optarg); 446 exit(EXIT_FAILURE); 447 } 448 } else { 449 timerlat_top_usage("--trigger requires a previous -e\n"); 450 } 451 break; 452 case '1': /* filter */ 453 if (params->events) { 454 retval = trace_event_add_filter(params->events, optarg); 455 if (retval) { 456 err_msg("Error adding filter %s\n", optarg); 457 exit(EXIT_FAILURE); 458 } 459 } else { 460 timerlat_top_usage("--filter requires a previous -e\n"); 461 } 462 break; 463 case '2': /* dma-latency */ 464 params->dma_latency = get_llong_from_str(optarg); 465 if (params->dma_latency < 0 || params->dma_latency > 10000) { 466 err_msg("--dma-latency needs to be >= 0 and < 10000"); 467 exit(EXIT_FAILURE); 468 } 469 break; 470 default: 471 timerlat_top_usage("Invalid option"); 472 } 473 } 474 475 if (geteuid()) { 476 err_msg("rtla needs root permission\n"); 477 exit(EXIT_FAILURE); 478 } 479 480 return params; 481 } 482 483 /* 484 * timerlat_top_apply_config - apply the top configs to the initialized tool 485 */ 486 static int 487 timerlat_top_apply_config(struct osnoise_tool *top, struct timerlat_top_params *params) 488 { 489 int retval; 490 491 if (!params->sleep_time) 492 params->sleep_time = 1; 493 494 if (params->cpus) { 495 retval = osnoise_set_cpus(top->context, params->cpus); 496 if (retval) { 497 err_msg("Failed to apply CPUs config\n"); 498 goto out_err; 499 } 500 } 501 502 if (params->stop_us) { 503 retval = osnoise_set_stop_us(top->context, params->stop_us); 504 if (retval) { 505 err_msg("Failed to set stop us\n"); 506 goto out_err; 507 } 508 } 509 510 if (params->stop_total_us) { 511 retval = osnoise_set_stop_total_us(top->context, params->stop_total_us); 512 if (retval) { 513 err_msg("Failed to set stop total us\n"); 514 goto out_err; 515 } 516 } 517 518 519 if (params->timerlat_period_us) { 520 retval = osnoise_set_timerlat_period_us(top->context, params->timerlat_period_us); 521 if (retval) { 522 err_msg("Failed to set timerlat period\n"); 523 goto out_err; 524 } 525 } 526 527 528 if (params->print_stack) { 529 retval = osnoise_set_print_stack(top->context, params->print_stack); 530 if (retval) { 531 err_msg("Failed to set print stack\n"); 532 goto out_err; 533 } 534 } 535 536 return 0; 537 538 out_err: 539 return -1; 540 } 541 542 /* 543 * timerlat_init_top - initialize a timerlat top tool with parameters 544 */ 545 static struct osnoise_tool 546 *timerlat_init_top(struct timerlat_top_params *params) 547 { 548 struct osnoise_tool *top; 549 int nr_cpus; 550 551 nr_cpus = sysconf(_SC_NPROCESSORS_CONF); 552 553 top = osnoise_init_tool("timerlat_top"); 554 if (!top) 555 return NULL; 556 557 top->data = timerlat_alloc_top(nr_cpus); 558 if (!top->data) 559 goto out_err; 560 561 top->params = params; 562 563 tep_register_event_handler(top->trace.tep, -1, "ftrace", "timerlat", 564 timerlat_top_handler, top); 565 566 return top; 567 568 out_err: 569 osnoise_destroy_tool(top); 570 return NULL; 571 } 572 573 static int stop_tracing; 574 static void stop_top(int sig) 575 { 576 stop_tracing = 1; 577 } 578 579 /* 580 * timerlat_top_set_signals - handles the signal to stop the tool 581 */ 582 static void 583 timerlat_top_set_signals(struct timerlat_top_params *params) 584 { 585 signal(SIGINT, stop_top); 586 if (params->duration) { 587 signal(SIGALRM, stop_top); 588 alarm(params->duration); 589 } 590 } 591 592 int timerlat_top_main(int argc, char *argv[]) 593 { 594 struct timerlat_top_params *params; 595 struct osnoise_tool *record = NULL; 596 struct osnoise_tool *top = NULL; 597 struct trace_instance *trace; 598 int dma_latency_fd = -1; 599 int return_value = 1; 600 int retval; 601 602 params = timerlat_top_parse_args(argc, argv); 603 if (!params) 604 exit(1); 605 606 top = timerlat_init_top(params); 607 if (!top) { 608 err_msg("Could not init osnoise top\n"); 609 goto out_exit; 610 } 611 612 retval = timerlat_top_apply_config(top, params); 613 if (retval) { 614 err_msg("Could not apply config\n"); 615 goto out_free; 616 } 617 618 trace = &top->trace; 619 620 retval = enable_timerlat(trace); 621 if (retval) { 622 err_msg("Failed to enable timerlat tracer\n"); 623 goto out_free; 624 } 625 626 if (params->set_sched) { 627 retval = set_comm_sched_attr("timerlat/", ¶ms->sched_param); 628 if (retval) { 629 err_msg("Failed to set sched parameters\n"); 630 goto out_free; 631 } 632 } 633 634 if (params->dma_latency >= 0) { 635 dma_latency_fd = set_cpu_dma_latency(params->dma_latency); 636 if (dma_latency_fd < 0) { 637 err_msg("Could not set /dev/cpu_dma_latency.\n"); 638 goto out_free; 639 } 640 } 641 642 trace_instance_start(trace); 643 644 if (params->trace_output) { 645 record = osnoise_init_trace_tool("timerlat"); 646 if (!record) { 647 err_msg("Failed to enable the trace instance\n"); 648 goto out_free; 649 } 650 651 if (params->events) { 652 retval = trace_events_enable(&record->trace, params->events); 653 if (retval) 654 goto out_top; 655 } 656 657 trace_instance_start(&record->trace); 658 } 659 660 top->start_time = time(NULL); 661 timerlat_top_set_signals(params); 662 663 while (!stop_tracing) { 664 sleep(params->sleep_time); 665 666 retval = tracefs_iterate_raw_events(trace->tep, 667 trace->inst, 668 NULL, 669 0, 670 collect_registered_events, 671 trace); 672 if (retval < 0) { 673 err_msg("Error iterating on events\n"); 674 goto out_top; 675 } 676 677 if (!params->quiet) 678 timerlat_print_stats(params, top); 679 680 if (trace_is_off(&top->trace, &record->trace)) 681 break; 682 683 } 684 685 timerlat_print_stats(params, top); 686 687 return_value = 0; 688 689 if (trace_is_off(&top->trace, &record->trace)) { 690 printf("rtla timerlat hit stop tracing\n"); 691 if (params->trace_output) { 692 printf(" Saving trace to %s\n", params->trace_output); 693 save_trace_to_file(record->trace.inst, params->trace_output); 694 } 695 } 696 697 out_top: 698 if (dma_latency_fd >= 0) 699 close(dma_latency_fd); 700 trace_events_destroy(&record->trace, params->events); 701 params->events = NULL; 702 out_free: 703 timerlat_free_top(top->data); 704 osnoise_destroy_tool(record); 705 osnoise_destroy_tool(top); 706 free(params); 707 out_exit: 708 exit(return_value); 709 } 710