Re: binary tracing

[Tom Zanussi <zanussi at us dot ibm dot com>]

Wanting to see whether it would make much difference if instead of
calling bin_write() at runtime for binary-only tracing, the translator
could generate the corresponding tracing code at translation time, I
hand-translated the bin_write_example in bug #2307 into an equivalent
form similar to what I thought the translator might generate.  In
fact, some of the probe code is copied from the output of code the
translator generated - to try this example on your system, you'll need
to replace the portions that contain dwarf info e.g. $fd, $count, etc.
Aside from those parts, though, the 'translated' code was made up by
me and while I did try to get some idea of the kind of code the
translator might generate for this, it may or may not be that close to
what the translator would actually output; for comparison with the
original bin_write example, though, it should be similar enough for
that purpose.

The attached tarball contains a patch to systemtap - since it doesn't
use bin_write(), it doesn't include bin_write.c, and it doesn't
actually make any changes to the runtime other than to comment out a
vlog print that was getting in the way of parsing the data in stpd.
It does add _stp_reserve() (in the probe code for now), which is used
to directly reserve space for the event in the relayfs buffer and
which the translated code generates the output into.  It also includes
the same changes to stpd/librelay that the bin_write example did
i.e. the print_binary output handler in place of merge().

To compare the bin_write() version and the 'compiled' versions, I just
used rdtsc at the beginning and end of the code that actually writes
the events; the two events that are instrumented are sys_read() and
sys_open(), which is what the timing output refers to.  The test
machine was a 3Ghz Pentium 4.  Basically, the timing output shows a
larger difference for sys_read(), where the data is mostly binary, and
not much difference for sys_open(), which is dominated by strings in
the data.

normal bin_write:

events_processed: 125584

Apr  5 22:05:24 lab klogd: total_read_cycles: 197619680
Apr  5 22:05:24 lab klogd: total_read_events: 45522
Apr  5 22:05:24 lab klogd: avg cycles/event (tracing read): 4341

Apr  5 22:05:24 lab klogd: total_open_cycles: 418164808
Apr  5 22:05:24 lab klogd: total_open_events: 80060
Apr  5 22:05:24 lab klogd: avg cycles/event (tracing open): 5223


compiled bin_write:

events_processed: 125707

Apr  5 21:52:47 lab klogd: total_read_cycles: 155600620
Apr  5 21:52:47 lab klogd: total_read_events: 45641
Apr  5 21:52:47 lab klogd: avg cycles/read event: 3409

Apr  5 21:52:47 lab klogd: total_open_cycles: 390740564
Apr  5 21:52:47 lab klogd: total_open_events: 80064
Apr  5 21:52:47 lab klogd: avg cycles/open event: 4880


I also did a couple runs but with the do_gettimeofday() call removed
and constants logged in its place, since it accounts for most of the
time in the numbers.

normal bin_write, no do_gettimeofday():

events_processed: 125579

Apr  5 22:08:46 lab klogd: total_read_cycles: 68971944
Apr  5 22:08:46 lab klogd: total_read_events: 45516
Apr  5 22:08:46 lab klogd: avg cycles/event (tracing read): 1515

Apr  5 22:08:46 lab klogd: total_open_cycles: 189553812
Apr  5 22:08:46 lab klogd: total_open_events: 80061
Apr  5 22:08:46 lab klogd: avg cycles/event (tracing open): 2367


compiled bin_write, no do_gettimeofday():

events_processed: 125695

Apr  5 21:56:43 lab klogd: total_read_cycles: 30247028
Apr  5 21:56:43 lab klogd: total_read_events: 45630
Apr  5 21:56:43 lab klogd: avg cycles/read event: 662

Apr  5 21:56:43 lab klogd: total_open_cycles: 172557104
Apr  5 21:56:43 lab klogd: total_open_events: 80063
Apr  5 21:56:43 lab klogd: avg cycles/open event: 2155

Tom

PS our mail server is still down, so while I can send mail, I can't
read it, so won't be able to reply to anything until it's back up...

Attachment: compiled-bin-write.tar.gz
Description: 'compiled' bin_write example prototype