Bug 2180328

With fresh rhel-9.3 nightlies, following simple stap script started to elaborate (pass 2) very slowly:

9 x86_64 # uname -r
5.14.0-285.el9.x86_64
9 x86_64 # time stap -gp4 -v -e 'probe kernel.function("kernel_clone").return { $return = -1 }' -vvvvv

[ ... stuff deleted ... ]

Skipping tapset "/usr/share/systemtap/tapset/tzinfo.stp", duplicate inode.
Skipping tapset "/usr/share/systemtap/tapset/uconversions-guru.stp", duplicate inode.
Skipping tapset "/usr/share/systemtap/tapset/uconversions.stp", duplicate inode.
Searched: "/usr/share/systemtap/tapset", found: 41, processed: 0
Pass 1: parsed user script and 501 library scripts using 132076virt/104328res/15232shr/88444data kb, in 310usr/100sys/476real ms.
derive-probes (location #0): kernel.function("kernel_clone").return of keyword at <input>:1:1
checking pattern '' vs. module 'kernel' file '/usr/lib/debug/lib/modules/5.14.0-285.el9.x86_64/vmlinux'
Attempting to extract kernel debuginfo build ID from /lib/modules/5.14.0-285.el9.x86_64/build/vmlinux.id
blocklist regexps:
blfn: ^(atomic_notifier_call_chain|default_do_nmi|__die|die_nmi|do_debug|do_general_protection|do_int3|do_IRQ|do_page_fault|do_sparc64_fault|do_trap|dummy_nmi_callback|flush_icache_range|ia64_bad_break|ia64_do_page_fault|ia64_fault|io_check_error|mem_parity_error|nmi_watchdog_tick|notifier_call_chain|oops_begin|oops_end|program_check_exception|single_step_exception|sync_regs|unhandled_fault|unknown_nmi_error|xen_[gs]et_debugreg|xen_irq_.*|xen_.*_fl_direct.*|check_events|xen_adjust_exception_frame|xen_iret.*|xen_sysret64.*|test_ti_thread_flag.*|inat_get_opcode_attribute|system_call_after_swapgs|HYPERVISOR_[gs]et_debugreg|HYPERVISOR_event_channel_op|hash_64|hash_ptr|native_set_pte|.*raw_.*_lock.*|.*raw_.*_unlock.*|.*raw_.*_trylock.*|.*read_lock.*|.*read_unlock.*|.*read_trylock.*|.*write_lock.*|.*write_unlock.*|.*write_trylock.*|.*write_seqlock.*|.*write_sequnlock.*|.*spin_lock.*|.*spin_unlock.*|.*spin_trylock.*|.*spin_is_locked.*|rwsem_.*lock.*|.*mutex_.*lock.*|atomic_.*|atomic64_.*|get_bh|put_bh|.*apic.*|.*APIC.*|.*softirq.*|.*IRQ.*|.*_intr.*|__delay|.*kernel_text.*|get_current|current_.*|.*exception_tables.*|.*setup_rt_frame.*|.*preempt_count.*|preempt_schedule|__switch_to|special_mapping_.*|.*_pte_.*)$
blfn_ret: ^(do_exit|sys_exit|sys_exit_group)$
blfile: ^(kernel/kprobes\.c|arch/.*/kernel/kprobes\.c|.*/include/asm/io\.h|.*/include/asm/io-defs\.h|.*/include/asm/io_64\.h|.*/include/asm/bitops\.h|drivers/ide/ide-iops\.c|arch/.*/kernel/paravirt\.c|.*/include/asm/paravirt\.h|fs/seq_file\.c)$
blsection: ^(\.init\.|\.exit\.|\.devinit\.|\.devexit\.|\.cpuinit\.|\.cpuexit\.|\.meminit\.|\.memexit\.)
dwarf_builder::build for 
parse 'kernel_clone', func 'kernel_clone'
pattern 'kernel' matches module 'kernel'
focused on module 'kernel' = [0xffffffff81000000-0xffffffff84400000, bias 0 file /usr/lib/debug/lib/modules/5.14.0-285.el9.x86_64/vmlinux ELF machine |x86_64 (code 62)
focused on module 'kernel'
module function cache kernel size 169214

module function cache kernel hit kernel_clone
querying dwarf func in file kernel/fork.c count 0 (func dieoffset: 0xe58ddb)
selected function kernel_clone
kernel_clone = dwfl_module_addrinfo(entrypc=0xffffffff810f6250 + (nil))
added to filtered_functions (dieoffset: 0xe58ddb)
function cache kernel:kernel/fork.c size 431
function cache kernel:kernel/fork.c hit kernel_clone
querying dwarf func in file kernel/fork.c count 0 (func dieoffset: 0xe58ddb)
selected function kernel_clone
kernel_clone = dwfl_module_addrinfo(entrypc=0xffffffff810f6250 + (nil))
added to filtered_functions (dieoffset: 0xe58ddb)
probe kernel_clone@kernel/fork.c:2607 kernel reloc=.dynamic pc=0xffffffff810f6250
literal_stmt_for_return: finding return value for kernel_clone (kernel/fork.c)


[ ... stall for apprx 25 mins ... ]


replaced $return with __private__input___dwarf_tvar_set_return_0()
replaced (__private__input___dwarf_tvar_set_return_0(-(1))) = (-(1)) with __private__input___dwarf_tvar_set_return_0(-(1))
Collapsing constant unary operator '-' at <input>:1:58
replaced -(1) with -1
Rerunning the code filters.
symbol resolution for derived-probe probe kernel.function("kernel_clone@kernel/fork.c:2607").return /* pc=_stext+0xf6250 */ /* <- kernel.function("kernel_clone@kernel/fork.c:2607").return */{
__private__input___dwarf_tvar_set_return_0(-1);
}
symbol resolution for function function __private__input___dwarf_tvar_set_return_0 (rvalue)
{
return (@kregister(0)) = (rvalue);
}
      local rvalue is formal parameter
number of probes with global-variable conditions: 0
Eliding side-effect-free singleton block operator '{' at <input>:1:46
replaced {
__private__input___dwarf_tvar_set_return_0(-1);
} with __private__input___dwarf_tvar_set_return_0(-1)
Eliding side-effect-free singleton block identifier '$return' at <input>:1:48
replaced {
return (@kregister(0)) = (rvalue);
} with return (@kregister(0)) = (rvalue)
resolved type long to identifier '$return' at <input>:1:48
resolved type long to identifier '$return' at <input>:1:48
deleting module_cache
Pass 2: analyzed script: 1 probe, 1 function, 0 embeds, 0 globals using 2634060virt/1861208res/81504shr/2479040data kb, in 1924630usr/4980sys/1472297real ms.
/root/.systemtap/cache/6c/stap_6c2ecbbca07f472cb787c2b35c9ee51a_1139.ko
Pass 3: using cached /root/.systemtap/cache/6c/stap_6c2ecbbca07f472cb787c2b35c9ee51a_1139.c
Pass 4: using cached /root/.systemtap/cache/6c/stap_6c2ecbbca07f472cb787c2b35c9ee51a_1139.ko
Running rm -rf /tmp/staphsC0mK
Spawn waitpid result (0x0): 0
Removed temporary directory "/tmp/staphsC0mK"

real    24m37.166s
user    32m6.321s
sys     0m7.637s
9 x86_64 #