This is the mail archive of the systemtap@sources.redhat.com 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]

runtime status


I've made a lot of changes in the runtime in the last week or so.

- _stp_stdout is a special String that writes to the transport. All the
print functions are now defines. For example,
#define _stp_printf(args...) _stp_sprintf(_stp_stdout,args)

- There are now register dump functions.  See current.c.  I'm interested
in feedback on the format of the dump, if we have any assembly programmers.
x86_64 dump looks like:

RIP: ffffffff801c0511
RSP: ffff81003746deb0  EFLAGS: 00000282
RAX: ffffffff801c0510 RBX: 0000000000000000 RCX: 0000000000000400
RDX: 0000000000000000 RSI: ffff81003746ded8 RDI: ffff81000fe98000
RBP: ffff81000fe98000 R08: ffff81003746ded4 R09: 0000000000000000
R10: 0000000000013cc0 R11: 0000000000000000 R12: 0000000000000400
R13: 0000000000506040 R14: 0000000000000400 R15: ffff81003746df50
FS:  00002aaaaaad1b00(0000) GS:ffffffff804e7a80(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000402f50 CR3: 0000000004622000 CR4: 00000000000006e0

- I've reimplemented the _stp_map_print() function to use
a custom format string. Special sequences start with '%'
If the next char is a number, it is a key number. The next char is the 
format.

--- KEYS and RESULTS ---
%p - address (hex padded to sizeof(void *))
%P - symbolic address
%x - hex int64
%X - HEX int64
%d - decimal int64
%s - string
--- STATS ---
%m - min
%M - max
%A - avg
%S - sum
%H - histogram
%C - count
--- MISC ---
%% - print '%'

So, "%d" is the value in decimal and "%1d" is key 1 in decimal.
A statistics example might look like:
"map[%1d] = count:%C  sum:%S  avg:%A  min:%m  max:%M\n%H"

And produce output like:
map[3] = count:49600  sum:3288450  avg:66  min:0  max:99
value |-------------------------------------------------- count
    0 |@@                                                  460
   10 |@@@@@@@                                            1460
   20 |@@@@@@@@@@@@                                       2460
   30 |@@@@@@@@@@@@@@@@@@                                 3460
   40 |@@@@@@@@@@@@@@@@@@@@@@@                            4460
   50 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@                       5460
   60 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@                 6460
   70 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@            7460
   80 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@       8460
   90 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  9460

Using the new format string, I updated the example probes. where_func
uses the following command
   _stp_map_print (funct_locations, "Count: %d\tCaller: %1P");
output now looks like this:

Count: 28538    Caller: 0xffffffff803461d3 : preempt_schedule+0x53/0x80
Count: 11715    Caller: 0xffffffff8014b281 : worker_thread+0x131/0x290
Count: 6831     Caller: 0xffffffff8013c58c : do_exit+0xbac/0xbc0
Count: 3690     Caller: 0xffffffff80135822 : migration_thread+0x212/0x3b0
Count: 8960     Caller: 0xffffffff8010ebe4 : retint_careful+0xd/0x21
Count: 4331     Caller: 0xffffffff8013d765 : do_wait+0xd95/0xf60
Count: 6460     Caller: 0xffffffff80346c76 : schedule_timeout+0x66/0x150
Count: 1        Caller: 0xffffffff80139044 : do_syslog+0x164/0x460
Count: 18293    Caller: 0xffffffff8010c8a7 : cpu_idle+0x57/0x60
Count: 18254    Caller: 0xffffffff80346d34 : schedule_timeout+0x124/0x150
Count: 1759     Caller: 0xffffffff80345178 : __down+0x98/0x110
Count: 3476     Caller: 0xffffffff8018f830 : pipe_wait+0xa0/0xf0
Count: 3066     Caller: 0xffffffff80346ba1 : io_schedule+0x31/0x40
Count: 10       Caller: 0xffffffff88048a15 : log_wait_commit+0xf5/0x150 [jbd]
Count: 1157     Caller: 0xffffffff80346123 : wait_for_completion+0xb3/0x110
Count: 35       Caller: 0xffffffff88048792 : kjournald+0x252/0x2f0 [jbd]
Count: 9        Caller: 0xffffffff88043838 : do_get_write_access+0x498/0x7a0 [jbd]
Count: 50       Caller: 0xffffffff801657bb : pdflush+0xbb/0x1f0
Count: 60       Caller: 0xffffffff80346aaf : cond_resched+0x2f/0x60
Count: 32       Caller: 0xffffffff8010e604 : sysret_careful+0xd/0x10
Count: 8        Caller: 0xffffffff803452bd : __down_interruptible+0xcd/0x140
Count: 70       Caller: 0xffffffff801351af : cond_resched_lock+0x8f/0xd0
Count: 21       Caller: 0xffffffff80347170 : __down_write+0x80/0xa0
Count: 10       Caller: 0xffffffff80347212 : __down_read+0x82/0x9a
Count: 1        Caller: 0xffffffff801b4941 : __mb_cache_entry_find+0xf1/0x230
Count: 182      Caller: 0xffffffff8016b905 : kswapd+0x125/0x150
Count: 144      Caller: 0xffffffff8013ef75 : ksoftirqd+0x45/0xe0

There is also a new probe called "scf" which demonstrates using a stack
trace as a map key and counting the number of times a function (in this case
smp_call_function()) is called via a particular path. Output looks like this:

trace[trace for 4026 (hald)
 0xffffffff8011a941 : smp_call_function+0x1/0x70
 0xffffffff80184996 : invalidate_bdev+0x26/0x70
 0xffffffff8019e148 : __invalidate_device+0x58/0x70
 0xffffffff8018aee9 : check_disk_change+0x39/0xa0
 0xffffffff802a89dc : cdrom_open+0xa2c/0xa70
 0xffffffff801343d0 : default_wake_function+0x0/0x10
 0xffffffff80347aa1 : _spin_unlock_irq+0x41/0x70
 0xffffffff80132c60 : finish_task_switch+0x40/0x90
 0xffffffff80347d93 : __reacquire_kernel_lock+0x73/0x90
 0xffffffff8034603a : thread_return+] = 12

trace[trace for 4026 (hald)
 0xffffffff8011a941 : smp_call_function+0x1/0x70
 0xffffffff80184996 : invalidate_bdev+0x26/0x70
 0xffffffff8018a45e : kill_bdev+0xe/0x30
 0xffffffff8018b03c : blkdev_put+0x7c/0x200
 0xffffffff80183bf6 : __fput+0x76/0x1a0
 0xffffffff801823ee : filp_close+0x7e/0xa0
 0xffffffff801824a3 : sys_close+0x93/0xc0
 0xffffffff8010e59a : system_call+0x7e/0x83
] = 12

(the internal string buffer truncated output in the first trace,
which is why the formatting looks a bit odd)

- Finally, I've implemented Counters and am working on Stats,  These are 
per-cpu aggregations. Stats are like map stats and have the ability to
include histograms or not.  If a Stat has histograms disabled, it just counts,
sums, and records min and max.  Are there any other aggregations we need?

Martin





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