ORC unwinder and 'reliable' flag to printk_stack_address()

ORC unwinder and 'reliable' flag to printk_stack_address()

[Jiri Kosina]

Hi Josh,

I just got the below stack trace with current Linus' tree with ORC 
unwinder enabled:

	[    8.652765] Call Trace:
	[    8.652767]  dump_stack+0x7c/0xbf
	[    8.652769]  print_circular_bug+0x2d3/0x2e0
	[    8.652771]  check_prev_add+0x666/0x700
	[    8.652772]  ? print_bfs_bug+0x40/0x40
	[    8.652775]  lock_commit_crosslock+0x3f1/0x570
	[    8.652777]  complete+0x24/0x60
	[    8.652779]  __kthread_parkme+0x42/0x90
	[    8.652780]  smpboot_thread_fn+0x92/0x210
	[    8.652782]  kthread+0x145/0x180
	[    8.652783]  ? sort_range+0x20/0x20
	[    8.652785]  ? kthread_create_on_node+0x40/0x40
	[    8.652787]  ret_from_fork+0x2a/0x40

Please note the kthread_create_on_node(), sort_range() and print_bfs_bug() 
entries ... I believe they actually shouldn't be there at all. All of them 
are at the last byte belonging to the function. Am I missing something?

Thanks,

-- 
Jiri Kosina
SUSE Labs

Re: ORC unwinder and 'reliable' flag to printk_stack_address()

[Josh Poimboeuf]

On Tue, Sep 05, 2017 at 03:15:12PM +0200, Jiri Kosina wrote:
> Hi Josh,
> 
> I just got the below stack trace with current Linus' tree with ORC 
> unwinder enabled:
> 
> 	[    8.652765] Call Trace:
> 	[    8.652767]  dump_stack+0x7c/0xbf
> 	[    8.652769]  print_circular_bug+0x2d3/0x2e0
> 	[    8.652771]  check_prev_add+0x666/0x700
> 	[    8.652772]  ? print_bfs_bug+0x40/0x40
> 	[    8.652775]  lock_commit_crosslock+0x3f1/0x570
> 	[    8.652777]  complete+0x24/0x60
> 	[    8.652779]  __kthread_parkme+0x42/0x90
> 	[    8.652780]  smpboot_thread_fn+0x92/0x210
> 	[    8.652782]  kthread+0x145/0x180
> 	[    8.652783]  ? sort_range+0x20/0x20
> 	[    8.652785]  ? kthread_create_on_node+0x40/0x40
> 	[    8.652787]  ret_from_fork+0x2a/0x40
> 
> Please note the kthread_create_on_node(), sort_range() and print_bfs_bug() 
> entries ... I believe they actually shouldn't be there at all. All of them 
> are at the last byte belonging to the function. Am I missing something?

The question marks are still supposed to be there.  They show any text
addresses found on the stack that weren't otherwise found by the
unwinder.  99.9% of the time, they're left over from a previous call
chain, and should be ignored.

They can be confusing, but IIRC, Linus wants to keep them because:

a) If the unwinder gets confused, they'll still be printed.

b) For some really sneaky bugs, it can give a few clues about what
   happened *before* the current trace.

Personally I've never seen (b), but (a) is definitely a good reason.

Note that while the "unreliable" addresses are shown for splats, they're
*not* reported by the unwinder for all its other uses like livepatch,
perf, /proc/<pid>/stack, etc.

-- 
Josh

Re: ORC unwinder and 'reliable' flag to printk_stack_address()

[Jiri Kosina]

On Wed, 6 Sep 2017, Josh Poimboeuf wrote:

> > I just got the below stack trace with current Linus' tree with ORC 
> > unwinder enabled:
> > 
> > 	[    8.652765] Call Trace:
> > 	[    8.652767]  dump_stack+0x7c/0xbf
> > 	[    8.652769]  print_circular_bug+0x2d3/0x2e0
> > 	[    8.652771]  check_prev_add+0x666/0x700
> > 	[    8.652772]  ? print_bfs_bug+0x40/0x40
> > 	[    8.652775]  lock_commit_crosslock+0x3f1/0x570
> > 	[    8.652777]  complete+0x24/0x60
> > 	[    8.652779]  __kthread_parkme+0x42/0x90
> > 	[    8.652780]  smpboot_thread_fn+0x92/0x210
> > 	[    8.652782]  kthread+0x145/0x180
> > 	[    8.652783]  ? sort_range+0x20/0x20
> > 	[    8.652785]  ? kthread_create_on_node+0x40/0x40
> > 	[    8.652787]  ret_from_fork+0x2a/0x40
> > 
> > Please note the kthread_create_on_node(), sort_range() and print_bfs_bug() 
> > entries ... I believe they actually shouldn't be there at all. All of them 
> > are at the last byte belonging to the function. Am I missing something?
> 
> The question marks are still supposed to be there.  They show any text
> addresses found on the stack that weren't otherwise found by the
> unwinder.  99.9% of the time, they're left over from a previous call
> chain, and should be ignored.

It's interesting though that all of them (and even in other instances I've 
encountered in the meantime) are always at the "last address" of the 
function address range. That's hardly a conincidence, and also hardly a 
result of a legitimate stacktrace -- 'call' is rather unlikely to be the 
last insn in a function.

> Note that while the "unreliable" addresses are shown for splats, they're 
> *not* reported by the unwinder for all its other uses like livepatch, 
> perf, /proc/<pid>/stack, etc.

Ah, I've missed that when looking at the code, now I see it. Thanks,

-- 
Jiri Kosina
SUSE Labs

Re: ORC unwinder and 'reliable' flag to printk_stack_address()

[Josh Poimboeuf]

On Fri, Sep 08, 2017 at 01:12:45PM +0200, Jiri Kosina wrote:
> On Wed, 6 Sep 2017, Josh Poimboeuf wrote:
> 
> > > I just got the below stack trace with current Linus' tree with ORC 
> > > unwinder enabled:
> > > 
> > > 	[    8.652765] Call Trace:
> > > 	[    8.652767]  dump_stack+0x7c/0xbf
> > > 	[    8.652769]  print_circular_bug+0x2d3/0x2e0
> > > 	[    8.652771]  check_prev_add+0x666/0x700
> > > 	[    8.652772]  ? print_bfs_bug+0x40/0x40
> > > 	[    8.652775]  lock_commit_crosslock+0x3f1/0x570
> > > 	[    8.652777]  complete+0x24/0x60
> > > 	[    8.652779]  __kthread_parkme+0x42/0x90
> > > 	[    8.652780]  smpboot_thread_fn+0x92/0x210
> > > 	[    8.652782]  kthread+0x145/0x180
> > > 	[    8.652783]  ? sort_range+0x20/0x20
> > > 	[    8.652785]  ? kthread_create_on_node+0x40/0x40
> > > 	[    8.652787]  ret_from_fork+0x2a/0x40
> > > 
> > > Please note the kthread_create_on_node(), sort_range() and print_bfs_bug() 
> > > entries ... I believe they actually shouldn't be there at all. All of them 
> > > are at the last byte belonging to the function. Am I missing something?
> > 
> > The question marks are still supposed to be there.  They show any text
> > addresses found on the stack that weren't otherwise found by the
> > unwinder.  99.9% of the time, they're left over from a previous call
> > chain, and should be ignored.
> 
> It's interesting though that all of them (and even in other instances I've 
> encountered in the meantime) are always at the "last address" of the 
> function address range. That's hardly a conincidence, and also hardly a 
> result of a legitimate stacktrace -- 'call' is rather unlikely to be the 
> last insn in a function.

Ah, I missed that detail.  In this case, these aren't actually bread
crumbs from a previous stack.  They're actually function pointers which
are saved on the current stack.

In my vmlinux, the function which comes after kthread_create_on_node()
is kthread().  Which means kthread_create_on_node+0x40/0x40 is the same
address as kthread+0x0.  So it's the 'kthread' function pointer.
Similarly, sort_range+0x20/0x20 is the same as smpboot_thread_fn+0x0.

So the 'kthread' and 'smpboot_thread_fn' function pointers are getting
saved on the stack in kthread()'s frame.  The oops dump code in
show_trace_log_lvl() sees those text addresses and prints them as bread
crumbs.

So your next question might be, why is it printed as

  kthread_create_on_node+0x40/0x40

instead of

  kthread+0x0/0x18e

?

The reason is, there are some "noreturn" functions which never return,
like panic().  They sometimes have a CALL instruction at the very end.
So if kthread_create_on_node()'s last instruction were a CALL, we'd want
to show *that* function name instead of kthread().

So when printing splats, we always assume that the boundary between the
end of a function and the beginning of a function belongs to the
previous function.  That's what the printk '%pB' specifier does.

The only exception to that is when printing regs->ip.  In that case, the
interrupt could have occurred right at the beginning of a function.  So
we would print 'kthread+0x0'.  Which is what the '%pS' specifier does.

-- 
Josh