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 #define _GNU_SOURCE 7 #include <getopt.h> 8 #include <stdlib.h> 9 #include <string.h> 10 #include <signal.h> 11 #include <unistd.h> 12 #include <stdio.h> 13 #include <time.h> 14 #include <sched.h> 15 #include <pthread.h> 16 17 #include "timerlat.h" 18 #include "timerlat_aa.h" 19 #include "timerlat_bpf.h" 20 21 struct timerlat_hist_cpu { 22 int *irq; 23 int *thread; 24 int *user; 25 26 unsigned long long irq_count; 27 unsigned long long thread_count; 28 unsigned long long user_count; 29 30 unsigned long long min_irq; 31 unsigned long long sum_irq; 32 unsigned long long max_irq; 33 34 unsigned long long min_thread; 35 unsigned long long sum_thread; 36 unsigned long long max_thread; 37 38 unsigned long long min_user; 39 unsigned long long sum_user; 40 unsigned long long max_user; 41 }; 42 43 struct timerlat_hist_data { 44 struct timerlat_hist_cpu *hist; 45 int entries; 46 int bucket_size; 47 int nr_cpus; 48 }; 49 50 /* 51 * timerlat_free_histogram - free runtime data 52 */ 53 static void 54 timerlat_free_histogram(struct timerlat_hist_data *data) 55 { 56 int cpu; 57 58 /* one histogram for IRQ and one for thread, per CPU */ 59 for (cpu = 0; cpu < data->nr_cpus; cpu++) { 60 if (data->hist[cpu].irq) 61 free(data->hist[cpu].irq); 62 63 if (data->hist[cpu].thread) 64 free(data->hist[cpu].thread); 65 66 if (data->hist[cpu].user) 67 free(data->hist[cpu].user); 68 69 } 70 71 /* one set of histograms per CPU */ 72 if (data->hist) 73 free(data->hist); 74 } 75 76 static void timerlat_free_histogram_tool(struct osnoise_tool *tool) 77 { 78 timerlat_free_histogram(tool->data); 79 timerlat_free(tool); 80 } 81 82 /* 83 * timerlat_alloc_histogram - alloc runtime data 84 */ 85 static struct timerlat_hist_data 86 *timerlat_alloc_histogram(int nr_cpus, int entries, int bucket_size) 87 { 88 struct timerlat_hist_data *data; 89 int cpu; 90 91 data = calloc(1, sizeof(*data)); 92 if (!data) 93 return NULL; 94 95 data->entries = entries; 96 data->bucket_size = bucket_size; 97 data->nr_cpus = nr_cpus; 98 99 /* one set of histograms per CPU */ 100 data->hist = calloc(1, sizeof(*data->hist) * nr_cpus); 101 if (!data->hist) 102 goto cleanup; 103 104 /* one histogram for IRQ and one for thread, per cpu */ 105 for (cpu = 0; cpu < nr_cpus; cpu++) { 106 data->hist[cpu].irq = calloc(1, sizeof(*data->hist->irq) * (entries + 1)); 107 if (!data->hist[cpu].irq) 108 goto cleanup; 109 110 data->hist[cpu].thread = calloc(1, sizeof(*data->hist->thread) * (entries + 1)); 111 if (!data->hist[cpu].thread) 112 goto cleanup; 113 114 data->hist[cpu].user = calloc(1, sizeof(*data->hist->user) * (entries + 1)); 115 if (!data->hist[cpu].user) 116 goto cleanup; 117 } 118 119 /* set the min to max */ 120 for (cpu = 0; cpu < nr_cpus; cpu++) { 121 data->hist[cpu].min_irq = ~0; 122 data->hist[cpu].min_thread = ~0; 123 data->hist[cpu].min_user = ~0; 124 } 125 126 return data; 127 128 cleanup: 129 timerlat_free_histogram(data); 130 return NULL; 131 } 132 133 /* 134 * timerlat_hist_update - record a new timerlat occurent on cpu, updating data 135 */ 136 static void 137 timerlat_hist_update(struct osnoise_tool *tool, int cpu, 138 unsigned long long context, 139 unsigned long long latency) 140 { 141 struct timerlat_params *params = to_timerlat_params(tool->params); 142 struct timerlat_hist_data *data = tool->data; 143 int entries = data->entries; 144 int bucket; 145 int *hist; 146 147 if (params->common.output_divisor) 148 latency = latency / params->common.output_divisor; 149 150 bucket = latency / data->bucket_size; 151 152 if (!context) { 153 hist = data->hist[cpu].irq; 154 data->hist[cpu].irq_count++; 155 update_min(&data->hist[cpu].min_irq, &latency); 156 update_sum(&data->hist[cpu].sum_irq, &latency); 157 update_max(&data->hist[cpu].max_irq, &latency); 158 } else if (context == 1) { 159 hist = data->hist[cpu].thread; 160 data->hist[cpu].thread_count++; 161 update_min(&data->hist[cpu].min_thread, &latency); 162 update_sum(&data->hist[cpu].sum_thread, &latency); 163 update_max(&data->hist[cpu].max_thread, &latency); 164 } else { /* user */ 165 hist = data->hist[cpu].user; 166 data->hist[cpu].user_count++; 167 update_min(&data->hist[cpu].min_user, &latency); 168 update_sum(&data->hist[cpu].sum_user, &latency); 169 update_max(&data->hist[cpu].max_user, &latency); 170 } 171 172 if (bucket < entries) 173 hist[bucket]++; 174 else 175 hist[entries]++; 176 } 177 178 /* 179 * timerlat_hist_handler - this is the handler for timerlat tracer events 180 */ 181 static int 182 timerlat_hist_handler(struct trace_seq *s, struct tep_record *record, 183 struct tep_event *event, void *data) 184 { 185 struct trace_instance *trace = data; 186 unsigned long long context, latency; 187 struct osnoise_tool *tool; 188 int cpu = record->cpu; 189 190 tool = container_of(trace, struct osnoise_tool, trace); 191 192 tep_get_field_val(s, event, "context", record, &context, 1); 193 tep_get_field_val(s, event, "timer_latency", record, &latency, 1); 194 195 timerlat_hist_update(tool, cpu, context, latency); 196 197 return 0; 198 } 199 200 /* 201 * timerlat_hist_bpf_pull_data - copy data from BPF maps into userspace 202 */ 203 static int timerlat_hist_bpf_pull_data(struct osnoise_tool *tool) 204 { 205 struct timerlat_hist_data *data = tool->data; 206 int i, j, err; 207 long long value_irq[data->nr_cpus], 208 value_thread[data->nr_cpus], 209 value_user[data->nr_cpus]; 210 211 /* Pull histogram */ 212 for (i = 0; i < data->entries; i++) { 213 err = timerlat_bpf_get_hist_value(i, value_irq, value_thread, 214 value_user, data->nr_cpus); 215 if (err) 216 return err; 217 for (j = 0; j < data->nr_cpus; j++) { 218 data->hist[j].irq[i] = value_irq[j]; 219 data->hist[j].thread[i] = value_thread[j]; 220 data->hist[j].user[i] = value_user[j]; 221 } 222 } 223 224 /* Pull summary */ 225 err = timerlat_bpf_get_summary_value(SUMMARY_COUNT, 226 value_irq, value_thread, value_user, 227 data->nr_cpus); 228 if (err) 229 return err; 230 for (i = 0; i < data->nr_cpus; i++) { 231 data->hist[i].irq_count = value_irq[i]; 232 data->hist[i].thread_count = value_thread[i]; 233 data->hist[i].user_count = value_user[i]; 234 } 235 236 err = timerlat_bpf_get_summary_value(SUMMARY_MIN, 237 value_irq, value_thread, value_user, 238 data->nr_cpus); 239 if (err) 240 return err; 241 for (i = 0; i < data->nr_cpus; i++) { 242 data->hist[i].min_irq = value_irq[i]; 243 data->hist[i].min_thread = value_thread[i]; 244 data->hist[i].min_user = value_user[i]; 245 } 246 247 err = timerlat_bpf_get_summary_value(SUMMARY_MAX, 248 value_irq, value_thread, value_user, 249 data->nr_cpus); 250 if (err) 251 return err; 252 for (i = 0; i < data->nr_cpus; i++) { 253 data->hist[i].max_irq = value_irq[i]; 254 data->hist[i].max_thread = value_thread[i]; 255 data->hist[i].max_user = value_user[i]; 256 } 257 258 err = timerlat_bpf_get_summary_value(SUMMARY_SUM, 259 value_irq, value_thread, value_user, 260 data->nr_cpus); 261 if (err) 262 return err; 263 for (i = 0; i < data->nr_cpus; i++) { 264 data->hist[i].sum_irq = value_irq[i]; 265 data->hist[i].sum_thread = value_thread[i]; 266 data->hist[i].sum_user = value_user[i]; 267 } 268 269 err = timerlat_bpf_get_summary_value(SUMMARY_OVERFLOW, 270 value_irq, value_thread, value_user, 271 data->nr_cpus); 272 if (err) 273 return err; 274 for (i = 0; i < data->nr_cpus; i++) { 275 data->hist[i].irq[data->entries] = value_irq[i]; 276 data->hist[i].thread[data->entries] = value_thread[i]; 277 data->hist[i].user[data->entries] = value_user[i]; 278 } 279 280 return 0; 281 } 282 283 /* 284 * timerlat_hist_header - print the header of the tracer to the output 285 */ 286 static void timerlat_hist_header(struct osnoise_tool *tool) 287 { 288 struct timerlat_params *params = to_timerlat_params(tool->params); 289 struct timerlat_hist_data *data = tool->data; 290 struct trace_seq *s = tool->trace.seq; 291 char duration[26]; 292 int cpu; 293 294 if (params->common.hist.no_header) 295 return; 296 297 get_duration(tool->start_time, duration, sizeof(duration)); 298 trace_seq_printf(s, "# RTLA timerlat histogram\n"); 299 trace_seq_printf(s, "# Time unit is %s (%s)\n", 300 params->common.output_divisor == 1 ? "nanoseconds" : "microseconds", 301 params->common.output_divisor == 1 ? "ns" : "us"); 302 303 trace_seq_printf(s, "# Duration: %s\n", duration); 304 305 if (!params->common.hist.no_index) 306 trace_seq_printf(s, "Index"); 307 308 for (cpu = 0; cpu < data->nr_cpus; cpu++) { 309 if (params->common.cpus && !CPU_ISSET(cpu, ¶ms->common.monitored_cpus)) 310 continue; 311 312 if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count) 313 continue; 314 315 if (!params->common.hist.no_irq) 316 trace_seq_printf(s, " IRQ-%03d", cpu); 317 318 if (!params->common.hist.no_thread) 319 trace_seq_printf(s, " Thr-%03d", cpu); 320 321 if (params->common.user_data) 322 trace_seq_printf(s, " Usr-%03d", cpu); 323 } 324 trace_seq_printf(s, "\n"); 325 326 327 trace_seq_do_printf(s); 328 trace_seq_reset(s); 329 } 330 331 /* 332 * format_summary_value - format a line of summary value (min, max or avg) 333 * of hist data 334 */ 335 static void format_summary_value(struct trace_seq *seq, 336 int count, 337 unsigned long long val, 338 bool avg) 339 { 340 if (count) 341 trace_seq_printf(seq, "%9llu ", avg ? val / count : val); 342 else 343 trace_seq_printf(seq, "%9c ", '-'); 344 } 345 346 /* 347 * timerlat_print_summary - print the summary of the hist data to the output 348 */ 349 static void 350 timerlat_print_summary(struct timerlat_params *params, 351 struct trace_instance *trace, 352 struct timerlat_hist_data *data) 353 { 354 int cpu; 355 356 if (params->common.hist.no_summary) 357 return; 358 359 if (!params->common.hist.no_index) 360 trace_seq_printf(trace->seq, "count:"); 361 362 for (cpu = 0; cpu < data->nr_cpus; cpu++) { 363 if (params->common.cpus && !CPU_ISSET(cpu, ¶ms->common.monitored_cpus)) 364 continue; 365 366 if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count) 367 continue; 368 369 if (!params->common.hist.no_irq) 370 trace_seq_printf(trace->seq, "%9llu ", 371 data->hist[cpu].irq_count); 372 373 if (!params->common.hist.no_thread) 374 trace_seq_printf(trace->seq, "%9llu ", 375 data->hist[cpu].thread_count); 376 377 if (params->common.user_data) 378 trace_seq_printf(trace->seq, "%9llu ", 379 data->hist[cpu].user_count); 380 } 381 trace_seq_printf(trace->seq, "\n"); 382 383 if (!params->common.hist.no_index) 384 trace_seq_printf(trace->seq, "min: "); 385 386 for (cpu = 0; cpu < data->nr_cpus; cpu++) { 387 if (params->common.cpus && !CPU_ISSET(cpu, ¶ms->common.monitored_cpus)) 388 continue; 389 390 if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count) 391 continue; 392 393 if (!params->common.hist.no_irq) 394 format_summary_value(trace->seq, 395 data->hist[cpu].irq_count, 396 data->hist[cpu].min_irq, 397 false); 398 399 if (!params->common.hist.no_thread) 400 format_summary_value(trace->seq, 401 data->hist[cpu].thread_count, 402 data->hist[cpu].min_thread, 403 false); 404 405 if (params->common.user_data) 406 format_summary_value(trace->seq, 407 data->hist[cpu].user_count, 408 data->hist[cpu].min_user, 409 false); 410 } 411 trace_seq_printf(trace->seq, "\n"); 412 413 if (!params->common.hist.no_index) 414 trace_seq_printf(trace->seq, "avg: "); 415 416 for (cpu = 0; cpu < data->nr_cpus; cpu++) { 417 if (params->common.cpus && !CPU_ISSET(cpu, ¶ms->common.monitored_cpus)) 418 continue; 419 420 if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count) 421 continue; 422 423 if (!params->common.hist.no_irq) 424 format_summary_value(trace->seq, 425 data->hist[cpu].irq_count, 426 data->hist[cpu].sum_irq, 427 true); 428 429 if (!params->common.hist.no_thread) 430 format_summary_value(trace->seq, 431 data->hist[cpu].thread_count, 432 data->hist[cpu].sum_thread, 433 true); 434 435 if (params->common.user_data) 436 format_summary_value(trace->seq, 437 data->hist[cpu].user_count, 438 data->hist[cpu].sum_user, 439 true); 440 } 441 trace_seq_printf(trace->seq, "\n"); 442 443 if (!params->common.hist.no_index) 444 trace_seq_printf(trace->seq, "max: "); 445 446 for (cpu = 0; cpu < data->nr_cpus; cpu++) { 447 if (params->common.cpus && !CPU_ISSET(cpu, ¶ms->common.monitored_cpus)) 448 continue; 449 450 if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count) 451 continue; 452 453 if (!params->common.hist.no_irq) 454 format_summary_value(trace->seq, 455 data->hist[cpu].irq_count, 456 data->hist[cpu].max_irq, 457 false); 458 459 if (!params->common.hist.no_thread) 460 format_summary_value(trace->seq, 461 data->hist[cpu].thread_count, 462 data->hist[cpu].max_thread, 463 false); 464 465 if (params->common.user_data) 466 format_summary_value(trace->seq, 467 data->hist[cpu].user_count, 468 data->hist[cpu].max_user, 469 false); 470 } 471 trace_seq_printf(trace->seq, "\n"); 472 trace_seq_do_printf(trace->seq); 473 trace_seq_reset(trace->seq); 474 } 475 476 static void 477 timerlat_print_stats_all(struct timerlat_params *params, 478 struct trace_instance *trace, 479 struct timerlat_hist_data *data) 480 { 481 struct timerlat_hist_cpu *cpu_data; 482 struct timerlat_hist_cpu sum; 483 int cpu; 484 485 if (params->common.hist.no_summary) 486 return; 487 488 memset(&sum, 0, sizeof(sum)); 489 sum.min_irq = ~0; 490 sum.min_thread = ~0; 491 sum.min_user = ~0; 492 493 for (cpu = 0; cpu < data->nr_cpus; cpu++) { 494 if (params->common.cpus && !CPU_ISSET(cpu, ¶ms->common.monitored_cpus)) 495 continue; 496 497 if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count) 498 continue; 499 500 cpu_data = &data->hist[cpu]; 501 502 sum.irq_count += cpu_data->irq_count; 503 update_min(&sum.min_irq, &cpu_data->min_irq); 504 update_sum(&sum.sum_irq, &cpu_data->sum_irq); 505 update_max(&sum.max_irq, &cpu_data->max_irq); 506 507 sum.thread_count += cpu_data->thread_count; 508 update_min(&sum.min_thread, &cpu_data->min_thread); 509 update_sum(&sum.sum_thread, &cpu_data->sum_thread); 510 update_max(&sum.max_thread, &cpu_data->max_thread); 511 512 sum.user_count += cpu_data->user_count; 513 update_min(&sum.min_user, &cpu_data->min_user); 514 update_sum(&sum.sum_user, &cpu_data->sum_user); 515 update_max(&sum.max_user, &cpu_data->max_user); 516 } 517 518 if (!params->common.hist.no_index) 519 trace_seq_printf(trace->seq, "ALL: "); 520 521 if (!params->common.hist.no_irq) 522 trace_seq_printf(trace->seq, " IRQ"); 523 524 if (!params->common.hist.no_thread) 525 trace_seq_printf(trace->seq, " Thr"); 526 527 if (params->common.user_data) 528 trace_seq_printf(trace->seq, " Usr"); 529 530 trace_seq_printf(trace->seq, "\n"); 531 532 if (!params->common.hist.no_index) 533 trace_seq_printf(trace->seq, "count:"); 534 535 if (!params->common.hist.no_irq) 536 trace_seq_printf(trace->seq, "%9llu ", 537 sum.irq_count); 538 539 if (!params->common.hist.no_thread) 540 trace_seq_printf(trace->seq, "%9llu ", 541 sum.thread_count); 542 543 if (params->common.user_data) 544 trace_seq_printf(trace->seq, "%9llu ", 545 sum.user_count); 546 547 trace_seq_printf(trace->seq, "\n"); 548 549 if (!params->common.hist.no_index) 550 trace_seq_printf(trace->seq, "min: "); 551 552 if (!params->common.hist.no_irq) 553 format_summary_value(trace->seq, 554 sum.irq_count, 555 sum.min_irq, 556 false); 557 558 if (!params->common.hist.no_thread) 559 format_summary_value(trace->seq, 560 sum.thread_count, 561 sum.min_thread, 562 false); 563 564 if (params->common.user_data) 565 format_summary_value(trace->seq, 566 sum.user_count, 567 sum.min_user, 568 false); 569 570 trace_seq_printf(trace->seq, "\n"); 571 572 if (!params->common.hist.no_index) 573 trace_seq_printf(trace->seq, "avg: "); 574 575 if (!params->common.hist.no_irq) 576 format_summary_value(trace->seq, 577 sum.irq_count, 578 sum.sum_irq, 579 true); 580 581 if (!params->common.hist.no_thread) 582 format_summary_value(trace->seq, 583 sum.thread_count, 584 sum.sum_thread, 585 true); 586 587 if (params->common.user_data) 588 format_summary_value(trace->seq, 589 sum.user_count, 590 sum.sum_user, 591 true); 592 593 trace_seq_printf(trace->seq, "\n"); 594 595 if (!params->common.hist.no_index) 596 trace_seq_printf(trace->seq, "max: "); 597 598 if (!params->common.hist.no_irq) 599 format_summary_value(trace->seq, 600 sum.irq_count, 601 sum.max_irq, 602 false); 603 604 if (!params->common.hist.no_thread) 605 format_summary_value(trace->seq, 606 sum.thread_count, 607 sum.max_thread, 608 false); 609 610 if (params->common.user_data) 611 format_summary_value(trace->seq, 612 sum.user_count, 613 sum.max_user, 614 false); 615 616 trace_seq_printf(trace->seq, "\n"); 617 trace_seq_do_printf(trace->seq); 618 trace_seq_reset(trace->seq); 619 } 620 621 /* 622 * timerlat_print_stats - print data for each CPUs 623 */ 624 static void 625 timerlat_print_stats(struct osnoise_tool *tool) 626 { 627 struct timerlat_params *params = to_timerlat_params(tool->params); 628 struct timerlat_hist_data *data = tool->data; 629 struct trace_instance *trace = &tool->trace; 630 int bucket, cpu; 631 int total; 632 633 timerlat_hist_header(tool); 634 635 for (bucket = 0; bucket < data->entries; bucket++) { 636 total = 0; 637 638 if (!params->common.hist.no_index) 639 trace_seq_printf(trace->seq, "%-6d", 640 bucket * data->bucket_size); 641 642 for (cpu = 0; cpu < data->nr_cpus; cpu++) { 643 if (params->common.cpus && !CPU_ISSET(cpu, ¶ms->common.monitored_cpus)) 644 continue; 645 646 if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count) 647 continue; 648 649 if (!params->common.hist.no_irq) { 650 total += data->hist[cpu].irq[bucket]; 651 trace_seq_printf(trace->seq, "%9d ", 652 data->hist[cpu].irq[bucket]); 653 } 654 655 if (!params->common.hist.no_thread) { 656 total += data->hist[cpu].thread[bucket]; 657 trace_seq_printf(trace->seq, "%9d ", 658 data->hist[cpu].thread[bucket]); 659 } 660 661 if (params->common.user_data) { 662 total += data->hist[cpu].user[bucket]; 663 trace_seq_printf(trace->seq, "%9d ", 664 data->hist[cpu].user[bucket]); 665 } 666 667 } 668 669 if (total == 0 && !params->common.hist.with_zeros) { 670 trace_seq_reset(trace->seq); 671 continue; 672 } 673 674 trace_seq_printf(trace->seq, "\n"); 675 trace_seq_do_printf(trace->seq); 676 trace_seq_reset(trace->seq); 677 } 678 679 if (!params->common.hist.no_index) 680 trace_seq_printf(trace->seq, "over: "); 681 682 for (cpu = 0; cpu < data->nr_cpus; cpu++) { 683 if (params->common.cpus && !CPU_ISSET(cpu, ¶ms->common.monitored_cpus)) 684 continue; 685 686 if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count) 687 continue; 688 689 if (!params->common.hist.no_irq) 690 trace_seq_printf(trace->seq, "%9d ", 691 data->hist[cpu].irq[data->entries]); 692 693 if (!params->common.hist.no_thread) 694 trace_seq_printf(trace->seq, "%9d ", 695 data->hist[cpu].thread[data->entries]); 696 697 if (params->common.user_data) 698 trace_seq_printf(trace->seq, "%9d ", 699 data->hist[cpu].user[data->entries]); 700 } 701 trace_seq_printf(trace->seq, "\n"); 702 trace_seq_do_printf(trace->seq); 703 trace_seq_reset(trace->seq); 704 705 timerlat_print_summary(params, trace, data); 706 timerlat_print_stats_all(params, trace, data); 707 osnoise_report_missed_events(tool); 708 } 709 710 /* 711 * timerlat_hist_usage - prints timerlat top usage message 712 */ 713 static void timerlat_hist_usage(char *usage) 714 { 715 int i; 716 717 char *msg[] = { 718 "", 719 " usage: [rtla] timerlat hist [-h] [-q] [-d s] [-D] [-n] [-a us] [-p us] [-i us] [-T us] [-s us] \\", 720 " [-t[file]] [-e sys[:event]] [--filter <filter>] [--trigger <trigger>] [-c cpu-list] [-H cpu-list]\\", 721 " [-P priority] [-E N] [-b N] [--no-irq] [--no-thread] [--no-header] [--no-summary] \\", 722 " [--no-index] [--with-zeros] [--dma-latency us] [-C[=cgroup_name]] [--no-aa] [--dump-task] [-u|-k]", 723 " [--warm-up s] [--deepest-idle-state n]", 724 "", 725 " -h/--help: print this menu", 726 " -a/--auto: set automatic trace mode, stopping the session if argument in us latency is hit", 727 " -p/--period us: timerlat period in us", 728 " -i/--irq us: stop trace if the irq latency is higher than the argument in us", 729 " -T/--thread us: stop trace if the thread latency is higher than the argument in us", 730 " -s/--stack us: save the stack trace at the IRQ if a thread latency is higher than the argument in us", 731 " -c/--cpus cpus: run the tracer only on the given cpus", 732 " -H/--house-keeping cpus: run rtla control threads only on the given cpus", 733 " -C/--cgroup[=cgroup_name]: set cgroup, if no cgroup_name is passed, the rtla's cgroup will be inherited", 734 " -d/--duration time[m|h|d]: duration of the session in seconds", 735 " --dump-tasks: prints the task running on all CPUs if stop conditions are met (depends on !--no-aa)", 736 " -D/--debug: print debug info", 737 " -t/--trace[file]: save the stopped trace to [file|timerlat_trace.txt]", 738 " -e/--event <sys:event>: enable the <sys:event> in the trace instance, multiple -e are allowed", 739 " --filter <filter>: enable a trace event filter to the previous -e event", 740 " --trigger <trigger>: enable a trace event trigger to the previous -e event", 741 " -n/--nano: display data in nanoseconds", 742 " --no-aa: disable auto-analysis, reducing rtla timerlat cpu usage", 743 " -b/--bucket-size N: set the histogram bucket size (default 1)", 744 " -E/--entries N: set the number of entries of the histogram (default 256)", 745 " --no-irq: ignore IRQ latencies", 746 " --no-thread: ignore thread latencies", 747 " --no-header: do not print header", 748 " --no-summary: do not print summary", 749 " --no-index: do not print index", 750 " --with-zeros: print zero only entries", 751 " --dma-latency us: set /dev/cpu_dma_latency latency <us> to reduce exit from idle latency", 752 " -P/--priority o:prio|r:prio|f:prio|d:runtime:period : set scheduling parameters", 753 " o:prio - use SCHED_OTHER with prio", 754 " r:prio - use SCHED_RR with prio", 755 " f:prio - use SCHED_FIFO with prio", 756 " d:runtime[us|ms|s]:period[us|ms|s] - use SCHED_DEADLINE with runtime and period", 757 " in nanoseconds", 758 " -u/--user-threads: use rtla user-space threads instead of kernel-space timerlat threads", 759 " -k/--kernel-threads: use timerlat kernel-space threads instead of rtla user-space threads", 760 " -U/--user-load: enable timerlat for user-defined user-space workload", 761 " --warm-up s: let the workload run for s seconds before collecting data", 762 " --trace-buffer-size kB: set the per-cpu trace buffer size in kB", 763 " --deepest-idle-state n: only go down to idle state n on cpus used by timerlat to reduce exit from idle latency", 764 " --on-threshold <action>: define action to be executed at latency threshold, multiple are allowed", 765 " --on-end <action>: define action to be executed at measurement end, multiple are allowed", 766 NULL, 767 }; 768 769 if (usage) 770 fprintf(stderr, "%s\n", usage); 771 772 fprintf(stderr, "rtla timerlat hist: a per-cpu histogram of the timer latency (version %s)\n", 773 VERSION); 774 775 for (i = 0; msg[i]; i++) 776 fprintf(stderr, "%s\n", msg[i]); 777 778 if (usage) 779 exit(EXIT_FAILURE); 780 781 exit(EXIT_SUCCESS); 782 } 783 784 /* 785 * timerlat_hist_parse_args - allocs, parse and fill the cmd line parameters 786 */ 787 static struct common_params 788 *timerlat_hist_parse_args(int argc, char *argv[]) 789 { 790 struct timerlat_params *params; 791 struct trace_events *tevent; 792 int auto_thresh; 793 int retval; 794 int c; 795 char *trace_output = NULL; 796 797 params = calloc(1, sizeof(*params)); 798 if (!params) 799 exit(1); 800 801 actions_init(¶ms->common.threshold_actions); 802 actions_init(¶ms->common.end_actions); 803 804 /* disabled by default */ 805 params->dma_latency = -1; 806 807 /* disabled by default */ 808 params->deepest_idle_state = -2; 809 810 /* display data in microseconds */ 811 params->common.output_divisor = 1000; 812 params->common.hist.bucket_size = 1; 813 params->common.hist.entries = 256; 814 815 /* default to BPF mode */ 816 params->mode = TRACING_MODE_BPF; 817 818 while (1) { 819 static struct option long_options[] = { 820 {"auto", required_argument, 0, 'a'}, 821 {"cpus", required_argument, 0, 'c'}, 822 {"cgroup", optional_argument, 0, 'C'}, 823 {"bucket-size", required_argument, 0, 'b'}, 824 {"debug", no_argument, 0, 'D'}, 825 {"entries", required_argument, 0, 'E'}, 826 {"duration", required_argument, 0, 'd'}, 827 {"house-keeping", required_argument, 0, 'H'}, 828 {"help", no_argument, 0, 'h'}, 829 {"irq", required_argument, 0, 'i'}, 830 {"nano", no_argument, 0, 'n'}, 831 {"period", required_argument, 0, 'p'}, 832 {"priority", required_argument, 0, 'P'}, 833 {"stack", required_argument, 0, 's'}, 834 {"thread", required_argument, 0, 'T'}, 835 {"trace", optional_argument, 0, 't'}, 836 {"user-threads", no_argument, 0, 'u'}, 837 {"kernel-threads", no_argument, 0, 'k'}, 838 {"user-load", no_argument, 0, 'U'}, 839 {"event", required_argument, 0, 'e'}, 840 {"no-irq", no_argument, 0, '0'}, 841 {"no-thread", no_argument, 0, '1'}, 842 {"no-header", no_argument, 0, '2'}, 843 {"no-summary", no_argument, 0, '3'}, 844 {"no-index", no_argument, 0, '4'}, 845 {"with-zeros", no_argument, 0, '5'}, 846 {"trigger", required_argument, 0, '6'}, 847 {"filter", required_argument, 0, '7'}, 848 {"dma-latency", required_argument, 0, '8'}, 849 {"no-aa", no_argument, 0, '9'}, 850 {"dump-task", no_argument, 0, '\1'}, 851 {"warm-up", required_argument, 0, '\2'}, 852 {"trace-buffer-size", required_argument, 0, '\3'}, 853 {"deepest-idle-state", required_argument, 0, '\4'}, 854 {"on-threshold", required_argument, 0, '\5'}, 855 {"on-end", required_argument, 0, '\6'}, 856 {0, 0, 0, 0} 857 }; 858 859 /* getopt_long stores the option index here. */ 860 int option_index = 0; 861 862 c = getopt_long(argc, argv, "a:c:C::b:d:e:E:DhH:i:knp:P:s:t::T:uU0123456:7:8:9\1\2:\3:", 863 long_options, &option_index); 864 865 /* detect the end of the options. */ 866 if (c == -1) 867 break; 868 869 switch (c) { 870 case 'a': 871 auto_thresh = get_llong_from_str(optarg); 872 873 /* set thread stop to auto_thresh */ 874 params->common.stop_total_us = auto_thresh; 875 params->common.stop_us = auto_thresh; 876 877 /* get stack trace */ 878 params->print_stack = auto_thresh; 879 880 /* set trace */ 881 trace_output = "timerlat_trace.txt"; 882 883 break; 884 case 'c': 885 retval = parse_cpu_set(optarg, ¶ms->common.monitored_cpus); 886 if (retval) 887 timerlat_hist_usage("\nInvalid -c cpu list\n"); 888 params->common.cpus = optarg; 889 break; 890 case 'C': 891 params->common.cgroup = 1; 892 if (!optarg) { 893 /* will inherit this cgroup */ 894 params->common.cgroup_name = NULL; 895 } else if (*optarg == '=') { 896 /* skip the = */ 897 params->common.cgroup_name = ++optarg; 898 } 899 break; 900 case 'b': 901 params->common.hist.bucket_size = get_llong_from_str(optarg); 902 if (params->common.hist.bucket_size == 0 || 903 params->common.hist.bucket_size >= 1000000) 904 timerlat_hist_usage("Bucket size needs to be > 0 and <= 1000000\n"); 905 break; 906 case 'D': 907 config_debug = 1; 908 break; 909 case 'd': 910 params->common.duration = parse_seconds_duration(optarg); 911 if (!params->common.duration) 912 timerlat_hist_usage("Invalid -D duration\n"); 913 break; 914 case 'e': 915 tevent = trace_event_alloc(optarg); 916 if (!tevent) { 917 err_msg("Error alloc trace event"); 918 exit(EXIT_FAILURE); 919 } 920 921 if (params->common.events) 922 tevent->next = params->common.events; 923 924 params->common.events = tevent; 925 break; 926 case 'E': 927 params->common.hist.entries = get_llong_from_str(optarg); 928 if (params->common.hist.entries < 10 || 929 params->common.hist.entries > 9999999) 930 timerlat_hist_usage("Entries must be > 10 and < 9999999\n"); 931 break; 932 case 'h': 933 case '?': 934 timerlat_hist_usage(NULL); 935 break; 936 case 'H': 937 params->common.hk_cpus = 1; 938 retval = parse_cpu_set(optarg, ¶ms->common.hk_cpu_set); 939 if (retval) { 940 err_msg("Error parsing house keeping CPUs\n"); 941 exit(EXIT_FAILURE); 942 } 943 break; 944 case 'i': 945 params->common.stop_us = get_llong_from_str(optarg); 946 break; 947 case 'k': 948 params->common.kernel_workload = 1; 949 break; 950 case 'n': 951 params->common.output_divisor = 1; 952 break; 953 case 'p': 954 params->timerlat_period_us = get_llong_from_str(optarg); 955 if (params->timerlat_period_us > 1000000) 956 timerlat_hist_usage("Period longer than 1 s\n"); 957 break; 958 case 'P': 959 retval = parse_prio(optarg, ¶ms->common.sched_param); 960 if (retval == -1) 961 timerlat_hist_usage("Invalid -P priority"); 962 params->common.set_sched = 1; 963 break; 964 case 's': 965 params->print_stack = get_llong_from_str(optarg); 966 break; 967 case 'T': 968 params->common.stop_total_us = get_llong_from_str(optarg); 969 break; 970 case 't': 971 if (optarg) { 972 if (optarg[0] == '=') 973 trace_output = &optarg[1]; 974 else 975 trace_output = &optarg[0]; 976 } else if (optind < argc && argv[optind][0] != '-') 977 trace_output = argv[optind]; 978 else 979 trace_output = "timerlat_trace.txt"; 980 break; 981 case 'u': 982 params->common.user_workload = 1; 983 /* fallback: -u implies in -U */ 984 case 'U': 985 params->common.user_data = 1; 986 break; 987 case '0': /* no irq */ 988 params->common.hist.no_irq = 1; 989 break; 990 case '1': /* no thread */ 991 params->common.hist.no_thread = 1; 992 break; 993 case '2': /* no header */ 994 params->common.hist.no_header = 1; 995 break; 996 case '3': /* no summary */ 997 params->common.hist.no_summary = 1; 998 break; 999 case '4': /* no index */ 1000 params->common.hist.no_index = 1; 1001 break; 1002 case '5': /* with zeros */ 1003 params->common.hist.with_zeros = 1; 1004 break; 1005 case '6': /* trigger */ 1006 if (params->common.events) { 1007 retval = trace_event_add_trigger(params->common.events, optarg); 1008 if (retval) { 1009 err_msg("Error adding trigger %s\n", optarg); 1010 exit(EXIT_FAILURE); 1011 } 1012 } else { 1013 timerlat_hist_usage("--trigger requires a previous -e\n"); 1014 } 1015 break; 1016 case '7': /* filter */ 1017 if (params->common.events) { 1018 retval = trace_event_add_filter(params->common.events, optarg); 1019 if (retval) { 1020 err_msg("Error adding filter %s\n", optarg); 1021 exit(EXIT_FAILURE); 1022 } 1023 } else { 1024 timerlat_hist_usage("--filter requires a previous -e\n"); 1025 } 1026 break; 1027 case '8': 1028 params->dma_latency = get_llong_from_str(optarg); 1029 if (params->dma_latency < 0 || params->dma_latency > 10000) { 1030 err_msg("--dma-latency needs to be >= 0 and < 10000"); 1031 exit(EXIT_FAILURE); 1032 } 1033 break; 1034 case '9': 1035 params->no_aa = 1; 1036 break; 1037 case '\1': 1038 params->dump_tasks = 1; 1039 break; 1040 case '\2': 1041 params->common.warmup = get_llong_from_str(optarg); 1042 break; 1043 case '\3': 1044 params->common.buffer_size = get_llong_from_str(optarg); 1045 break; 1046 case '\4': 1047 params->deepest_idle_state = get_llong_from_str(optarg); 1048 break; 1049 case '\5': 1050 retval = actions_parse(¶ms->common.threshold_actions, optarg, 1051 "timerlat_trace.txt"); 1052 if (retval) { 1053 err_msg("Invalid action %s\n", optarg); 1054 exit(EXIT_FAILURE); 1055 } 1056 break; 1057 case '\6': 1058 retval = actions_parse(¶ms->common.end_actions, optarg, 1059 "timerlat_trace.txt"); 1060 if (retval) { 1061 err_msg("Invalid action %s\n", optarg); 1062 exit(EXIT_FAILURE); 1063 } 1064 break; 1065 default: 1066 timerlat_hist_usage("Invalid option"); 1067 } 1068 } 1069 1070 if (trace_output) 1071 actions_add_trace_output(¶ms->common.threshold_actions, trace_output); 1072 1073 if (geteuid()) { 1074 err_msg("rtla needs root permission\n"); 1075 exit(EXIT_FAILURE); 1076 } 1077 1078 if (params->common.hist.no_irq && params->common.hist.no_thread) 1079 timerlat_hist_usage("no-irq and no-thread set, there is nothing to do here"); 1080 1081 if (params->common.hist.no_index && !params->common.hist.with_zeros) 1082 timerlat_hist_usage("no-index set with with-zeros is not set - it does not make sense"); 1083 1084 /* 1085 * Auto analysis only happens if stop tracing, thus: 1086 */ 1087 if (!params->common.stop_us && !params->common.stop_total_us) 1088 params->no_aa = 1; 1089 1090 if (params->common.kernel_workload && params->common.user_workload) 1091 timerlat_hist_usage("--kernel-threads and --user-threads are mutually exclusive!"); 1092 1093 /* 1094 * If auto-analysis or trace output is enabled, switch from BPF mode to 1095 * mixed mode 1096 */ 1097 if (params->mode == TRACING_MODE_BPF && 1098 (params->common.threshold_actions.present[ACTION_TRACE_OUTPUT] || 1099 params->common.end_actions.present[ACTION_TRACE_OUTPUT] || 1100 !params->no_aa)) 1101 params->mode = TRACING_MODE_MIXED; 1102 1103 return ¶ms->common; 1104 } 1105 1106 /* 1107 * timerlat_hist_apply_config - apply the hist configs to the initialized tool 1108 */ 1109 static int 1110 timerlat_hist_apply_config(struct osnoise_tool *tool) 1111 { 1112 struct timerlat_params *params = to_timerlat_params(tool->params); 1113 int retval; 1114 1115 retval = timerlat_apply_config(tool, params); 1116 if (retval) 1117 goto out_err; 1118 1119 return 0; 1120 1121 out_err: 1122 return -1; 1123 } 1124 1125 /* 1126 * timerlat_init_hist - initialize a timerlat hist tool with parameters 1127 */ 1128 static struct osnoise_tool 1129 *timerlat_init_hist(struct common_params *params) 1130 { 1131 struct osnoise_tool *tool; 1132 int nr_cpus; 1133 1134 nr_cpus = sysconf(_SC_NPROCESSORS_CONF); 1135 1136 tool = osnoise_init_tool("timerlat_hist"); 1137 if (!tool) 1138 return NULL; 1139 1140 tool->data = timerlat_alloc_histogram(nr_cpus, params->hist.entries, 1141 params->hist.bucket_size); 1142 if (!tool->data) 1143 goto out_err; 1144 1145 tep_register_event_handler(tool->trace.tep, -1, "ftrace", "timerlat", 1146 timerlat_hist_handler, tool); 1147 1148 return tool; 1149 1150 out_err: 1151 osnoise_destroy_tool(tool); 1152 return NULL; 1153 } 1154 1155 static int timerlat_hist_bpf_main_loop(struct osnoise_tool *tool) 1156 { 1157 struct timerlat_params *params = to_timerlat_params(tool->params); 1158 int retval; 1159 1160 while (!stop_tracing) { 1161 timerlat_bpf_wait(-1); 1162 1163 if (!stop_tracing) { 1164 /* Threshold overflow, perform actions on threshold */ 1165 actions_perform(¶ms->common.threshold_actions); 1166 1167 if (!params->common.threshold_actions.continue_flag) 1168 /* continue flag not set, break */ 1169 break; 1170 1171 /* continue action reached, re-enable tracing */ 1172 if (tool->record) 1173 trace_instance_start(&tool->record->trace); 1174 if (tool->aa) 1175 trace_instance_start(&tool->aa->trace); 1176 timerlat_bpf_restart_tracing(); 1177 } 1178 } 1179 timerlat_bpf_detach(); 1180 1181 retval = timerlat_hist_bpf_pull_data(tool); 1182 if (retval) 1183 err_msg("Error pulling BPF data\n"); 1184 1185 return retval; 1186 } 1187 1188 static int timerlat_hist_main(struct osnoise_tool *tool) 1189 { 1190 struct timerlat_params *params = to_timerlat_params(tool->params); 1191 int retval; 1192 1193 if (params->mode == TRACING_MODE_TRACEFS) 1194 retval = hist_main_loop(tool); 1195 else 1196 retval = timerlat_hist_bpf_main_loop(tool); 1197 1198 return retval; 1199 } 1200 1201 struct tool_ops timerlat_hist_ops = { 1202 .tracer = "timerlat", 1203 .comm_prefix = "timerlat/", 1204 .parse_args = timerlat_hist_parse_args, 1205 .init_tool = timerlat_init_hist, 1206 .apply_config = timerlat_hist_apply_config, 1207 .enable = timerlat_enable, 1208 .main = timerlat_hist_main, 1209 .print_stats = timerlat_print_stats, 1210 .analyze = timerlat_analyze, 1211 .free = timerlat_free_histogram_tool, 1212 }; 1213