Re: [PATCH] ftrace: Fix softlockup in ftrace_module_enable

[Steven Rostedt]

On Thu, 11 Sep 2025 20:16:41 +0200
Vladimir Riabchun <ferr.lambarginio@xxxxxxxxx> 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@xxxxxxxxx> 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