dtrace discuss - Sep 2006 - Looking for guidance on UDP tracing problem

I am totally new to dtrace and more than a little overwhelmed with
attempting to digest all the information. 

I am looking into a problem with ClearCase view_server on Solaris.

Here''s the issue

  The problem we are up against is that when we look at a network trace on
  the view host- we see packets being responded to after hundreds or
  thousands of milliseconds by our view_server process.  But, when we look
  at the system call trace for the view_server,  it is responding to RPCs
  very crisply.  So there is clearly a queue forming in the incoming IP and
  UDP layers. The questions we would have are:

  1. how can we measure the size of the queue in the incoming UDP
     socket for the view_server process?

  2. more specifically, how can we measure how long an incoming RPC sits in
     that/those queues?

  We think that we should be able get at this information with dtrace
  in the new Solaris 10 TCP/IP code


Any pointers to appropriate dtrace-discuss messages, weblogs or other
guidance would be appreciated.

I have looked at

http://www.opensolaris.org/os/community/networking/docs/dtrace_networking_cookbook/

But again, I am a bit overwhelmed. 

Feel free to tell me to RTFM, just indicate which section to read :-)

-- 
Eric M. Boehm                  /"\  ASCII Ribbon Campaign
boehm at nortel.com               \ /  No HTML or RTF in mail
                                X   No proprietary word-processing
Respect Open Standards         / \  files in mail

[Ccing networking-discuss at opensolaris.org, for any insights they may have]
> Here''s the issue
> 
>   The problem we are up against is that when we look at a network trace on
>   the view host- we see packets being responded to after hundreds or
>   thousands of milliseconds by our view_server process.  But, when we look
>   at the system call trace for the view_server,  it is responding to RPCs
>   very crisply.  So there is clearly a queue forming in the incoming IP and
>   UDP layers. The questions we would have are:
> 
>   1. how can we measure the size of the queue in the incoming UDP
>      socket for the view_server process?
> 
>   2. more specifically, how can we measure how long an incoming RPC sits in
>      that/those queues?
> 
I think you want to measure latency for a specific packet. 
Currently it is not possible to do this easily with dtrace.

See http://www.opensolaris.org/jive/thread.jspa?threadID=13865&tstart=0

the closest approximation to this is to try to use fbt/sdt
of the interesting packet and "narrow" the results as much as you
can..

I would suggest putting sdt probes at ip_udp_input:entry (set self->trace
and self->timestamp for the interesting ipha_src and ipha_dst) and
follow it up the stack? I can help you with coming up with a script,
if you have difficulties with this.

--Sowmini

On Fri, Sep 22, 2006 at 12:45:25PM -0400, sowmini.varadhan at sun.com
wrote:
> I would suggest putting sdt probes at ip_udp_input:entry (set
self->trace
> and self->timestamp for the interesting ipha_src and ipha_dst) and
> follow it up the stack? I can help you with coming up with a script,
> if you have difficulties with this.
Hi Sowmini,

What does this mean exactly? Are you saying we should put an SDT probe
in ip_udp_input() or are telling Eric to enable fbt::ip_udp_input:entry?

Adam

-- 
Adam Leventhal, Solaris Kernel Development       http://blogs.sun.com/ahl

> 
> On Fri, Sep 22, 2006 at 12:45:25PM -0400, sowmini.varadhan at sun.com
wrote:
> > I would suggest putting sdt probes at ip_udp_input:entry (set
self->trace
> > and self->timestamp for the interesting ipha_src and ipha_dst) and
> > follow it up the stack? I can help you with coming up with a script,
> > if you have difficulties with this.
> 
> Hi Sowmini,
> 
> What does this mean exactly? Are you saying we should put an SDT probe
> in ip_udp_input() or are telling Eric to enable fbt::ip_udp_input:entry?
> 
> Adam
I was replying to Eric (external customer), so obviously I was telling
Eric to write a dscript with the fbt/sdt probe.

--Sowmini

Just so no one draws the wrong conclusions, I''d like to clarify a small
misunderstanding. DTrace has several different instrumentation providers
each of which instrument a different part of the system. For example,
the syscall provider instruments system calls, and the pid provider
instruments user-land processes. The sdt and fbt providers both instrument
kernel functions, but have different semantics and uses. The fbt provider
makes probes available for every function entry and return in the kernel
(well, every function that it can verify is safe to instrument). The
sdt provider (and the derived providers like proc, io, and mib) provides
probes at static points in the code; this can be done to expose higher
level semantics in a stable way. For example, the probe io:::start (the
io provider uses the sdt instrumentation methodology) lets users trace
the start of every I/O operation without needing to know the various
kernel function where we initiate I/O (e.g. bdev_strategy, aphysio, and
others).

Adam

On Fri, Sep 22, 2006 at 01:10:55PM -0400, sowmini.varadhan at Sun.COM
wrote:
> > 
> > On Fri, Sep 22, 2006 at 12:45:25PM -0400, sowmini.varadhan at sun.com
wrote:
> > > I would suggest putting sdt probes at ip_udp_input:entry (set
self->trace
> > > and self->timestamp for the interesting ipha_src and ipha_dst)
and
> > > follow it up the stack? I can help you with coming up with a
script,
> > > if you have difficulties with this.
> > 
> > Hi Sowmini,
> > 
> > What does this mean exactly? Are you saying we should put an SDT probe
> > in ip_udp_input() or are telling Eric to enable
fbt::ip_udp_input:entry?
> > 
> > Adam
> 
> I was replying to Eric (external customer), so obviously I was telling
> Eric to write a dscript with the fbt/sdt probe.
> 
> --Sowmini
> 
-- 
Adam Leventhal, Solaris Kernel Development       http://blogs.sun.com/ahl

> Just so no one draws the wrong conclusions, I''d like to clarify a
small
> misunderstanding. DTrace has several different instrumentation providers
> each of which instrument a different part of the system. For example,
> the syscall provider instruments system calls, and the pid provider
> instruments user-land processes. The sdt and fbt providers both instrument
> kernel functions, but have different semantics and uses. The fbt provider
> makes probes available for every function entry and return in the kernel
> (well, every function that it can verify is safe to instrument). The
> sdt provider (and the derived providers like proc, io, and mib) provides
> probes at static points in the code; this can be done to expose higher
> level semantics in a stable way. For example, the probe io:::start (the
Yes, and to clarify my own response, I was suggesting that Eric start by
putting probes of the form  (the address 10.4.5.6 is used as the address
of interest in the example) 

ip_udp_input:entry
/ ((ipha_t *)arg2)->ipha_src == 0xa040506 /
{
	self->trace = 1;
        self->in = timestamp;
}
ip_udp_input:return
{
        self->trace = 0;
        printf("time spent in ip_udp_input %d ns", timestamp -
self->in)
}

I''d be interested in hearing if there are more elegant ways to approach
this (e.g., is er_kernel or the CallStackAnalyzer more appropriate here?)

As far as I know, solving this problem is an iterative process,
where one has to successively narrow down the focus, looking at both
fbt results and the stack, and using any sdt probes available along the
way. In the above example, it might be necessary to turn on more fbt if
one wishes to narrow the focus to functions called within fbt.

--Sowmini