[PATCH] ftrace: Show timings of how long nop patching took

[PATCH] ftrace: Show timings of how long nop patching took

[Steven Rostedt]

From: Steven Rostedt <rostedt@goodmis.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)

Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.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) { }
-- 
2.45.2

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

[Christophe Leroy]

Hi Steven,

Le 17/10/2024 à 17:31, Steven Rostedt a écrit :
> From: Steven Rostedt <rostedt@goodmis.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@goodmis.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) { }

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

[Steven Rostedt]

On Sun, 1 Dec 2024 20:37:42 +0100
Christophe Leroy <christophe.leroy@csgroup.eu> wrote:

> Hi Steven,
> 
> Le 17/10/2024 à 17:31, Steven Rostedt a écrit :
> > From: Steven Rostedt <rostedt@goodmis.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)

Hmm, does powerpc support "trace_clock_local()" at early boot? I
probably can just switch from using "ftrace_now()" to using
ktime_get_real_ts64(). Hmm.

-- Steve

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

[Mike Rapoport]

On Sun, Dec 01, 2024 at 03:04:06PM -0500, Steven Rostedt wrote:
> On Sun, 1 Dec 2024 20:37:42 +0100
> Christophe Leroy <christophe.leroy@csgroup.eu> wrote:
> 
> > Hi Steven,
> > 
> > Le 17/10/2024 à 17:31, Steven Rostedt a écrit :
> > > From: Steven Rostedt <rostedt@goodmis.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)
> 
> Hmm, does powerpc support "trace_clock_local()" at early boot? I
> probably can just switch from using "ftrace_now()" to using
> ktime_get_real_ts64(). Hmm.

The calls to timekeeping_init() and time_init() are after ftrace_init() so
unless an architecture sets up some clock in setup_arch() like x86 does
there won't be a clock to use.
 
> -- Steve

-- 
Sincerely yours,
Mike.

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

[Steven Rostedt]

On Mon, 2 Dec 2024 08:37:19 +0200
Mike Rapoport <rppt@kernel.org> wrote:

> > > On powerpc I get:
> > > 
> > > 25850 pages:14 groups: 3
> > > ftrace boot update time = 0 (ns)
> > > ftrace module total update time = 0 (ns)  
> > 
> > Hmm, does powerpc support "trace_clock_local()" at early boot? I
> > probably can just switch from using "ftrace_now()" to using
> > ktime_get_real_ts64(). Hmm.  
> 
> The calls to timekeeping_init() and time_init() are after ftrace_init() so
> unless an architecture sets up some clock in setup_arch() like x86 does
> there won't be a clock to use.

Hmm, maybe I should add:

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index be62f0ea1814..362a125d7bcc 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -8588,14 +8588,23 @@ tracing_read_dyn_info(struct file *filp, char __user *ubuf,
 		return -ENOMEM;
 
 	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",
+		      "%ld pages:%ld groups: %ld\n",
 		      ftrace_update_tot_cnt,
 		      ftrace_number_of_pages,
-		      ftrace_number_of_groups,
-		      ftrace_update_time,
-		      ftrace_total_mod_time);
+		      ftrace_number_of_groups);
+
+	if (ftrace_update_time) {
+		r += scnprintf(buf + r, DYN_INFO_BUF_SIZE - r,
+			       "ftrace boot update time = %llu (ns)\n",
+			       ftrace_update_time);
+	} else {
+		r += scnprintf(buf + r, DYN_INFO_BUF_SIZE - r,
+			       "ftrace boot update time = [Unavailable]\n");
+	}
+
+	r += scnprintf(buf + r, DYN_INFO_BUF_SIZE - r,
+		       "ftrace module total update time = %llu (ns)\n",
+		       ftrace_total_mod_time);
 
 	ret = simple_read_from_buffer(ubuf, cnt, ppos, buf, r);
 	kfree(buf);

Which should turn the above to:

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

Which should at least make it not confusing.

I'm assuming that the module timings are zero because no modules were loaded?

-- Steve

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

[Christophe Leroy]

Le 02/12/2024 à 21:05, Steven Rostedt a écrit :
> On Mon, 2 Dec 2024 08:37:19 +0200
> Mike Rapoport <rppt@kernel.org> wrote:
> 
>>>> On powerpc I get:
>>>>
>>>> 25850 pages:14 groups: 3
>>>> ftrace boot update time = 0 (ns)
>>>> ftrace module total update time = 0 (ns)
>>>
>>> Hmm, does powerpc support "trace_clock_local()" at early boot? I
>>> probably can just switch from using "ftrace_now()" to using
>>> ktime_get_real_ts64(). Hmm.
>>
>> The calls to timekeeping_init() and time_init() are after ftrace_init() so
>> unless an architecture sets up some clock in setup_arch() like x86 does
>> there won't be a clock to use.
> 
> Hmm, maybe I should add:
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index be62f0ea1814..362a125d7bcc 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -8588,14 +8588,23 @@ tracing_read_dyn_info(struct file *filp, char __user *ubuf,
>   		return -ENOMEM;
>   
>   	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",
> +		      "%ld pages:%ld groups: %ld\n",
>   		      ftrace_update_tot_cnt,
>   		      ftrace_number_of_pages,
> -		      ftrace_number_of_groups,
> -		      ftrace_update_time,
> -		      ftrace_total_mod_time);
> +		      ftrace_number_of_groups);
> +
> +	if (ftrace_update_time) {
> +		r += scnprintf(buf + r, DYN_INFO_BUF_SIZE - r,
> +			       "ftrace boot update time = %llu (ns)\n",
> +			       ftrace_update_time);
> +	} else {
> +		r += scnprintf(buf + r, DYN_INFO_BUF_SIZE - r,
> +			       "ftrace boot update time = [Unavailable]\n");
> +	}
> +
> +	r += scnprintf(buf + r, DYN_INFO_BUF_SIZE - r,
> +		       "ftrace module total update time = %llu (ns)\n",
> +		       ftrace_total_mod_time);
>   
>   	ret = simple_read_from_buffer(ubuf, cnt, ppos, buf, r);
>   	kfree(buf);
> 
> Which should turn the above to:
> 
>    25850 pages:14 groups: 3
>    ftrace boot update time = [Unavailable]
>    ftrace module total update time = 0 (ns)
> 
> Which should at least make it not confusing.

Well. Maybe, but at the end what we need is the measured value, if it 
only works on x86 it is just pointless, isn't it ?

trace_clock_local() calls sched_clock()

I don't know about other architectures, but on powerpc sched_clock() is:

	notrace unsigned long long sched_clock(void)
	{
		return mulhdu(get_tb() - boot_tb, tb_to_ns_scale) << tb_to_ns_shift;
	}

boot_tb, tb_to_ns_scale and tb_to_ns_shift are not known before 
time_init() is called.

But get_tb() returns a valid value already so it is possible to get the 
ticks and do the calculation later with tb_to_ns()


> 
> I'm assuming that the module timings are zero because no modules were loaded?

Indeed I don't even have CONFIG_MODULES, maybe the complete line should 
be removed in that case.

Christophe

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

[Steven Rostedt]

On Tue, 3 Dec 2024 08:21:49 +0100
Christophe Leroy <christophe.leroy@csgroup.eu> wrote:

> > Which should turn the above to:
> > 
> >    25850 pages:14 groups: 3
> >    ftrace boot update time = [Unavailable]
> >    ftrace module total update time = 0 (ns)
> > 
> > Which should at least make it not confusing.  
> 
> Well. Maybe, but at the end what we need is the measured value, if it 
> only works on x86 it is just pointless, isn't it ?
> 
> trace_clock_local() calls sched_clock()
> 
> I don't know about other architectures, but on powerpc sched_clock() is:
> 
> 	notrace unsigned long long sched_clock(void)
> 	{
> 		return mulhdu(get_tb() - boot_tb, tb_to_ns_scale) << tb_to_ns_shift;
> 	}
> 
> boot_tb, tb_to_ns_scale and tb_to_ns_shift are not known before 
> time_init() is called.
> 
> But get_tb() returns a valid value already so it is possible to get the 
> ticks and do the calculation later with tb_to_ns()

We could add code to make that work for all archs via arch_xxx() functions.

But as the merge window is already closed, I'll just submit a
"[Unavailable]" patch to Linus as a "fix" and then for the next merge
window we can have code that will allow architectures to print real timings.

-- Steve