lkml.org 
[lkml]   [2015]   [Apr]   [9]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [PATCH v4 2/2] perf: report/annotate: fix segfault problem.
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.




\
 
 \ /
  Last update: 2015-04-09 09:41    [W:0.328 / U:0.784 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site