Re: [PATCH] perf top: fix crash on annotate request

[Brian Gitonga Marete]

On Thu, Dec 1, 2011 at 5:11 PM, Arnaldo Carvalho de Melo
<acme@xxxxxxxxxxxxx> wrote:
>
> Its just this one, can you try doing something like:
>
> perf top -vvv > /tmp/debug.top 2>&1
> bzip2 /tmp/debug.top
>
> That will print lots of information about symbols being loaded,
> overlapping maps, etc that can help me understand why that symbol name
> looks garbage.
>
> And send me in pvt the result together with a fresh backtrace with those
> symbols printed? Also which distro are you using?
>

Hello Arnaldo. Curiously, I am unable to reproduce the crash when
stdout is redirected to a file. I am able to capture lots of output if
I redirect stdout to a file in verbose mode, but it won't crash when I
do that. Just the same, I am still able to always reproduce (within a
few seconds) with your perf/core branch on the tree you pointed me to.
This time, I did a `thread apply all bt' in gdb to show the trace for
the UI thread since it now seems to me to probably have something with
the UI output (because I cannot reproduce if o/put is to a file). The
trace is attached in the file gdb.txt.

Is the `perf top -vvv > /tmp/debug.top 2>&1' output useful even if it
is captured in a session that does not crash? If so will send the
output privately to you.

I am using Ubuntu 10.10

Thanks!

-- 
Brian Gitonga Marete
Toshnix Systems
Tel: +254722151590
Reading symbols from /home/marebri/devel/perf-core.git/tools/perf/perf...done.
Starting program: /home/marebri/devel/perf-core.git/tools/perf/perf top
[Thread debugging using libthread_db enabled]
[New Thread 0x7ffff4959700 (LWP 7780)]

Program received signal SIGSEGV, Segmentation fault.
0x000000000042fda7 in symbol__inc_addr_samples (sym=0x17e6a60, map=0x8e8b60, 
    evidx=0, addr=93553) at util/annotate.c:73
73		h->addr[offset]++;

###### Output of bt follows

#0  0x000000000042fda7 in symbol__inc_addr_samples (sym=0x17e6a60, map=
    0x8e8b60, evidx=0, addr=93553) at util/annotate.c:73
#1  0x000000000042229d in perf_top__record_precise_ip (top=0x7fffffffd5a0, he=
    0x222e8c0, counter=0, ip=93553) at builtin-top.c:188
#2  0x0000000000423a8a in perf_event__process_sample (tool=0x7fffffffd5a0, 
    event=0x7ffff7f45710, evsel=0x832e90, sample=0x7fffffffcbe0, machine=
    0x833370) at builtin-top.c:743
#3  0x0000000000423ce5 in perf_top__mmap_read_idx (top=0x7fffffffd5a0, idx=0)
    at builtin-top.c:804
#4  0x0000000000423da7 in perf_top__mmap_read (top=0x7fffffffd5a0)
    at builtin-top.c:819
#5  0x0000000000424380 in __cmd_top (top=0x7fffffffd5a0) at builtin-top.c:985
#6  0x000000000042535e in cmd_top (argc=0, argv=0x7fffffffda30, prefix=0x0)
    at builtin-top.c:1272
#7  0x00000000004102d5 in run_builtin (p=0x6a6be8, argc=1, argv=0x7fffffffda30)
    at perf.c:273
#8  0x00000000004104a8 in handle_internal_command (argc=1, argv=0x7fffffffda30)
    at perf.c:345
#9  0x00000000004105ae in run_argv (argcp=0x7fffffffd91c, argv=0x7fffffffd910)
    at perf.c:389
#10 0x00000000004107b3 in main (argc=1, argv=0x7fffffffda30) at perf.c:487

####### Output of p *sym follows

$1 = {rb_node = {rb_parent_color = 18917441, rb_right = 0x1213130, rb_left = 
    0x179d920}, start = 228720, end = 228916, namelen = 14, 
  binding = 1 '\001', ignore = false, name = 0x17e6a60 "A\250 \001"}

###### Output of p *map follows

$2 = {{rb_node = {rb_parent_color = 9342289, rb_right = 0x8e8c50, rb_left = 
    0x8e8a70}, node = {next = 0x8e8d51, prev = 0x8e8c50}}, start = 4144279552, 
  end = 4145426432, type = 0 '\000', referenced = true, priv = 0, pgoff = 0, 
  map_ip = 0x4523cd <map__map_ip>, unmap_ip = 0x4523f6 <map__unmap_ip>, dso = 
    0x8e8bc0, groups = 0x8eaf68}

###### Output of info thread follows

  2 Thread 0x7ffff4959700 (LWP 7780)  0x00007ffff65602c3 in select ()
    at ../sysdeps/unix/syscall-template.S:82
* 1 Thread 0x7ffff7fc1700 (LWP 7777)  0x000000000042fda7 in symbol__inc_addr_samples (sym=0x17e6a60, map=0x8e8b60, evidx=0, addr=93553) at util/annotate.c:73

####### Output of thread apply all bt follows

Thread 2 (Thread 0x7ffff4959700 (LWP 7780)):
#0  0x00007ffff65602c3 in select () at ../sysdeps/unix/syscall-template.S:82
#1  0x0000000000471ad1 in ui__getch (delay_secs=2) at util/ui/setup.c:62
#2  0x00000000004729ee in ui_browser__run (self=0xca23b0, delay_secs=2)
    at util/ui/browser.c:364
#3  0x0000000000474e4e in hist_browser__run (self=0xca23b0, ev_name=
    0x833140 "cycles", timer=0x42335d <perf_top__sort_new_samples>, arg=
    0x7fffffffd5a0, delay_secs=2) at util/ui/browsers/hists.c:324
#4  0x0000000000476442 in perf_evsel__hists_browse (evsel=0x832e90, 
    nr_events=1, helpline=
    0x4847c8 "For a higher level overview, try: perf top --sort comm,dso", 
    ev_name=0x833140 "cycles", left_exits=false, timer=
    0x42335d <perf_top__sort_new_samples>, arg=0x7fffffffd5a0, delay_secs=2)
    at util/ui/browsers/hists.c:883
#5  0x0000000000477317 in perf_evlist__tui_browse_hists (evlist=0x8095c0, help=
    0x4847c8 "For a higher level overview, try: perf top --sort comm,dso", 
    timer=0x42335d <perf_top__sort_new_samples>, arg=0x7fffffffd5a0, 
    delay_secs=2) at util/ui/browsers/hists.c:1254
#6  0x0000000000423470 in display_thread_tui (arg=0x7fffffffd5a0)
    at builtin-top.c:546
#7  0x00007ffff7bc6971 in start_thread (arg=<value optimized out>)
    at pthread_create.c:304
#8  0x00007ffff656792d in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#9  0x0000000000000000 in ?? ()

Thread 1 (Thread 0x7ffff7fc1700 (LWP 7777)):
#0  0x000000000042fda7 in symbol__inc_addr_samples (sym=0x17e6a60, map=
    0x8e8b60, evidx=0, addr=93553) at util/annotate.c:73
#1  0x000000000042229d in perf_top__record_precise_ip (top=0x7fffffffd5a0, he=
    0x222e8c0, counter=0, ip=93553) at builtin-top.c:188
#2  0x0000000000423a8a in perf_event__process_sample (tool=0x7fffffffd5a0, 
    event=0x7ffff7f45710, evsel=0x832e90, sample=0x7fffffffcbe0, machine=
    0x833370) at builtin-top.c:743
#3  0x0000000000423ce5 in perf_top__mmap_read_idx (top=0x7fffffffd5a0, idx=0)
    at builtin-top.c:804
#4  0x0000000000423da7 in perf_top__mmap_read (top=0x7fffffffd5a0)
    at builtin-top.c:819
#5  0x0000000000424380 in __cmd_top (top=0x7fffffffd5a0) at builtin-top.c:985
#6  0x000000000042535e in cmd_top (argc=0, argv=0x7fffffffda30, prefix=0x0)
    at builtin-top.c:1272
#7  0x00000000004102d5 in run_builtin (p=0x6a6be8, argc=1, argv=0x7fffffffda30)
    at perf.c:273
#8  0x00000000004104a8 in handle_internal_command (argc=1, argv=0x7fffffffda30)
    at perf.c:345
#9  0x00000000004105ae in run_argv (argcp=0x7fffffffd91c, argv=0x7fffffffd910)
    at perf.c:389
#10 0x00000000004107b3 in main (argc=1, argv=0x7fffffffda30) at perf.c:487
Kill the program being debugged? (y or n)