I am looking at some malloc issues and am confused by what dtrace is
telling me. In a particular core that I captured, I can see the
following code path to get me into t_splay:
----------------- lwp# 12 / thread# 12 --------------------
ffffffff7f25f628 t_splay (101a9b6a0, 41, 18, 40, 0, 101a9b6c0) + c8
ffffffff7f25f3d4 t_delete (101a9b6a0, 0, 184c80, ffffffff7f25f8e8,
ffffffff7f3e4000, 0) + 60
ffffffff7f25e9e0 _malloc_unlocked (a0, 20, 101a9b6a0, 0,
ffffffff7f3eef40, 0) + 1a8
ffffffff7f25e818 malloc (98, 21d8, 185838, ffffffff7f2c364c,
ffffffff7f3e4000, 2000) + 5c
. . .
It seems as though the only way to get to t_splay is through
_malloc_unlocked() [1] or t_delete() [2].
1.http://cvs.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/lib/libc/port/gen/malloc.c#259
2.http://cvs.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/lib/libc/port/gen/malloc.c#767
What confuses me is:
CPU ID FUNCTION:NAME
66 66733 :tick-30sec
libc.so.1`t_splay
libc.so.1`malloc+0x5c
crsd.bin`__1cKRunContextJrunScript6M_v_+0x3c
crsd.bin`__1cJrunScript6FrknDstdMbasic_string4Ccn0ALchar_traits4Cc__n0
AJallocator4Cc____rk1ipkc_i_+0x218
crsd.bin`__1cOcaaApplicationNCheckResource6Fpkcpi_i_+0x328
crsd.bin`__1cMRTI_ResourceNCheckResource6M_i_+0x5c
crsd.bin`__1cHrunPoll6Fpv_0_+0x1b8
crsd.bin`__1cGPollerDrun6M_v_+0xc
crsd.bin`__1cNCAATimerEventPrunDetachedStub6Fpv_v_+0x20
crsd.bin`__1cNCLS_ThreadingNCLSthreadMainIcppStart6Fpv_v_+0x54
libc.so.1`_lwp_start
1
libc.so.1`t_splay
libc.so.1`malloc+0x5c
libhasgen10.so`crs_qstat_allocresarr+0x54
libhasgen10.so`crs_qstat_get_options+0x88
libhasgen10.so`crs_qstat_ocr+0x94
crsd.bin`crs_qstat_process+0x2bc
libc.so.1`_lwp_start
1
libc.so.1`t_splay
libc.so.1`malloc+0x5c
libc.so.1`calloc+0x44
libocr10.so`lmmstvrt+0x8c
libocr10.so`lmmstlrg+0x70
libocr10.so`lmmstmalloc+0x134
libocr10.so`lmmmalloc+0x90
libocr10.so`lmmstvrt+0xe8
libocr10.so`lmmstlrg+0x70
libocr10.so`lmmstmalloc+0x134
libocr10.so`lmmstcalloc+0x34
libocrutl10.so`lmmcalloc+0x164
libocrutl10.so`prou_allocm+0xd8
libocr10.so`proath_procctx_init+0x88
libocr10.so`proath_select_wait_for_request+0x2ec
libc.so.1`_lwp_start
1
libc.so.1`t_splay
libc.so.1`_malloc_unlocked+0x1a8
libc.so.1`malloc+0x5c
0x239
1
libc.so.1`t_splay
libc.so.1`_malloc_unlocked+0x1a8
libc.so.1`malloc+0x5c
libCrun.so.1`__1c2n6FL_pv_+0x28
crsd.bin`__1cDstdJallocator4CpnKPermission__Iallocate6MLpv_4_+0x44
(lotsa lines deleted)
The script is...
#! /usr/sbin/dtrace -s
pid$target:libc.so:t_splay:
{
@splayers[ustack()] = count();
}
tick-30sec
{
printa(@splayers);
exit(0);
}
Why would some of the stacks show:
libc.so.1`t_splay
libc.so.1`_malloc_unlocked+0x1a8
libc.so.1`malloc+0x5c
While others show:
libc.so.1`t_splay
libc.so.1`malloc+0x5c
mdb says that malloc+0x5c should be malloc_unlocked:
> libc.so.1`malloc+0x5c::dis -n 1
libc.so.1`malloc+0x58: ldx [%i4 + %l4], %o0
libc.so.1`malloc+0x5c: call +0x20
<libc.so.1`_malloc_unlocked>
libc.so.1`malloc+0x60: mov %i0, %o0
What am I missing? FWIW, I am running S10U2, 118833-23.
Mike
Mike,
you''re probably running on sparc HW, and probably running
code that has been "tail-call" optimized, in which case if
the last thing a function does before exiting is to call another
function, then the optimization lets the called function use
the callers register window and stack frame space - hence the
stack backtrace no longer contains the true caller... This has
an overall longterm benefit of less window spill-fill traps which
is good for performance.
the optimization can be performed differently in different code
paths through a function, so if in some code paths malloc_unlocked
calls t_splay as its very last operation, that call gets tail-call
optimized (the stack backtrace will not show malloc_unlocked), and
if on other paths through malloc_unlocked there is additional code
to execute after t_splay returns then tail-call-opt cann''t be
applied on that path (the stack backtrace will show malloc_unlocked).
if you''re not running on sparc then disregard this email!
-Pete Lawrence.
Gerdts wrote On 02/28/07 04:45 PM,:
>I am looking at some malloc issues and am confused by what dtrace is
>telling me. In a particular core that I captured, I can see the
>following code path to get me into t_splay:
>
>----------------- lwp# 12 / thread# 12 --------------------
> ffffffff7f25f628 t_splay (101a9b6a0, 41, 18, 40, 0, 101a9b6c0) + c8
> ffffffff7f25f3d4 t_delete (101a9b6a0, 0, 184c80, ffffffff7f25f8e8,
>ffffffff7f3e4000, 0) + 60
> ffffffff7f25e9e0 _malloc_unlocked (a0, 20, 101a9b6a0, 0,
>ffffffff7f3eef40, 0) + 1a8
> ffffffff7f25e818 malloc (98, 21d8, 185838, ffffffff7f2c364c,
>ffffffff7f3e4000, 2000) + 5c
>. . .
>
>It seems as though the only way to get to t_splay is through
>_malloc_unlocked() [1] or t_delete() [2].
>
>1.http://cvs.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/lib/libc/port/gen/malloc.c#259
>2.http://cvs.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/lib/libc/port/gen/malloc.c#767
>
>What confuses me is:
>
>CPU ID FUNCTION:NAME
> 66 66733 :tick-30sec
>
> libc.so.1`t_splay
> libc.so.1`malloc+0x5c
> crsd.bin`__1cKRunContextJrunScript6M_v_+0x3c
>
crsd.bin`__1cJrunScript6FrknDstdMbasic_string4Ccn0ALchar_traits4Cc__n0
>AJallocator4Cc____rk1ipkc_i_+0x218
> crsd.bin`__1cOcaaApplicationNCheckResource6Fpkcpi_i_+0x328
> crsd.bin`__1cMRTI_ResourceNCheckResource6M_i_+0x5c
> crsd.bin`__1cHrunPoll6Fpv_0_+0x1b8
> crsd.bin`__1cGPollerDrun6M_v_+0xc
> crsd.bin`__1cNCAATimerEventPrunDetachedStub6Fpv_v_+0x20
> crsd.bin`__1cNCLS_ThreadingNCLSthreadMainIcppStart6Fpv_v_+0x54
> libc.so.1`_lwp_start
> 1
>
> libc.so.1`t_splay
> libc.so.1`malloc+0x5c
> libhasgen10.so`crs_qstat_allocresarr+0x54
> libhasgen10.so`crs_qstat_get_options+0x88
> libhasgen10.so`crs_qstat_ocr+0x94
> crsd.bin`crs_qstat_process+0x2bc
> libc.so.1`_lwp_start
> 1
>
> libc.so.1`t_splay
> libc.so.1`malloc+0x5c
> libc.so.1`calloc+0x44
> libocr10.so`lmmstvrt+0x8c
> libocr10.so`lmmstlrg+0x70
> libocr10.so`lmmstmalloc+0x134
> libocr10.so`lmmmalloc+0x90
> libocr10.so`lmmstvrt+0xe8
> libocr10.so`lmmstlrg+0x70
> libocr10.so`lmmstmalloc+0x134
> libocr10.so`lmmstcalloc+0x34
> libocrutl10.so`lmmcalloc+0x164
> libocrutl10.so`prou_allocm+0xd8
> libocr10.so`proath_procctx_init+0x88
> libocr10.so`proath_select_wait_for_request+0x2ec
> libc.so.1`_lwp_start
> 1
>
> libc.so.1`t_splay
> libc.so.1`_malloc_unlocked+0x1a8
> libc.so.1`malloc+0x5c
> 0x239
> 1
>
> libc.so.1`t_splay
> libc.so.1`_malloc_unlocked+0x1a8
> libc.so.1`malloc+0x5c
> libCrun.so.1`__1c2n6FL_pv_+0x28
>
crsd.bin`__1cDstdJallocator4CpnKPermission__Iallocate6MLpv_4_+0x44
>
>(lotsa lines deleted)
>
>The script is...
>
>#! /usr/sbin/dtrace -s
>
>pid$target:libc.so:t_splay:
>{
> @splayers[ustack()] = count();
>}
>
>tick-30sec
>{
> printa(@splayers);
> exit(0);
>}
>
>Why would some of the stacks show:
>
> libc.so.1`t_splay
> libc.so.1`_malloc_unlocked+0x1a8
> libc.so.1`malloc+0x5c
>
>While others show:
>
> libc.so.1`t_splay
> libc.so.1`malloc+0x5c
>
>mdb says that malloc+0x5c should be malloc_unlocked:
>
>
>
>>libc.so.1`malloc+0x5c::dis -n 1
>>
>>
>libc.so.1`malloc+0x58: ldx [%i4 + %l4], %o0
>libc.so.1`malloc+0x5c: call +0x20
><libc.so.1`_malloc_unlocked>
>libc.so.1`malloc+0x60: mov %i0, %o0
>
>
>What am I missing? FWIW, I am running S10U2, 118833-23.
>
>Mike
>_______________________________________________
>dtrace-discuss mailing list
>dtrace-discuss at opensolaris.org
>
>
On 2/28/07, Peter Lawrence <Peter.Lawrence at sun.com> wrote:> Mike, > you''re probably running on sparc HW, and probably running > code that has been "tail-call" optimized, in which case if > the last thing a function does before exiting is to call another > function, then the optimization lets the called function use > the callers register window and stack frame space - hence the > stack backtrace no longer contains the true caller... This has > an overall longterm benefit of less window spill-fill traps which > is good for performance.Yep, running on sparc. While the code I''m looking at has no terribly obvious code paths that do what you suggest, I can see at least one case where optimization could pick this up. Thanks! Mike
It might be a case of dtrace ustack() being tricked by it''s own instrumentation. The script below instruments all instructions of t_splay. t_splay is a ''leaf function'' which means that register %o7 should be included in the ucallstack (points to _malloc_unlocked). But if the heuristic wrongly decides that t_splay is a non-leaf, then it discard %o7 from the stack (_malloc_unlocked is skipped). The disassembly of t_splay on my system seems to indicate that it is a leaf function which falls in the covered dtrace heuristic. However once t_splay is instrumented by the d-script something seems to break.>pid$target:libc.so:t_splay: >{ > @splayers[ustack()] = count(); >} >See dtrace_getpcstack(): http://cvs.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/sparc/dtrace/dtrace_isa.c You might have better luck by having less instrumentation in t_splay: pid$target:libc.so:t_splay:entry { @splayers[ustack()] = count(); } -r
> What am I missing? FWIW, I am running S10U2, 118833-23.Hey Mike, As Roch mentioned, you probably want to be using the entry probe for t_splay rather than _every_ probe, but the problem you''re seeing is this known bug: 6517308 ustack() results may vary with pid provider entry probes The first call to ustack() will produce slightly different results than the second call namely that the first call will include the correct calling frame whereas the second will skip it. But, you may observe, you''re apparently only invoking ustack() once per probe! Since you''ve enabled _all_ probes, this includes both the entry probe and offset 0 probe which correspond to the same logical tracepoint. While there''s nothing wrong with your script per se, using just the entry probe should resolve your problem. If it doesn''t let me know -- this may be another bug. Adam On Wed, Feb 28, 2007 at 06:45:53PM -0600, Mike Gerdts wrote:> I am looking at some malloc issues and am confused by what dtrace is > telling me. In a particular core that I captured, I can see the > following code path to get me into t_splay: > > ----------------- lwp# 12 / thread# 12 -------------------- > ffffffff7f25f628 t_splay (101a9b6a0, 41, 18, 40, 0, 101a9b6c0) + c8 > ffffffff7f25f3d4 t_delete (101a9b6a0, 0, 184c80, ffffffff7f25f8e8, > ffffffff7f3e4000, 0) + 60 > ffffffff7f25e9e0 _malloc_unlocked (a0, 20, 101a9b6a0, 0, > ffffffff7f3eef40, 0) + 1a8 > ffffffff7f25e818 malloc (98, 21d8, 185838, ffffffff7f2c364c, > ffffffff7f3e4000, 2000) + 5c > . . . > > It seems as though the only way to get to t_splay is through > _malloc_unlocked() [1] or t_delete() [2]. > > 1.http://cvs.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/lib/libc/port/gen/malloc.c#259 > 2.http://cvs.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/lib/libc/port/gen/malloc.c#767 > > What confuses me is: > > CPU ID FUNCTION:NAME > 66 66733 :tick-30sec > > libc.so.1`t_splay > libc.so.1`malloc+0x5c > crsd.bin`__1cKRunContextJrunScript6M_v_+0x3c > crsd.bin`__1cJrunScript6FrknDstdMbasic_string4Ccn0ALchar_traits4Cc__n0 > AJallocator4Cc____rk1ipkc_i_+0x218 > crsd.bin`__1cOcaaApplicationNCheckResource6Fpkcpi_i_+0x328 > crsd.bin`__1cMRTI_ResourceNCheckResource6M_i_+0x5c > crsd.bin`__1cHrunPoll6Fpv_0_+0x1b8 > crsd.bin`__1cGPollerDrun6M_v_+0xc > crsd.bin`__1cNCAATimerEventPrunDetachedStub6Fpv_v_+0x20 > crsd.bin`__1cNCLS_ThreadingNCLSthreadMainIcppStart6Fpv_v_+0x54 > libc.so.1`_lwp_start > 1 > > libc.so.1`t_splay > libc.so.1`malloc+0x5c > libhasgen10.so`crs_qstat_allocresarr+0x54 > libhasgen10.so`crs_qstat_get_options+0x88 > libhasgen10.so`crs_qstat_ocr+0x94 > crsd.bin`crs_qstat_process+0x2bc > libc.so.1`_lwp_start > 1 > > libc.so.1`t_splay > libc.so.1`malloc+0x5c > libc.so.1`calloc+0x44 > libocr10.so`lmmstvrt+0x8c > libocr10.so`lmmstlrg+0x70 > libocr10.so`lmmstmalloc+0x134 > libocr10.so`lmmmalloc+0x90 > libocr10.so`lmmstvrt+0xe8 > libocr10.so`lmmstlrg+0x70 > libocr10.so`lmmstmalloc+0x134 > libocr10.so`lmmstcalloc+0x34 > libocrutl10.so`lmmcalloc+0x164 > libocrutl10.so`prou_allocm+0xd8 > libocr10.so`proath_procctx_init+0x88 > libocr10.so`proath_select_wait_for_request+0x2ec > libc.so.1`_lwp_start > 1 > > libc.so.1`t_splay > libc.so.1`_malloc_unlocked+0x1a8 > libc.so.1`malloc+0x5c > 0x239 > 1 > > libc.so.1`t_splay > libc.so.1`_malloc_unlocked+0x1a8 > libc.so.1`malloc+0x5c > libCrun.so.1`__1c2n6FL_pv_+0x28 > crsd.bin`__1cDstdJallocator4CpnKPermission__Iallocate6MLpv_4_+0x44 > > (lotsa lines deleted) > > The script is... > > #! /usr/sbin/dtrace -s > > pid$target:libc.so:t_splay: > { > @splayers[ustack()] = count(); > } > > tick-30sec > { > printa(@splayers); > exit(0); > } > > Why would some of the stacks show: > > libc.so.1`t_splay > libc.so.1`_malloc_unlocked+0x1a8 > libc.so.1`malloc+0x5c > > While others show: > > libc.so.1`t_splay > libc.so.1`malloc+0x5c > > mdb says that malloc+0x5c should be malloc_unlocked: > > >libc.so.1`malloc+0x5c::dis -n 1 > libc.so.1`malloc+0x58: ldx [%i4 + %l4], %o0 > libc.so.1`malloc+0x5c: call +0x20 > <libc.so.1`_malloc_unlocked> > libc.so.1`malloc+0x60: mov %i0, %o0 > > > What am I missing? FWIW, I am running S10U2, 118833-23. > > Mike > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org-- Adam Leventhal, Solaris Kernel Development http://blogs.sun.com/ahl
On Thu, Mar 01, 2007 at 05:46:21PM -0800, Adam Leventhal wrote:> As Roch mentioned, you probably want to be using the entry probe for t_splay > rather than _every_ probe, but the problem you''re seeing is this known bug: > > 6517308 ustack() results may vary with pid provider entry probesI neglected to mention that this bug only exists in S10 -- it has been fixed in Solaris Nevada and OpenSolaris. Adam -- Adam Leventhal, Solaris Kernel Development http://blogs.sun.com/ahl
On 3/1/07, Adam Leventhal <ahl at eng.sun.com> wrote:> While there''s nothing wrong with your script per se, using just the entry > probe should resolve your problem. If it doesn''t let me know -- this may be > another bug.I started with: dtrace -n pid\$target:libc.so:t_splay:''{}'' -p <pid> Which was recommended by two different kernel engineers... That takes 20 seconds to generate 100,000 lines of output. The script I posted here was my first attempt at summarizing the data a bit. Perhaps there is a commonly used support document that could be updated a bit. I still need to dig into the source referenced by Roch to understand what all of the targets other than entry and return are. Haven''t seen that before. Mike -- Mike Gerdts http://mgerdts.blogspot.com/
On Thu, Mar 01, 2007 at 08:33:48PM -0600, Mike Gerdts wrote:> On 3/1/07, Adam Leventhal <ahl at eng.sun.com> wrote: > >While there''s nothing wrong with your script per se, using just the entry > >probe should resolve your problem. If it doesn''t let me know -- this may be > >another bug. > > I started with: > > dtrace -n pid\$target:libc.so:t_splay:''{}'' -p <pid> > > Which was recommended by two different kernel engineers...You''re right to keep them safely anonymous ;-)> Perhaps > there is a commonly used support document that could be updated a bit.The DTrace manual seems pretty clear on this sort of use of the pid provider in the chapter on User Land Tracing.> I still need to dig into the source referenced by Roch to understand > what all of the targets other than entry and return are. Haven''t seen > that before.Take a look at the chapter in the Solaris Dynamic Tracing Guide on the pid provider. Adam -- Adam Leventhal, Solaris Kernel Development http://blogs.sun.com/ahl
Mike Gerdts wrote:> On 3/1/07, Adam Leventhal <ahl at eng.sun.com> wrote: >> While there''s nothing wrong with your script per se, using just the entry >> probe should resolve your problem. If it doesn''t let me know -- this >> may be >> another bug. > > I started with: > > dtrace -n pid\$target:libc.so:t_splay:''{}'' -p <pid> > > Which was recommended by two different kernel engineers...it wasn''t me, but: this is an appropriate sort of line for kernel dtrace, since the only defined probes are likely to be entry and return. For the pid provider, it''s....different. :) (that is, I can imagine how the kernel engineers missed that point.)