From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 21051 invoked by alias); 14 Dec 2005 02:25:23 -0000 Received: (qmail 21029 invoked by uid 22791); 14 Dec 2005 02:25:22 -0000 X-Spam-Status: No, hits=-1.3 required=5.0 tests=AWL,BAYES_50 X-Spam-Check-By: sourceware.org Received: from tomts43-srv.bellnexxia.net (HELO tomts43-srv.bellnexxia.net) (209.226.175.110) by sourceware.org (qpsmtpd/0.31) with ESMTP; Wed, 14 Dec 2005 02:25:19 +0000 Received: from krystal.dyndns.org ([70.49.125.187]) by tomts43-srv.bellnexxia.net (InterMail vM.5.01.06.13 201-253-122-130-113-20050324) with ESMTP id <20051214022516.RURB23065.tomts43-srv.bellnexxia.net@krystal.dyndns.org> for ; Tue, 13 Dec 2005 21:25:16 -0500 Received: from localhost (localhost [127.0.0.1]) (uid 1000) by krystal.dyndns.org with local; Tue, 13 Dec 2005 21:25:15 -0500 id 000083F9.439F828B.0000587B Date: Wed, 14 Dec 2005 04:05:00 -0000 From: Mathieu Desnoyers To: ltt-dev@shafik.org, systemtap@sources.redhat.com Subject: Interoperability of LTTng and LTTV with SystemTAP Message-ID: <20051214022515.GA1488@Krystal> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Content-Transfer-Encoding: quoted-printable X-Editor: vi X-Info: http://krystal.dyndns.org:8080 X-Operating-System: Linux/2.4.31-grsec (i686) X-Uptime: 20:26:05 up 47 days, 3:25, 2 users, load average: 0.06, 0.01, 0.00 User-Agent: Mutt/1.5.11 X-Originating-IP: [0] X-IsSubscribed: yes Mailing-List: contact systemtap-help@sourceware.org; run by ezmlm Precedence: bulk List-Subscribe: List-Post: List-Help: , Sender: systemtap-owner@sourceware.org X-SW-Source: 2005-q4/txt/msg00431.txt.bz2 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 p= oints 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. Sim= ple plugins can show generically some information (detailed event list, for instance), while more sophisticated plugins can show a particular represent= ation 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 m= ore 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 numb= ers about how much information is transferred. Here is the first result : a tra= ce 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 ve= ry heavily loaded system (I will try ping -f and a few others) as soon as I ha= ve the time. I have also been asked about the impact of the copy of the information to d= isk 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, a= bout 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 c= pu 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 import= ant 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= =20 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. 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=20 12MB/651851 =3D 19.30 bytes per event OpenPGP public key: http://krystal.dyndns.org:8080/key/compudj= .gpg Key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68=20