Hi,
I am using dtrace to trace function calls made by an application.
I have found that for some functions, the return probe is never
hit. Specifically, this happens with functions that use
an optimization that causes the stack frame and register window
to be recycled. Here is an example function from libc.so.1:
libc.so.1`_read::dis
libc.so.1`_read: st %o0, [%sp + 0x44]
libc.so.1`_read+4: mov 3, %g1
libc.so.1`_read+8: ta %icc, %g0 + 8
libc.so.1`_read+0xc: bcc,pt %icc, +0x14
<libc.so.1`_read+0x20>
libc.so.1`_read+0x10: cmp %o0, 0x5b
libc.so.1`_read+0x14: be,a,pn %icc, -0x10
<libc.so.1`_read+4>
libc.so.1`_read+0x18: ld [%sp + 0x44], %o0
libc.so.1`_read+0x1c: ba,a -0x9cc4c
<libc.so.1`_cerror>
libc.so.1`_read+0x20: retl
libc.so.1`_read+0x24: nop
When using dtrace, the entry probe changes the first instruction (no
problems with that). The return probe changes the retl instruction.
This probe never triggers. Here is a simple dtrace script to show this:
/* _read.d */
pid$$1:libc.so.1:_read:entry
{
}
pid$$1:libc.so.1:_read:return
{
}
When you run this on some app that does read(2) system calls, you''ll
see _read:entry traces, but never _read:return.
I have encountered a similar problem on some fbt kernel probes where
the return probe fires before other function entry probes fire
that the original probe calls. Assembler looks like:
foo:
...
call bar
retl
dtrace will show foo being entered AND returning before showing bar
being called, as is documented in the dtrace guide
for tail-call optimization. (In a sense, dtrace is showing exactly what
is happening, but it makes for difficult reading of the output).
I can handle seeing functions return before a function that was called
is entered, but not seeing the return at all can cause flowindent to indent
thousands of spaces if tracing something large. Can anything be done
about this? I don''t really need to trace _read calls, but I am tracing
all functions called by a function in the app, and this function calls
read(2) frequently. The read routine in libc.so.1 calls _read().
thanks,
max
G''Day Max, On Thu, 9 Jun 2005, Max Bruning wrote:> Hi, > I am using dtrace to trace function calls made by an application. > I have found that for some functions, the return probe is never > hit.[...]> I can handle seeing functions return before a function that was called > is entered, but not seeing the return at all can cause flowindent to indent > thousands of spaces if tracing something large. Can anything be doneI''ve encountered a similar problem. I wanted to code my own stackdepth variable to measure elapsed time between function calls (and take into account recursive functions), as well as to code my own flowindent. (There was some reason (can''t remember offhand) why I didn''t use DTrace''s own "stackdepth"). My stackdepth variable didn''t work as expected. Functions that don''t have a return screw it up. Here I mean the return probe doesn''t exist at all - not just skipping it. Eg, # dtrace -l -n ''pid$target:libc:malloc:???*'' -c ''/usr/bin/date'' ID PROVIDER MODULE FUNCTION NAME 37197 pid3639 libc.so.1 malloc return 37198 pid3639 libc.so.1 malloc entry Looks good. # dtrace -l -n ''pid$target:libc:sysconf:'' -c ''/usr/bin/date'' ID PROVIDER MODULE FUNCTION NAME 37197 pid3643 libc.so.1 sysconf entry Missing a return! ... How I got around this problem in tools like dapptrace is with the following, /* set function depth */ this->fdepth = ++fdepth[probefunc]; so I''m not maintaining a stack-depth, more of a probefunc-depth. So for probes that don''t return, it doesn''t interfere with the ''private'' depth for probes that do. This solves recursive funcitons too. Although I hate to use an associative array so heavily (it''s eating up to 5 us per function call on my 867 MHz dekstop). As for flowindent depth - that needs to be a global depth. It can''t be relative to the function so the above can''t be used. So... how I solved the "gathering entropy" of my flowindent stackdepth goes like this, /* reset indent depth */ profile:::tick-1sec { /* * some probes generated by the pid provider have entries * but not returns. this is a klude to fix that problem. this * also explains fdepth[probefunc] rather than a single depth. */ depth = 0; } /me ducks ok, it''s a kludge. I even said it was a kludge. buuuuttt.. I didn''t think of it all by myself! I eyeballed tons of dtrace -F outputs to determine how the D-Team solved this flowindent problem. Funnily enough, every second or so the flowindent seemed to ''reset''. hmm. smells like a kludge to me. but it''ll do for now :) I haven''t found it in the source, so I could be completely wrong about that. ... hope I mentioned something useful in all of that! I do agree with your suggestion - having some way to make the return probe fire would be useful. Or just a fast funcdepth variable that I could use that worked with the pid provider would be nice... cheers, Brendan
Adam Leventhal
2005-Jun-10 07:09 UTC
[dtrace-discuss] sparc frame recycling dtrace problem
Hi Max, Sorry about that. This bug has already been fixed in the latest build of Solaris and will be available through a patch for Solaris 10 in the near term. In case you''re interested, this is the bug in question: 6230315 pid123::ioctl:return finds the wrong instruction This was fixed in snv_10 so I don''t think you should be seeing this on the latest OpenSolaris and Solaris Express builds. Please let me know if you are. Adam On Thu, Jun 09, 2005 at 04:31:56PM -0700, Max Bruning wrote:> > Hi, > I am using dtrace to trace function calls made by an application. > I have found that for some functions, the return probe is never > hit. Specifically, this happens with functions that use > an optimization that causes the stack frame and register window > to be recycled. Here is an example function from libc.so.1: > > libc.so.1`_read::dis > libc.so.1`_read: st %o0, [%sp + 0x44] > libc.so.1`_read+4: mov 3, %g1 > libc.so.1`_read+8: ta %icc, %g0 + 8 > libc.so.1`_read+0xc: bcc,pt %icc, +0x14 > <libc.so.1`_read+0x20> > libc.so.1`_read+0x10: cmp %o0, 0x5b > libc.so.1`_read+0x14: be,a,pn %icc, -0x10 <libc.so.1`_read+4> > libc.so.1`_read+0x18: ld [%sp + 0x44], %o0 > libc.so.1`_read+0x1c: ba,a -0x9cc4c <libc.so.1`_cerror> > libc.so.1`_read+0x20: retl > libc.so.1`_read+0x24: nop > > When using dtrace, the entry probe changes the first instruction (no > problems with that). The return probe changes the retl instruction. > This probe never triggers. Here is a simple dtrace script to show this: > > /* _read.d */ > pid$$1:libc.so.1:_read:entry > { > } > > pid$$1:libc.so.1:_read:return > { > } > > > When you run this on some app that does read(2) system calls, you''ll > see _read:entry traces, but never _read:return. > > I have encountered a similar problem on some fbt kernel probes where > the return probe fires before other function entry probes fire > that the original probe calls. Assembler looks like: > > foo: > ... > call bar > retl > > dtrace will show foo being entered AND returning before showing bar > being called, as is documented in the dtrace guide > for tail-call optimization. (In a sense, dtrace is showing exactly what > is happening, but it makes for difficult reading of the output). > > I can handle seeing functions return before a function that was called > is entered, but not seeing the return at all can cause flowindent to indent > thousands of spaces if tracing something large. Can anything be done > about this? I don''t really need to trace _read calls, but I am tracing > all functions called by a function in the app, and this function calls > read(2) frequently. The read routine in libc.so.1 calls _read(). > > thanks, > max > > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org-- Adam Leventhal, Solaris Kernel Development http://blogs.sun.com/ahl
Adam Leventhal
2005-Jun-10 07:13 UTC
[dtrace-discuss] sparc frame recycling dtrace problem
Hi Brendan, This is a different problem, but similar in appearance. The first problem that Max hit was on SPARC and this (I''m pretty sure) is on x86. The problem here is that the sysconf function has a jump table and there was a bug with our heuristic for handling returns from functions with jump tables. 6228044 the pid provider can miss some function returns This was also fixed in snv_10 and will be fixed in a forthcoming patch for Solaris 10. Sorry for the inconvenience. Adam On Fri, Jun 10, 2005 at 05:07:36PM +1000, Brendan Gregg wrote:> G''Day Max, > > On Thu, 9 Jun 2005, Max Bruning wrote: > > > Hi, > > I am using dtrace to trace function calls made by an application. > > I have found that for some functions, the return probe is never > > hit. > [...] > > I can handle seeing functions return before a function that was called > > is entered, but not seeing the return at all can cause flowindent to indent > > thousands of spaces if tracing something large. Can anything be done > > I''ve encountered a similar problem. I wanted to code my own stackdepth > variable to measure elapsed time between function calls (and take into > account recursive functions), as well as to code my own flowindent. (There > was some reason (can''t remember offhand) why I didn''t use DTrace''s own > "stackdepth"). > > My stackdepth variable didn''t work as expected. Functions that don''t have a > return screw it up. Here I mean the return probe doesn''t exist at all - > not just skipping it. Eg, > > # dtrace -l -n ''pid$target:libc:malloc:???*'' -c ''/usr/bin/date'' > ID PROVIDER MODULE FUNCTION NAME > 37197 pid3639 libc.so.1 malloc return > 37198 pid3639 libc.so.1 malloc entry > > Looks good. > > # dtrace -l -n ''pid$target:libc:sysconf:'' -c ''/usr/bin/date'' > ID PROVIDER MODULE FUNCTION NAME > 37197 pid3643 libc.so.1 sysconf entry > > Missing a return! > > ... > > How I got around this problem in tools like dapptrace is with the > following, > > /* set function depth */ > this->fdepth = ++fdepth[probefunc]; > > so I''m not maintaining a stack-depth, more of a probefunc-depth. So for > probes that don''t return, it doesn''t interfere with the ''private'' depth > for probes that do. This solves recursive funcitons too. > > Although I hate to use an associative array so heavily (it''s eating > up to 5 us per function call on my 867 MHz dekstop). > > As for flowindent depth - that needs to be a global depth. It can''t be > relative to the function so the above can''t be used. So... how I solved > the "gathering entropy" of my flowindent stackdepth goes like this, > > /* reset indent depth */ > profile:::tick-1sec > { > /* > * some probes generated by the pid provider have entries > * but not returns. this is a klude to fix that problem. this > * also explains fdepth[probefunc] rather than a single depth. > */ > depth = 0; > } > > /me ducks > > ok, it''s a kludge. I even said it was a kludge. > > buuuuttt.. > > I didn''t think of it all by myself! > > I eyeballed tons of dtrace -F outputs to determine how the D-Team solved > this flowindent problem. Funnily enough, every second or so the flowindent > seemed to ''reset''. hmm. smells like a kludge to me. but it''ll do for now :) > > I haven''t found it in the source, so I could be completely wrong about > that. > > ... > > hope I mentioned something useful in all of that! > > I do agree with your suggestion - having some way to make the return probe > fire would be useful. Or just a fast funcdepth variable that I could use > that worked with the pid provider would be nice... > > cheers, > > Brendan > > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org-- Adam Leventhal, Solaris Kernel Development http://blogs.sun.com/ahl
Jonathan Haslam
2005-Jun-10 08:14 UTC
[dtrace-discuss] sparc frame recycling dtrace problem
Hi Brendan,> I do agree with your suggestion - having some way to make the return probe > fire would be useful. Or just a fast funcdepth variable that I could use > that worked with the pid provider would be nice...There is an open RFE for this last one which I''ll add you to: 4970475: There should be a stackdepth equivalent for userland Cheers. Jon.
G''Day Adam, On Fri, 10 Jun 2005, Adam Leventhal wrote:> Hi Brendan, > > This is a different problem, but similar in appearance. The first problem > that Max hit was on SPARC and this (I''m pretty sure) is on x86. The problem > here is that the sysconf function has a jump table and there was a bug > with our heuristic for handling returns from functions with jump tables. > > 6228044 the pid provider can miss some function returnsYes - this is x86. Cool, so I haven''t missed something silly - it really is a little bug.> This was also fixed in snv_10 and will be fixed in a forthcoming patch for > Solaris 10. Sorry for the inconvenience.Great! I wouldn''t say inconvenient - the bugs in DTrace are really minor so far, other "first release" products can be a real pain to get working. DTrace is very pleasent. That reminds me - unless people think this is a crazy idea, I''m going to write DTraceToolkit tools to work on an unpatched Solaris 10 3/05 build as much as possible - to aim at the lowest common denominator. - this isn''t to say that patches are unappreciated, they are! This is purely to aim at the lowest common denominator build, if possible. Thanks Adam! (12:13am? :) Brendan> Adam > > On Fri, Jun 10, 2005 at 05:07:36PM +1000, Brendan Gregg wrote: > > G''Day Max,[...]> > My stackdepth variable didn''t work as expected. Functions that don''t have a > > return screw it up. Here I mean the return probe doesn''t exist at all - > > not just skipping it. Eg, > > > > # dtrace -l -n ''pid$target:libc:malloc:???*'' -c ''/usr/bin/date'' > > ID PROVIDER MODULE FUNCTION NAME > > 37197 pid3639 libc.so.1 malloc return > > 37198 pid3639 libc.so.1 malloc entry > > > > Looks good. > > > > # dtrace -l -n ''pid$target:libc:sysconf:'' -c ''/usr/bin/date'' > > ID PROVIDER MODULE FUNCTION NAME > > 37197 pid3643 libc.so.1 sysconf entry > > > > Missing a return![...]
G''Day Jon, On Fri, 10 Jun 2005, Jonathan Haslam wrote:> Hi Brendan, > > > I do agree with your suggestion - having some way to make the return probe > > fire would be useful. Or just a fast funcdepth variable that I could use > > that worked with the pid provider would be nice... > > There is an open RFE for this last one which I''ll add you to: > > 4970475: There should be a stackdepth equivalent for userlandOh cool! thanks. :) ... If there ever becomes a way to make these RFE and BugTraq lists for DTrace public, or slightly public, I''d be quite interested. :) Brendan
Brendan Gregg <brendan.gregg at tpg.com.au> writes:> If there ever becomes a way to make these RFE and BugTraq lists for DTrace > public, or slightly public, I''d be quite interested. :)They are, sort of: someone hinted at http://bugs.opensolaris.org/ where you can find the two Adam mentioned. Rainer
G''Day Rainer, On 10 Jun 2005, Rainer Orth wrote:> Brendan Gregg <brendan.gregg at tpg.com.au> writes: > > > If there ever becomes a way to make these RFE and BugTraq lists for DTrace > > public, or slightly public, I''d be quite interested. :) > > They are, sort of: someone hinted at > > http://bugs.opensolaris.org/Great - I hadn''t seen this link before. Most of the bugs listed have good descriptions too. :) Brendan
Adam Leventhal
2005-Jun-10 15:04 UTC
[dtrace-discuss] sparc frame recycling dtrace problem
On Fri, Jun 10, 2005 at 08:19:07PM +1000, Brendan Gregg wrote:> Thanks Adam! (12:13am? :)We -- the DTrace team -- have split up the work day so that one of us is always online to answer questions. Of course, the interest-list-graveyard- shift is a strain on all of us. Adam -- Adam Leventhal, Solaris Kernel Development http://blogs.sun.com/ahl
Thanks Adam and Brendan! Adam, does the "graveyard shift" rotate between the different members of the dtrace team? Maybe you could get Joerg S. or Alan DuBoff since they seem to be on at all hours anyway... max> On Fri, Jun 10, 2005 at 08:19:07PM +1000, Brendan Gregg wrote: >> Thanks Adam! (12:13am? :) > > We -- the DTrace team -- have split up the work day so that one of us is > always online to answer questions. Of course, the interest-list-graveyard- > shift is a strain on all of us. > > Adam > > -- > Adam Leventhal, Solaris Kernel Development http://blogs.sun.com/ahl > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org >