From ec183d22cc284a7a1e17f0341219d8ec8ca070cc Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Tue, 26 Jan 2016 14:05:20 +0200 Subject: [PATCH 1/4] perf tools: tracepoint_error() can receive e=NULL, robustify it Fixes segmentation fault using, for instance: (gdb) run record -I -e intel_pt/tsc=1,noretcomp=1/u /bin/ls Starting program: /home/acme/bin/perf record -I -e intel_pt/tsc=1,noretcomp=1/u /bin/ls Missing separate debuginfos, use: dnf debuginfo-install glibc-2.22-7.fc23.x86_64 [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib64/libthread_db.so.1". Program received signal SIGSEGV, Segmentation fault. 0 x00000000004b9ea5 in tracepoint_error (e=0x0, err=13, sys=0x19b1370 "sched", name=0x19a5d00 "sched_switch") at util/parse-events.c:410 (gdb) bt #0 0x00000000004b9ea5 in tracepoint_error (e=0x0, err=13, sys=0x19b1370 "sched", name=0x19a5d00 "sched_switch") at util/parse-events.c:410 #1 0x00000000004b9fc5 in add_tracepoint (list=0x19a5d20, idx=0x7fffffffb8c0, sys_name=0x19b1370 "sched", evt_name=0x19a5d00 "sched_switch", err=0x0, head_config=0x0) at util/parse-events.c:433 #2 0x00000000004ba334 in add_tracepoint_event (list=0x19a5d20, idx=0x7fffffffb8c0, sys_name=0x19b1370 "sched", evt_name=0x19a5d00 "sched_switch", err=0x0, head_config=0x0) at util/parse-events.c:498 #3 0x00000000004bb699 in parse_events_add_tracepoint (list=0x19a5d20, idx=0x7fffffffb8c0, sys=0x19b1370 "sched", event=0x19a5d00 "sched_switch", err=0x0, head_config=0x0) at util/parse-events.c:936 #4 0x00000000004f6eda in parse_events_parse (_data=0x7fffffffb8b0, scanner=0x19a49d0) at util/parse-events.y:391 #5 0x00000000004bc8e5 in parse_events__scanner (str=0x663ff2 "sched:sched_switch", data=0x7fffffffb8b0, start_token=258) at util/parse-events.c:1361 #6 0x00000000004bca57 in parse_events (evlist=0x19a5220, str=0x663ff2 "sched:sched_switch", err=0x0) at util/parse-events.c:1401 #7 0x0000000000518d5f in perf_evlist__can_select_event (evlist=0x19a3b90, str=0x663ff2 "sched:sched_switch") at util/record.c:253 #8 0x0000000000553c42 in intel_pt_track_switches (evlist=0x19a3b90) at arch/x86/util/intel-pt.c:364 #9 0x00000000005549d1 in intel_pt_recording_options (itr=0x19a2c40, evlist=0x19a3b90, opts=0x8edf68 ) at arch/x86/util/intel-pt.c:664 #10 0x000000000051e076 in auxtrace_record__options (itr=0x19a2c40, evlist=0x19a3b90, opts=0x8edf68 ) at util/auxtrace.c:539 #11 0x0000000000433368 in cmd_record (argc=1, argv=0x7fffffffde60, prefix=0x0) at builtin-record.c:1264 #12 0x000000000049bec2 in run_builtin (p=0x8fa2a8 , argc=5, argv=0x7fffffffde60) at perf.c:390 #13 0x000000000049c12a in handle_internal_command (argc=5, argv=0x7fffffffde60) at perf.c:451 #14 0x000000000049c278 in run_argv (argcp=0x7fffffffdcbc, argv=0x7fffffffdcb0) at perf.c:495 #15 0x000000000049c60a in main (argc=5, argv=0x7fffffffde60) at perf.c:618 (gdb) Intel PT attempts to find the sched:sched_switch tracepoint but that seg faults if tracefs is not readable, because the error reporting structure is null, as errors are not reported when automatically adding tracepoints. Fix by checking before using. Committer note: This doesn't take place in a kernel that supports perf_event_attr.context_switch, that is the default way that will be used for tracking context switches, only in older kernels, like 4.2, in a machine with Intel PT (e.g. Broadwell) for non-priviledged users. Further info from a similar patch by Wang: The error is in tracepoint_error: it assumes the 'e' parameter is valid. However, there are many situation a parse_event() can be called without parse_events_error. See result of $ grep 'parse_events(.*NULL)' ./tools/perf/ -r' Signed-off-by: Adrian Hunter Tested-by: Arnaldo Carvalho de Melo Cc: Jiri Olsa Cc: Josh Poimboeuf Cc: Tong Zhang Cc: Wang Nan Cc: stable@vger.kernel.org # v4.4+ Fixes: 196581717d85 ("perf tools: Enhance parsing events tracepoint error output") Link: http://lkml.kernel.org/r/1453809921-24596-2-git-send-email-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/parse-events.c | 3 +++ 1 file changed, 3 insertions(+) diff --git a/tools/perf/util/parse-events.c b/tools/perf/util/parse-events.c index 4f7b0efdde2f..813d9b272c81 100644 --- a/tools/perf/util/parse-events.c +++ b/tools/perf/util/parse-events.c @@ -399,6 +399,9 @@ static void tracepoint_error(struct parse_events_error *e, int err, { char help[BUFSIZ]; + if (!e) + return; + /* * We get error directly from syscall errno ( > 0), * or from encoded pointer's error ( < 0). From 3a4acda1ecbd290973de08250d7dcdfaf5b2fe0f Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Mon, 1 Feb 2016 03:21:04 +0000 Subject: [PATCH 2/4] perf tools: Fix thread lifetime related segfaut in intel_pt intel_pt_process_auxtrace_info() creates a pt->unknown_thread thread that eventually needs to be freed by the last thread__put() on it, when its refcount hits zero, which may happen in intel_pt_process_auxtrace_info() error handling path and triggers the following segfault, which would happen as well at intel_pt_free, when tools using this intel_pt codebase frees up resources: # perf record -I -e intel_pt/tsc=1,noretcomp=1/u /bin/ls 0 a anaconda-ks.cfg bin perf.data perf.data.old perf-f23-bringup.todo [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.217 MB perf.data ] # # perf script -F event,comm,pid,tid,time,addr,ip,sym,dso,iregs Samples for 'instructions:u' event do not have IREGS attribute set. Cannot print 'iregs' field. intel_pt_synth_events: failed to synthesize 'instructions' event type Segmentation fault (core dumped) # The problem is: there's a union in 'struct thread' combines a list_head and a rb_node. The standard life cycle of a thread is: init rb_node in the constructor, insert it into machine->threads rbtree using rb_node, move it to machine->dead_threads using list_head, clean in the last thread__put: list_del_init(&thread->node). In the above command, it clean a thread before adding it into list, causes the above segfault. Since pt->unknown_thread will never live in an rbtree, initialize its list node so that when list_del_init() is done on it we don't segfault. After this patch: # perf script -F event,comm,pid,tid,time,addr,ip,sym,dso,iregs Samples for 'instructions:u' event do not have IREGS attribute set. Cannot print 'iregs' field. intel_pt_synth_events: failed to synthesize 'instructions' event type 0x248 [0x88]: failed to process type: 70 # Reported-by: Tong Zhang Reported-by: Wang Nan Signed-off-by: Adrian Hunter Tested-by: Arnaldo Carvalho de Melo Cc: Josh Poimboeuf Link: http://lkml.kernel.org/r/1454296865-19749-1-git-send-email-wangnan0@huawei.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/intel-pt.c | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/tools/perf/util/intel-pt.c b/tools/perf/util/intel-pt.c index 81a2eb77ba7f..05d815851be1 100644 --- a/tools/perf/util/intel-pt.c +++ b/tools/perf/util/intel-pt.c @@ -2068,6 +2068,15 @@ int intel_pt_process_auxtrace_info(union perf_event *event, err = -ENOMEM; goto err_free_queues; } + + /* + * Since this thread will not be kept in any rbtree not in a + * list, initialize its list node so that at thread__put() the + * current thread lifetime assuption is kept and we don't segfault + * at list_del_init(). + */ + INIT_LIST_HEAD(&pt->unknown_thread->node); + err = thread__set_comm(pt->unknown_thread, "unknown", 0); if (err) goto err_delete_thread; From 270bde1e76f400d81f8d0ab68905a18ee17fa2e8 Mon Sep 17 00:00:00 2001 From: Hemant Kumar Date: Tue, 2 Feb 2016 20:56:46 +0530 Subject: [PATCH 3/4] perf probe: Search both .eh_frame and .debug_frame sections for probe location 'perf probe' through debuginfo__find_probes() in util/probe-finder.c checks for the functions' frame descriptions in either .eh_frame section of an ELF or the .debug_frame. The check is based on whether either one of these sections is present. Depending on distro, toolchain defaults, architetcutre, build flags, etc., CFI might be found in either .eh_frame and/or .debug_frame. Sometimes, it may happen that, .eh_frame, even if present, may not be complete and may miss some descriptions. Therefore, to be sure, to find the CFI covering an address we will always have to investigate both if available. For e.g., in powerpc, this may happen: $ gcc -g bin.c -o bin $ objdump --dwarf ./bin <1><145>: Abbrev Number: 7 (DW_TAG_subprogram) <146> DW_AT_external : 1 <146> DW_AT_name : (indirect string, offset: 0x9e): main <14a> DW_AT_decl_file : 1 <14b> DW_AT_decl_line : 39 <14c> DW_AT_prototyped : 1 <14c> DW_AT_type : <0x57> <150> DW_AT_low_pc : 0x100007b8 If the .eh_frame and .debug_frame are checked for the same binary, we will find that, .eh_frame (although present) doesn't contain a description for "main" function. But, .debug_frame has a description: 000000d8 00000024 00000000 FDE cie=00000000 pc=100007b8..10000838 DW_CFA_advance_loc: 16 to 100007c8 DW_CFA_def_cfa_offset: 144 DW_CFA_offset_extended_sf: r65 at cfa+16 ... Due to this (since, perf checks whether .eh_frame is present and goes on searching for that address inside that frame), perf is unable to process the probes: # perf probe -x ./bin main Failed to get call frame on 0x100007b8 Error: Failed to add events. To avoid this issue, we need to check both the sections (.eh_frame and .debug_frame), which is done in this patch. Note that, we can always force everything into both .eh_frame and .debug_frame by: $ gcc bin.c -fasynchronous-unwind-tables -fno-dwarf2-cfi-asm -g -o bin Signed-off-by: Hemant Kumar Acked-by: Masami Hiramatsu Cc: linuxppc-dev@lists.ozlabs.org Cc: Mark Wielaard Cc: Naveen N. Rao Cc: Srikar Dronamraju Link: http://lkml.kernel.org/r/1454426806-13974-1-git-send-email-hemant@linux.vnet.ibm.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/probe-finder.c | 62 ++++++++++++++++++++-------------- tools/perf/util/probe-finder.h | 5 ++- 2 files changed, 41 insertions(+), 26 deletions(-) diff --git a/tools/perf/util/probe-finder.c b/tools/perf/util/probe-finder.c index 2be10fb27172..4ce5c5e18f48 100644 --- a/tools/perf/util/probe-finder.c +++ b/tools/perf/util/probe-finder.c @@ -686,8 +686,9 @@ static int call_probe_finder(Dwarf_Die *sc_die, struct probe_finder *pf) pf->fb_ops = NULL; #if _ELFUTILS_PREREQ(0, 142) } else if (nops == 1 && pf->fb_ops[0].atom == DW_OP_call_frame_cfa && - pf->cfi != NULL) { - if (dwarf_cfi_addrframe(pf->cfi, pf->addr, &frame) != 0 || + (pf->cfi_eh != NULL || pf->cfi_dbg != NULL)) { + if ((dwarf_cfi_addrframe(pf->cfi_eh, pf->addr, &frame) != 0 && + (dwarf_cfi_addrframe(pf->cfi_dbg, pf->addr, &frame) != 0)) || dwarf_frame_cfa(frame, &pf->fb_ops, &nops) != 0) { pr_warning("Failed to get call frame on 0x%jx\n", (uintmax_t)pf->addr); @@ -1015,8 +1016,7 @@ static int pubname_search_cb(Dwarf *dbg, Dwarf_Global *gl, void *data) return DWARF_CB_OK; } -/* Find probe points from debuginfo */ -static int debuginfo__find_probes(struct debuginfo *dbg, +static int debuginfo__find_probe_location(struct debuginfo *dbg, struct probe_finder *pf) { struct perf_probe_point *pp = &pf->pev->point; @@ -1025,27 +1025,6 @@ static int debuginfo__find_probes(struct debuginfo *dbg, Dwarf_Die *diep; int ret = 0; -#if _ELFUTILS_PREREQ(0, 142) - Elf *elf; - GElf_Ehdr ehdr; - GElf_Shdr shdr; - - /* Get the call frame information from this dwarf */ - elf = dwarf_getelf(dbg->dbg); - if (elf == NULL) - return -EINVAL; - - if (gelf_getehdr(elf, &ehdr) == NULL) - return -EINVAL; - - if (elf_section_by_name(elf, &ehdr, &shdr, ".eh_frame", NULL) && - shdr.sh_type == SHT_PROGBITS) { - pf->cfi = dwarf_getcfi_elf(elf); - } else { - pf->cfi = dwarf_getcfi(dbg->dbg); - } -#endif - off = 0; pf->lcache = intlist__new(NULL); if (!pf->lcache) @@ -1108,6 +1087,39 @@ found: return ret; } +/* Find probe points from debuginfo */ +static int debuginfo__find_probes(struct debuginfo *dbg, + struct probe_finder *pf) +{ + int ret = 0; + +#if _ELFUTILS_PREREQ(0, 142) + Elf *elf; + GElf_Ehdr ehdr; + GElf_Shdr shdr; + + if (pf->cfi_eh || pf->cfi_dbg) + return debuginfo__find_probe_location(dbg, pf); + + /* Get the call frame information from this dwarf */ + elf = dwarf_getelf(dbg->dbg); + if (elf == NULL) + return -EINVAL; + + if (gelf_getehdr(elf, &ehdr) == NULL) + return -EINVAL; + + if (elf_section_by_name(elf, &ehdr, &shdr, ".eh_frame", NULL) && + shdr.sh_type == SHT_PROGBITS) + pf->cfi_eh = dwarf_getcfi_elf(elf); + + pf->cfi_dbg = dwarf_getcfi(dbg->dbg); +#endif + + ret = debuginfo__find_probe_location(dbg, pf); + return ret; +} + struct local_vars_finder { struct probe_finder *pf; struct perf_probe_arg *args; diff --git a/tools/perf/util/probe-finder.h b/tools/perf/util/probe-finder.h index bed82716e1b4..0aec7704e395 100644 --- a/tools/perf/util/probe-finder.h +++ b/tools/perf/util/probe-finder.h @@ -76,7 +76,10 @@ struct probe_finder { /* For variable searching */ #if _ELFUTILS_PREREQ(0, 142) - Dwarf_CFI *cfi; /* Call Frame Information */ + /* Call Frame Information from .eh_frame */ + Dwarf_CFI *cfi_eh; + /* Call Frame Information from .debug_frame */ + Dwarf_CFI *cfi_dbg; #endif Dwarf_Op *fb_ops; /* Frame base attribute */ struct perf_probe_arg *pvar; /* Current target variable */ From 51fd2df1e882a3c2a3f4b6c9ff243a93c9046dba Mon Sep 17 00:00:00 2001 From: Jiri Olsa Date: Wed, 3 Feb 2016 08:43:56 +0100 Subject: [PATCH 4/4] perf stat: Fix interval output values We broke interval data displays with commit: 3f416f22d1e2 ("perf stat: Do not clean event's private stats") This commit removed stats cleaning, which is important for '-r' option to carry counters data over the whole run. But it's necessary to clean it for interval mode, otherwise the displayed value is avg of all previous values. Before: $ perf stat -e cycles -a -I 1000 record # time counts unit events 1.000240796 75,216,287 cycles 2.000512791 107,823,524 cycles $ perf stat report # time counts unit events 1.000240796 75,216,287 cycles 2.000512791 91,519,906 cycles Now: $ perf stat report # time counts unit events 1.000240796 75,216,287 cycles 2.000512791 107,823,524 cycles Notice the second value being bigger (91,.. < 107,..). This could be easily verified by using perf script which displays raw stat data: $ perf script CPU THREAD VAL ENA RUN TIME EVENT 0 -1 23855779 1000209530 1000209530 1000240796 cycles 1 -1 33340397 1000224964 1000224964 1000240796 cycles 2 -1 15835415 1000226695 1000226695 1000240796 cycles 3 -1 2184696 1000228245 1000228245 1000240796 cycles 0 -1 97014312 2000514533 2000514533 2000512791 cycles 1 -1 46121497 2000543795 2000543795 2000512791 cycles 2 -1 32269530 2000543566 2000543566 2000512791 cycles 3 -1 7634472 2000544108 2000544108 2000512791 cycles The sum of the first 4 values is the first interval aggregated value: 23855779 + 33340397 + 15835415 + 2184696 = 75,216,287 The sum of the second 4 values minus first value is the second interval aggregated value: 97014312 + 46121497 + 32269530 + 7634472 - 75216287 = 107,823,524 Signed-off-by: Jiri Olsa Cc: Andi Kleen Cc: David Ahern Cc: Namhyung Kim Cc: Peter Zijlstra Cc: Stephane Eranian Link: http://lkml.kernel.org/r/1454485436-20639-1-git-send-email-jolsa@kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/stat.c | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/tools/perf/util/stat.c b/tools/perf/util/stat.c index 2b58edccd56f..afb0c45eba34 100644 --- a/tools/perf/util/stat.c +++ b/tools/perf/util/stat.c @@ -311,6 +311,16 @@ int perf_stat_process_counter(struct perf_stat_config *config, aggr->val = aggr->ena = aggr->run = 0; + /* + * We calculate counter's data every interval, + * and the display code shows ps->res_stats + * avg value. We need to zero the stats for + * interval mode, otherwise overall avg running + * averages will be shown for each interval. + */ + if (config->interval) + init_stats(ps->res_stats); + if (counter->per_pkg) zero_per_pkg(counter);