Skip to content

Commit 548d3dd

Browse files
lclaudiolclaudio
committed
rtla/auto-analysis: Replace \t with spaces
JIRA: https://issues.redhat.com/browse/RHEL-50869 commit a40e5e4 Author: Daniel Bristot de Oliveira <bristot@kernel.org> Date: Wed Apr 24 16:36:51 2024 +0200 rtla/auto-analysis: Replace \t with spaces When copying timerlat auto-analysis from a terminal to some web pages or chats, the \t are being replaced with a single ' ' or ' ', breaking the output. For example: ## CPU 3 hit stop tracing, analyzing it ## IRQ handler delay: 1.30 us (0.11 %) IRQ latency: 1.90 us Timerlat IRQ duration: 3.00 us (0.24 %) Blocking thread: 1223.16 us (99.00 %) insync:4048 1223.16 us IRQ interference 4.93 us (0.40 %) local_timer:236 4.93 us ------------------------------------------------------------------------ Thread latency: 1235.47 us (100%) Replace \t with spaces to avoid this problem. Link: https://lkml.kernel.org/r/ec7ed2b2809c22ab0dfc8eb7c805ab9cddc4254a.1713968967.git.bristot@kernel.org Cc: stable@vger.kernel.org Cc: Jonathan Corbet <corbet@lwn.net> Cc: Juri Lelli <juri.lelli@redhat.com> Fixes: 27e348b ("rtla/timerlat: Add auto-analysis core") Signed-off-by: Daniel Bristot de Oliveira <bristot@kernel.org> Signed-off-by: Luis Claudio R. Goncalves <lgoncalv@redhat.com>
1 parent 5c9a2f2 commit 548d3dd

File tree

1 file changed

+63
-46
lines changed

1 file changed

+63
-46
lines changed

‎tools/tracing/rtla/src/timerlat_aa.c‎

Lines changed: 63 additions & 46 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,9 @@ enum timelat_state {
1616
TIMERLAT_WAITING_THREAD,
1717
};
1818

19+
/* Used to fill spaces in the output */
20+
static const char *spaces = " ";
21+
1922
#define MAX_COMM 24
2023

2124
/*
@@ -274,14 +277,17 @@ static int timerlat_aa_nmi_handler(struct trace_seq *s, struct tep_record *recor
274277
taa_data->prev_irq_timstamp = start;
275278

276279
trace_seq_reset(taa_data->prev_irqs_seq);
277-
trace_seq_printf(taa_data->prev_irqs_seq, "\t%24s \t\t\t%9.2f us\n",
278-
"nmi", ns_to_usf(duration));
280+
trace_seq_printf(taa_data->prev_irqs_seq, " %24s %.*s %9.2f us\n",
281+
"nmi",
282+
24, spaces,
283+
ns_to_usf(duration));
279284
return 0;
280285
}
281286

282287
taa_data->thread_nmi_sum += duration;
283-
trace_seq_printf(taa_data->nmi_seq, " %24s \t\t\t%9.2f us\n",
284-
"nmi", ns_to_usf(duration));
288+
trace_seq_printf(taa_data->nmi_seq, " %24s %.*s %9.2f us\n",
289+
"nmi",
290+
24, spaces, ns_to_usf(duration));
285291

286292
return 0;
287293
}
@@ -323,8 +329,10 @@ static int timerlat_aa_irq_handler(struct trace_seq *s, struct tep_record *recor
323329
taa_data->prev_irq_timstamp = start;
324330

325331
trace_seq_reset(taa_data->prev_irqs_seq);
326-
trace_seq_printf(taa_data->prev_irqs_seq, "\t%24s:%-3llu \t\t%9.2f us\n",
327-
desc, vector, ns_to_usf(duration));
332+
trace_seq_printf(taa_data->prev_irqs_seq, " %24s:%-3llu %.*s %9.2f us\n",
333+
desc, vector,
334+
15, spaces,
335+
ns_to_usf(duration));
328336
return 0;
329337
}
330338

@@ -372,8 +380,10 @@ static int timerlat_aa_irq_handler(struct trace_seq *s, struct tep_record *recor
372380
* IRQ interference.
373381
*/
374382
taa_data->thread_irq_sum += duration;
375-
trace_seq_printf(taa_data->irqs_seq, " %24s:%-3llu \t %9.2f us\n",
376-
desc, vector, ns_to_usf(duration));
383+
trace_seq_printf(taa_data->irqs_seq, " %24s:%-3llu %.*s %9.2f us\n",
384+
desc, vector,
385+
24, spaces,
386+
ns_to_usf(duration));
377387

378388
return 0;
379389
}
@@ -408,8 +418,10 @@ static int timerlat_aa_softirq_handler(struct trace_seq *s, struct tep_record *r
408418

409419
taa_data->thread_softirq_sum += duration;
410420

411-
trace_seq_printf(taa_data->softirqs_seq, "\t%24s:%-3llu \t %9.2f us\n",
412-
softirq_name[vector], vector, ns_to_usf(duration));
421+
trace_seq_printf(taa_data->softirqs_seq, " %24s:%-3llu %.*s %9.2f us\n",
422+
softirq_name[vector], vector,
423+
24, spaces,
424+
ns_to_usf(duration));
413425
return 0;
414426
}
415427

@@ -452,8 +464,10 @@ static int timerlat_aa_thread_handler(struct trace_seq *s, struct tep_record *re
452464
} else {
453465
taa_data->thread_thread_sum += duration;
454466

455-
trace_seq_printf(taa_data->threads_seq, "\t%24s:%-3llu \t\t%9.2f us\n",
456-
comm, pid, ns_to_usf(duration));
467+
trace_seq_printf(taa_data->threads_seq, " %24s:%-12llu %.*s %9.2f us\n",
468+
comm, pid,
469+
15, spaces,
470+
ns_to_usf(duration));
457471
}
458472

459473
return 0;
@@ -482,7 +496,8 @@ static int timerlat_aa_stack_handler(struct trace_seq *s, struct tep_record *rec
482496
function = tep_find_function(taa_ctx->tool->trace.tep, caller[i]);
483497
if (!function)
484498
break;
485-
trace_seq_printf(taa_data->stack_seq, "\t\t-> %s\n", function);
499+
trace_seq_printf(taa_data->stack_seq, " %.*s -> %s\n",
500+
14, spaces, function);
486501
}
487502
}
488503
return 0;
@@ -568,23 +583,24 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu,
568583
exp_irq_ts = taa_data->timer_irq_start_time - taa_data->timer_irq_start_delay;
569584
if (exp_irq_ts < taa_data->prev_irq_timstamp + taa_data->prev_irq_duration) {
570585
if (taa_data->prev_irq_timstamp < taa_data->timer_irq_start_time)
571-
printf(" Previous IRQ interference: \t\t up to %9.2f us\n",
572-
ns_to_usf(taa_data->prev_irq_duration));
586+
printf(" Previous IRQ interference: %.*s up to %9.2f us\n",
587+
16, spaces,
588+
ns_to_usf(taa_data->prev_irq_duration));
573589
}
574590

575591
/*
576592
* The delay that the IRQ suffered before starting.
577593
*/
578-
printf(" IRQ handler delay: %16s %9.2f us (%.2f %%)\n",
579-
(ns_to_usf(taa_data->timer_exit_from_idle) > 10) ? "(exit from idle)" : "",
580-
ns_to_usf(taa_data->timer_irq_start_delay),
581-
ns_to_per(total, taa_data->timer_irq_start_delay));
594+
printf(" IRQ handler delay: %.*s %16s %9.2f us (%.2f %%)\n", 16, spaces,
595+
(ns_to_usf(taa_data->timer_exit_from_idle) > 10) ? "(exit from idle)" : "",
596+
ns_to_usf(taa_data->timer_irq_start_delay),
597+
ns_to_per(total, taa_data->timer_irq_start_delay));
582598

583599
/*
584600
* Timerlat IRQ.
585601
*/
586-
printf(" IRQ latency: \t\t\t\t %9.2f us\n",
587-
ns_to_usf(taa_data->tlat_irq_latency));
602+
printf(" IRQ latency: %.*s %9.2f us\n", 40, spaces,
603+
ns_to_usf(taa_data->tlat_irq_latency));
588604

589605
if (irq) {
590606
/*
@@ -595,29 +611,30 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu,
595611
* so it will be displayed, it is the key.
596612
*/
597613
printf(" Blocking thread:\n");
598-
printf(" %24s:%-9llu\n",
599-
taa_data->run_thread_comm, taa_data->run_thread_pid);
614+
printf(" %.*s %24s:%-9llu\n", 6, spaces, taa_data->run_thread_comm,
615+
taa_data->run_thread_pid);
600616
} else {
601617
/*
602618
* The duration of the IRQ handler that handled the timerlat IRQ.
603619
*/
604-
printf(" Timerlat IRQ duration: \t\t %9.2f us (%.2f %%)\n",
605-
ns_to_usf(taa_data->timer_irq_duration),
606-
ns_to_per(total, taa_data->timer_irq_duration));
620+
printf(" Timerlat IRQ duration: %.*s %9.2f us (%.2f %%)\n",
621+
30, spaces,
622+
ns_to_usf(taa_data->timer_irq_duration),
623+
ns_to_per(total, taa_data->timer_irq_duration));
607624

608625
/*
609626
* The amount of time that the current thread postponed the scheduler.
610627
*
611628
* Recalling that it is net from NMI/IRQ/Softirq interference, so there
612629
* is no need to compute values here.
613630
*/
614-
printf(" Blocking thread: \t\t\t %9.2f us (%.2f %%)\n",
615-
ns_to_usf(taa_data->thread_blocking_duration),
616-
ns_to_per(total, taa_data->thread_blocking_duration));
631+
printf(" Blocking thread: %.*s %9.2f us (%.2f %%)\n", 36, spaces,
632+
ns_to_usf(taa_data->thread_blocking_duration),
633+
ns_to_per(total, taa_data->thread_blocking_duration));
617634

618-
printf(" %24s:%-9llu %9.2f us\n",
619-
taa_data->run_thread_comm, taa_data->run_thread_pid,
620-
ns_to_usf(taa_data->thread_blocking_duration));
635+
printf(" %.*s %24s:%-9llu %.*s %9.2f us\n", 6, spaces,
636+
taa_data->run_thread_comm, taa_data->run_thread_pid,
637+
12, spaces, ns_to_usf(taa_data->thread_blocking_duration));
621638
}
622639

623640
/*
@@ -629,9 +646,9 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu,
629646
* NMIs can happen during the IRQ, so they are always possible.
630647
*/
631648
if (taa_data->thread_nmi_sum)
632-
printf(" NMI interference \t\t\t %9.2f us (%.2f %%)\n",
633-
ns_to_usf(taa_data->thread_nmi_sum),
634-
ns_to_per(total, taa_data->thread_nmi_sum));
649+
printf(" NMI interference %.*s %9.2f us (%.2f %%)\n", 36, spaces,
650+
ns_to_usf(taa_data->thread_nmi_sum),
651+
ns_to_per(total, taa_data->thread_nmi_sum));
635652

636653
/*
637654
* If it is an IRQ latency, the other factors can be skipped.
@@ -643,9 +660,9 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu,
643660
* Prints the interference caused by IRQs to the thread latency.
644661
*/
645662
if (taa_data->thread_irq_sum) {
646-
printf(" IRQ interference \t\t\t %9.2f us (%.2f %%)\n",
647-
ns_to_usf(taa_data->thread_irq_sum),
648-
ns_to_per(total, taa_data->thread_irq_sum));
663+
printf(" IRQ interference %.*s %9.2f us (%.2f %%)\n", 36, spaces,
664+
ns_to_usf(taa_data->thread_irq_sum),
665+
ns_to_per(total, taa_data->thread_irq_sum));
649666

650667
trace_seq_do_printf(taa_data->irqs_seq);
651668
}
@@ -654,9 +671,9 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu,
654671
* Prints the interference caused by Softirqs to the thread latency.
655672
*/
656673
if (taa_data->thread_softirq_sum) {
657-
printf(" Softirq interference \t\t\t %9.2f us (%.2f %%)\n",
658-
ns_to_usf(taa_data->thread_softirq_sum),
659-
ns_to_per(total, taa_data->thread_softirq_sum));
674+
printf(" Softirq interference %.*s %9.2f us (%.2f %%)\n", 32, spaces,
675+
ns_to_usf(taa_data->thread_softirq_sum),
676+
ns_to_per(total, taa_data->thread_softirq_sum));
660677

661678
trace_seq_do_printf(taa_data->softirqs_seq);
662679
}
@@ -670,9 +687,9 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu,
670687
* timer handling latency.
671688
*/
672689
if (taa_data->thread_thread_sum) {
673-
printf(" Thread interference \t\t\t %9.2f us (%.2f %%)\n",
674-
ns_to_usf(taa_data->thread_thread_sum),
675-
ns_to_per(total, taa_data->thread_thread_sum));
690+
printf(" Thread interference %.*s %9.2f us (%.2f %%)\n", 33, spaces,
691+
ns_to_usf(taa_data->thread_thread_sum),
692+
ns_to_per(total, taa_data->thread_thread_sum));
676693

677694
trace_seq_do_printf(taa_data->threads_seq);
678695
}
@@ -682,8 +699,8 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu,
682699
*/
683700
print_total:
684701
printf("------------------------------------------------------------------------\n");
685-
printf(" %s latency: \t\t\t %9.2f us (100%%)\n", irq ? "IRQ" : "Thread",
686-
ns_to_usf(total));
702+
printf(" %s latency: %.*s %9.2f us (100%%)\n", irq ? " IRQ" : "Thread",
703+
37, spaces, ns_to_usf(total));
687704
}
688705

689706
static int timerlat_auto_analysis_collect_trace(struct timerlat_aa_context *taa_ctx)

0 commit comments

Comments
 (0)