Ryan Johnson
2010-Jul-14 10:05 UTC
[dtrace-discuss] ustack() misses caller of leaf under profile probe
Hi all,
There was a discussion about this a while back, but now some new
information has come to light:
Consider the situation where a thread calls a leaf function which does
not create a stack frame (such as atomic_*). The following toy program
demonstrates this scenario:
--- begin backtrace.c ------------
#include <atomic.h>
unsigned int x;
int foo() {
int y = 1;
while(y != 100) {
y = atomic_swap_32(&x, y);
}
return x;
}
int main() {
return 10 + foo();
}
--- end backtrace.c ------------
If we grab stack frames by instrumenting the function directly --
"pid$target::atomic_swap_32:entry {@counts[ustack()]=count();}" --
then
we get:
libc.so.1`atomic_swap_32
a.out`foo+0x2c
a.out`main+0x4
a.out`_start+0x108
1054138
If, on the other hand, we profile the process --
"profile-7777us/pid==$target/ {@counts[ustack()]=count(); }" -- and
grab
stack frames again, we get (among other far rarer variants):
libc.so.1`atomic_swap_32
a.out`main+0x4
a.out`_start+0x108
1167
Note that this is *not* related to tail calls (there are none here).
Since in both cases $pc is the same, the problem must be due to either
the profile probe''s way of saving process context or else the stack
walking code doing something wrong under profiling...
Ideas?
Ryan
Adam Leventhal
2010-Jul-19 17:55 UTC
[dtrace-discuss] ustack() misses caller of leaf under profile probe
Hey Ryan, We have special logic in pid provider entry and return probes to account for the fact that they execute in leaf call context. Unfortunately, this is not generally possible. Search for uses of CPU_DTRACE_ENTRY on cvs.opensolaris.org. Adam On Jul 14, 2010, at 3:05 AM, Ryan Johnson wrote:> Hi all, > > There was a discussion about this a while back, but now some new information has come to light: > > Consider the situation where a thread calls a leaf function which does not create a stack frame (such as atomic_*). The following toy program demonstrates this scenario: > > --- begin backtrace.c ------------ > #include <atomic.h> > unsigned int x; > int foo() { > int y = 1; > while(y != 100) { > y = atomic_swap_32(&x, y); > } > return x; > } > int main() { > return 10 + foo(); > } > --- end backtrace.c ------------ > > If we grab stack frames by instrumenting the function directly -- "pid$target::atomic_swap_32:entry {@counts[ustack()]=count();}" -- then we get: > > libc.so.1`atomic_swap_32 > a.out`foo+0x2c > a.out`main+0x4 > a.out`_start+0x108 > 1054138 > > If, on the other hand, we profile the process -- "profile-7777us/pid==$target/ {@counts[ustack()]=count(); }" -- and grab stack frames again, we get (among other far rarer variants): > > libc.so.1`atomic_swap_32 > a.out`main+0x4 > a.out`_start+0x108 > 1167 > > Note that this is *not* related to tail calls (there are none here). Since in both cases $pc is the same, the problem must be due to either the profile probe''s way of saving process context or else the stack walking code doing something wrong under profiling... > > Ideas? > Ryan > > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org-- Adam Leventhal, Fishworks http://blogs.sun.com/ahl
Ryan Johnson
2010-Jul-20 15:50 UTC
[dtrace-discuss] ustack() misses caller of leaf under profile probe
Hi Adam, CPU_DTRACE_ENTRY: that would explain the difference between the two use cases... Not generally possible: I guess this is technically true, thanks to trampolines, tail calls, and JMPL whose source registers have probably been clobbered. However, we should at least be able to detect vanilla CALL reliably by decoding %i7 (I''ve never heard of a compiler clobbering it). The attached scripts do this. The dtrace script reads in the instruction at %i7, decodes it and computes the target when possible, and emits the result at the head of each stack trace. The awk script (which takes the dtrace script''s output as input) then checks whether i7''s target points to the same function as the leaf''s caller and decide whether to filter it out. Running the two scripts on a process, I got 13.5k total samples, with with 214 of those unable to read %i7 for some reason; of the valid samples, 8.2k had %i7''s target point to a different function than the leaf. I''ve checked source code for a smattering of the samples, and every time the i7-enhanced stack trace is the correct one. Maybe this won''t ever get baked into dtrace, but at least there''s a workaround now if other folks need it. Also, it might be good to update the wiki with this gotcha. Missing tail calls is one thing... silently missing legitimate callers who made a stack frame is pretty annoying (and makes profiling significantly less useful if you''re hunting for the caller of that expensive function). Regards, Ryan On 7/19/2010 7:55 PM, Adam Leventhal wrote:> Hey Ryan, > > We have special logic in pid provider entry and return probes to account for the fact that they execute in leaf call context. Unfortunately, this is not generally possible. > > Search for uses of CPU_DTRACE_ENTRY on cvs.opensolaris.org. > > Adam > > On Jul 14, 2010, at 3:05 AM, Ryan Johnson wrote: > > >> Hi all, >> >> There was a discussion about this a while back, but now some new information has come to light: >> >> Consider the situation where a thread calls a leaf function which does not create a stack frame (such as atomic_*). The following toy program demonstrates this scenario: >> >> --- begin backtrace.c ------------ >> #include<atomic.h> >> unsigned int x; >> int foo() { >> int y = 1; >> while(y != 100) { >> y = atomic_swap_32(&x, y); >> } >> return x; >> } >> int main() { >> return 10 + foo(); >> } >> --- end backtrace.c ------------ >> >> If we grab stack frames by instrumenting the function directly -- "pid$target::atomic_swap_32:entry {@counts[ustack()]=count();}" -- then we get: >> >> libc.so.1`atomic_swap_32 >> a.out`foo+0x2c >> a.out`main+0x4 >> a.out`_start+0x108 >> 1054138 >> >> If, on the other hand, we profile the process -- "profile-7777us/pid==$target/ {@counts[ustack()]=count(); }" -- and grab stack frames again, we get (among other far rarer variants): >> >> libc.so.1`atomic_swap_32 >> a.out`main+0x4 >> a.out`_start+0x108 >> 1167 >> >> Note that this is *not* related to tail calls (there are none here). Since in both cases $pc is the same, the problem must be due to either the profile probe''s way of saving process context or else the stack walking code doing something wrong under profiling... >> >> Ideas? >> Ryan >> >> _______________________________________________ >> dtrace-discuss mailing list >> dtrace-discuss at opensolaris.org >> > > -- > Adam Leventhal, Fishworks http://blogs.sun.com/ahl > >-------------- next part -------------- An embedded and charset-unspecified text was scrubbed... Name: profile-i7.d URL: <http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20100720/9bb2be2b/attachment.ksh> -------------- next part -------------- An embedded and charset-unspecified text was scrubbed... Name: profile-i7.awk URL: <http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20100720/9bb2be2b/attachment-0001.ksh>
Adam Leventhal
2010-Jul-21 00:18 UTC
[dtrace-discuss] ustack() misses caller of leaf under profile probe
> Not generally possible: I guess this is technically true, thanks to trampolines, tail calls, and JMPL whose source registers have probably been clobbered. However, we should at least be able to detect vanilla CALL reliably by decoding %i7 (I''ve never heard of a compiler clobbering it). The attached scripts do this. The dtrace script reads in the instruction at %i7, decodes it and computes the target when possible, and emits the result at the head of each stack trace. The awk script (which takes the dtrace script''s output as input) then checks whether i7''s target points to the same function as the leaf''s caller and decide whether to filter it out.It it not generally possible to determine the the probe fires whether or not the thread is currently executing in leaf context. All symbolic translations happens in user-land after the fact for both ustack() and uaddr().> Running the two scripts on a process, I got 13.5k total samples, with with 214 of those unable to read %i7 for some reason; of the valid samples, 8.2k had %i7''s target point to a different function than the leaf. > > I''ve checked source code for a smattering of the samples, and every time the i7-enhanced stack trace is the correct one. > > Maybe this won''t ever get baked into dtrace, but at least there''s a workaround now if other folks need it.What we could do is have the ustack() action record %o7 as well and then figure out in user-land whether or not it''s relevant.> Also, it might be good to update the wiki with this gotcha. Missing tail calls is one thing... silently missing legitimate callers who made a stack frame is pretty annoying (and makes profiling significantly less useful if you''re hunting for the caller of that expensive function).Good idea. Propose some changes to the list and we''ll get it reviewed. Thanks. Adam> Regards, > Ryan > > On 7/19/2010 7:55 PM, Adam Leventhal wrote: >> Hey Ryan, >> >> We have special logic in pid provider entry and return probes to account for the fact that they execute in leaf call context. Unfortunately, this is not generally possible. >> >> Search for uses of CPU_DTRACE_ENTRY on cvs.opensolaris.org. >> >> Adam >> >> On Jul 14, 2010, at 3:05 AM, Ryan Johnson wrote: >> >> >>> Hi all, >>> >>> There was a discussion about this a while back, but now some new information has come to light: >>> >>> Consider the situation where a thread calls a leaf function which does not create a stack frame (such as atomic_*). The following toy program demonstrates this scenario: >>> >>> --- begin backtrace.c ------------ >>> #include<atomic.h> >>> unsigned int x; >>> int foo() { >>> int y = 1; >>> while(y != 100) { >>> y = atomic_swap_32(&x, y); >>> } >>> return x; >>> } >>> int main() { >>> return 10 + foo(); >>> } >>> --- end backtrace.c ------------ >>> >>> If we grab stack frames by instrumenting the function directly -- "pid$target::atomic_swap_32:entry {@counts[ustack()]=count();}" -- then we get: >>> >>> libc.so.1`atomic_swap_32 >>> a.out`foo+0x2c >>> a.out`main+0x4 >>> a.out`_start+0x108 >>> 1054138 >>> >>> If, on the other hand, we profile the process -- "profile-7777us/pid==$target/ {@counts[ustack()]=count(); }" -- and grab stack frames again, we get (among other far rarer variants): >>> >>> libc.so.1`atomic_swap_32 >>> a.out`main+0x4 >>> a.out`_start+0x108 >>> 1167 >>> >>> Note that this is *not* related to tail calls (there are none here). Since in both cases $pc is the same, the problem must be due to either the profile probe''s way of saving process context or else the stack walking code doing something wrong under profiling... >>> >>> Ideas? >>> Ryan >>> >>> _______________________________________________ >>> dtrace-discuss mailing list >>> dtrace-discuss at opensolaris.org >>> >> >> -- >> Adam Leventhal, Fishworks http://blogs.sun.com/ahl >> >> > > <profile-i7.d><profile-i7.awk>-- Adam Leventhal, Fishworks http://blogs.sun.com/ahl
Ryan Johnson
2010-Jul-21 06:46 UTC
[dtrace-discuss] ustack() misses caller of leaf under profile probe
On 7/21/2010 2:18 AM, Adam Leventhal wrote:>> Not generally possible: I guess this is technically true, thanks to trampolines, tail calls, and JMPL whose source registers have probably been clobbered. However, we should at least be able to detect vanilla CALL reliably by decoding %i7 (I''ve never heard of a compiler clobbering it). The attached scripts do this. The dtrace script reads in the instruction at %i7, decodes it and computes the target when possible, and emits the result at the head of each stack trace. The awk script (which takes the dtrace script''s output as input) then checks whether i7''s target points to the same function as the leaf''s caller and decide whether to filter it out. >> > It it not generally possible to determine the the probe fires whether or not the thread is currently executing in leaf context. All symbolic translations happens in user-land after the fact for both ustack() and uaddr(). >I''m afraid you lost me. What does symbolic translation have to do with detecting the presence of a stack frame? I could imagine it being possible to stash this info in debug sections (at least for dwarf2), but I don''t think that''s what you''re referring to here. By ''leaf'' I just meant ''the top of the user stack'' (as in the analyzer''s ''leaf is'' predicate) but maybe there''s a more precise definition of leaf I wasn''t aware of?>> Running the two scripts on a process, I got 13.5k total samples, with with 214 of those unable to read %i7 for some reason; of the valid samples, 8.2k had %i7''s target point to a different function than the leaf. >> >> I''ve checked source code for a smattering of the samples, and every time the i7-enhanced stack trace is the correct one. >> >> Maybe this won''t ever get baked into dtrace, but at least there''s a workaround now if other folks need it. >> > What we could do is have the ustack() action record %o7 as well and then figure out in user-land whether or not it''s relevant. >Actually, I tried %o7 first, and it''s pretty dodgy -- once a stack frame has been created, it can hold anything. CC seems to use it a lot for bit-shifting and as the target of JMPL. In contrast, %i7 is (nearly) always valid.>> Also, it might be good to update the wiki with this gotcha. Missing tail calls is one thing... silently missing legitimate callers who made a stack frame is pretty annoying (and makes profiling significantly less useful if you''re hunting for the caller of that expensive function). >> > Good idea. Propose some changes to the list and we''ll get it reviewed. >Two changes, I think. BTW, is this a sparc-only issue or would it also affect x86? http://wikis.sun.com/display/DTrace/Actions+and+Subroutines#ActionsandSubroutines-%7B%7Bustack%7D%7D, needs something resembling: Limitations: Because ustack() must traverse stack frames to build its stack trace, functions which do not establish a stack frame can lead to unpredictable results. In particular * Functions making tail calls will not appear because they tear down their own stack frame before making the call. * Except inside function entry probes, leaf functions which have not (yet) established a stack frame sometimes prevent their caller from appearing in the stack trace (e.g. foo -> bar -> baz will appear as foo -> baz). See <link-to-note-at-profile-provider>. http://wikis.sun.com/display/DTrace/profile+Provider needs a new section at the end (before ''Stability''): Limitations: ustack() only reports the caller of a leaf function if the latter has established a stack frame. Otherwise, the caller''s caller appears to call the leaf function (e.g. foo -> bar -> baz will be repoted as foo -> baz). This behavior occurs because dtrace has no way to determine whether the current top of stack has established a frame or not. DTrace can avoid the problem with function entry probes because they always fire before the target has established a stack frame, and with the return address is in a known location, neither of which is necessarily true in profile probe context. Thoughts? Ryan -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20100721/54b61635/attachment-0001.html>
Adam Leventhal
2010-Jul-22 01:15 UTC
[dtrace-discuss] ustack() misses caller of leaf under profile probe
>> It it not generally possible to determine the the probe fires whether or not the thread is currently executing in leaf context. All symbolic translations happens in user-land after the fact for both ustack() and uaddr(). >> >> > I''m afraid you lost me. What does symbolic translation have to do with detecting the presence of a stack frame? I could imagine it being possible to stash this info in debug sections (at least for dwarf2), but I don''t think that''s what you''re referring to here.Neither the symbol table nor stabs-like sections are available from the context in which the probe fires.> By ''leaf'' I just meant ''the top of the user stack'' (as in the analyzer''s ''leaf is'' predicate) but maybe there''s a more precise definition of leaf I wasn''t aware of?Yes, I understand what you mean.>> What we could do is have the ustack() action record %o7 as well and then figure out in user-land whether or not it''s relevant. >> > Actually, I tried %o7 first, and it''s pretty dodgy -- once a stack frame has been created, it can hold anything. CC seems to use it a lot for bit-shifting and as the target of JMPL. In contrast, %i7 is (nearly) always valid.In leaf-context, %o7 is all you have -- the %is and %ls belong to the previous frame.> Two changes, I think. BTW, is this a sparc-only issue or would it also affect x86?This would apply for x86/x64 as well as SPARC.> http://wikis.sun.com/display/DTrace/Actions+and+Subroutines#ActionsandSubroutines-%7B%7Bustack%7D%7D, needs something resembling: > > Limitations: Because ustack() must traverse stack frames to build its stack trace, functions which do not establish a stack frame can lead to unpredictable results. In particular > ? Functions making tail calls will not appear because they tear down their own stack frame before making the call. > ? Except inside function entry probes, leaf functions which have not (yet) established a stack frame sometimes prevent their caller from appearing in the stack trace (e.g. foo -> bar -> baz will appear as foo -> baz). See <link-to-note-at-profile-provider>. > > http://wikis.sun.com/display/DTrace/profile+Provider needs a new section at the end (before ''Stability''): > > Limitations: > > ustack() only reports the caller of a leaf function if the latter has established a stack frame.A leaf function is typically used to refer to one that doesn''t establish a stack frame.> Otherwise, the caller''s caller appears to call the leaf function (e.g. foo -> bar -> baz will be repoted as foo -> baz). This behavior occurs because dtrace has no way to determine whether the current top of stack has established a frame or not. DTrace can avoid the problem with function entry probes because they always fire before the target has established a stack frame, and with the return address is in a known location, neither of which is necessarily true in profile probe context.Close enough. Adam -- Adam Leventhal, Fishworks http://blogs.sun.com/ahl
Ryan Johnson
2010-Jul-22 10:09 UTC
[dtrace-discuss] ustack() misses caller of leaf under profile probe
On 7/22/2010 3:15 AM, Adam Leventhal wrote:>>> What we could do is have the ustack() action record %o7 as well and then figure out in user-land whether or not it''s relevant. >>> >>> >> Actually, I tried %o7 first, and it''s pretty dodgy -- once a stack frame has been created, it can hold anything. CC seems to use it a lot for bit-shifting and as the target of JMPL. In contrast, %i7 is (nearly) always valid. >> > In leaf-context, %o7 is all you have -- the %is and %ls belong to the previous frame. >That''s exactly why %i7 works so well compared to %o7 -- the leaf doesn''t mess with it. At all times %i7 points to a CALL (or JMPL***) somewhere higher in the call chain, but not higher than the ustack() reports as the current function''s caller. This target might be the caller of a leaf, or the first in a sequence of tail calls (which may or may not call a leaf), but either way it''s accurate to add that target to the stack trace if it''s not the current function: 1. foo -> bar --- bar owns %i7, mem[%i7] is inside foo, target_of(mem[%i7]) == bar (ustack is accurate) 2. foo -> tail1 -> ... -> tailN -> bar --- same as #1, but target_of(mem[%i7]) == tail1 != bar (insert tail1 just above leaf) 3. foo -> bar -> leaf --- same as #1, but target_of(mem[%i7]) == bar != leaf (insert bar just above leaf) 4. foo -> bar -> tail1 -> ... tailN -> leaf --- bar owns %i7 (insert bar just above leaf... no way to recover tail calls) 5. foo -> tail1 -> ... -> tailN -> bar -> leaf --- bar owns %i7, mem[%i7] is inside foo, target_of(mem[%i7]) == tail1 != leaf (insert tail1 just above leaf... no way to recover other tail calls or bar) 6. foo -> tail1 -> ... -> tailN -> bar -> tailA -> ... -> tailZ -> foo --- combination of previous two (insert tail1 just above leaf, other functions lost) In every case, if mem[%i7] is a CALL and target_of(mem[%i7]) isn''t the current function, then it is correct to insert that target function as second-from-top -- it is either a lost tail call or a missing caller we can''t see because of the leaf context. The one caveat is the inserted caller will not have an offset, but this doesn''t matter if we''re only reconstructing a control flow graph. *** If %i7 points to a CALL instruction, we can decode it and compute the target address as %i7 + (int) (4*mem[%i7]). However, we''re out of luck if it was a JMPL instruction, because we can''t assume anything about the current content of registers used in the past to compute the target address.> >> http://wikis.sun.com/display/DTrace/Actions+and+Subroutines#ActionsandSubroutines-%7B%7Bustack%7D%7D, needs something resembling: >> >> Limitations: Because ustack() must traverse stack frames to build its stack trace, functions which do not establish a stack frame can lead to unpredictable results. In particular >> ? Functions making tail calls will not appear because they tear down their own stack frame before making the call. >> ? Except inside function entry probes, leaf functions which have not (yet) established a stack frame sometimes prevent their caller from appearing in the stack trace (e.g. foo -> bar -> baz will appear as foo -> baz). See<link-to-note-at-profile-provider>. >> >> http://wikis.sun.com/display/DTrace/profile+Provider needs a new section at the end (before ''Stability''): >> >> Limitations: >> >> ustack() only reports the caller of a leaf function if the latter has established a stack frame. >> > A leaf function is typically used to refer to one that doesn''t establish a stack frame. >OK. How about this for the ustack entry: Limitations: ustack() only reports callers identified by a return address in some stack frame: * Functions making tail calls do not appear because control never returns to them * Unless ustack() is called from a pid provider :::entry or :::return probe, a leaf function''s caller will not appear because the return address does not reside in a stack frame. Entry/return probes are a special case because the return address is known even without a stack frame, but this not true in general For example, suppose a program makes the following sequence of function calls:: foo -> tail_caller1 -> bar -> tail_caller2 -> baz Calling ustack() from pid$target::baz:entry would report foo -> bar -> baz, because foo is mentioned in a stack frame and the pid provider can identify bar. However, calling ustack() from an unanchored (asynchronous) context, such as a profile or tick probe, can report foo -> baz. This always occurs if baz is a leaf function (e.g. never establishes a stack frame), or occasionally if baz does not have a stack frame yet (or any more) because the probe fired inside prologue (or epilogue) code. Note that the two functions making tail calls do not appear in the stack trace under any circumstances. ==== and this for the profile provider entry (added at the end of the first paragraph) Caveat: ustack() has some limitations when called from unanchored context (See <link-to-ustack-limitations>). ==== Incidentally, I think the ustack entry would be much easier to follow if it presented the general case first -- ustack(void) and ustack(nframes) -- and explained what it does (similar to kstack, it can also be used as a key for aggregation). Then it could explain (in one sentence) that the strsize arg exists to support java applications and forward-reference the jstack entry. All the examples about java stacks could then move there, where they belong. Thoughts? Ryan -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20100722/773d73f5/attachment.html>
Nicolas Williams
2010-Aug-23 19:07 UTC
[dtrace-discuss] ustack() misses caller of leaf under profile probe
On Wed, Jul 21, 2010 at 06:15:21PM -0700, Adam Leventhal wrote:> >> It it not generally possible to determine the the probe fires > >> whether or not the thread is currently executing in leaf context. > >> All symbolic translations happens in user-land after the fact for > >> both ustack() and uaddr(). > >> > >> > > I''m afraid you lost me. What does symbolic translation have to do > > with detecting the presence of a stack frame? I could imagine it > > being possible to stash this info in debug sections (at least for > > dwarf2), but I don''t think that''s what you''re referring to here. > > Neither the symbol table nor stabs-like sections are available from > the context in which the probe fires.Incidentally, for frame-pointer-less code this is fatal to ustack(). GCC generates debug code for traversing stacks of frame-pointer-less code. That debug code requires interpretation, and it requires the live stack. That implies that DTrace would have to have the debug sections mapped in and the interpreter code (running in dtrace context!). DTrace context can''t page fault, so debug sections would have to be pinned in memory by the kernel, and that''s not bloody likely (particularly if there is memory pressure). Nico --