Re: [BUGFIX PATCH 0/3] perf/probe: Fix available line bugs

[Arnaldo Carvalho de Melo]

Em Fri, Oct 25, 2019 at 12:36:48AM +0900, Masami Hiramatsu escreveu:
> On Thu, 24 Oct 2019 10:43:25 -0300 Arnaldo Carvalho de Melo <acme@xxxxxxxxxx> wrote:

> > Em Thu, Oct 24, 2019 at 06:12:27PM +0900, Masami Hiramatsu escreveu:
> > > Here are some bugfixes related to showing available line (--line/-L)
> > > option. I found that gcc generated some subprogram DIE with only
> > > range attribute but no entry_pc or low_pc attributes.
> > > In that case, perf probe failed to show the available lines in that
> > > subprogram (function). To fix that, I introduced some bugfixes to
> > > handle such cases correctly.

> > Thanks, applied, next time please provide concrete examples for things
> > that don't work before and gets fixed with your patches, this way we can
> > more easily reproduce your steps.
 
> OK, I'll try, but I found that this kind of examples depend on
> gcc optimization (like build option, gcc version etc.) So even if you
> can not reproduce, don't be disappointed ;)

Don't worry about that, even if I don't manage to reproduce I'm
convinced that having the set of steps to reproduce the problem, with
actual output from tools, and your step-by-step explanations helps
whoever feels like reviewing your patch, so thanks a lot for doing what
I suggested.
 
> Anyway, for this series, I found that clear_tasks_mm_cpumask() caused
> the (triple) issues.

So, lets try to repro...
 
> So, without any patch, I got below error.
 
> $ tools/perf/perf probe -k ../build-x86_64/vmlinux -L clear_tasks_mm_cpumask
> Specified source line is not found.
>   Error: Failed to show lines.

[root@quaco ~]# perf probe clear_tasks_mm_cpumask
Probe point 'clear_tasks_mm_cpumask' not found.
  Error: Failed to add events.
[root@quaco ~]# uname -r
5.2.18-200.fc30.x86_64
[root@quaco ~]# rpm -q kernel-debuginfo
kernel-debuginfo-5.2.15-200.fc30.x86_64
kernel-debuginfo-5.2.17-200.fc30.x86_64
kernel-debuginfo-5.2.18-200.fc30.x86_64
[root@quaco ~]# grep clear_tasks /proc/kallsyms
ffffffffaa0e09a0 T clear_tasks_mm_cpumask
ffffffffaa0e10d3 t clear_tasks_mm_cpumask.cold
[root@quaco ~]#

woah! Seems I'm on the right track :-)

> 
> Hmm, there should be something wrong... so I fixed it with [1/3].
> (to find appropriate target function, you can use "eu-readelf -w vmlinux"

So I don't know where is this vmlinux, lets try to find it:

[root@quaco ~]# perf probe -v clear_tasks_mm_cpumask
probe-definition(0): clear_tasks_mm_cpumask
symbol:clear_tasks_mm_cpumask file:(null) line:0 offset:0 return:0 lazy:(null)
0 arguments
Looking at the vmlinux_path (8 entries long)
Using /usr/lib/debug/lib/modules/5.2.18-200.fc30.x86_64/vmlinux for symbols
Open Debuginfo file: /usr/lib/debug/lib/modules/5.2.18-200.fc30.x86_64/vmlinux
Try to find probe point from debuginfo.
Matched function: clear_tasks_mm_cpumask [14d33f6]
clear_tasks_mm_cpumask has no entry PC. Skipped
Symbol clear_tasks_mm_cpumask address found : ffffffff810e09a0
Matched function: clear_tasks_mm_cpumask [14d33f6]
clear_tasks_mm_cpumask has no entry PC. Skipped
Probe point 'clear_tasks_mm_cpumask' not found.
  Error: Failed to add events. Reason: No such file or directory (Code: -2)
[root@quaco ~]#

Ok /usr/lib/debug/lib/modules/5.2.18-200.fc30.x86_64/vmlinux, then:

[root@quaco ~]# eu-readelf -w /usr/lib/debug/lib/modules/5.2.18-200.fc30.x86_64/vmlinux | grep clear_tasks_mm_cpumask -B5 -A30
<go grab some coffee>
 [14d3770]      inlined_subroutine   abbrev: 32
               abstract_origin      (ref4) [14d8d01]
               entry_pc             (addr) 0xffffffff810e09b7 <clear_tasks_mm_cpumask+0x17>
               GNU_entry_view       (data2) 7
               ranges               (sec_offset) range list [11e9d0]
               call_file            (data1) cpu.c (1)
               call_line            (data2) 817
               call_column          (data1) 2
               sibling              (ref4) [14d37b0]
 [14d378b]        inlined_subroutine   abbrev: 176
                 abstract_origin      (ref4) [14d8d16]
                 entry_pc             (addr) 0xffffffff810e09b7 <clear_tasks_mm_cpumask+0x17>
                 GNU_entry_view       (data2) 9
                 low_pc               (addr) 0xffffffff810e09b7 <clear_tasks_mm_cpumask+0x17>
                 high_pc              (data8) 0 (0xffffffff810e09b7 <clear_tasks_mm_cpumask+0x17>)
                 call_file            (data1) rcupdate.h (23)
                 call_line            (data2) 591
                 call_column          (data1) 2
 [14d37b0]      inlined_subroutine   abbrev: 53
               abstract_origin      (ref4) [14d8cf6]
               entry_pc             (addr) 0xffffffff810e0a07 <clear_tasks_mm_cpumask+0x67>
               GNU_entry_view       (data2) 2
               ranges               (sec_offset) range list [11ec40]
               call_file            (data1) cpu.c (1)
               call_line            (data2) 831
               call_column          (data1) 2
 [14d37c7]        inlined_subroutine   abbrev: 176
                 abstract_origin      (ref4) [14d8d0c]
                 entry_pc             (addr) 0xffffffff810e0a07 <clear_tasks_mm_cpumask+0x67>
                 GNU_entry_view       (data2) 8
                 low_pc               (addr) 0xffffffff810e0a07 <clear_tasks_mm_cpumask+0x67>
                 high_pc              (data8) 0 (0xffffffff810e0a07 <clear_tasks_mm_cpumask+0x67>)
                 call_file            (data1) rcupdate.h (23)
                 call_line            (data2) 646
                 call_column          (data1


>  and find the subprogram which has no entry_pc nor low_pc but has ranges)
> 
> $ tools/perf/perf probe -k ../build-x86_64/vmlinux -L clear_tasks_mm_cpumask
> <clear_tasks_mm_cpumask@/home/mhiramat/ksrc/mincs/work/linux/linux/kernel/cpu.c:
>          void clear_tasks_mm_cpumask(int cpu)
>       1  {
>       2         struct task_struct *p;
>          
>                 /*
>                  * This function is called after the cpu is taken down and marke
>                  * offline, so its not like new tasks will ever get this cpu set
>                  * their mm mask. -- Peter Zijlstra
>                  * Thus, we may use rcu_read_lock() here, instead of grabbing
>                  * full-fledged tasklist_lock.
>                  */
>      11         WARN_ON(cpu_online(cpu));
>      12         rcu_read_lock();
>      13         for_each_process(p) {
>      14                 struct task_struct *t;
>          
>                         /*
>                          * Main thread might exit, but other threads may still h
>                          * a valid mm. Find one.
>                          */
>      20                 t = find_lock_task_mm(p);
>      21                 if (!t)
>                                 continue;
>                         cpumask_clear_cpu(cpu, mm_cpumask(t->mm));
>                         task_unlock(t);
>                 }
>      26         rcu_read_unlock();
>      27  }
>          
> OK! it looks working... but a bit wired. why line #0, #23 and #24 are not
> available?
> I investigated it and found a wrong logic and fixed it with [2/3]
> 
> $ tools/perf/perf probe -k ../build-x86_64/vmlinux -L clear_tasks_mm_cpumask:20
> <clear_tasks_mm_cpumask@/home/mhiramat/ksrc/mincs/work/linux/linux/kernel/cpu.c:
>      20                 t = find_lock_task_mm(p);
>      21                 if (!t)
>                                 continue;
>      23                 cpumask_clear_cpu(cpu, mm_cpumask(t->mm));
>      24                 task_unlock(t);
>                 }
>      26         rcu_read_unlock();
>      27  }
> 
> OK, it found line #23 and #24. And add [3/3]
> 
> $ tools/perf/perf probe -k ../build-x86_64/vmlinux -L clear_tasks_mm_cpumask
> <clear_tasks_mm_cpumask@/home/mhiramat/ksrc/mincs/work/linux/linux/kernel/cpu.c:
>       0  void clear_tasks_mm_cpumask(int cpu)
>       1  {
>       2         struct task_struct *p;
> 
> OK, so now it works well :)

Ok, so, the above output is with your patches, as well as the following,
which, for -L, matches your results:

[root@quaco ~]# perf probe -L clear_tasks_mm_cpumask
<clear_tasks_mm_cpumask@/usr/src/debug/kernel-5.2.fc30/linux-5.2.18-200.fc30.x86_64/kernel/cpu.c:0>
      0  void clear_tasks_mm_cpumask(int cpu)
      1  {
      2         struct task_struct *p;

                /*
                 * This function is called after the cpu is taken down and marked
                 * offline, so its not like new tasks will ever get this cpu set in
                 * their mm mask. -- Peter Zijlstra
                 * Thus, we may use rcu_read_lock() here, instead of grabbing
                 * full-fledged tasklist_lock.
                 */
     11         WARN_ON(cpu_online(cpu));
     12         rcu_read_lock();
     13         for_each_process(p) {
     14                 struct task_struct *t;

                        /*
                         * Main thread might exit, but other threads may still have
                         * a valid mm. Find one.
                         */
     20                 t = find_lock_task_mm(p);
     21                 if (!t)
                                continue;
     23                 cpumask_clear_cpu(cpu, mm_cpumask(t->mm));
     24                 task_unlock(t);
                }
     26         rcu_read_unlock();
     27  }

         /* Take this CPU down. */
         static int take_cpu_down(void *_param)

[root@quaco ~]# perf probe clear_tasks_mm_cpumask
Probe point 'clear_tasks_mm_cpumask' not found.
  Error: Failed to add events.
[root@quaco ~]#

But why can't I probe this thing again?

[root@quaco ~]# perf probe clear_tasks_mm_cpumask:0
Probe point 'clear_tasks_mm_cpumask' not found.
  Error: Failed to add events.
[root@quaco ~]# perf probe clear_tasks_mm_cpumask:1
Failed to get entry address of clear_tasks_mm_cpumask
  Error: Failed to add events.
[root@quaco ~]# perf probe clear_tasks_mm_cpumask:2
Failed to get entry address of clear_tasks_mm_cpumask
  Error: Failed to add events.
[root@quaco ~]# perf probe clear_tasks_mm_cpumask:11
Failed to get entry address of clear_tasks_mm_cpumask
  Error: Failed to add events.
[root@quaco ~]# perf probe clear_tasks_mm_cpumask:12
Failed to get entry address of clear_tasks_mm_cpumask
  Error: Failed to add events.
[root@quaco ~]# perf probe clear_tasks_mm_cpumask:13
Failed to get entry address of clear_tasks_mm_cpumask
  Error: Failed to add events.
root@quaco ~]#

[root@quaco ~]# rpm -qf /usr/lib/debug/lib/modules/5.2.18-200.fc30.x86_64/vmlinux
kernel-debuginfo-5.2.18-200.fc30.x86_64
[root@quaco ~]#

[root@quaco ~]# readelf -wi /usr/lib/debug/lib/modules/5.2.18-200.fc30.x86_64/vmlinux | grep "DW_AT_producer.*GNU C" -m1 -A6
    <2e>   DW_AT_producer    : (indirect string, offset: 0xf1c6): GNU C89 9.2.1 20190827 (Red Hat 9.2.1-1) -mno-sse -mno-mmx -mno-sse2 -mno-3dnow -mno-avx -m64 -mno-80387 -mno-fp-ret-in-387 -mpreferred-stack-boundary=3 -mskip-rax-setup -mtune=generic -mno-red-zone -mcmodel=kernel -mindirect-branch=thunk-extern -mindirect-branch-register -mrecord-mcount -mfentry -march=x86-64 -g -O2 -std=gnu90 -fno-strict-aliasing -fno-common -fshort-wchar -fno-PIE -falign-jumps=1 -falign-loops=1 -fno-asynchronous-unwind-tables -fno-jump-tables -fno-delete-null-pointer-checks -fstack-protector-strong -fvar-tracking-assignments -fno-strict-overflow -fno-merge-all-constants -fmerge-constants -fstack-check=no -fconserve-stack --param allow-store-data-races=0
    <32>   DW_AT_language    : 1	(ANSI C)
    <33>   DW_AT_name        : (indirect string, offset: 0xdfe59): arch/x86/kernel/head64.c
    <37>   DW_AT_comp_dir    : (indirect string, offset: 0x4d33f): /usr/src/debug/kernel-5.2.fc30/linux-5.2.18-200.fc30.x86_64
    <3b>   DW_AT_ranges      : 0x5f0
    <3f>   DW_AT_low_pc      : 0x0
    <47>   DW_AT_stmt_list   : 0x165
[root@quaco ~]#

- Arnaldo