Interoperability of LTTng and LTTV with SystemTAP

[Mathieu Desnoyers <compudj at krystal dot dyndns dot org>]

Hi,

I just had a discussion with Frank Ch. Eigler from the SystemTAP team on the
topic "how can the tools cooperate well together".

SystemTAP is especially made for running user defined scripts at specific points
in the kernel. I has the ability to add/remove scripts and instrumentation
dynamically from a running kernel.

LTTng is a kernel tracer designed to have the minimum impact on the system while
having a design solid enough that it can trace NMI handlers (no locking). It
supports native C types and alignment. It can register new instrumentation sites
from dynamically loaded modules on-the-fly.

LTTV is a modular text/graphical trace analysis tool. You can think of it as
framework offered for plugins to interact together to show information. Simple
plugins can show generically some information (detailed event list, for
instance), while more sophisticated plugins can show a particular representation
of the system (each process state (user mode, system call, interrupted,
in trap, ...) evolving through time).

While the SystemTAP project focus on pre-processing of the information, LTT
focus on raw data copy (limiting the impact at probe site) at the cost of more
data to be transferred and analysed afterward.

I think that both approaches are complementary. I am trying to see where
integrated analysis of pre-processed and post-processed information could be
interesting, but I'm sure there are areas where it is.

If you have application ideas, feel free to express yourself.


-- end of the "discussion initiation" part, now with the technical part :

Frank asked me, at the end of our IRC discussion, if I could send some numbers
about how much information is transferred. Here is the first result : a trace
taken on a system used for start/stop of web broser (mozilla) and doing a "find"
on the root of the system. I plan to do the same on heavily loaded
system (I am trying to get an heavy commercial application for this) and very
heavily loaded system (I will try ping -f and a few others) as soon as I have
the time.

I have also been asked about the impact of the copy of the information to disk
on the system behavior. The percentage of cpu time used is not relevant in this
first usage scenario because the system was most of the time idle. Still, about
1.79% (cpu 0) and 1.89% (cpu 1) of cpu time has been used by the disk writer
daemon, which is not much considering that the system usage was 6.78% for cpu 0
and 9.79% for cpu 1. A heavily loaded system will give us a better insight.

However, I would say that probe effect at the call site is much more important
than the effect of a much lower priority disk writer daemon. For the probe
effect, the microbenchmarks I made tells that logging an event takes about 
220 ns.

Here are the results. Note that I have taken a short trace (15 seconds) just
because I was in a hurry before preparing a presentation at that moment.


<begin>

LTTng 0.4.3

Usage scenarios

Scenario 1 (low event rate)

Web browsing and using find (low event rate)
12MB trace, duration : 15.079714935 seconds
2MB per-cpu buffers used, written to disk 1MB at a time by the daemon.

The machine is a 3Ghz Pentium 4 with hyperthread. Each virtual CPU is seen as
a physical one by the kernel, except for the scheduler.

All the instrumentation set of LTTng is active. See
http://ltt.polymtl.ca/packages/LinuxTraceToolkitViewer-0.6.9-10102005.tar.gz
directory facilities for the description of the structures of events logged.


trace :

(units are in seconds)

real time :
start 16591.856649974
end 16606.936364909

trace duration : 15.079714935

(idle time is the time spent doing nothing (syscall mode) at process 0.
idle time on cpu 0 : 14.056580720
idle time on cpu 1 : 13.692558631

cpu 0 : total CPU time used : 1.023134215
        cpu 0 is used at 6.78%
cpu 1 : total CPU time used : 1.387156304
        cpu 1 is used at 9.19%

lttd (cpu time) (note : the daemon is currently non multithreaded)

cpu 0 :

usermode : 0.000098216
trap 14 (page fault) : 0.000192750 (count : 258)
irqs :
0 (timer) : 0.000157657
16 (audio) : 0.000079536
system calls :
none (unknown at the beginning of the trace) : 0.000799137
4 (write) : 0.016877408
54 (ioctl) : 0.000019114
168 (poll) : 0.000766053

Total cpu time accountable to the process :
usermode + traps + system calls
0.017953541


cpu 1 :

usermode : 0.000094188
trap 14 (page fault) : 0.000761918 (count : 771)
irqs : none
system calls :
4 (write) : 0.017939435
54 (ioctl) : 0.000021459
168 (poll) : 0.007352545

Total cpu time accountable to the process :
usermode + traps + system calls
0.026169545


ratio of time for write / cpu time :
cpu 0 : 1.75%
cpu 1 : 1.89%

ratio of time for write / real time :
cpu 0 : 0.12%
cpu 1 : 0.17%


overall event count (for the whole 15.079714935s trace):

events count :  651851

detail per event type (40 different event types) :

state_dump_facility_load :  10
wait :  326
fork :  24
exit :  24
free :  24
kernel_thread :  4
syscall_exit :  75564
trap_exit :  30149
syscall_entry :  75562
call :  84
recvmsg :  152
close :  1915
wakeup :  14614
schedchange :  21141
soft_irq_entry :  31313
softirq :  29477
soft_irq_exit :  31313
tasklet_entry :  1714
tasklet_exit :  1714
expired :  2563
trap_entry :  30149
irq_entry :  16169
irq_exit :  16169
packet_in :  6
packet_out :  7
sendmsg :  3237
select :  213105
write :  9974
page_alloc :  8661
read :  19378
set_itimer :  1232
ioctl :  7066
buf_wait_start :  20
buf_wait_end :  19
open :  1826
poll :  5762
page_free :  5
exec :  17
seek :  1345
shm_create :  2
create :  15

The per record data amount per record is statistically 
12MB/651851 = 19.30 bytes per event


<end>



OpenPGP public key:              http://krystal.dyndns.org:8080/key/compudj.gpg
Key fingerprint:     8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68