Re: [PATCH v4 2/2] perf: report/annotate: fix segfault problem.

[Wang Nan <wangnan0@huawei.com>]

On 2015/4/8 21:59, Jiri Olsa wrote:
> On Wed, Apr 08, 2015 at 03:52:18AM +0000, Wang Nan wrote:
>> perf report and perf annotate are easy to trigger segfault if trace data
>> contain kernel module information like this:
>>
>>  # perf report -D -i ./perf.data
>>  ...
>>  0 0 0x188 [0x50]: PERF_RECORD_MMAP -1/0: [0xffffffbff1018000(0xf068000) @ 0]: x [test_module]
>>  ...
>>
>>  # perf report -i ./perf.data --objdump=/path/to/objdump --kallsyms=/path/to/kallsyms
>>
>>  perf: Segmentation fault
>>  -------- backtrace --------
>>  /path/to/perf[0x503478]
>>  /lib64/libc.so.6(+0x3545f)[0x7fb201f3745f]
>>  /path/to/perf[0x499b56]
>>  /path/to/perf(dso__load_kallsyms+0x13c)[0x49b56c]
>>  /path/to/perf(dso__load+0x72e)[0x49c21e]
>>  /path/to/perf(map__load+0x6e)[0x4ae9ee]
>>  /path/to/perf(thread__find_addr_map+0x24c)[0x47deec]
>>  /path/to/perf(perf_event__preprocess_sample+0x88)[0x47e238]
>>  /path/to/perf[0x43ad02]
>>  /path/to/perf[0x4b55bc]
>>  /path/to/perf(ordered_events__flush+0xca)[0x4b57ea]
>>  /path/to/perf[0x4b1a01]
>>  /path/to/perf(perf_session__process_events+0x3be)[0x4b428e]
>>  /path/to/perf(cmd_report+0xf11)[0x43bfc1]
>>  /path/to/perf[0x474702]
>>  /path/to/perf(main+0x5f5)[0x42de95]
>>  /lib64/libc.so.6(__libc_start_main+0xf4)[0x7fb201f23bd4]
>>  /path/to/perf[0x42dfc4]
> 
> hum, I'm strugling to reproduce this, but I guess it's
> because the other patch is already in:
> 
>   37e9744467d7 perf kmaps: Check kmaps to make code more robust
> 
>>
>> This is because __kmod_path__parse regard '[' leading name as kernel
>> instead of kernel module. The DSO will then be passed to
>> dso__load_kernel_sym() then dso__load_kcore() because of --kallsyms
>> argument. The segfault is triggered because the kmap structure is not
>> initialized.
> 
> could you please be more detailed on describing the segfault code path?
> 
> I can see that we should parse [xxx] as a module, however I fail to see
> how it could cause the scenario you described above.
> 
> If it's no longer the case, because of the above patch is in, please
> describe current issue..
> 
> thanks,
> jirka
>

Sorry, I think some infors are missed in the description above:
to reproduce such segfault, perf.data you use should have buildid
infos for [test_module].

* Reproducing the segfault *

I think you have already have a perf.data which contains sth like:

 ...
 0 0 0x188 [0x50]: PERF_RECORD_MMAP -1/0: [0xffffffbff1018000(0xf068000) @ 0]: x [test_module]
 ...

In my case, perf.data also contains a HEADER_BUILD_ID feature in its header. Which contains
build_ids of vmlinux and all modules retrived by perf_session__create_kernel_maps() during
recording, and written into perf.data. Therefore, during reporting, __event_process_build_id()
will be called for [test_module]:

 $ perf report -i ./test-annotation/perf.data -v  --stdio --header-only
  build id event received for [kernel.kallsyms]: xxxxxxxxxxxxxxxxxxxxxxxx
  build id event received for [test_module]: xxxxxxxxxxxxxxxxxxxxxxxx
  ...
  # ========
  # captured on: Fri Apr  3 02:59:11 2015
  # hostname : ...
  # os release : ...
  # perf version : 4.0.rc5.g9f66
  # ...


If we don't have such buildid in our buildid-cache, perf is unable to find symbols from [test_module]
but the bug won't be trigger. However, if that module can be found in our buildid-cache, something bad
will happen.

To help you reproduce this problem, I suggest you to remove your buildid cache using

 # rm -rf ~/.debug

then add test_module.ko into it:

 # perf buildid-cache -a ./path-to-module/test_module.ko

During report, use --kallsyms explicitly:

 # ~/perf report -i ./path-to-data/perf.data --kallsyms=./path-to-kallsyms/kallsyms

Then you will see the segfault:

perf: Segmentation fault
-------- backtrace --------
/path/to/perf[0x502958]
/lib64/libc.so.6(+0x3545f)[0x7f820bdab45f]
/path/to/perf[0x499ab6]
/path/to/perf(dso__load_kallsyms+0x13c)[0x49b4cc]
/path/to/perf(dso__load+0x72e)[0x49c17e]
/path/to/perf(map__load+0x6e)[0x4adf5e]
/path/to/perf(thread__find_addr_map+0x24c)[0x47de4c]
/path/to/perf(perf_event__preprocess_sample+0x88)[0x47e198]
/path/to/perf[0x43ac92]
/path/to/perf[0x4b4b2c]
/path/to/perf(ordered_events__flush+0xca)[0x4b4d5a]
/path/to/perf[0x4b0f71]
/path/to/perf(perf_session__process_events+0x3be)[0x4b37fe]
/path/to/perf(cmd_report+0xed9)[0x43bf19]
/path/to/perf[0x474662]
/path/to/perf(main+0x5f5)[0x42de25]
/lib64/libc.so.6(__libc_start_main+0xf4)[0x7f820bd97bd4]
/path/to/perf[0x42df54]

Using gdb I can get following call stack:

Program received signal SIGSEGV, Segmentation fault.
dso__load_kcore (dso=dso@entry=0x959710, map=map@entry=0x9a4410,
    kallsyms_filename=kallsyms_filename@entry=0x7fffffffe2ed "./test-annotation/kallsyms") at util/symbol.c:1094
1094		if (map != machine->vmlinux_maps[map->type])
(gdb) bt
#0  dso__load_kcore (dso=dso@entry=0x959710, map=map@entry=0x9a4410,
    kallsyms_filename=kallsyms_filename@entry=0x7fffffffe2ed "./test-annotation/kallsyms") at util/symbol.c:1094
#1  0x000000000049b4cd in dso__load_kallsyms (dso=dso@entry=0x959710,
    filename=filename@entry=0x7fffffffe2ed "./test-annotation/kallsyms", map=map@entry=0x9a4410,
    filter=filter@entry=0x476070 <symbol__annotate_init>) at util/symbol.c:1239
#2  0x000000000049c17f in dso__load_kernel_sym (filter=0x476070 <symbol__annotate_init>, map=0x9a4410, dso=0x959710)
    at util/symbol.c:1715
#3  dso__load (dso=0x959710, map=map@entry=0x9a4410, filter=filter@entry=0x476070 <symbol__annotate_init>) at util/symbol.c:1364
#4  0x00000000004adf5f in map__load (map=0x9a4410, filter=0x476070 <symbol__annotate_init>) at util/map.c:259
#5  0x000000000047de4d in thread__find_addr_map (thread=<optimized out>, cpumode=<optimized out>, type=<optimized out>,
    addr=<optimized out>, al=0x7fffffffbdf0) at util/event.c:819
#6  0x000000000047e199 in perf_event__preprocess_sample (event=event@entry=0x7ffff3fe51e0, machine=0x9587f0,
    al=al@entry=0x7fffffffbdf0, sample=sample@entry=0x7fffffffbf00) at util/event.c:860
#7  0x000000000043ac93 in process_sample_event (tool=0x7fffffffc730, event=0x7ffff3fe51e0, sample=0x7fffffffbf00, evsel=0x9593c0,
    machine=<optimized out>) at builtin-report.c:145
#8  0x00000000004b4b2d in __ordered_events__flush (oe=oe@entry=0x958920) at util/ordered-events.c:214
#9  0x00000000004b4d5b in ordered_events__flush (oe=0x958920, how=OE_FLUSH__ROUND) at util/ordered-events.c:279
#10 0x00000000004b0f72 in perf_session__process_user_event (file_offset=2539904, event=0x7ffff4242180, session=0x958730)
    at util/session.c:972
#11 perf_session__process_event (session=session@entry=0x958730, event=event@entry=0x7ffff4242180,
    file_offset=file_offset@entry=2539904) at util/session.c:1076
#12 0x00000000004b37ff in __perf_session__process_events (file_size=2539912, data_size=<optimized out>, data_offset=<optimized out>,
    session=0x958730) at util/session.c:1369
#13 perf_session__process_events (session=session@entry=0x958730) at util/session.c:1412
#14 0x000000000043bf1a in __cmd_report (rep=0x7fffffffc730) at builtin-report.c:485
#15 cmd_report (argc=0, argv=0x7fffffffdea0, prefix=<optimized out>) at builtin-report.c:867
#16 0x0000000000474663 in run_builtin (p=p@entry=0x89cae8 <commands+168>, argc=argc@entry=4, argv=argv@entry=0x7fffffffdea0)
    at perf.c:370
#17 0x000000000042de26 in handle_internal_command (argv=0x7fffffffdea0, argc=4) at perf.c:429
#18 run_argv (argv=0x7fffffffdc20, argcp=0x7fffffffdc2c) at perf.c:473
#19 main (argc=4, argv=0x7fffffffdea0) at perf.c:588
(gdb)

* Path to the failure *

I'll explain what lead to the segfault.

Step 1: during __event_process_build_id():
        ....
        misc = bev->header.misc & PERF_RECORD_MISC_CPUMODE_MASK;

        switch (misc) {
        case PERF_RECORD_MISC_KERNEL:
                dso_type = DSO_TYPE_KERNEL;
                dsos = &machine->kernel_dsos;
                break;
        ....
                if (!is_kernel_module(filename))
                        dso->kernel = dso_type;
        ....

Here, is_kernel_module("[test_module]") is false, and cpumode here is PERF_RECORD_MISC_KERNEL,
so dso->kernel will become DSO_TYPE_KERNEL, which means the kernel itself. This is the root cause
of everything.

Step 2: machine__process_mmap_event(), which creates map structure for both kernel and modules.
        struct map is allocated using map__new2(). Since according dso ->type is kernel,
        the extra kmap structure is allocated. However, the only place initializes
        map__kmap(map)->kmaps is __machine__create_kernel_maps(), which is called by
        machine__process_kernel_mmap_event():


static int machine__process_kernel_mmap_event(struct machine *machine,
                                              union perf_event *event)
{
        ...
        is_kernel_mmap = memcmp(event->mmap.filename,
                                kmmap_prefix,
                                strlen(kmmap_prefix) - 1) == 0;
        if (event->mmap.filename[0] == '/' ||
            (!is_kernel_mmap && event->mmap.filename[0] == '[')) {
                map = machine__new_module(machine, event->mmap.start,
                                          event->mmap.filename);
                if (map == NULL)
                        goto out_problem;

                map->end = map->start + event->mmap.len;
        } else if (is_kernel_mmap) {
                ...
                if (__machine__create_kernel_maps(machine, kernel) < 0)
                        goto out_problem;
                ...
        }
        ...
}

When mmap event at kernel address space occures, it distinguishes kernel and kernel module
according to the name in mmap event. Unfortunately, '[test_module]' won't be regarded as kernel
at this time, so according map__kmap(map)->kmaps won't get initialized.

If we don't have buildid-cache for [test_module], machine__process_kernel_mmap_event -->
machine__new_module --> machine__module_dso --> dsos__find will return failuer, and a new
struct dso is created using dsos__addnew, its default dso->kernel is DSO_TYPE_USER.

Step 3: process_sample_event -> map__load: a sample with kernel IP is arise, perf
        tries to load DSO of such address.

Step 4: map__load -> dso__load: in dso__load():

int dso__load(struct dso *dso, struct map *map, symbol_filter_t filter)
{
	...
	if (dso->kernel == DSO_TYPE_KERNEL)
                return dso__load_kernel_sym(dso, map, filter);
	...
}

Because dso->kernel of "[test_module]" is incorrectly set to DSO_TYPE_KERNEL, it goes to
dso__load_kernel_sym. Where, since we use --kallsyms explicitly, dso__load_kallsyms() will
be called.

Step 5: dso__load_kallsyms -> dso__load_kcore:

dso__load_kallsyms tries to call dso__load_kcore. In my case it should fail because I don't have
/proc/kcore at all. However,

static int dso__load_kcore(struct dso *dso, struct map *map,
                           const char *kallsyms_filename)
{
        struct map_groups *kmaps = map__kmap(map)->kmaps;
        struct machine *machine = kmaps->machine;
        ...
}

dso__load_kcore requires both map__kmap(map) and map__kmap(map)->kmaps to be valid.

However, although '[test_module]' is regarded to kernel itself, its map__kmap(map)->kmaps is invalid.
See step 2.

* Conclusion *

According to the above discussion, we can conclude that, the segfault is caused by mismatching
of dso and map for [test_module]. In most cases, map and dso of [test_module] is incorrectly be
treated as kernel itself. However, in machine__process_kernel_mmap_event(), it is treated like
a kernel module.

We can also see that the code in dso__load_kcore() is also dangerous. If there is no such mmap
in perf.data, "machine = kmaps->machine" will also causes segfault.