x86/ftrace: fix boot time slowdown

[PATCH] x86/ftrace: fix boot time slowdown

Posted by Mike Rapoport 1 year, 2 months ago

From: "Mike Rapoport (Microsoft)" <rppt@kernel.org>

Steven Rostedt reported slowdown by over 30ms caused by commit 9bfc4824fd48
("x86/module: prepare module loading for ROX allocations of text")

  Before:

   # cat /sys/kernel/tracing/dyn_ftrace_total_info
  57695 pages:231 groups: 9
  ftrace boot update time = 14733459 (ns)
  ftrace module total update time = 449016 (ns)

  After:

   # cat /sys/kernel/tracing/dyn_ftrace_total_info
  57708 pages:231 groups: 9
  ftrace boot update time = 47195374 (ns)
  ftrace module total update time = 592080 (ns)

The slowdown happened because initial patching of kernel code for ftrace
was switched from text_poke_early() to text_poke() to accommodate ftrace
updates of module text allocated as ROX.

Restore the use of text_poke_early() for boot time patching of the kernel
code.

Reported-by: Steven Rostedt <rostedt@goodmis.org>
Closes: https://lore.kernel.org/all/20241118132501.4eddb46c@gandalf.local.home
Fixes: 9bfc4824fd48 ("x86/module: prepare module loading for ROX allocations of text")
Signed-off-by: Mike Rapoport (Microsoft) <rppt@kernel.org>
---
 arch/x86/kernel/ftrace.c | 8 +++++---
 1 file changed, 5 insertions(+), 3 deletions(-)

diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
index 4dd0ad6c94d6..9e50288abbaa 100644
--- a/arch/x86/kernel/ftrace.c
+++ b/arch/x86/kernel/ftrace.c
@@ -111,7 +111,7 @@ static int ftrace_verify_code(unsigned long ip, const char *old_code)
  */
 static int __ref
 ftrace_modify_code_direct(unsigned long ip, const char *old_code,
-			  const char *new_code)
+			  const char *new_code, struct module *mod)
 {
 	int ret = ftrace_verify_code(ip, old_code);
 	if (ret)
@@ -120,6 +120,8 @@ ftrace_modify_code_direct(unsigned long ip, const char *old_code,
 	/* replace the text with the new text */
 	if (ftrace_poke_late) {
 		text_poke_queue((void *)ip, new_code, MCOUNT_INSN_SIZE, NULL);
+	} else if (!mod) {
+		text_poke_early((void *)ip, new_code, MCOUNT_INSN_SIZE);
 	} else {
 		mutex_lock(&text_mutex);
 		text_poke((void *)ip, new_code, MCOUNT_INSN_SIZE);
@@ -145,7 +147,7 @@ int ftrace_make_nop(struct module *mod, struct dyn_ftrace *rec, unsigned long ad
 	 * just modify the code directly.
 	 */
 	if (addr == MCOUNT_ADDR)
-		return ftrace_modify_code_direct(ip, old, new);
+		return ftrace_modify_code_direct(ip, old, new, mod);
 
 	/*
 	 * x86 overrides ftrace_replace_code -- this function will never be used
@@ -164,7 +166,7 @@ int ftrace_make_call(struct dyn_ftrace *rec, unsigned long addr)
 	new = ftrace_call_replace(ip, addr);
 
 	/* Should only be called when module is loaded */
-	return ftrace_modify_code_direct(rec->ip, old, new);
+	return ftrace_modify_code_direct(rec->ip, old, new, NULL);
 }
 
 /*

base-commit: 9f16d5e6f220661f73b36a4be1b21575651d8833
-- 
2.45.2

Re: [PATCH] x86/ftrace: fix boot time slowdown

Posted by Mike Rapoport 1 year, 2 months ago

Gentle ping

On Sun, Nov 24, 2024 at 04:07:05PM +0200, Mike Rapoport wrote:
> From: "Mike Rapoport (Microsoft)" <rppt@kernel.org>
> 
> Steven Rostedt reported slowdown by over 30ms caused by commit 9bfc4824fd48
> ("x86/module: prepare module loading for ROX allocations of text")
> 
>   Before:
> 
>    # cat /sys/kernel/tracing/dyn_ftrace_total_info
>   57695 pages:231 groups: 9
>   ftrace boot update time = 14733459 (ns)
>   ftrace module total update time = 449016 (ns)
> 
>   After:
> 
>    # cat /sys/kernel/tracing/dyn_ftrace_total_info
>   57708 pages:231 groups: 9
>   ftrace boot update time = 47195374 (ns)
>   ftrace module total update time = 592080 (ns)
> 
> The slowdown happened because initial patching of kernel code for ftrace
> was switched from text_poke_early() to text_poke() to accommodate ftrace
> updates of module text allocated as ROX.
> 
> Restore the use of text_poke_early() for boot time patching of the kernel
> code.
> 
> Reported-by: Steven Rostedt <rostedt@goodmis.org>
> Closes: https://lore.kernel.org/all/20241118132501.4eddb46c@gandalf.local.home
> Fixes: 9bfc4824fd48 ("x86/module: prepare module loading for ROX allocations of text")
> Signed-off-by: Mike Rapoport (Microsoft) <rppt@kernel.org>
> ---
>  arch/x86/kernel/ftrace.c | 8 +++++---
>  1 file changed, 5 insertions(+), 3 deletions(-)
> 
> diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
> index 4dd0ad6c94d6..9e50288abbaa 100644
> --- a/arch/x86/kernel/ftrace.c
> +++ b/arch/x86/kernel/ftrace.c
> @@ -111,7 +111,7 @@ static int ftrace_verify_code(unsigned long ip, const char *old_code)
>   */
>  static int __ref
>  ftrace_modify_code_direct(unsigned long ip, const char *old_code,
> -			  const char *new_code)
> +			  const char *new_code, struct module *mod)
>  {
>  	int ret = ftrace_verify_code(ip, old_code);
>  	if (ret)
> @@ -120,6 +120,8 @@ ftrace_modify_code_direct(unsigned long ip, const char *old_code,
>  	/* replace the text with the new text */
>  	if (ftrace_poke_late) {
>  		text_poke_queue((void *)ip, new_code, MCOUNT_INSN_SIZE, NULL);
> +	} else if (!mod) {
> +		text_poke_early((void *)ip, new_code, MCOUNT_INSN_SIZE);
>  	} else {
>  		mutex_lock(&text_mutex);
>  		text_poke((void *)ip, new_code, MCOUNT_INSN_SIZE);
> @@ -145,7 +147,7 @@ int ftrace_make_nop(struct module *mod, struct dyn_ftrace *rec, unsigned long ad
>  	 * just modify the code directly.
>  	 */
>  	if (addr == MCOUNT_ADDR)
> -		return ftrace_modify_code_direct(ip, old, new);
> +		return ftrace_modify_code_direct(ip, old, new, mod);
>  
>  	/*
>  	 * x86 overrides ftrace_replace_code -- this function will never be used
> @@ -164,7 +166,7 @@ int ftrace_make_call(struct dyn_ftrace *rec, unsigned long addr)
>  	new = ftrace_call_replace(ip, addr);
>  
>  	/* Should only be called when module is loaded */
> -	return ftrace_modify_code_direct(rec->ip, old, new);
> +	return ftrace_modify_code_direct(rec->ip, old, new, NULL);
>  }
>  
>  /*
> 
> base-commit: 9f16d5e6f220661f73b36a4be1b21575651d8833
> -- 
> 2.45.2
> 

-- 
Sincerely yours,
Mike.

Re: [PATCH] x86/ftrace: fix boot time slowdown

Posted by Steven Rostedt 1 year, 1 month ago

On Tue, 3 Dec 2024 11:08:44 +0200
Mike Rapoport <rppt@kernel.org> wrote:

> Gentle ping

I'll take this if nobody else will.

-- Steve

> 
> On Sun, Nov 24, 2024 at 04:07:05PM +0200, Mike Rapoport wrote:
> > From: "Mike Rapoport (Microsoft)" <rppt@kernel.org>
> > 
> > Steven Rostedt reported slowdown by over 30ms caused by commit 9bfc4824fd48
> > ("x86/module: prepare module loading for ROX allocations of text")
> > 
> >   Before:
> > 
> >    # cat /sys/kernel/tracing/dyn_ftrace_total_info
> >   57695 pages:231 groups: 9
> >   ftrace boot update time = 14733459 (ns)
> >   ftrace module total update time = 449016 (ns)
> > 
> >   After:
> > 
> >    # cat /sys/kernel/tracing/dyn_ftrace_total_info
> >   57708 pages:231 groups: 9
> >   ftrace boot update time = 47195374 (ns)
> >   ftrace module total update time = 592080 (ns)
> > 
> > The slowdown happened because initial patching of kernel code for ftrace
> > was switched from text_poke_early() to text_poke() to accommodate ftrace
> > updates of module text allocated as ROX.
> > 
> > Restore the use of text_poke_early() for boot time patching of the kernel
> > code.
> > 
> > Reported-by: Steven Rostedt <rostedt@goodmis.org>
> > Closes: https://lore.kernel.org/all/20241118132501.4eddb46c@gandalf.local.home
> > Fixes: 9bfc4824fd48 ("x86/module: prepare module loading for ROX allocations of text")
> > Signed-off-by: Mike Rapoport (Microsoft) <rppt@kernel.org>
> > ---
> >  arch/x86/kernel/ftrace.c | 8 +++++---
> >  1 file changed, 5 insertions(+), 3 deletions(-)
> > 
> > diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
> > index 4dd0ad6c94d6..9e50288abbaa 100644
> > --- a/arch/x86/kernel/ftrace.c
> > +++ b/arch/x86/kernel/ftrace.c
> > @@ -111,7 +111,7 @@ static int ftrace_verify_code(unsigned long ip, const char *old_code)
> >   */
> >  static int __ref
> >  ftrace_modify_code_direct(unsigned long ip, const char *old_code,
> > -			  const char *new_code)
> > +			  const char *new_code, struct module *mod)
> >  {
> >  	int ret = ftrace_verify_code(ip, old_code);
> >  	if (ret)
> > @@ -120,6 +120,8 @@ ftrace_modify_code_direct(unsigned long ip, const char *old_code,
> >  	/* replace the text with the new text */
> >  	if (ftrace_poke_late) {
> >  		text_poke_queue((void *)ip, new_code, MCOUNT_INSN_SIZE, NULL);
> > +	} else if (!mod) {
> > +		text_poke_early((void *)ip, new_code, MCOUNT_INSN_SIZE);
> >  	} else {
> >  		mutex_lock(&text_mutex);
> >  		text_poke((void *)ip, new_code, MCOUNT_INSN_SIZE);
> > @@ -145,7 +147,7 @@ int ftrace_make_nop(struct module *mod, struct dyn_ftrace *rec, unsigned long ad
> >  	 * just modify the code directly.
> >  	 */
> >  	if (addr == MCOUNT_ADDR)
> > -		return ftrace_modify_code_direct(ip, old, new);
> > +		return ftrace_modify_code_direct(ip, old, new, mod);
> >  
> >  	/*
> >  	 * x86 overrides ftrace_replace_code -- this function will never be used
> > @@ -164,7 +166,7 @@ int ftrace_make_call(struct dyn_ftrace *rec, unsigned long addr)
> >  	new = ftrace_call_replace(ip, addr);
> >  
> >  	/* Should only be called when module is loaded */
> > -	return ftrace_modify_code_direct(rec->ip, old, new);
> > +	return ftrace_modify_code_direct(rec->ip, old, new, NULL);
> >  }
> >  
> >  /*
> > 
> > base-commit: 9f16d5e6f220661f73b36a4be1b21575651d8833
> > -- 
> > 2.45.2
> >   
>

Re: [PATCH] x86/ftrace: fix boot time slowdown

Posted by Steven Rostedt 11 months, 1 week ago

On Tue, 10 Dec 2024 23:00:56 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Tue, 3 Dec 2024 11:08:44 +0200
> Mike Rapoport <rppt@kernel.org> wrote:
> 
> > Gentle ping  
> 
> I'll take this if nobody else will.

I guess I'll take this for the next merge window.

-- Steve

Re: [PATCH] x86/ftrace: fix boot time slowdown

Posted by Mike Rapoport 11 months, 1 week ago

On Mon, Mar 03, 2025 at 05:24:27PM -0500, Steven Rostedt wrote:
> On Tue, 10 Dec 2024 23:00:56 -0500
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > On Tue, 3 Dec 2024 11:08:44 +0200
> > Mike Rapoport <rppt@kernel.org> wrote:
> > 
> > > Gentle ping  
> > 
> > I'll take this if nobody else will.
> 
> I guess I'll take this for the next merge window.

It's not relevant anymore, the commit that changed text_poke_early() to
text_poke() is now reverted in tip tree.
 
> -- Steve

-- 
Sincerely yours,
Mike.

Re: [PATCH] x86/ftrace: fix boot time slowdown

Posted by Steven Rostedt 11 months, 1 week ago

On Tue, 4 Mar 2025 09:08:12 +0200
Mike Rapoport <rppt@kernel.org> wrote:

> It's not relevant anymore, the commit that changed text_poke_early() to
> text_poke() is now reverted in tip tree.
>  

Will that be going into 6.14?

-- Steve

Re: [PATCH] x86/ftrace: fix boot time slowdown

Posted by Mike Rapoport 11 months, 1 week ago

On Tue, Mar 04, 2025 at 09:55:05AM -0500, Steven Rostedt wrote:
> On Tue, 4 Mar 2025 09:08:12 +0200
> Mike Rapoport <rppt@kernel.org> wrote:
> 
> > It's not relevant anymore, the commit that changed text_poke_early() to
> > text_poke() is now reverted in tip tree.
> >  
> 
> Will that be going into 6.14?

It seems so.
 
> -- Steve

-- 
Sincerely yours,
Mike.

Re: [PATCH] x86/ftrace: fix boot time slowdown

Posted by Steven Rostedt 1 year, 2 months ago

On Sun, 24 Nov 2024 16:07:05 +0200
Mike Rapoport <rppt@kernel.org> wrote:

> From: "Mike Rapoport (Microsoft)" <rppt@kernel.org>
> 
> Steven Rostedt reported slowdown by over 30ms caused by commit 9bfc4824fd48
> ("x86/module: prepare module loading for ROX allocations of text")
> 
>   Before:
> 
>    # cat /sys/kernel/tracing/dyn_ftrace_total_info
>   57695 pages:231 groups: 9
>   ftrace boot update time = 14733459 (ns)
>   ftrace module total update time = 449016 (ns)
> 
>   After:
> 
>    # cat /sys/kernel/tracing/dyn_ftrace_total_info
>   57708 pages:231 groups: 9
>   ftrace boot update time = 47195374 (ns)
>   ftrace module total update time = 592080 (ns)
> 
> The slowdown happened because initial patching of kernel code for ftrace
> was switched from text_poke_early() to text_poke() to accommodate ftrace
> updates of module text allocated as ROX.
> 
> Restore the use of text_poke_early() for boot time patching of the kernel
> code.
> 
> Reported-by: Steven Rostedt <rostedt@goodmis.org>

Tested-by: Steven Rostedt (Google) <rostedt@goodmis.org>

-- Steve

> Closes: https://lore.kernel.org/all/20241118132501.4eddb46c@gandalf.local.home
> Fixes: 9bfc4824fd48 ("x86/module: prepare module loading for ROX allocations of text")
> Signed-off-by: Mike Rapoport (Microsoft) <rppt@kernel.org>
> ---
>  arch/x86/kernel/ftrace.c | 8 +++++---
>  1 file changed, 5 insertions(+), 3 deletions(-)
> 
> diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
> index 4dd0ad6c94d6..9e50288abbaa 100644
> --- a/arch/x86/kernel/ftrace.c
> +++ b/arch/x86/kernel/ftrace.c
> @@ -111,7 +111,7 @@ static int ftrace_verify_code(unsigned long ip, const char *old_code)
>   */
>  static int __ref
>  ftrace_modify_code_direct(unsigned long ip, const char *old_code,
> -			  const char *new_code)
> +			  const char *new_code, struct module *mod)
>  {
>  	int ret = ftrace_verify_code(ip, old_code);
>  	if (ret)
> @@ -120,6 +120,8 @@ ftrace_modify_code_direct(unsigned long ip, const char *old_code,
>  	/* replace the text with the new text */
>  	if (ftrace_poke_late) {
>  		text_poke_queue((void *)ip, new_code, MCOUNT_INSN_SIZE, NULL);
> +	} else if (!mod) {
> +		text_poke_early((void *)ip, new_code, MCOUNT_INSN_SIZE);
>  	} else {
>  		mutex_lock(&text_mutex);
>  		text_poke((void *)ip, new_code, MCOUNT_INSN_SIZE);
> @@ -145,7 +147,7 @@ int ftrace_make_nop(struct module *mod, struct dyn_ftrace *rec, unsigned long ad
>  	 * just modify the code directly.
>  	 */
>  	if (addr == MCOUNT_ADDR)
> -		return ftrace_modify_code_direct(ip, old, new);
> +		return ftrace_modify_code_direct(ip, old, new, mod);
>  
>  	/*
>  	 * x86 overrides ftrace_replace_code -- this function will never be used
> @@ -164,7 +166,7 @@ int ftrace_make_call(struct dyn_ftrace *rec, unsigned long addr)
>  	new = ftrace_call_replace(ip, addr);
>  
>  	/* Should only be called when module is loaded */
> -	return ftrace_modify_code_direct(rec->ip, old, new);
> +	return ftrace_modify_code_direct(rec->ip, old, new, NULL);
>  }
>  
>  /*
> 
> base-commit: 9f16d5e6f220661f73b36a4be1b21575651d8833

Re: [PATCH] x86/ftrace: fix boot time slowdown

Posted by Masami Hiramatsu (Google) 1 year, 2 months ago

On Sun, 24 Nov 2024 16:07:05 +0200
Mike Rapoport <rppt@kernel.org> wrote:

> From: "Mike Rapoport (Microsoft)" <rppt@kernel.org>
> 
> Steven Rostedt reported slowdown by over 30ms caused by commit 9bfc4824fd48
> ("x86/module: prepare module loading for ROX allocations of text")
> 
>   Before:
> 
>    # cat /sys/kernel/tracing/dyn_ftrace_total_info
>   57695 pages:231 groups: 9
>   ftrace boot update time = 14733459 (ns)
>   ftrace module total update time = 449016 (ns)
> 
>   After:
> 
>    # cat /sys/kernel/tracing/dyn_ftrace_total_info
>   57708 pages:231 groups: 9
>   ftrace boot update time = 47195374 (ns)
>   ftrace module total update time = 592080 (ns)
> 
> The slowdown happened because initial patching of kernel code for ftrace
> was switched from text_poke_early() to text_poke() to accommodate ftrace
> updates of module text allocated as ROX.
> 
> Restore the use of text_poke_early() for boot time patching of the kernel
> code.
> 

Looks good to me.

Reviewed-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>

Thank you!

> Reported-by: Steven Rostedt <rostedt@goodmis.org>
> Closes: https://lore.kernel.org/all/20241118132501.4eddb46c@gandalf.local.home
> Fixes: 9bfc4824fd48 ("x86/module: prepare module loading for ROX allocations of text")
> Signed-off-by: Mike Rapoport (Microsoft) <rppt@kernel.org>
> ---
>  arch/x86/kernel/ftrace.c | 8 +++++---
>  1 file changed, 5 insertions(+), 3 deletions(-)
> 
> diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
> index 4dd0ad6c94d6..9e50288abbaa 100644
> --- a/arch/x86/kernel/ftrace.c
> +++ b/arch/x86/kernel/ftrace.c
> @@ -111,7 +111,7 @@ static int ftrace_verify_code(unsigned long ip, const char *old_code)
>   */
>  static int __ref
>  ftrace_modify_code_direct(unsigned long ip, const char *old_code,
> -			  const char *new_code)
> +			  const char *new_code, struct module *mod)
>  {
>  	int ret = ftrace_verify_code(ip, old_code);
>  	if (ret)
> @@ -120,6 +120,8 @@ ftrace_modify_code_direct(unsigned long ip, const char *old_code,
>  	/* replace the text with the new text */
>  	if (ftrace_poke_late) {
>  		text_poke_queue((void *)ip, new_code, MCOUNT_INSN_SIZE, NULL);
> +	} else if (!mod) {
> +		text_poke_early((void *)ip, new_code, MCOUNT_INSN_SIZE);
>  	} else {
>  		mutex_lock(&text_mutex);
>  		text_poke((void *)ip, new_code, MCOUNT_INSN_SIZE);
> @@ -145,7 +147,7 @@ int ftrace_make_nop(struct module *mod, struct dyn_ftrace *rec, unsigned long ad
>  	 * just modify the code directly.
>  	 */
>  	if (addr == MCOUNT_ADDR)
> -		return ftrace_modify_code_direct(ip, old, new);
> +		return ftrace_modify_code_direct(ip, old, new, mod);
>  
>  	/*
>  	 * x86 overrides ftrace_replace_code -- this function will never be used
> @@ -164,7 +166,7 @@ int ftrace_make_call(struct dyn_ftrace *rec, unsigned long addr)
>  	new = ftrace_call_replace(ip, addr);
>  
>  	/* Should only be called when module is loaded */
> -	return ftrace_modify_code_direct(rec->ip, old, new);
> +	return ftrace_modify_code_direct(rec->ip, old, new, NULL);
>  }
>  
>  /*
> 
> base-commit: 9f16d5e6f220661f73b36a4be1b21575651d8833
> -- 
> 2.45.2
> 


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>