Linux kernel mirror (for testing) git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
kernel os linux

rtla/timerlat: Add auto-analysis only option

Parsing and formating timerlat data might consume a reasonable
amount of CPU time on very large systems, or when timerlat
has a too short period.

Add an option to run timerlat with auto-analysis enabled while
skipping the statistics parsing. In this mode, rtla timerlat
periodically checks if the tracing is on, going to sleep waiting
for the stop tracing condition to stop tracing, or for the
tracing session to finish.

If the stop tracing condition is hit, the tool prints the auto
analysis. Otherwise, the tool prints the max observed latency and
exit. The max observed latency is captured via tracing_max_latency.

Link: https://lore.kernel.org/linux-trace-devel/4dc514d1d5dc353c537a466a9b5af44c266b6da2.1680106912.git.bristot@kernel.org

Cc: Jonathan Corbet <corbet@lwn.net>
Signed-off-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>

authored by

Daniel Bristot de Oliveira and committed by
Steven Rostedt (Google)
9fa48a24 73e053cb

+51 -5
+7
Documentation/tools/rtla/common_timerlat_aa.rst
··· 5 5 **--no-aa** 6 6 7 7 disable auto-analysis, reducing rtla timerlat cpu usage 8 + 9 + **--aa-only** *us* 10 + 11 + Set stop tracing conditions and run without collecting and displaying statistics. 12 + Print the auto-analysis if the system hits the stop tracing condition. This option 13 + is useful to reduce rtla timerlat CPU, enabling the debug without the overhead of 14 + collecting the statistics.
+44 -5
tools/tracing/rtla/src/timerlat_top.c
··· 33 33 int set_sched; 34 34 int dma_latency; 35 35 int no_aa; 36 + int aa_only; 36 37 int dump_tasks; 37 38 struct sched_attr sched_param; 38 39 struct trace_events *events; ··· 143 142 top = container_of(trace, struct osnoise_tool, trace); 144 143 params = top->params; 145 144 146 - tep_get_field_val(s, event, "context", record, &thread, 1); 147 - tep_get_field_val(s, event, "timer_latency", record, &latency, 1); 145 + if (!params->aa_only) { 146 + tep_get_field_val(s, event, "context", record, &thread, 1); 147 + tep_get_field_val(s, event, "timer_latency", record, &latency, 1); 148 148 149 - timerlat_top_update(top, cpu, thread, latency); 149 + timerlat_top_update(top, cpu, thread, latency); 150 + } 150 151 151 152 if (!params->no_aa) 152 153 timerlat_aa_handler(s, record, event, context); ··· 253 250 static int nr_cpus = -1; 254 251 int i; 255 252 253 + if (params->aa_only) 254 + return; 255 + 256 256 if (nr_cpus == -1) 257 257 nr_cpus = sysconf(_SC_NPROCESSORS_CONF); 258 258 ··· 285 279 "", 286 280 " usage: rtla timerlat [top] [-h] [-q] [-a us] [-d s] [-D] [-n] [-p us] [-i us] [-T us] [-s us] \\", 287 281 " [[-t[=file]] [-e sys[:event]] [--filter <filter>] [--trigger <trigger>] [-c cpu-list] \\", 288 - " [-P priority] [--dma-latency us]", 282 + " [-P priority] [--dma-latency us] [--aa-only us]", 289 283 "", 290 284 " -h/--help: print this menu", 291 285 " -a/--auto: set automatic trace mode, stopping the session if argument in us latency is hit", 286 + " --aa-only us: stop if <us> latency is hit, only printing the auto analysis (reduces CPU usage)", 292 287 " -p/--period us: timerlat period in us", 293 288 " -i/--irq us: stop trace if the irq latency is higher than the argument in us", 294 289 " -T/--thread us: stop trace if the thread latency is higher than the argument in us", ··· 369 362 {"dma-latency", required_argument, 0, '2'}, 370 363 {"no-aa", no_argument, 0, '3'}, 371 364 {"dump-tasks", no_argument, 0, '4'}, 365 + {"aa-only", required_argument, 0, '5'}, 372 366 {0, 0, 0, 0} 373 367 }; 374 368 375 369 /* getopt_long stores the option index here. */ 376 370 int option_index = 0; 377 371 378 - c = getopt_long(argc, argv, "a:c:d:De:hi:np:P:qs:t::T:0:1:2:34", 372 + c = getopt_long(argc, argv, "a:c:d:De:hi:np:P:qs:t::T:0:1:2:345:", 379 373 long_options, &option_index); 380 374 381 375 /* detect the end of the options. */ ··· 396 388 397 389 /* set trace */ 398 390 params->trace_output = "timerlat_trace.txt"; 391 + break; 392 + case '5': 393 + /* it is here because it is similar to -a */ 394 + auto_thresh = get_llong_from_str(optarg); 395 + 396 + /* set thread stop to auto_thresh */ 397 + params->stop_total_us = auto_thresh; 398 + params->stop_us = auto_thresh; 399 + 400 + /* get stack trace */ 401 + params->print_stack = auto_thresh; 402 + 403 + /* set aa_only to avoid parsing the trace */ 404 + params->aa_only = 1; 399 405 break; 400 406 case 'c': 401 407 retval = parse_cpu_list(optarg, &params->monitored_cpus); ··· 524 502 */ 525 503 if (!params->stop_us && !params->stop_total_us) 526 504 params->no_aa = 1; 505 + 506 + if (params->no_aa && params->aa_only) 507 + timerlat_top_usage("--no-aa and --aa-only are mutually exclusive!"); 527 508 528 509 return params; 529 510 } ··· 659 634 struct trace_instance *trace; 660 635 int dma_latency_fd = -1; 661 636 int return_value = 1; 637 + char *max_lat; 662 638 int retval; 663 639 664 640 params = timerlat_top_parse_args(argc, argv); ··· 726 700 while (!stop_tracing) { 727 701 sleep(params->sleep_time); 728 702 703 + if (params->aa_only && !trace_is_off(&top->trace, &record->trace)) 704 + continue; 705 + 729 706 retval = tracefs_iterate_raw_events(trace->tep, 730 707 trace->inst, 731 708 NULL, ··· 761 732 if (params->trace_output) { 762 733 printf(" Saving trace to %s\n", params->trace_output); 763 734 save_trace_to_file(record->trace.inst, params->trace_output); 735 + } 736 + } else if (params->aa_only) { 737 + /* 738 + * If the trace did not stop with --aa-only, at least print the 739 + * max known latency. 740 + */ 741 + max_lat = tracefs_instance_file_read(trace->inst, "tracing_max_latency", NULL); 742 + if (max_lat) { 743 + printf(" Max latency was %s\n", max_lat); 744 + free(max_lat); 764 745 } 765 746 } 766 747