This is the mail archive of the systemtap@sourceware.org mailing list for the systemtap project.


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]
Other format: [Raw text]

Re: LTTng very heavy system usage scenario : probes


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 


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]