Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753258AbbDIHGJ (ORCPT ); Thu, 9 Apr 2015 03:06:09 -0400 Received: from szxga02-in.huawei.com ([119.145.14.65]:49594 "EHLO szxga02-in.huawei.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751493AbbDIHGF (ORCPT ); Thu, 9 Apr 2015 03:06:05 -0400 Message-ID: <552624B7.30903@huawei.com> Date: Thu, 9 Apr 2015 15:05:27 +0800 From: Wang Nan User-Agent: Mozilla/5.0 (Windows NT 6.1; rv:24.0) Gecko/20100101 Thunderbird/24.0.1 MIME-Version: 1.0 To: Jiri Olsa CC: , , , , , , Subject: Re: [PATCH v4 2/2] perf: report/annotate: fix segfault problem. References: <20150407151322.GK11983@kernel.org> <1428465138-124112-1-git-send-email-wangnan0@huawei.com> <20150408135954.GA1339@krava.redhat.com> In-Reply-To: <20150408135954.GA1339@krava.redhat.com> Content-Type: text/plain; charset="ISO-8859-1" Content-Transfer-Encoding: 7bit X-Originating-IP: [10.111.69.129] X-CFilter-Loop: Reflected Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 11961 Lines: 277 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 ) at util/symbol.c:1239 #2 0x000000000049c17f in dso__load_kernel_sym (filter=0x476070 , map=0x9a4410, dso=0x959710) at util/symbol.c:1715 #3 dso__load (dso=0x959710, map=map@entry=0x9a4410, filter=filter@entry=0x476070 ) at util/symbol.c:1364 #4 0x00000000004adf5f in map__load (map=0x9a4410, filter=0x476070 ) at util/map.c:259 #5 0x000000000047de4d in thread__find_addr_map (thread=, cpumode=, type=, addr=, 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=) 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=, data_offset=, 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=) at builtin-report.c:867 #16 0x0000000000474663 in run_builtin (p=p@entry=0x89cae8 , 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. -- 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/