linux-kernel - Re: [PATCH] ftrace: Show timings of how long nop patching took

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <6fb1e232-3bc3-4d5d-bff9-9f1a8c784782@csgroup.eu>
Date: Sun, 1 Dec 2024 20:37:42 +0100
From: Christophe Leroy <christophe.leroy@...roup.eu>
To: Steven Rostedt <rostedt@...dmis.org>
Cc: Masami Hiramatsu <mhiramat@...nel.org>,
 Mark Rutland <mark.rutland@....com>,
 Linux Trace Kernel <linux-trace-kernel@...r.kernel.org>,
 Mathieu Desnoyers <mathieu.desnoyers@...icios.com>,
 Mike Rapoport <rppt@...nel.org>, Peter Zijlstra <peterz@...radead.org>,
 LKML <linux-kernel@...r.kernel.org>
Subject: Re: [PATCH] ftrace: Show timings of how long nop patching took

Hi Steven,

Le 17/10/2024 à 17:31, Steven Rostedt a écrit :
> From: Steven Rostedt <rostedt@...dmis.org>
> 
> Since the beginning of ftrace, the code that did the patching had its
> timings saved on how long it took to complete. But this information was
> never exposed. It was used for debugging and exposing it was always
> something that was on the TODO list. Now it's time to expose it. There's
> even a file that is where it should go!
> 
> Also include how long patching modules took as a separate value.
> 
>   # cat /sys/kernel/tracing/dyn_ftrace_total_info
>   57680 pages:231 groups: 9
>   ftrace boot update time = 14024666 (ns)
>   ftrace module total update time = 126070 (ns)

What is this supposed to report / measure ?

On powerpc I get:

25850 pages:14 groups: 3
ftrace boot update time = 0 (ns)
ftrace module total update time = 0 (ns)

Christophe

> 
> Signed-off-by: Steven Rostedt (Google) <rostedt@...dmis.org>
> ---
>   kernel/trace/ftrace.c | 11 ++++++++---
>   kernel/trace/trace.c  | 15 +++++++++++----
>   kernel/trace/trace.h  |  2 ++
>   3 files changed, 21 insertions(+), 7 deletions(-)
> 
> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> index e9fd4fb2769e..7fb0d2934a23 100644
> --- a/kernel/trace/ftrace.c
> +++ b/kernel/trace/ftrace.c
> @@ -3686,7 +3686,8 @@ static int ftrace_hash_move_and_update_subops(struct ftrace_ops *subops,
>   }
>   
>   
> -static u64		ftrace_update_time;
> +u64			ftrace_update_time;
> +u64			ftrace_total_mod_time;
>   unsigned long		ftrace_update_tot_cnt;
>   unsigned long		ftrace_number_of_pages;
>   unsigned long		ftrace_number_of_groups;
> @@ -3706,7 +3707,7 @@ static int ftrace_update_code(struct module *mod, struct ftrace_page *new_pgs)
>   	bool init_nop = ftrace_need_init_nop();
>   	struct ftrace_page *pg;
>   	struct dyn_ftrace *p;
> -	u64 start, stop;
> +	u64 start, stop, update_time;
>   	unsigned long update_cnt = 0;
>   	unsigned long rec_flags = 0;
>   	int i;
> @@ -3750,7 +3751,11 @@ static int ftrace_update_code(struct module *mod, struct ftrace_page *new_pgs)
>   	}
>   
>   	stop = ftrace_now(raw_smp_processor_id());
> -	ftrace_update_time = stop - start;
> +	update_time = stop - start;
> +	if (mod)
> +		ftrace_total_mod_time += update_time;
> +	else
> +		ftrace_update_time = update_time;
>   	ftrace_update_tot_cnt += update_cnt;
>   
>   	return 0;
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index c01375adc471..405dcf498159 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -8548,15 +8548,22 @@ tracing_read_dyn_info(struct file *filp, char __user *ubuf,
>   	char *buf;
>   	int r;
>   
> -	/* 256 should be plenty to hold the amount needed */
> -	buf = kmalloc(256, GFP_KERNEL);
> +	/* 512 should be plenty to hold the amount needed */
> +#define DYN_INFO_BUF_SIZE	512
> +
> +	buf = kmalloc(DYN_INFO_BUF_SIZE, GFP_KERNEL);
>   	if (!buf)
>   		return -ENOMEM;
>   
> -	r = scnprintf(buf, 256, "%ld pages:%ld groups: %ld\n",
> +	r = scnprintf(buf, DYN_INFO_BUF_SIZE,
> +		      "%ld pages:%ld groups: %ld\n"
> +		      "ftrace boot update time = %llu (ns)\n"
> +		      "ftrace module total update time = %llu (ns)\n",
>   		      ftrace_update_tot_cnt,
>   		      ftrace_number_of_pages,
> -		      ftrace_number_of_groups);
> +		      ftrace_number_of_groups,
> +		      ftrace_update_time,
> +		      ftrace_total_mod_time);
>   
>   	ret = simple_read_from_buffer(ubuf, cnt, ppos, buf, r);
>   	kfree(buf);
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index 6adf48ef4312..3307dad4d917 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -775,6 +775,8 @@ extern void trace_event_follow_fork(struct trace_array *tr, bool enable);
>   extern unsigned long ftrace_update_tot_cnt;
>   extern unsigned long ftrace_number_of_pages;
>   extern unsigned long ftrace_number_of_groups;
> +extern u64 ftrace_update_time;
> +extern u64 ftrace_total_mod_time;
>   void ftrace_init_trace_array(struct trace_array *tr);
>   #else
>   static inline void ftrace_init_trace_array(struct trace_array *tr) { }