Re: stptracer-20060828 has released.

[Li Guanglei <guanglei at cn dot ibm dot com>]

Frank Ch. Eigler wrote:
> Hi -
>
> On Fri, Sep 01, 2006 at 11:47:05AM +0800, Li Guanglei wrote:
>
> > [...]  But I have some questions about compiled approach. stap will
> > treat all integer data as 64-bit, but most binary trace integer data
> > items need only 1 or 2 bytes. [...] And will it use a fix length for
> > all string items? Some string trace data items only have a few
> > chars.
>
> The translator could apply obvious policies to this question.  If the
> formatting string includes "%1b", it would write just the low-order
> byte of the integer.  If the formatting string includes "%64s", this
> would result in a fixed-width substring field.  For plain "%s", it
> would be a dynamic-width field, which alone would not be ideal for
> binary format streams.
>
> The idea here is to make this compiled tracing a pure optimization:
> not to change the script input nor data output, but just to produce it
> quicker.

Thanks. I see.

> > [...] But in some situations I will put the print/trace statement in
> > embedded c codes to avoid the calls to function__dwarf_tvar_get*.
>
> If you don't call those tvar_get functions, how are you safely
> extracting target data?

> > One example is the struct scsi_cmnd in scsi trace hooks in LKET. I
> > need to retrieve 10 arguments from this struct. In the embedded c
> > codes they are only 10 assignments while in stap script they will be
> > extended to 10 function calls.
>
> In exchange for those function calls, you're getting safe
> dereferencing of all those values.  How much slowdown is
> that worth?

I run a series of tests to figure it out. I use the same single-thread 
application named app_getsid with will call getsid() in a loop, the 
results are:

<1> without probe

 cpu 0: loops=5000000, average=392 ns

<2> probe using LKET(2.stp): log 4 integers

 cpu 0: loops=5000000, average=2280 ns

<3> probe using LKET(3.stp): log 4 integers + visit 5 target variables

 cpu 0: loops=5000000, average=2445 ns

<4> probe using LKST(4.stp): log 4 integers

 cpu 0: loops=5000000, average=1710 ns

<5> probe using LKST(5.stp): log 4 integers + visit 5 target variables

 cpu 0: loops=5000000, average=1859 ns

The testing shows that visiting 5 target variables will cost ~150ns, 
and LKST is ~570ns faster than LKET if only log 4 integers. I think 
the compiled approach should have almost the same speed as <5>, so it 
will roughly be at least ~420ns faster than LKET.

But it's not common that the trace handler will visit a number of data 
members of a single struct. In most cases it will just visit different 
target variables and in such case LKET will also need the same number 
of tvar_get functions as the compiled approach does in script level.

Most target variables can be visited safely unless there is a bug in 
Kernel. Those target variables that could potentially have invalid 
values need explicitly checking before use them, and LKET needs a 
piece of c codes to check them. But we can't make sure every one 
doesn't miss some checking codes. So considering the benefit of 
tvar_get() and its cost, I think it is worth to use tvar_get().

The following is the stp scripts.

2.stp:

  function foo()
  %{
     _lket_trace(1, 1, "%8b%8b%8b%8b", 111,22,333,444);
  %}

  probe syscall.getsid {
    foo()
  }

3.stp:

 function foo(a:long, b:long, c:long, d:long, e:long)
  %{
      _lket_trace(1, 1, "%8b%8b%8b%8b", 111,22,333,444);
  %}

  probe syscall.getsid {
     foo($pid, $pid, $pid, $pid, $pid)
  }

4.stp:

  probe syscall.getsid {
     lkst_trace_n (4, 1, 12, 222, 333, 4444)
  }

5.stp:

  function foo:long(a:long, b:long, c:long, d:long, e:long)
  %{
     THIS->__retvalue = 0;
  %}

  probe syscall.getsid {
     foo($pid, $pid, $pid, $pid, $pid)
     lkst_trace_n (4, 1, 12, 222, 333, 4444)
  }

- Guanglei