Re: [GIT PULL 00/30] perf/core improvements and fixes

[Namhyung Kim <namhyung@kernel.org>]

Hi Arnaldo,

On Thu, May 14, 2015 at 10:18:27AM -0300, Arnaldo Carvalho de Melo wrote:
> Em Thu, May 14, 2015 at 05:23:30PM +0900, Namhyung Kim escreveu:
> > On Mon, May 11, 2015 at 11:06:26AM -0300, Arnaldo Carvalho de Melo wrote:
> > > Em Mon, May 11, 2015 at 02:09:39PM +0900, Namhyung Kim escreveu:
> > > > I'm seeing a segfault on 'perf report' with a large data file after
> > > > applying thread refcount change - it happens regardless of the atomic
> > > > operation.
> 
> > > Any specific 'perf record' command line? Does it take a long time to
> > > reproduce? Any backtraces? I'll try to repro, its possible that we're
> > > doing one too many thread__put()...
>  
> > It's a kernel build with '-j 20' and recorded data size is ~2.1GB.
> > It takes ~30 sec to reproduce.
> > 
> >   $ perf report -i threaded/kbuild7.data --header-only
> >   # ========
> >   # captured on: Thu Dec 18 12:06:35 2014
> >   # hostname : sejong
> >   # os release : 3.17.4-1-ARCH
> >   # perf version : 3.18.rc3.gcb4774b
> >   # arch : x86_64
> >   # nrcpus online : 12
> >   # nrcpus avail : 12
> >   # cpudesc : Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
> >   # cpuid : GenuineIntel,6,45,7
> >   # total memory : 24646828 kB
> >   # cmdline : /home/namhyung/project/linux/tools/perf/perf record -ag -o /home/namhyung/tmp/perf/threaded/kbuild7.data -- make -j20
> >   # event : name = cycles, , size = 104, { sample_period, sample_freq } = 4000, sample_type = IP|TID|TIME|CALLCHAIN|CPU|PERIOD, disabled = 1, inherit
> >   # HEADER_CPU_TOPOLOGY info available, use -I to display
> >   # HEADER_NUMA_TOPOLOGY info available, use -I to display
> >   # pmu mappings: cpu = 4, software = 1, power = 24, uncore_pcu = 13, tracepoint = 2, uncore_imc_0 = 15, uncore_imc_1 = 16, uncore_imc_2 = 17, uncore_
> >   # ========
> >   #
> > 
> > 
> >   $ perf data stat -i threaded/kbuild7.data
> > 
> >    Total event stats for 'threaded/kbuild7.data' file:
> >   
> >              TOTAL events:   25126492
> >               MMAP events:        114
> >               COMM events:     117957
> >               EXIT events:     240544
> >           THROTTLE events:         16
> >         UNTHROTTLE events:         16
> >               FORK events:     120488
> >             SAMPLE events:   23878219
> >              MMAP2 events:     745325
> >     FINISHED_ROUND events:      23813
> >   
> >    Sample event stats:
> >   
> >   20,579,564,471,104      cycles
> >           23,878,219      samples                   #   sampling ratio  99.745% (3989/4000)
> > 
> >        498.736917889 second time sampled
> > 
> > 
> >   $ perf report -i threaded/kbuild7.data
> 
> We need to improve this segfault backtrace, I have to always use
> addr2line to resolve those missing entries, i.e. if you try:
> 
> addr2line -fe /path/to/your/perf 0x4dd9c8
> addr2line -fe /path/to/your/perf 0x4e2580
> 
> We would have resolved those lines :-/

Right, I'll add it to my TODO list.

Anyway, this is a backtrace using gdb..

Thanks,
Namhyung


Program received signal SIGSEGV, Segmentation fault.
0x00007ffff5fb229e in __strcmp_sse2_unaligned () from /usr/lib/libc.so.6
(gdb) bt
#0  0x00007ffff5fb229e in __strcmp_sse2_unaligned () from /usr/lib/libc.so.6
#1  0x00000000004d3948 in _sort__dso_cmp (map_r=<optimized out>, map_l=<optimized out>) at util/sort.c:142
#2  sort__dso_cmp (left=<optimized out>, right=<optimized out>) at util/sort.c:148
#3  0x00000000004d7f08 in hist_entry__cmp (right=0x7fffffffc530, left=0x323a27f0) at util/hist.c:911
#4  add_hist_entry (sample_self=true, al=0x7fffffffc710, entry=0x7fffffffc530, hists=0x18f6690) at util/hist.c:389
#5  __hists__add_entry (hists=0x18f6690, al=0x7fffffffc710, sym_parent=<optimized out>, bi=bi@entry=0x0, mi=mi@entry=0x0, period=<optimized out>,
    weight=0, transaction=0, sample_self=true) at util/hist.c:471
#6  0x00000000004d8234 in iter_add_single_normal_entry (iter=0x7fffffffc740, al=<optimized out>) at util/hist.c:662
#7  0x00000000004d8765 in hist_entry_iter__add (iter=0x7fffffffc740, al=0x7fffffffc710, evsel=0x18f6550, sample=<optimized out>,
    max_stack_depth=<optimized out>, arg=0x7fffffffd0a0) at util/hist.c:871
#8  0x0000000000436353 in process_sample_event (tool=0x7fffffffd0a0, event=<optimized out>, sample=0x7fffffffc870, evsel=0x18f6550,
    machine=<optimized out>) at builtin-report.c:171
#9  0x00000000004bbe23 in perf_evlist__deliver_sample (machine=0x18f4cc0, evsel=0x18f6550, sample=0x7fffffffc870, event=0x7fffe0bd3220,
    tool=0x7fffffffd0a0, evlist=0x18f5b50) at util/session.c:972
#10 machines__deliver_event (machines=machines@entry=0x18f4cc0, evlist=<optimized out>, event=event@entry=0x7fffe0bd3220,
    sample=sample@entry=0x7fffffffc870, tool=tool@entry=0x7fffffffd0a0, file_offset=file_offset@entry=1821434400) at util/session.c:1009
#11 0x00000000004bc681 in perf_session__deliver_event (file_offset=1821434400, tool=0x7fffffffd0a0, sample=0x7fffffffc870, event=0x7fffe0bd3220,
    session=<optimized out>) at util/session.c:1050
#12 ordered_events__deliver_event (oe=0x18f4e00, event=<optimized out>) at util/session.c:109
#13 0x00000000004bf12b in __ordered_events__flush (oe=0x18f4e00) at util/ordered-events.c:207
#14 ordered_events__flush (oe=0x18f4e00, how=OE_FLUSH__ROUND) at util/ordered-events.c:271
#15 0x00000000004bc8aa in perf_session__process_user_event (file_offset=1821919744, event=0x7fffe0c49a00, session=0x18f4c00) at util/session.c:1087
#16 perf_session__process_event (session=session@entry=0x18f4c00, event=event@entry=0x7fffe0c49a00, file_offset=file_offset@entry=1821919744)
    at util/session.c:1200
#17 0x00000000004bdcd0 in __perf_session__process_events (file_size=2160054608, data_size=<optimized out>, data_offset=<optimized out>,
    session=0x18f4c00) at util/session.c:1501
#18 perf_session__process_events (session=session@entry=0x18f4c00) at util/session.c:1548
#19 0x0000000000437609 in __cmd_report (rep=0x7fffffffd0a0) at builtin-report.c:487
#20 cmd_report (argc=0, argv=0x7fffffffe8d0, prefix=<optimized out>) at builtin-report.c:878
#21 0x000000000047de33 in run_builtin (p=p@entry=0x85a6e8 <commands+168>, argc=argc@entry=6, argv=argv@entry=0x7fffffffe8d0) at perf.c:370
#22 0x000000000042893a in handle_internal_command (argv=0x7fffffffe8d0, argc=6) at perf.c:429
#23 run_argv (argv=0x7fffffffe660, argcp=0x7fffffffe66c) at perf.c:473
#24 main (argc=6, argv=0x7fffffffe8d0) at perf.c:588
				

> 
> But I think this is a longstanding bug in handling hist_entries, i.e.
> probably we have more than one pointer to a hist_entry and are accessing
> it in two places at the same time, with one of them deleting it and
> possibly reusing the data.
> 
> >   perf: Segmentation fault
> >   -------- backtrace --------
> >   perf[0x51c7cb]
> >   /usr/lib/libc.so.6(+0x33540)[0x7f37eb37e540]
> >   /usr/lib/libc.so.6(+0x9029e)[0x7f37eb3db29e]
> >   perf[0x4dd9c8]
> >   perf(__hists__add_entry+0x188)[0x4e2258]
> >   perf[0x4e2580]
> >   perf(hist_entry_iter__add+0x9d)[0x4e2a7d]
> >   perf[0x437fda]
> >   perf[0x4c4c8e]
> >   perf[0x4c5176]
> >   perf[0x4c8bab]
> >   perf[0x4c53c2]
> >   perf[0x4c5f0c]
> >   perf(perf_session__process_events+0xb3)[0x4c6b23]
> >   perf(cmd_report+0x12a0)[0x439310]
> >   perf[0x483ec3]
> >   perf(main+0x60a)[0x42979a]
> >   /usr/lib/libc.so.6(__libc_start_main+0xf0)[0x7f37eb36b800]
> >   perf(_start+0x29)[0x4298b9]
> >   [0x0]
> > 
> > It seems like some memory area was corrupted..
> 
> Right, looks like use after free, for instance, freeing something still
> on a list or rbtree :-/
> 
> - Arnaldo
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/