Re: [PATCH v2] tracing: Function stack size and its name mismatch in arm64

From: Jiping Ma <Jiping.Ma2@windriver.com>
To: Will Deacon <will@kernel.org>
Cc: <rostedt@goodmis.org>, <mingo@redhat.com>,
	<catalin.marinas@arm.com>, <will.deacon@arm.com>,
	<joel@joelfernandes.org>, <linux-kernel@vger.kernel.org>,
	<linux-arm-kernel@lists.infradead.org>
Subject: Re: [PATCH v2] tracing: Function stack size and its name mismatch in arm64
Date: Fri, 2 Aug 2019 10:43:03 +0800	[thread overview]
Message-ID: <47e90170-e971-c2f5-b6c9-d3c6a694a4a7@windriver.com> (raw)
In-Reply-To: <20190801094156.emo36ekvrm74nndl@willie-the-truck>


On 2019年08月01日 17:41, Will Deacon wrote:
> On Thu, Aug 01, 2019 at 04:33:40PM +0800, Jiping Ma wrote:
>> In arm64, the PC of the frame is matched to the last frame function,
>> rather than the function of his frame. For the following example, the
>> stack size of occupy_stack_init function should be 3376, rather than 176.
>>
>> Wrong info:
>> Depth Size Location (16 entries)
>> ----- ---- --------
>> 0) 5400 16 __update_load_avg_se.isra.2+0x28/0x220
>> 1) 5384 96 put_prev_entity+0x250/0x338
>> 2) 5288 80 pick_next_task_fair+0x4c4/0x508
>> 3) 5208 72 __schedule+0x100/0x600
>> 4) 5136 184 preempt_schedule_common+0x28/0x48
>> 5) 4952 32 preempt_schedule+0x28/0x30
>> 6) 4920 16 vprintk_emit+0x170/0x1f8
>> 7) 4904 128 vprintk_default+0x48/0x58
>> 8) 4776 64 vprintk_func+0xf8/0x1c8
>> 9) 4712 112 printk+0x70/0x90
>> 10) 4600 176 occupy_stack_init+0x64/0xc0 [kernel_stack]
>> 11) 4424 3376 do_one_initcall+0x68/0x248
>> 12) 1048 144 do_init_module+0x60/0x1f0
>> 13) 904 48 load_module+0x1d50/0x2340
>> 14) 856 352 sys_finit_module+0xd0/0xe8
>> 15) 504 504 el0_svc_naked+0x30/0x34
>>
>> Correct info:
>> Depth Size Location (18 entries)
>> ----- ---- --------
>> 0) 5464 48 cgroup_rstat_updated+0x20/0x100
>> 1) 5416 32 cgroup_base_stat_cputime_account_end.isra.0+0x30/0x60
>> 2) 5384 32 __cgroup_account_cputime+0x3c/0x48
>> 3) 5352 64 update_curr+0xc4/0x1d0
>> 4) 5288 72 pick_next_task_fair+0x444/0x508
>> 5) 5216 184 __schedule+0x100/0x600
>> 6) 5032 32 preempt_schedule_common+0x28/0x48
>> 7) 5000 16 preempt_schedule+0x28/0x30
>> 8) 4984 128 vprintk_emit+0x170/0x1f8
>> 9) 4856 64 vprintk_default+0x48/0x58
>> 10) 4792 112 vprintk_func+0xf8/0x1c8
>> 11) 4680 176 printk+0x70/0x90
>> 12) 4504 80 func_test+0x7c/0xb8 [kernel_stack]
>> 13) 4424 3376 occupy_stack_init+0x7c/0xc0 [kernel_stack]
>> 14) 1048 144 do_one_initcall+0x68/0x248
>> 15) 904 48 do_init_module+0x60/0x1f0
>> 16) 856 352 load_module+0x1d50/0x2340
>> 17) 504 504 sys_finit_module+0xd0/0xe8
>>
>> Signed-off-by: Jiping Ma <jiping.ma2@windriver.com>
>> ---
>>   kernel/trace/trace_stack.c | 28 ++++++++++++++++++++++++++--
>>   1 file changed, 26 insertions(+), 2 deletions(-)
>>
>> diff --git a/kernel/trace/trace_stack.c b/kernel/trace/trace_stack.c
>> index 5d16f73898db..ed80b95abf06 100644
>> --- a/kernel/trace/trace_stack.c
>> +++ b/kernel/trace/trace_stack.c
>> @@ -40,16 +40,28 @@ static void print_max_stack(void)
>>   
>>   	pr_emerg("        Depth    Size   Location    (%d entries)\n"
>>   			   "        -----    ----   --------\n",
>> +#ifdef CONFIG_ARM64
>> +			   stack_trace_nr_entries - 1);
>> +#else
>>   			   stack_trace_nr_entries);
> Sorry, but I have no idea what the problem is here. All I know is that the
> solution looks highly dubious and I find it very hard to believe that the
> arm64 backtracing code is uniquely special as to deserve being called out
> like this. I suspect there's a bug lurking somewhere, but you really need
> to do a better job of explaining the issue rather than simply providing a
> couple of backtraces with no context.
>
> *Why* does the frame appear to be off-by-one?
Because the PC is LR in ARM64 stack actually.  Following is ARM64 stack 
layout. Please refer to the figure 3 in 
http://infocenter.arm.com/help/topic/com.arm.doc.ihi0055b/IHI0055B_aapcs64.pdf
             LR
             FP
             ......
             LR
             FP
Jiping
>
> Will