From patchwork Thu Jul 16 14:24:05 2015 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 6807271 Return-Path: X-Original-To: patchwork-linux-arm@patchwork.kernel.org Delivered-To: patchwork-parsemail@patchwork1.web.kernel.org Received: from mail.kernel.org (mail.kernel.org [198.145.29.136]) by patchwork1.web.kernel.org (Postfix) with ESMTP id 7B5B39F536 for ; Thu, 16 Jul 2015 14:26:40 +0000 (UTC) Received: from mail.kernel.org (localhost [127.0.0.1]) by mail.kernel.org (Postfix) with ESMTP id 45621206F7 for ; Thu, 16 Jul 2015 14:26:39 +0000 (UTC) Received: from bombadil.infradead.org (bombadil.infradead.org [198.137.202.9]) (using TLSv1.2 with cipher AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPS id 1D7EC206D6 for ; Thu, 16 Jul 2015 14:26:38 +0000 (UTC) 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 1ZFk5Q-0004Da-Lb; Thu, 16 Jul 2015 14:24:32 +0000 Received: from smtprelay0193.hostedemail.com ([216.40.44.193] helo=smtprelay.hostedemail.com) by bombadil.infradead.org with esmtp (Exim 4.80.1 #2 (Red Hat Linux)) id 1ZFk5N-00045m-KA for linux-arm-kernel@lists.infradead.org; Thu, 16 Jul 2015 14:24:30 +0000 Received: from filter.hostedemail.com (unknown [216.40.38.60]) by smtprelay04.hostedemail.com (Postfix) with ESMTP id 9CB1935215D; Thu, 16 Jul 2015 14:24:07 +0000 (UTC) X-Session-Marker: 726F737465647440676F6F646D69732E6F7267 X-Spam-Summary: 2, 0, 0, , d41d8cd98f00b204, rostedt@goodmis.org, :::::::::::::::::, RULES_HIT:2:41:69:355:379:541:599:800:960:973:988:989:1260:1277:1311:1313:1314:1345:1359:1437:1515:1516:1518:1535:1593:1594:1605:1730:1747:1777:1792:1981:2194:2196:2199:2200:2393:2553:2559:2562:2693:2895:3138:3139:3140:3141:3142:3622:3865:3866:3867:3868:3870:3871:3872:3873:3874:4051:4120:4321:4605:4641:5007:6120:6261:7514:7875:7903:7904:8603:8660:9592:10004:10848:10967:11026:11232:11473:11658:11914:12043:12291:12296:12438:12517:12519:12555:12663:12679:12683:12740:13138:13148:13230:13231:14096:14097:21080, 0, RBL:none, CacheIP:none, Bayesian:0.5, 0.5, 0.5, Netcheck:none, DomainCache:0, MSF:not bulk, SPF:fn, MSBL:0, DNSBL:none, Custom_rules:0:0:0 X-HE-Tag: event61_5e14528c80326 X-Filterd-Recvd-Size: 9726 Received: from gandalf.local.home (cpe-67-246-153-56.stny.res.rr.com [67.246.153.56]) (Authenticated sender: rostedt@goodmis.org) by omf11.hostedemail.com (Postfix) with ESMTPA; Thu, 16 Jul 2015 14:24:06 +0000 (UTC) Date: Thu, 16 Jul 2015 10:24:05 -0400 From: Steven Rostedt To: Jungseok Lee Subject: Re: [RFC 2/3] arm64: refactor save_stack_trace() Message-ID: <20150716102405.2cc8c406@gandalf.local.home> In-Reply-To: References: <1436765375-7119-1-git-send-email-takahiro.akashi@linaro.org> <1436765375-7119-3-git-send-email-takahiro.akashi@linaro.org> <20150714093154.4d73e551@gandalf.local.home> <55A5A75A.1060401@linaro.org> <20150714225105.6c1e4f15@gandalf.local.home> <55A646EE.6030402@linaro.org> <20150715105536.42949ea9@gandalf.local.home> <20150715121337.3b31aa84@gandalf.local.home> <55A6FA82.9000901@linaro.org> <55A703F3.8050203@linaro.org> X-Mailer: Claws Mail 3.11.1 (GTK+ 2.24.28; x86_64-pc-linux-gnu) MIME-Version: 1.0 X-CRM114-Version: 20100106-BlameMichelson ( TRE 0.8.0 (BSD) ) MR-646709E3 X-CRM114-CacheID: sfid-20150716_072429_821316_EBE8751B X-CRM114-Status: GOOD ( 24.58 ) X-Spam-Score: -1.9 (-) 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, linux-kernel@vger.kernel.org, AKASHI Takahiro , broonie@kernel.org, david.griego@linaro.org, olof@lixom.net, linux-arm-kernel@lists.infradead.org Sender: "linux-arm-kernel" Errors-To: linux-arm-kernel-bounces+patchwork-linux-arm=patchwork.kernel.org@lists.infradead.org X-Spam-Status: No, score=-5.5 required=5.0 tests=BAYES_00, RCVD_IN_DNSWL_MED, RP_MATCHES_RCVD, UNPARSEABLE_RELAY autolearn=unavailable version=3.3.1 X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on mail.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP On Thu, 16 Jul 2015 22:29:05 +0900 Jungseok Lee wrote: > First of all, let's look at the following data. > > 1) stack_trace data > Depth Size Location (55 entries) > ----- ---- -------- > 0) 4808 16 notifier_call_chain+0x2c/0x94 > 1) 4792 64 raw_notifier_call_chain+0x34/0x44 > 2) 4728 48 timekeeping_update.constprop.9+0xb8/0x114 > 3) 4680 48 update_wall_time+0x408/0x6dc > 4) 4632 128 tick_do_update_jiffies64+0xd8/0x154 > 5) 4504 80 tick_sched_do_timer+0x50/0x60 > 6) 4424 32 tick_sched_timer+0x34/0x90 > 7) 4392 48 __run_hrtimer+0x60/0x258 > 8) 4344 64 hrtimer_interrupt+0xe8/0x260 > 9) 4280 128 arch_timer_handler_virt+0x38/0x48 > 10) 4152 32 handle_percpu_devid_irq+0x84/0x188 > 11) 4120 64 generic_handle_irq+0x38/0x54 > 12) 4056 32 __handle_domain_irq+0x68/0xbc > 13) 4024 64 gic_handle_irq+0x38/0x88 > 14) 3960 336 el1_irq+0x64/0xd8 > 15) 3624 16 netif_rx_internal+0x14/0x198 > 16) 3608 64 netif_rx+0x20/0xa4 > 17) 3544 32 loopback_xmit+0x64/0xf4 > 18) 3512 48 dev_hard_start_xmit+0x25c/0x3f8 > 19) 3464 160 __dev_queue_xmit+0x440/0x4dc > 20) 3304 96 dev_queue_xmit_sk+0x20/0x30 > 21) 3208 32 ip_finish_output+0x1e0/0xabc > 22) 3176 96 ip_output+0xf0/0x120 > 23) 3080 64 ip_local_out_sk+0x44/0x54 > 24) 3016 32 ip_send_skb+0x24/0xbc > 25) 2984 48 ip_push_pending_frames+0x40/0x60 > 26) 2936 64 icmp_push_reply+0x104/0x144 > 27) 2872 96 icmp_send+0x3c0/0x3c8 > 28) 2776 192 __udp4_lib_rcv+0x5b8/0x684 > 29) 2584 96 udp_rcv+0x2c/0x3c > 30) 2488 32 ip_local_deliver+0xa0/0x224 > 31) 2456 48 ip_rcv+0x360/0x57c > 32) 2408 64 __netif_receive_skb_core+0x4d0/0x80c > 33) 2344 128 __netif_receive_skb+0x24/0x84 > 34) 2216 32 process_backlog+0x9c/0x15c > 35) 2184 80 net_rx_action+0x1ec/0x32c > 36) 2104 160 __do_softirq+0x114/0x2f0 > 37) 1944 128 do_softirq+0x60/0x68 > 38) 1816 32 __local_bh_enable_ip+0xb0/0xd4 > 39) 1784 32 ip_finish_output+0x1f4/0xabc > 40) 1752 96 ip_output+0xf0/0x120 > 41) 1656 64 ip_local_out_sk+0x44/0x54 > 42) 1592 32 ip_send_skb+0x24/0xbc > 43) 1560 48 udp_send_skb+0x1b4/0x2f4 > 44) 1512 80 udp_sendmsg+0x2a8/0x7a0 > 45) 1432 272 inet_sendmsg+0xa0/0xd0 > 46) 1160 48 sock_sendmsg+0x30/0x78 > 47) 1112 32 ___sys_sendmsg+0x15c/0x26c > 48) 1080 400 __sys_sendmmsg+0x94/0x180 > 49) 680 320 SyS_sendmmsg+0x38/0x54 > 50) 360 360 el0_svc_naked+0x20/0x28 > > 2) stack_max_size data > 4888 > > The data looks odd in two points. > 1) the number of entry > There is a mismatch between start token and real data Yep, good catch. As soon as I read that, I realized exactly what the issue was ;-) > > 2) 80-byte gap > stack_max_size is not aligned with "Depth" field of the first entry of stack_trace. > > IMHO, two items are not considered in this series as digging them out. > > 1) skipped entries > As x variable is introduced in Steve's patch, it is needed to track down > how many entries are recorded in both stack_dump_trace and stack_dump_index. Yep. > > 2) max_stack_trace.skip value > max_stack_trace.skip is 0 as applying Steve's patch. The above gap could be > observed unless the value is not considered in arch code. In the above example, > 80-byte gap is save_stack_trace function in arch/arm64/kernel/stacktrace.c. > > As applying the following fix, stack_trace and stack_max_size are okay. > However, I'm not sure which code, arch or generic ftrace, should handle trace->skip. > The latter one is responsible for it under current implementation, not Steve's change. > > Please correct me if I am wrong. No, it's a bug in my patch. I'll make an update. Does this new patch fix it for you? -- Steve --- kernel/trace/trace_stack.c | 58 +++++++++++++-------------------------------- 1 file changed, 17 insertions(+), 41 deletions(-) Index: linux-trace.git/kernel/trace/trace_stack.c =================================================================== --- linux-trace.git.orig/kernel/trace/trace_stack.c 2015-07-15 12:49:59.290063597 -0400 +++ linux-trace.git/kernel/trace/trace_stack.c 2015-07-16 09:55:37.936188197 -0400 @@ -18,12 +18,6 @@ #define STACK_TRACE_ENTRIES 500 -#ifdef CC_USING_FENTRY -# define fentry 1 -#else -# define fentry 0 -#endif - static unsigned long stack_dump_trace[STACK_TRACE_ENTRIES+1] = { [0 ... (STACK_TRACE_ENTRIES)] = ULONG_MAX }; static unsigned stack_dump_index[STACK_TRACE_ENTRIES]; @@ -35,7 +29,7 @@ static unsigned stack_dump_index[STACK_T */ static struct stack_trace max_stack_trace = { .max_entries = STACK_TRACE_ENTRIES - 1, - .entries = &stack_dump_trace[1], + .entries = &stack_dump_trace[0], }; static unsigned long max_stack_size; @@ -77,7 +71,7 @@ check_stack(unsigned long ip, unsigned l unsigned long this_size, flags; unsigned long *p, *top, *start; static int tracer_frame; int frame_size = ACCESS_ONCE(tracer_frame); - int i; + int i, x; this_size = ((unsigned long)stack) & (THREAD_SIZE-1); this_size = THREAD_SIZE - this_size; @@ -105,26 +99,20 @@ check_stack(unsigned long ip, unsigned l max_stack_size = this_size; max_stack_trace.nr_entries = 0; - - if (using_ftrace_ops_list_func()) - max_stack_trace.skip = 4; - else - max_stack_trace.skip = 3; + max_stack_trace.skip = 3; save_stack_trace(&max_stack_trace); - /* - * Add the passed in ip from the function tracer. - * Searching for this on the stack will skip over - * most of the overhead from the stack tracer itself. - */ - stack_dump_trace[0] = ip; - max_stack_trace.nr_entries++; + /* Skip over the overhead of the stack tracer itself */ + for (i = 0; i < max_stack_trace.nr_entries; i++) { + if (stack_dump_trace[i] == ip) + break; + } /* * Now find where in the stack these are. */ - i = 0; + x = 0; start = stack; top = (unsigned long *) (((unsigned long)start & ~(THREAD_SIZE-1)) + THREAD_SIZE); @@ -139,12 +127,13 @@ check_stack(unsigned long ip, unsigned l while (i < max_stack_trace.nr_entries) { int found = 0; - stack_dump_index[i] = this_size; + stack_dump_index[x] = this_size; p = start; for (; p < top && i < max_stack_trace.nr_entries; p++) { if (*p == stack_dump_trace[i]) { - this_size = stack_dump_index[i++] = + stack_dump_trace[x] = stack_dump_trace[i++]; + this_size = stack_dump_index[x++] = (top - p) * sizeof(unsigned long); found = 1; /* Start the search from here */ @@ -168,6 +157,10 @@ check_stack(unsigned long ip, unsigned l i++; } + max_stack_trace.nr_entries = x; + for (; x < i; x++) + stack_dump_trace[x] = ULONG_MAX; + if (task_stack_end_corrupted(current)) { print_max_stack(); BUG(); @@ -192,24 +185,7 @@ stack_trace_call(unsigned long ip, unsig if (per_cpu(trace_active, cpu)++ != 0) goto out; - /* - * When fentry is used, the traced function does not get - * its stack frame set up, and we lose the parent. - * The ip is pretty useless because the function tracer - * was called before that function set up its stack frame. - * In this case, we use the parent ip. - * - * By adding the return address of either the parent ip - * or the current ip we can disregard most of the stack usage - * caused by the stack tracer itself. - * - * The function tracer always reports the address of where the - * mcount call was, but the stack will hold the return address. - */ - if (fentry) - ip = parent_ip; - else - ip += MCOUNT_INSN_SIZE; + ip += MCOUNT_INSN_SIZE; check_stack(ip, &stack);