Commit a40e5e4d authored by Daniel Bristot de Oliveira's avatar Daniel Bristot de Oliveira
Browse files

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: 27e348b2 ("rtla/timerlat: Add auto-analysis core")
Signed-off-by: default avatarDaniel Bristot de Oliveira <bristot@kernel.org>
parent 5f076933

tools/tracing/rtla/src/timerlat_aa.c

+63 −46
Original line number Diff line number Diff line
@@ -16,6 +16,9 @@ enum timelat_state { 
	TIMERLAT_WAITING_THREAD,

};



/* Used to fill spaces in the output */

static const char *spaces  = "                                                         ";



#define MAX_COMM		24



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



		trace_seq_reset(taa_data->prev_irqs_seq);

		trace_seq_printf(taa_data->prev_irqs_seq, "\t%24s	\t\t\t%9.2f us\n",

			 "nmi", ns_to_usf(duration));

		trace_seq_printf(taa_data->prev_irqs_seq, "  %24s %.*s %9.2f us\n",

				 "nmi",

				 24, spaces,

				 ns_to_usf(duration));

		return 0;

	}



	taa_data->thread_nmi_sum += duration;

	trace_seq_printf(taa_data->nmi_seq, "	%24s	\t\t\t%9.2f us\n",

		 "nmi", ns_to_usf(duration));

	trace_seq_printf(taa_data->nmi_seq, "  %24s %.*s %9.2f us\n",

			 "nmi",

			 24, spaces, ns_to_usf(duration));



	return 0;

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



		trace_seq_reset(taa_data->prev_irqs_seq);

		trace_seq_printf(taa_data->prev_irqs_seq, "\t%24s:%-3llu	\t\t%9.2f us\n",

				 desc, vector, ns_to_usf(duration));

		trace_seq_printf(taa_data->prev_irqs_seq, "  %24s:%-3llu %.*s %9.2f us\n",

				 desc, vector,

				 15, spaces,

				 ns_to_usf(duration));

		return 0;

	}
@@ -372,8 +380,10 @@ static int timerlat_aa_irq_handler(struct trace_seq *s, struct tep_record *recor 
	 * IRQ interference.

	 */

	taa_data->thread_irq_sum += duration;

	trace_seq_printf(taa_data->irqs_seq, "	%24s:%-3llu	\t	%9.2f us\n",

			 desc, vector, ns_to_usf(duration));

	trace_seq_printf(taa_data->irqs_seq, "  %24s:%-3llu %.*s %9.2f us\n",

			 desc, vector,

			 24, spaces,

			 ns_to_usf(duration));



	return 0;

}
@@ -408,8 +418,10 @@ static int timerlat_aa_softirq_handler(struct trace_seq *s, struct tep_record *r 


	taa_data->thread_softirq_sum += duration;



	trace_seq_printf(taa_data->softirqs_seq, "\t%24s:%-3llu	\t	%9.2f us\n",

			 softirq_name[vector], vector, ns_to_usf(duration));

	trace_seq_printf(taa_data->softirqs_seq, "  %24s:%-3llu %.*s %9.2f us\n",

			 softirq_name[vector], vector,

			 24, spaces,

			 ns_to_usf(duration));

	return 0;

}
@@ -452,8 +464,10 @@ static int timerlat_aa_thread_handler(struct trace_seq *s, struct tep_record *re 
	} else {

		taa_data->thread_thread_sum += duration;



		trace_seq_printf(taa_data->threads_seq, "\t%24s:%-3llu	\t\t%9.2f us\n",

			 comm, pid, ns_to_usf(duration));

		trace_seq_printf(taa_data->threads_seq, "  %24s:%-12llu %.*s %9.2f us\n",

				 comm, pid,

				 15, spaces,

				 ns_to_usf(duration));

	}



	return 0;
@@ -482,7 +496,8 @@ static int timerlat_aa_stack_handler(struct trace_seq *s, struct tep_record *rec 
			function = tep_find_function(taa_ctx->tool->trace.tep, caller[i]);

			if (!function)

				break;

			trace_seq_printf(taa_data->stack_seq, "\t\t-> %s\n", function);

			trace_seq_printf(taa_data->stack_seq, " %.*s -> %s\n",

					 14, spaces, function);

		}

	}

	return 0;
@@ -568,14 +583,15 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu, 
	exp_irq_ts = taa_data->timer_irq_start_time - taa_data->timer_irq_start_delay;

	if (exp_irq_ts < taa_data->prev_irq_timstamp + taa_data->prev_irq_duration) {

		if (taa_data->prev_irq_timstamp < taa_data->timer_irq_start_time)

			printf("  Previous IRQ interference:	\t\t up to  %9.2f us\n",

			printf("  Previous IRQ interference: %.*s up to  %9.2f us\n",

			       16, spaces,

			       ns_to_usf(taa_data->prev_irq_duration));

	}



	/*

	 * The delay that the IRQ suffered before starting.

	 */

	printf("  IRQ handler delay:		%16s	%9.2f us (%.2f %%)\n",

	printf("  IRQ handler delay: %.*s %16s  %9.2f us (%.2f %%)\n", 16, spaces,

	       (ns_to_usf(taa_data->timer_exit_from_idle) > 10) ? "(exit from idle)" : "",

	       ns_to_usf(taa_data->timer_irq_start_delay),

	       ns_to_per(total, taa_data->timer_irq_start_delay));
@@ -583,7 +599,7 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu, 
	/*

	 * Timerlat IRQ.

	 */

	printf("  IRQ latency:	\t\t\t\t	%9.2f us\n",

	printf("  IRQ latency: %.*s %9.2f us\n", 40, spaces,

	       ns_to_usf(taa_data->tlat_irq_latency));



	if (irq) {
@@ -595,13 +611,14 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu, 
		 * so it will be displayed, it is the key.

		 */

		printf("  Blocking thread:\n");

		printf("	%24s:%-9llu\n",

			taa_data->run_thread_comm, taa_data->run_thread_pid);

		printf(" %.*s %24s:%-9llu\n", 6, spaces, taa_data->run_thread_comm,

		       taa_data->run_thread_pid);

	} else  {

		/*

		 * The duration of the IRQ handler that handled the timerlat IRQ.

		 */

		printf("  Timerlat IRQ duration:	\t\t	%9.2f us (%.2f %%)\n",

		printf("  Timerlat IRQ duration: %.*s %9.2f us (%.2f %%)\n",

		       30, spaces,

		       ns_to_usf(taa_data->timer_irq_duration),

		       ns_to_per(total, taa_data->timer_irq_duration));
@@ -611,13 +628,13 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu, 
		 * Recalling that it is net from NMI/IRQ/Softirq interference, so there

		 * is no need to compute values here.

		 */

		printf("  Blocking thread:	\t\t\t	%9.2f us (%.2f %%)\n",

		printf("  Blocking thread: %.*s %9.2f us (%.2f %%)\n", 36, spaces,

		       ns_to_usf(taa_data->thread_blocking_duration),

		       ns_to_per(total, taa_data->thread_blocking_duration));



		printf("	%24s:%-9llu		%9.2f us\n",

		printf(" %.*s %24s:%-9llu %.*s %9.2f us\n", 6, spaces,

		       taa_data->run_thread_comm, taa_data->run_thread_pid,

			ns_to_usf(taa_data->thread_blocking_duration));

		       12, spaces, ns_to_usf(taa_data->thread_blocking_duration));

	}



	/*
@@ -629,7 +646,7 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu, 
	 * NMIs can happen during the IRQ, so they are always possible.

	 */

	if (taa_data->thread_nmi_sum)

		printf("  NMI interference	\t\t\t	%9.2f us (%.2f %%)\n",

		printf("  NMI interference %.*s %9.2f us (%.2f %%)\n", 36, spaces,

		       ns_to_usf(taa_data->thread_nmi_sum),

		       ns_to_per(total, taa_data->thread_nmi_sum));
@@ -643,7 +660,7 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu, 
	 * Prints the interference caused by IRQs to the thread latency.

	 */

	if (taa_data->thread_irq_sum) {

		printf("  IRQ interference	\t\t\t	%9.2f us (%.2f %%)\n",

		printf("  IRQ interference %.*s %9.2f us (%.2f %%)\n", 36, spaces,

		       ns_to_usf(taa_data->thread_irq_sum),

		       ns_to_per(total, taa_data->thread_irq_sum));
@@ -654,7 +671,7 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu, 
	 * Prints the interference caused by Softirqs to the thread latency.

	 */

	if (taa_data->thread_softirq_sum) {

		printf("  Softirq interference	\t\t\t	%9.2f us (%.2f %%)\n",

		printf("  Softirq interference %.*s %9.2f us (%.2f %%)\n", 32, spaces,

		       ns_to_usf(taa_data->thread_softirq_sum),

		       ns_to_per(total, taa_data->thread_softirq_sum));
@@ -670,7 +687,7 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu, 
	 * timer handling latency.

	 */

	if (taa_data->thread_thread_sum) {

		printf("  Thread interference	\t\t\t	%9.2f us (%.2f %%)\n",

		printf("  Thread interference %.*s %9.2f us (%.2f %%)\n", 33, spaces,

		       ns_to_usf(taa_data->thread_thread_sum),

		       ns_to_per(total, taa_data->thread_thread_sum));
@@ -682,8 +699,8 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu, 
	 */

print_total:

	printf("------------------------------------------------------------------------\n");

	printf("  %s latency:	\t\t\t	%9.2f us (100%%)\n", irq ? "IRQ" : "Thread",

		ns_to_usf(total));

	printf("  %s latency: %.*s %9.2f us (100%%)\n", irq ? "   IRQ" : "Thread",

	       37, spaces, ns_to_usf(total));

}



static int timerlat_auto_analysis_collect_trace(struct timerlat_aa_context *taa_ctx)