From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 21401 invoked by alias); 17 Dec 2005 19:52:25 -0000 Received: (qmail 21389 invoked by uid 22791); 17 Dec 2005 19:52:23 -0000 X-Spam-Status: No, hits=-2.3 required=5.0 tests=AWL,BAYES_00 X-Spam-Check-By: sourceware.org Received: from tomts10.bellnexxia.net (HELO tomts10-srv.bellnexxia.net) (209.226.175.54) by sourceware.org (qpsmtpd/0.31) with ESMTP; Sat, 17 Dec 2005 19:52:21 +0000 Received: from krystal.dyndns.org ([70.49.125.187]) by tomts10-srv.bellnexxia.net (InterMail vM.5.01.06.13 201-253-122-130-113-20050324) with ESMTP id <20051217195219.WHVB14963.tomts10-srv.bellnexxia.net@krystal.dyndns.org> for ; Sat, 17 Dec 2005 14:52:19 -0500 Received: from localhost (localhost [127.0.0.1]) (uid 1000) by krystal.dyndns.org with local; Sat, 17 Dec 2005 14:52:17 -0500 id 0017A899.43A46C71.00000B67 Date: Sat, 17 Dec 2005 20:00:00 -0000 From: Mathieu Desnoyers To: ltt-dev@shafik.org, systemtap@sources.redhat.com Subject: Re: LTTng very heavy system usage scenario : probes Message-ID: <20051217195217.GA23138@Krystal> References: <20051214022515.GA1488@Krystal> <20051216010459.GA11668@Krystal> <20051217055851.GA30401@Krystal> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit Content-Disposition: inline In-Reply-To: <20051217055851.GA30401@Krystal> X-Editor: vi X-Info: http://krystal.dyndns.org:8080 X-Operating-System: Linux/2.4.31-grsec (i686) X-Uptime: 14:40:30 up 50 days, 21:39, 2 users, load average: 0.99, 1.07, 0.97 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/msg00469.txt.bz2 Oh, and I almost forgot the most important : Probe execution time at probe site : 220ns/event 220ns*9588836 = 2.11s Ratio of probe time / cpu time used 2.11/(25.57-7.297325362) = 11.55% Ratio of probe time / cpu time available 2.11/25.57 = 8.25% * Mathieu Desnoyers (compudj@krystal.dyndns.org) wrote: > Well, I finally managed to finish my brand new LTTng+LTTV implementation. This > third usage scenario has been made with it. > > I tried something that always turns out to make tracers dead : a loopback ping > flood (ping -f 127.0.0.1). Here are the results :-) > > Mathieu > > > Usage scenario 3 > > Very heavy system usage (ping flood on the loopback pseudo interface) > > Tests made on a 3Ghz pentium 4, with hyperthreading enabled. > > Trace taken with LTTng 0.5.0 > > No event has been lost while tracing. > > (units are in seconds) > > Trace duration : 12.785209485 > Total cpu time available (approximately : it's hyperthreading...) : 25.57s > Trace size : 176M > > Trace data rate : 13.76MB/s > > idle cpu time : 7.297325362s (sum of the two HT cpus) > System load : (25.57-7.297325362)/25.57 = 71.5% > > > lttd cpu time (process 4773 in the trace) > > usermode : 3.613249328 > traps : none > irqs : > 21 (3com 3c940 10/100/1000Base-T) : 0.094693456 > 0 (timer) : 0.015632051 > 19 (USB and IDE) : 0.000242789 > system calls : > unknown (beginning of trace) : 0.000024347 > 175 (rt_sigprocmask) : 0.352830699 > 3 (read) : 0.697699884 > 142 (newselect) : 2.055746440 > 4 (write) : 1.522248853 > 54 (ioctl) : 0.000014157 > > Total cpu time accountable to process : > usermode + traps + system calls > 8.241813708 > > > ratio of time for write / cpu time used : > 45.10% > > ratio of time for write / cpu time available (doesn't mean much with HT) : > 32.23% > > > Overall information on the trace > > event count 9588836 > > Event rate : 749994 events per second > > detail per event type (38 event types) > > Statistic for 'event_types' : > > state_dump_facility_load : 10 > exit : 3 > wait : 17 > free : 3 > fork : 3 > schedchange : 42076 > syscall_entry : 2297497 > write : 427383 > wakeup : 37268 > soft_irq_entry : 309692 > softirq : 25105 > soft_irq_exit : 309692 > read : 166746 > syscall_exit : 2297497 > expired : 258 > irq_exit : 170318 > packet_in : 259254 > irq_entry : 170318 > tasklet_entry : 62 > tasklet_exit : 62 > packet_out : 408715 > trap_exit : 2448 > call : 386428 > recvmsg : 258803 > close : 93 > trap_entry : 2448 > select : 1406394 > buf_wait_start : 19 > page_alloc : 478581 > buf_wait_end : 19 > create : 8 > sendmsg : 127608 > poll : 3449 > ioctl : 443 > open : 79 > set_itimer : 11 > page_free : 3 > exec : 4 > seek : 19 > > > > > OpenPGP public key: http://krystal.dyndns.org:8080/key/compudj.gpg > Key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68 > OpenPGP public key: http://krystal.dyndns.org:8080/key/compudj.gpg Key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68