Customization of LKET

Customization of LKET

[Li Guanglei]

[-- Attachment #1: Type: text/plain, Size: 2547 bytes --]

Hi folks,

  I had a talk with Jose last week and we think it would be useful to
make the user able to append extra data on the trace at script level.

  Of course the user could modify the tapsets in tapset/LKET to let
_lket_trace() log more data. But it's not a convenient way. It's
obvious that a function like printf() at script level is better, i.e:

 probe addevent.pagefault
 {
    lket_trace_extra("%4b", $numa_node)
 }

 lket_trace_extra is defined as:

#define _lket_trace_extra(fmt, args...)  do {\
        _stp_printf("%1b%2n%0s"fmt, LKET_PKT_USER, fmt, args);\
} while(0)

  I modified systemtap to make it able to support lket_trace_extra at
script level. In fact, lket_trace_extra has the same signature as
printf, the difference is that printf will be turned into
_stp_printf() in pass 3 while lket_trace_extra will be turned into
_lket_trace_extra(). Attached is a draft patch against 0527 snapshot
for this.

  But there is a trouble here. Now we use epilogue mode alias to
support backtrace. For these aliases, it will always put
_lket_trace_extra() before the original lket_trace, e.g:

probe addevent.scsi.ioentry
{
    lket_trace_extra(...)
}
will be expanded as:

probe module("scsi_mod").function("scsi_prep_fn")
{
  ...
    lket_trace_extra(...)
    log_scsi_ioentry(HOOKID_SCSI_IOENTRY, _dwarf_tvar_get_q_3(), ...
}

You can see that lket_trace_extra() is put before log_scsi_ioentry().

So I think we should reconsider the current way of logging backtrace

I suggest we should not use epilogue mode alias for backtrace logging.
So there seem to me two alternatives. The first one is to log
backtrace in lket_trace_extra, i.e:

probe addevent.pagefault
{
   lket_trace_extra("%4b%0s", $numa_node, backtrace())
}
But there is trouble that MAXSTRINGLEN is defined as 128 so backtrace
string will be truncated. Simply raising MAXSTRINGLEN will cause a lot
of waste of memory.

So I think we could use the second way. We defined a new function that
dedicated for backtrace:

function lket_backtrace () %{
  if (CONTEXT->regs) {
      String str = _stp_string_init (0);
      _stp_stack_sprint (str, CONTEXT->regs, 0);
      _stp_printf("%1b%2n%0s", LKET_PKT_BT, _stp_string_ptr(str));
  }
%}

Then the user could:

probe addevent.pagefault
{
   lket_backtrace()
   lket_trace_extra("%4b%0s", $numa_node, backtrace())
}

Then he can add as more extra data by lket_trace_extra() as he like
and the post-processing app(lket-b2a) could recognize the format of
these extra data.

Do you have any comments about this?

Thanks.





[-- Attachment #2: Patch --]
[-- Type: text/plain, Size: 1672 bytes --]

--- src/parse.cxx	2006-05-25 17:39:37.000000000 -0400
+++ src.mod/parse.cxx	2006-05-30 07:12:50.000000000 -0400
@@ -2082,12 +2082,22 @@ parser::parse_symbol () 
       else if (name.size() > 0 && (name == "print"
 				   || name == "sprint"
 				   || name == "printf"
-				   || name == "sprintf"))
+				   || name == "sprintf"
+				   || name == "lket_trace_extra"))
+
 	{
 	  print_format *fmt = new print_format;
 	  fmt->tok = t;
 	  fmt->print_with_format = (name[name.size() - 1] == 'f');
 	  fmt->print_to_stream = (name[0] == 'p');
+
+          if(name == "lket_trace_extra")
+            {
+                fmt->print_with_format = 1;
+                fmt->print_to_stream = 1;
+                fmt->lket_trace_extra = 1;
+            }
+
 	  expect_op("(");
 	  if (fmt->print_with_format)
 	    {
--- src/staptree.h	2006-05-18 19:11:22.000000000 -0400
+++ src.mod/staptree.h	2006-05-30 07:13:20.000000000 -0400
@@ -261,6 +261,7 @@ struct print_format: public expression
 {
   bool print_with_format;
   bool print_to_stream;
+  bool lket_trace_extra;
 
   enum format_flag
     {
--- src/translate.cxx	2006-05-24 22:03:01.000000000 -0400
+++ src.mod/translate.cxx	2006-05-30 07:14:25.000000000 -0400
@@ -3591,7 +3591,10 @@ c_unparser::visit_print_format (print_fo
       if (e->print_to_stream)
         {
           o->newline() << res.qname() << " = 0;";
-          o->newline() << "_stp_printf (";
+          if( e->lket_trace_extra)
+                  o->newline() << "_lket_trace_extra (";
+          else
+                  o->newline() << "_stp_printf (";
         }
       else
 	o->newline() << "_stp_snprintf (" << res.qname() << ", MAXSTRINGLEN, ";

Re: Customization of LKET

[Li Guanglei]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset=GB2312, Size: 867 bytes --]

Li Guanglei дµÀ:
> 
>   I modified systemtap to make it able to support lket_trace_extra at
> script level. In fact, lket_trace_extra has the same signature as
> printf, the difference is that printf will be turned into
> _stp_printf() in pass 3 while lket_trace_extra will be turned into
> _lket_trace_extra(). Attached is a draft patch against 0527 snapshot
> for this.

  After some testing, I found there are some bugs in this patch. Here
is an updated patch.

  The LKET's tapsets also need some changes. Now if a use want to
append extra trace data, he could use lket_trace_extra() at script
level and he can also call as many times of lket_trace_extra &
lket_backtrace as he want, e.g:

probe addevent.pagefault
{
  lket_trace_extra("%4b%0s", $numa_node, "testing str")
  lket_backtrace()
  lket_trace_extra(%8b", $address)
}

Any comments?

- Guanglei



[-- Attachment #2: patch-lket_trace_extra --]
[-- Type: text/plain, Size: 2466 bytes --]

--- src/parse.cxx	2006-05-25 17:39:37.000000000 -0400
+++ src.mod/parse.cxx	2006-05-31 08:06:58.000000000 -0400
@@ -2082,12 +2082,23 @@ parser::parse_symbol () 
       else if (name.size() > 0 && (name == "print"
 				   || name == "sprint"
 				   || name == "printf"
-				   || name == "sprintf"))
+				   || name == "sprintf"
+				   || name == "lket_trace_extra"))
 	{
 	  print_format *fmt = new print_format;
 	  fmt->tok = t;
 	  fmt->print_with_format = (name[name.size() - 1] == 'f');
 	  fmt->print_to_stream = (name[0] == 'p');
+
+	  fmt->lket_trace_extra = false;
+
+          if(name == "lket_trace_extra")
+            {
+                fmt->print_with_format = true;
+                fmt->print_to_stream = true;
+                fmt->lket_trace_extra = true;
+            }
+
 	  expect_op("(");
 	  if (fmt->print_with_format)
 	    {
--- src/staptree.h	2006-05-18 19:11:22.000000000 -0400
+++ src.mod/staptree.h	2006-05-30 07:13:20.000000000 -0400
@@ -261,6 +261,7 @@ struct print_format: public expression
 {
   bool print_with_format;
   bool print_to_stream;
+  bool lket_trace_extra;
 
   enum format_flag
     {
--- src/staptree.cxx	2006-05-18 19:11:22.000000000 -0400
+++ src.mod/staptree.cxx	2006-05-31 08:05:51.000000000 -0400
@@ -626,6 +626,7 @@ void print_format::print (ostream& o) co
   string name = (string(print_to_stream ? "" : "s") 
 		 + string("print") 
 		 + string(print_with_format ? "f" : ""));
+  if(lket_trace_extra)  name="lket_trace_extra";
   o << name << "(";
   if (print_with_format)
     {
@@ -2203,6 +2204,7 @@ deep_copy_visitor::visit_print_format (p
   n->tok = e->tok;
   n->print_with_format = e->print_with_format;
   n->print_to_stream = e->print_to_stream;
+  n->lket_trace_extra = e->lket_trace_extra;
   n->raw_components = e->raw_components;
   n->components = e->components;
   for (unsigned i = 0; i < e->args.size(); ++i)
--- src/translate.cxx	2006-05-24 22:03:01.000000000 -0400
+++ src.mod/translate.cxx	2006-05-31 08:04:35.000000000 -0400
@@ -3591,7 +3591,10 @@ c_unparser::visit_print_format (print_fo
       if (e->print_to_stream)
         {
           o->newline() << res.qname() << " = 0;";
-          o->newline() << "_stp_printf (";
+          if(e->lket_trace_extra)
+                  o->newline() << "_lket_trace_extra (";
+          else
+                  o->newline() << "_stp_printf (";
         }
       else
 	o->newline() << "_stp_snprintf (" << res.qname() << ", MAXSTRINGLEN, ";

Re: Customization of LKET

[Frank Ch. Eigler]

Li Guanglei <guanglei@cn.ibm.com> writes:

> I had a talk with Jose last week and we think it would be useful to
> make the user able to append extra data on the trace at script
> level.

It was this kind of flexibility in mind that I proposed the "compiled"
binary tracing alternative in
<http://sourceware.org/ml/systemtap/2006-q1/msg00277.html>.  It was
more recently been mentioned indirectly by Tom in
<http://sourceware.org/ml/systemtap/2006-q2/msg00070.html>.  This
would be a more general solution to flexible & incremental
construction of binary trace records.


> Of course the user could modify the tapsets in tapset/LKET to let
> _lket_trace() log more data. But it's not a convenient way. It's
> obvious that a function like printf() at script level is better, i.e:
> [...]
>     lket_trace_extra("%4b", $numa_node)
> [...]
> #define _lket_trace_extra(fmt, args...)  do {\
>         _stp_printf("%1b%2n%0s"fmt, LKET_PKT_USER, fmt, args);\
> } while(0)

I must say I don't much like this approach.  Is the only point
here to add "LKET_PKT_USER" as a constant byte into the printf?

> I modified systemtap to make it able to support lket_trace_extra at
> script level. [...]

Modify LKET tapset sources at will, but please consider
application-specific changes to the translator proper as possibly
controversial, and allow more time for review.


> [...]
> probe addevent.pagefault
> {
>    lket_trace_extra("%4b%0s", $numa_node, backtrace())
> }
> But there is trouble that MAXSTRINGLEN is defined as 128 so backtrace
> string will be truncated. Simply raising MAXSTRINGLEN will cause a lot
> of waste of memory.

It would be wise to test that assumption.  Remember that the
translator uses a statically allocated array for local values like
string temporaries.  Temporaries for adjacent statements are overlaid.
The overall size of the context structure may be small enough even
with a quadrupled MAXSTRINGLEN for it to work out fine.  Test it and
see.


> Then the user could:
> probe addevent.pagefault
> {
>    lket_backtrace()
>    lket_trace_extra("%4b%0s", $numa_node, backtrace())
> }
> Then he can add as more extra data by lket_trace_extra() as he like
> and the post-processing app(lket-b2a) could recognize the format of
> these extra data.

This whole area seems pretty messy.  Let's think about it for a little
longer before committing to a solution.


- FChE

Re: Customization of LKET

[Li Guanglei]

Frank Ch. Eigler ??:
> Li Guanglei <guanglei@cn.ibm.com> writes:
> 
>> I had a talk with Jose last week and we think it would be useful to
>> make the user able to append extra data on the trace at script
>> level.
> 
> It was this kind of flexibility in mind that I proposed the "compiled"
> binary tracing alternative in
> <http://sourceware.org/ml/systemtap/2006-q1/msg00277.html>.  It was
> more recently been mentioned indirectly by Tom in
> <http://sourceware.org/ml/systemtap/2006-q2/msg00070.html>.  This
> would be a more general solution to flexible & incremental
> construction of binary trace records.
> 

Thanks. I will think about it.

> 
>> Of course the user could modify the tapsets in tapset/LKET to let
>> _lket_trace() log more data. But it's not a convenient way. It's
>> obvious that a function like printf() at script level is better, i.e:
>> [...]
>>     lket_trace_extra("%4b", $numa_node)
>> [...]
>> #define _lket_trace_extra(fmt, args...)  do {\
>>         _stp_printf("%1b%2n%0s"fmt, LKET_PKT_USER, fmt, args);\
>> } while(0)
> 
> I must say I don't much like this approach.  Is the only point
> here to add "LKET_PKT_USER" as a constant byte into the printf?

lket_trace_extra is actually a wrapper around printf. Actually the 
user could directly use printf if he could remember to add 
"%1b%2n%0s". LKET_PKT_USER and %2n is used by post-processing app to 
properly found the boundary of the record. %0s(fmt) is also used by 
post-processing app to correctly decode the user appended trace data.

So the reason I use lket_trace_extra() is that I want to hide 
something from the user since I can't expect everyone following the 
rules of adding extra data.

But I have to confess that it seems a waste to introduce such a new 
function into systemtap's translator. It seems too application 
specific. A more generic trace facilities at script level is more 
meaningful.

Before we find the final solution, I think I can use a temp solution, 
that is:
   _lket_trace() add a magic number(4 or 8 bytes) at the beginning of 
record to specify the boundary of every record.
   The user can just use printf to add extra data, no LKET_PKT_USER 
flag and %2n is needed. lket-b2a can simply dump all the extra data in 
hex mode, or we introduce a function: register_eventhook(GRPID:long, 
HOOKID:long, Format:string) for user to register the format of his 
extra data. But I think the later seems better.
   I am not sure this is a good idea but at least it won't need to 
modify translator :-)

I am thinking of revert my changes of lket_trace_extra() to translator.

> 
>> I modified systemtap to make it able to support lket_trace_extra at
>> script level. [...]
> 
> Modify LKET tapset sources at will, but please consider
> application-specific changes to the translator proper as possibly
> controversial, and allow more time for review.
> 
> 
>> [...]
>> probe addevent.pagefault
>> {
>>    lket_trace_extra("%4b%0s", $numa_node, backtrace())
>> }
>> But there is trouble that MAXSTRINGLEN is defined as 128 so backtrace
>> string will be truncated. Simply raising MAXSTRINGLEN will cause a lot
>> of waste of memory.
> 
> It would be wise to test that assumption.  Remember that the
> translator uses a statically allocated array for local values like
> string temporaries.  Temporaries for adjacent statements are overlaid.
> The overall size of the context structure may be small enough even
> with a quadrupled MAXSTRINGLEN for it to work out fine.  Test it and
> see.

I tested using a simple script:
function foo()
%{
         _stp_printf("%d\n", sizeof(struct context));
%}
probe addevent.syscall.*
{
         printf("%s\n", "aa")
         foo()
}

it shows that the size of context will increase from 6608 to 51408  if 
MAXSTRINGLEN is defined as 1024. Seems acceptable, right?

> 
> 
> - FChE

Re: Customization of LKET

[Frank Ch. Eigler]

Hi -

On Fri, Jun 02, 2006 at 11:19:37AM +0800, Li Guanglei wrote:
> [...]
> But I have to confess that it seems a waste to introduce such a new
> function into systemtap's translator. It seems too application
> specific. A more generic trace facilities at script level is more
> meaningful.

That's what I was thinking.

> Before we find the final solution, I think I can use a temp solution [...]

It's worth the try.

> I am thinking of revert my changes of lket_trace_extra() to
> translator.

Sure.

> >[...]  The overall size of the context structure may be small
> >enough even with a quadrupled MAXSTRINGLEN for it to work out fine.
> >Test it and see.
>
> I tested using a simple script:

Thank you!

> [...]  it shows that the size of context will increase from 6608 to
> 51408 if MAXSTRINGLEN is defined as 1024. Seems acceptable, right?

My understanding is that a number below 64K is fine.  I expect that we
can have another round of context size reduction with translator
improvements.  One possibility is to have it detect absence of
recursion, to let it compute a minimal MAXNESTING parameter.

- FChE

Re: Customization of LKET

[Li Guanglei]

Li Guanglei ??:
> Frank Ch. Eigler ??:
> 
> lket_trace_extra is actually a wrapper around printf 
 > [...]
 > I am thinking of revert my changes of lket_trace_extra() to
 > translator.

I though of another way of allowing the user add arbitrary extra trace 
data using just printf. It has the same convenience as deprecated 
lket_trace_extra(), no flag/%2n is needed, no changes to translator is 
needed, and user can call printf() multiple times. I implemented it 
and tested it for a while, and it worked fine for me.

And I think we can also add a function register_user_event() whose 
signature is:
   function register_user_event(grpid:long, hookid:long, fmt:string,
      name:string)
Then event register provides a way to tell the post-processing app the 
data/name of the extra trace data

The following shows an example of the above:

probe addevent.regevt
{
     register_user_event(GROUP_NETDEV, HOOKID_NETDEV_RECEIVE,
	"STRING:INT8:INT16", "sample string:sample id1:sample id2")
}

probe addevent.netdev.receive
{
     printf("%0s%1b%2b", "sample str", 11, 112)
}

Basically, this new way of user customizable tracing is done by a 
function named update_record() which will is called in a epilogue mode 
alias so it will be the last one to be called and it will update the 
total length of the trace data according to _stp_pbuf_len[cpu], 
including those logged by _lket_trace() and printf(). Every trace 
record has the format of:

total_len, sys_len(without user trace data), groupid, hookid, ...

> it shows that the size of context will increase from 6608 to 51408  if 
> MAXSTRINGLEN is defined as 1024. Seems acceptable, right?
> 
I want also delete backtrace() function now. If a user want to print 
backtrace, he can just use printf and backtrace() function, e.g:
   printf("%1b%0s", 11, backtrace())

Any comments?

- Guanglei

Re: Customization of LKET

[Frank Ch. Eigler]

Li Guanglei <guanglei@cn.ibm.com> writes:

> [...]
> I though of another way of allowing the user add arbitrary extra trace
> data using just printf. [...]
>      register_user_event(GROUP_NETDEV, HOOKID_NETDEV_RECEIVE,
> 	"STRING:INT8:INT16", "sample string:sample id1:sample id2")
> [...]

Yes, this could work, though the script author will have to make the
register declarative call match his later actual usage.

It is worth realizing though that this is just the kind of metadata
that the "compiled" binary tracing we proposed could provide
automatically.

- FChE