linux-kernel - Re: [PATCH] ftrace: Fix softlockup in ftrace_module

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: <20250911143758.06ef1230@gandalf.local.home>
Date: Thu, 11 Sep 2025 14:37:58 -0400
From: Steven Rostedt <rostedt@...dmis.org>
To: Vladimir Riabchun <ferr.lambarginio@...il.com>
Cc: 20250911104138.2830f60b@...dalf.local.home,
 linux-kernel@...r.kernel.org, linux-trace-kernel@...r.kernel.org,
 mark.rutland@....com, mhiramat@...nel.org
Subject: Re: [PATCH] ftrace: Fix softlockup in ftrace_module_enable

On Thu, 11 Sep 2025 20:16:41 +0200
Vladimir Riabchun <ferr.lambarginio@...il.com> wrote:

> On Thu, Sep 11, 2025 at 10:41:38AM -0400, Steven Rostedt wrote:
> > On Thu, 11 Sep 2025 15:33:15 +0200
> > Vladimir Riabchun <ferr.lambarginio@...il.com> wrote:
> >   
> > > A soft lockup was observed when loading amdgpu module,  
> > 
> > I'd like to see more about that soft lockup.  
> Sure, here is a call trace:

Thanks, because this helps out a lot in understanding this!


> [  397.861521] [      C1]  <TASK>
> [  397.861562] [      C1]  ? asm_sysvec_apic_timer_interrupt+0x1b/0x20
> [  397.861663] [      C1]  ? find_kallsyms_symbol+0x1c5/0x350
> [  397.861739] [      C1]  ? __asan_load4+0x35/0xd0
> [  397.861806] [      C1]  find_kallsyms_symbol+0x1c5/0x350
> [  397.861879] [      C1]  ? mod_hdcp_hdcp2_dp_transition+0x1140/0x1140 [amdgpu]
> [  397.864007] [      C1]  ? __pfx_CalculatePrefetchSchedule.isra.0+0x10/0x10 [amdgpu]
> [  397.868240] [      C1]  ? __pfx_dc_edid_parser_recv_cea_ack+0x10/0x10 [amdgpu]
> [  397.872439] [      C1]  ? __pfx_dc_edid_parser_recv_cea_ack+0x10/0x10 [amdgpu]
> [  397.876605] [      C1]  module_address_lookup+0x7f/0xd0
> [  397.878686] [      C1]  ? __pfx_dc_edid_parser_recv_cea_ack+0x10/0x10 [amdgpu]
> [  397.882809] [      C1]  kallsyms_lookup_buildid+0xf8/0x190
> [  397.884811] [      C1]  kallsyms_lookup+0x14/0x30
> [  397.886734] [      C1]  test_for_valid_rec+0xcf/0x160

As you pointed out below, the test_for_valid_rec() looks to be the culprit.
Most likely because of the kallsyms lookup it's doing. Which requires a
search. It's binary, but still quite expensive when executed over 10
thousand times.


> > How big is the amdgpu driver? How many functions does it have?
> > 
> >  # grep amdgpu /sys/kernel/tracing/available_filter_functions | wc -l  
> 14334 functions, hefty one.

And why this is a problem.

> > 
> > And I'm guessing that this is only an issue when ftrace is enabled:
> > 
> > 		if (ftrace_start_up && cnt) {
> > 			int failed = __ftrace_replace_code(rec, 1);
> > 			if (failed) {
> > 				ftrace_bug(failed, rec);
> > 				goto out_loop;
> > 			}
> > 		}
> > 
> > As that could slow things down.  
> Call trace shows that kernel got stuck in test_for_valid_rec. It calls
> kallsyms_lookup, which then calls module_address_lookup,
> bpf_address_lookup and ftrace_mod_address_lookup. All of these guys hold
> RCU read lock or disable preemption and may consume some time (mostly
> because of debug kernel checks, but still there shouldn't be a panic).

Agreed. The kallsyms lookup is the problem
> 
> Probably it may worth moving cond_resched under within_module check, but
> before test_for_valid_rec call.

Hmm, do modules even have weak functions? If they don't then that test is
useless.

-- Steve