From patchwork Wed Nov 25 05:29:36 2015 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: AKASHI Takahiro X-Patchwork-Id: 57287 Delivered-To: patch@linaro.org Received: by 10.112.155.196 with SMTP id vy4csp2527169lbb; Tue, 24 Nov 2015 21:31:50 -0800 (PST) X-Received: by 10.98.12.151 with SMTP id 23mr28888048pfm.60.1448429510121; Tue, 24 Nov 2015 21:31:50 -0800 (PST) Return-Path: Received: from bombadil.infradead.org (bombadil.infradead.org. [2001:1868:205::9]) by mx.google.com with ESMTPS id p86si31799745pfi.138.2015.11.24.21.31.49 for (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Tue, 24 Nov 2015 21:31:50 -0800 (PST) Received-SPF: pass (google.com: domain of linux-arm-kernel-bounces+patch=linaro.org@lists.infradead.org designates 2001:1868:205::9 as permitted sender) client-ip=2001:1868:205::9; Authentication-Results: mx.google.com; spf=pass (google.com: domain of linux-arm-kernel-bounces+patch=linaro.org@lists.infradead.org designates 2001:1868:205::9 as permitted sender) smtp.mailfrom=linux-arm-kernel-bounces+patch=linaro.org@lists.infradead.org; dkim=neutral (body hash did not verify) header.i=@linaro-org.20150623.gappssmtp.com Received: from localhost ([127.0.0.1] helo=bombadil.infradead.org) by bombadil.infradead.org with esmtp (Exim 4.80.1 #2 (Red Hat Linux)) id 1a1Seg-0007rP-4L; Wed, 25 Nov 2015 05:30:10 +0000 Received: from mail-pa0-x236.google.com ([2607:f8b0:400e:c03::236]) by bombadil.infradead.org with esmtps (Exim 4.80.1 #2 (Red Hat Linux)) id 1a1Sea-00074z-FA for linux-arm-kernel@lists.infradead.org; Wed, 25 Nov 2015 05:30:06 +0000 Received: by pacej9 with SMTP id ej9so45755091pac.2 for ; Tue, 24 Nov 2015 21:29:43 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=linaro-org.20150623.gappssmtp.com; s=20150623; h=subject:to:references:cc:from:message-id:date:user-agent :mime-version:in-reply-to:content-type:content-transfer-encoding; bh=WyZlHPTeF+J+b2fW2KkXunJC2qq8eGy7mvxcFXuQmts=; b=JE4pIbcUqRQrahyxZpuc0u6Rb1EzmhuE9Edh/H3RAYq90HUqFAODco5BwZusdKtjQ/ r/Cx1t5JXhJj8k9Sh9G/WVa4/ImF1MgM8v+i1xmOWYrKS6F0gVf2kOqfmkRhR7gKRur4 yWVRqhWzjTvIQs7uM9fLPeq7yQN1DuJH6rkescYQO7WXBcffx6+jKlV/eEtmNqiI0nai X9IGHKKkwfH57dS6Ez0dgaGXbSxz52If/NIXGMmjhItj+pvWLoBVCXgVctInBeNzSKC2 zgMgbNnUIKFva//tDdkMEXyE2WHfBT2qBacdncFdtvCFwrbipi1BisDzf7a4D8XIAcmS oHmQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:subject:to:references:cc:from:message-id:date :user-agent:mime-version:in-reply-to:content-type :content-transfer-encoding; bh=WyZlHPTeF+J+b2fW2KkXunJC2qq8eGy7mvxcFXuQmts=; b=BWElGlpvrRsux+OFa4b/iCFImhMhAvNzoTkC6j3LnSmR1oUv/wnQ7TexpkbnK8Y6Sh KD8wGZUPJnErDNMXGRQoY6GuHTUGE0eovuhmyiXml1VVsW2f/oUrVlZIWJTQJzE6Bp5x DwOMpD6GPHqirgbN5GplgmApPV35qQg/fhtroyAIGsiDH1Ju+K9Hb8wLIA/t0yPwNN9H M73yAB0eCRMhKk321Xkmfdw07d5rmLiwwN/r/8m9ctnYM+Cl7w1p/RqBpsQS5DAhsXml giJ5vYNq9fTLmuWfiBpRhZnCEf/W8PW1U/M6iQ6nZdnVZ9rhP5JiC3a93Ko4TJSbxBTh idlg== X-Gm-Message-State: ALoCoQnB2PQhWGuNnoT6aC2NW3F3cUNz0mzPXz364AKOwtOg3J5fCbrgdO5p+LiSy78YLgsXJlWG X-Received: by 10.66.192.193 with SMTP id hi1mr48330967pac.110.1448429383059; Tue, 24 Nov 2015 21:29:43 -0800 (PST) Received: from [192.168.1.225] (61-205-2-67m5.grp1.mineo.jp. [61.205.2.67]) by smtp.googlemail.com with ESMTPSA id o63sm2758485pfi.77.2015.11.24.21.29.38 (version=TLSv1/SSLv3 cipher=OTHER); Tue, 24 Nov 2015 21:29:41 -0800 (PST) Subject: Re: [PATCH v6 3/6] arm64: ftrace: fix a stack tracer's output under function graph tracer To: Jungseok Lee References: <1447828989-4980-1-git-send-email-takahiro.akashi@linaro.org> <1447828989-4980-4-git-send-email-takahiro.akashi@linaro.org> <0FD87840-2C67-4267-9FF5-AAE929348755@gmail.com> From: AKASHI Takahiro Message-ID: <56554740.4070904@linaro.org> Date: Wed, 25 Nov 2015 14:29:36 +0900 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101 Thunderbird/38.2.0 MIME-Version: 1.0 In-Reply-To: <0FD87840-2C67-4267-9FF5-AAE929348755@gmail.com> X-CRM114-Version: 20100106-BlameMichelson ( TRE 0.8.0 (BSD) ) MR-646709E3 X-CRM114-CacheID: sfid-20151124_213004_638236_B4B48738 X-CRM114-Status: GOOD ( 35.19 ) X-Spam-Score: -2.6 (--) X-Spam-Report: SpamAssassin version 3.4.0 on bombadil.infradead.org summary: Content analysis details: (-2.6 points) pts rule name description ---- ---------------------- -------------------------------------------------- -0.7 RCVD_IN_DNSWL_LOW RBL: Sender listed at http://www.dnswl.org/, low trust [2607:f8b0:400e:c03:0:0:0:236 listed in] [list.dnswl.org] -0.0 SPF_PASS SPF: sender matches SPF record -1.9 BAYES_00 BODY: Bayes spam probability is 0 to 1% [score: 0.0000] -0.1 DKIM_VALID Message has at least one valid DKIM or DK signature 0.1 DKIM_SIGNED Message has a DKIM or DK signature, not necessarily valid X-BeenThere: linux-arm-kernel@lists.infradead.org X-Mailman-Version: 2.1.20 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: catalin.marinas@arm.com, will.deacon@arm.com, rostedt@goodmis.org, broonie@kernel.org, yalin.wang2010@gmail.com, david.griego@linaro.org, linux-arm-kernel@lists.infradead.org Sender: "linux-arm-kernel" Errors-To: linux-arm-kernel-bounces+patch=linaro.org@lists.infradead.org On 11/24/2015 10:37 PM, Jungseok Lee wrote: > On Nov 18, 2015, at 3:43 PM, AKASHI Takahiro wrote: > > Hi Akashi, > >> Function graph tracer modifies a return address (LR) in a stack frame >> to hook a function return. This will result in many useless entries >> (return_to_handler) showing up in >> a) a stack tracer's output >> b) perf call graph (with perf record -g) >> c) dump_backtrace (at panic et al.) >> >> For example, in case of a), >> $ echo function_graph > /sys/kernel/debug/tracing/current_tracer >> $ echo 1 > /proc/sys/kernel/stack_trace_enabled >> $ cat /sys/kernel/debug/tracing/stack_trace >> Depth Size Location (54 entries) >> ----- ---- -------- >> 0) 4504 16 gic_raise_softirq+0x28/0x150 >> 1) 4488 80 smp_cross_call+0x38/0xb8 >> 2) 4408 48 return_to_handler+0x0/0x40 >> 3) 4360 32 return_to_handler+0x0/0x40 >> ... >> >> In case of b), >> $ echo function_graph > /sys/kernel/debug/tracing/current_tracer >> $ perf record -e mem:XXX:x -ag -- sleep 10 >> $ perf report >> ... >> | | |--0.22%-- 0x550f8 >> | | | 0x10888 >> | | | el0_svc_naked >> | | | sys_openat >> | | | return_to_handler >> | | | return_to_handler >> ... >> >> In case of c), >> $ echo function_graph > /sys/kernel/debug/tracing/current_tracer >> $ echo c > /proc/sysrq-trigger >> ... >> Call trace: >> [] sysrq_handle_crash+0x24/0x30 >> [] return_to_handler+0x0/0x40 >> [] return_to_handler+0x0/0x40 >> ... >> >> This patch replaces such entries with real addresses preserved in >> current->ret_stack[] at unwind_frame(). This way, we can cover all >> the cases. > > I've observed a strange behavior when playing with case c). Call trace > is as follows when function_graph is not used. > > Call trace: > [] sysrq_handle_crash+0x24/0x30 <- (1) > [] __handle_sysrq+0x128/0x19c <- (2) > [] write_sysrq_trigger+0x60/0x74 > [] proc_reg_write+0x84/0xc0 > [] __vfs_write+0x44/0x104 <- (3) > [] vfs_write+0x98/0x1a8 > [] SyS_write+0x50/0xb0 > [] el0_svc_naked+0x20/0x28 <- (4) > > When function_graph is set, some entries, such as do_mem_abort, are added > between (1) and (2). In addition, entries from (3) to (4) are not printed > out. As tracking down elements of ret_stack[], I realize dump_backtrace() > has been terminated before reaching to ret_stack[0]. Have you seen this > kind of behavior? I believe push & pop operations work correctly. > > Please correct me if I'm wrong. Oops, I mis-interpreted the result output. You are right. This can happen because the original dump_backtrace() wants to trace a stack from a function where an exception has taken place, sysrq_handle_crash(), while ret_stack[curr_ret_stack] doesn't point to that function, but the very top of traced functions in callchains, that is, __do_kernel_fault in your case, probably. So it results in replacing entries of return_to_handler to wrong function addresses. A fixup! patch attached below (informative only) fixes this issue by once tracing all the functions on a stack, but preventing a top few ones from being printed. But there is a tricky thing here: we have to use 'regs->pc' instead of frame.pc as a trapped function because, as I've already mentioned before, we always miss the function when walking through a stack from an exception handler to functions in a thread context. (Please note that we will introduce a dummy stack frame at interrupt, but not at exception.) >> Signed-off-by: AKASHI Takahiro >> --- >> arch/arm64/include/asm/ftrace.h | 2 ++ >> arch/arm64/include/asm/stacktrace.h | 3 +++ >> arch/arm64/kernel/perf_callchain.c | 3 +++ >> arch/arm64/kernel/process.c | 3 +++ >> arch/arm64/kernel/return_address.c | 3 +++ >> arch/arm64/kernel/stacktrace.c | 17 +++++++++++++++++ >> arch/arm64/kernel/time.c | 3 +++ >> arch/arm64/kernel/traps.c | 3 +++ >> 8 files changed, 37 insertions(+) >> >> diff --git a/arch/arm64/include/asm/ftrace.h b/arch/arm64/include/asm/ftrace.h >> index c5534fa..3c60f37 100644 >> --- a/arch/arm64/include/asm/ftrace.h >> +++ b/arch/arm64/include/asm/ftrace.h >> @@ -28,6 +28,8 @@ struct dyn_arch_ftrace { >> >> extern unsigned long ftrace_graph_call; >> >> +extern void return_to_handler(void); >> + >> static inline unsigned long ftrace_call_adjust(unsigned long addr) >> { >> /* >> diff --git a/arch/arm64/include/asm/stacktrace.h b/arch/arm64/include/asm/stacktrace.h >> index 6fb61c5..801a16db 100644 >> --- a/arch/arm64/include/asm/stacktrace.h >> +++ b/arch/arm64/include/asm/stacktrace.h >> @@ -22,6 +22,9 @@ struct stackframe { >> unsigned long fp; >> unsigned long sp; >> unsigned long pc; >> +#ifdef CONFIG_FUNCTION_GRAPH_TRACER >> + unsigned int graph; >> +#endif >> }; > > How about using int instead of unsigned int to align with cure_ret_stack > of struct task_struct? > >> extern int unwind_frame(struct task_struct *tsk, struct stackframe *frame); >> diff --git a/arch/arm64/kernel/perf_callchain.c b/arch/arm64/kernel/perf_callchain.c >> index 797220d..ff46654 100644 >> --- a/arch/arm64/kernel/perf_callchain.c >> +++ b/arch/arm64/kernel/perf_callchain.c >> @@ -164,6 +164,9 @@ void perf_callchain_kernel(struct perf_callchain_entry *entry, >> frame.fp = regs->regs[29]; >> frame.sp = regs->sp; >> frame.pc = regs->pc; >> +#ifdef CONFIG_FUNCTION_GRAPH_TRACER >> + frame.graph = current->curr_ret_stack; >> +#endif >> >> walk_stackframe(current, &frame, callchain_trace, entry); >> } >> diff --git a/arch/arm64/kernel/process.c b/arch/arm64/kernel/process.c >> index 98bf546..88d742b 100644 >> --- a/arch/arm64/kernel/process.c >> +++ b/arch/arm64/kernel/process.c >> @@ -344,6 +344,9 @@ unsigned long get_wchan(struct task_struct *p) >> frame.fp = thread_saved_fp(p); >> frame.sp = thread_saved_sp(p); >> frame.pc = thread_saved_pc(p); >> +#ifdef CONFIG_FUNCTION_GRAPH_TRACER >> + frame.graph = p->curr_ret_stack; >> +#endif >> stack_page = (unsigned long)task_stack_page(p); >> do { >> if (frame.sp < stack_page || >> diff --git a/arch/arm64/kernel/return_address.c b/arch/arm64/kernel/return_address.c >> index 07b37ac..1718706 100644 >> --- a/arch/arm64/kernel/return_address.c >> +++ b/arch/arm64/kernel/return_address.c >> @@ -43,6 +43,9 @@ void *return_address(unsigned int level) >> frame.fp = (unsigned long)__builtin_frame_address(0); >> frame.sp = current_stack_pointer; >> frame.pc = (unsigned long)return_address; /* dummy */ >> +#ifdef CONFIG_FUNCTION_GRAPH_TRACER >> + frame.graph = current->curr_ret_stack; >> +#endif >> >> walk_stackframe(current, &frame, save_return_addr, &data); >> >> diff --git a/arch/arm64/kernel/stacktrace.c b/arch/arm64/kernel/stacktrace.c >> index 9c7acf8..0a39049 100644 >> --- a/arch/arm64/kernel/stacktrace.c >> +++ b/arch/arm64/kernel/stacktrace.c >> @@ -17,6 +17,7 @@ >> */ >> #include >> #include >> +#include >> #include >> #include >> >> @@ -66,6 +67,19 @@ int notrace unwind_frame(struct task_struct *tsk, struct stackframe *frame) >> frame->fp = *(unsigned long *)(fp); >> frame->pc = *(unsigned long *)(fp + 8); >> >> +#ifdef CONFIG_FUNCTION_GRAPH_TRACER >> + if (tsk && tsk->ret_stack && >> + (frame->pc == (unsigned long)return_to_handler)) { >> + /* >> + * This is a case where function graph tracer has >> + * modified a return address (LR) in a stack frame >> + * to hook a function return. >> + * So replace it to an original value. >> + */ >> + frame->pc = tsk->ret_stack[frame->graph--].ret; >> + } >> +#endif /* CONFIG_FUNCTION_GRAPH_TRACER */ > > There is an index check of ret_stack[] in case of x86 [1]. Even though > graph is unsigned int, I think we need to check the value of frame->graph > before accessing ret_stack[]. I'm not sure that the checking is very useful because, if it happens, it is a bug. It might make sense to avoid a possible panic though. >> + >> /* >> * Check whether we are going to walk through from interrupt stack >> * to task stack. >> @@ -137,6 +151,9 @@ void save_stack_trace_tsk(struct task_struct *tsk, struct stack_trace *trace) >> frame.sp = current_stack_pointer; >> frame.pc = (unsigned long)save_stack_trace_tsk; >> } >> +#ifdef CONFIG_FUNCTION_GRAPH_TRACER >> + frame.graph = tsk->curr_ret_stack; >> +#endif >> >> walk_stackframe(tsk, &frame, save_trace, &data); >> if (trace->nr_entries < trace->max_entries) >> diff --git a/arch/arm64/kernel/time.c b/arch/arm64/kernel/time.c >> index 6e5c521..5977969 100644 >> --- a/arch/arm64/kernel/time.c >> +++ b/arch/arm64/kernel/time.c >> @@ -52,6 +52,9 @@ unsigned long profile_pc(struct pt_regs *regs) >> frame.fp = regs->regs[29]; >> frame.sp = regs->sp; >> frame.pc = regs->pc; >> +#ifdef CONFIG_FUNCTION_GRAPH_TRACER >> + frame.graph = -1; /* no task info */ >> +#endif > > graph is unsigned int type. Is this intentional? No. This initialization is, I believe, redundant as it is not checked anywhere, but I will re-think of it along with the checking above. Thanks, -Takahiro AKASHI > Best Regards > Jungseok Lee > > [1] arch/x86/kernel/dumpstack.c > ----8<---- From 9ebba7167f7838daf68d8231f04141d2f4d4b7b5 Mon Sep 17 00:00:00 2001 From: AKASHI Takahiro Date: Wed, 25 Nov 2015 13:29:54 +0900 Subject: [PATCH] fixup! arm64: ftrace: fix a stack tracer's output under function graph tracer Signed-off-by: AKASHI Takahiro --- arch/arm64/kernel/traps.c | 23 +++++++++++++++++------ 1 file changed, 17 insertions(+), 6 deletions(-) -- 1.7.9.5 _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel diff --git a/arch/arm64/kernel/traps.c b/arch/arm64/kernel/traps.c index 46053c2..f140029 100644 --- a/arch/arm64/kernel/traps.c +++ b/arch/arm64/kernel/traps.c @@ -147,17 +147,14 @@ static void dump_backtrace(struct pt_regs *regs, struct task_struct *tsk) { struct stackframe frame; unsigned long _irq_stack_ptr = per_cpu(irq_stack_ptr, smp_processor_id()); + int skip; pr_debug("%s(regs = %p tsk = %p)\n", __func__, regs, tsk); if (!tsk) tsk = current; - if (regs) { - frame.fp = regs->regs[29]; - frame.sp = regs->sp; - frame.pc = regs->pc; - } else if (tsk == current) { + if (tsk == current) { frame.fp = (unsigned long)__builtin_frame_address(0); frame.sp = current_stack_pointer; frame.pc = (unsigned long)dump_backtrace; @@ -173,13 +170,27 @@ static void dump_backtrace(struct pt_regs *regs, struct task_struct *tsk) frame.graph = tsk->curr_ret_stack; #endif + skip = (regs ? 1 : 0); pr_emerg("Call trace:\n"); while (1) { unsigned long where = frame.pc; unsigned long stack; int ret; - dump_backtrace_entry(where); + /* skip until specified stack frame */ + if (!skip) + dump_backtrace_entry(where); + else if (frame.fp == regs->regs[29]) { + skip = 0; + /* + * Mostly, this is the case where this function is + * called in panic/abort. As exception handler's + * stack frame does not contain the corresponding pc + * at which an exception has taken place, use regs->pc + * instead. + */ + dump_backtrace_entry(regs->pc); + } ret = unwind_frame(tsk, &frame); if (ret < 0) break;